Check-in [e4fd58cbb9]
Overview
Comment:Added timing information to debug output

Fixed issue where readers that were removed and readded weren't connected to properly

Downloads: Tarball | ZIP archive | SQL archive
Timelines: family | ancestors | descendants | both | trunk
Files: files | file ages | folders
SHA1: e4fd58cbb96569e996100be1b6929ecc429e3f95
User & Date: rkeene on 2010-07-23 21:23:41
Other Links: manifest | tags
Context
2010-07-23
21:46
Consolidated slot resetting into a single function.

Updated slot resetting to invalidate slot PC/SC handle. check-in: 1edf82bc16 user: rkeene tags: trunk

21:23
Added timing information to debug output

Fixed issue where readers that were removed and readded weren't connected to properly check-in: e4fd58cbb9 user: rkeene tags: trunk

17:24
Fixed retry on NOT_TRANSACTED to retry at a higher level

Consolidated all SCardReconnect calls into a wrapper that takes care of T=0 or T=1 selection check-in: 93bc06dab6 user: rkeene tags: trunk

Changes

Modified cackey.c from [5f33c366a8] to [5667b1108e].

164
165
166
167
168
169
170







171
172
173
174
175
176
177
178
179
180
181

182
183
184
185
186
187
188
189
190
191
192
193
194
195

196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213

214
215
216
217
218
219
220
#define GSCIS_AID_CCC                 0xA0, 0x00, 0x00, 0x01, 0x16, 0xDB, 0x00

/* Maximum size of data portion of APDUs */
/** Do not set this above 250 **/
#define CACKEY_APDU_MTU               250

#ifdef CACKEY_DEBUG








#  define CACKEY_DEBUG_PRINTF(x...) { fprintf(stderr, "%s():%i: ", __func__, __LINE__); fprintf(stderr, x); fprintf(stderr, "\n"); fflush(stderr); }
#  define CACKEY_DEBUG_PRINTBUF(f, x, y) { unsigned char *TMPBUF; unsigned long idx; TMPBUF = (unsigned char *) (x); fprintf(stderr, "%s():%i: %s  (%s/%lu = {%02x", __func__, __LINE__, f, #x, (unsigned long) (y), TMPBUF[0]); for (idx = 1; idx < (y); idx++) { fprintf(stderr, ", %02x", TMPBUF[idx]); }; fprintf(stderr, "})\n"); fflush(stderr); }
#  define CACKEY_DEBUG_PERROR(x) { fprintf(stderr, "%s():%i: ", __func__, __LINE__); perror(x); fflush(stderr); }
#  define free(x) { CACKEY_DEBUG_PRINTF("FREE(%p) (%s)", x, #x); free(x); }

static void *CACKEY_DEBUG_FUNC_MALLOC(size_t size, const char *func, int line) {
	void *retval;

	retval = malloc(size);


	fprintf(stderr, "%s():%i: ", func, line);
	fprintf(stderr, "MALLOC() = %p", retval);
	fprintf(stderr, "\n");
	fflush(stderr);

	return(retval);
}

static void *CACKEY_DEBUG_FUNC_REALLOC(void *ptr, size_t size, const char *func, int line) {
	void *retval;

	retval = realloc(ptr, size);

	if (retval != ptr) {

		fprintf(stderr, "%s():%i: ", func, line);
		fprintf(stderr, "REALLOC(%p) = %p", ptr, retval);
		fprintf(stderr, "\n");
		fflush(stderr);
	}

	if (retval == NULL) {
		CACKEY_DEBUG_PRINTF(" *** ERROR *** realloc returned NULL (size = %lu)", (unsigned long) size);
	}

	return(retval);
}

static char *CACKEY_DEBUG_FUNC_STRDUP(const char *ptr, const char *func, int line) {
	char *retval;

	retval = strdup(ptr);


	fprintf(stderr, "%s():%i: ", func, line);
	fprintf(stderr, "STRDUP_MALLOC() = %p", retval);
	fprintf(stderr, "\n");
	fflush(stderr);

	return(retval);
}







>
>
>
>
>
>
>

|
|
|







>














>


















>







164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
#define GSCIS_AID_CCC                 0xA0, 0x00, 0x00, 0x01, 0x16, 0xDB, 0x00

/* Maximum size of data portion of APDUs */
/** Do not set this above 250 **/
#define CACKEY_APDU_MTU               250

#ifdef CACKEY_DEBUG
#  ifdef HAVE_TIME_H
#    include <time.h>
static time_t cackey_debug_start_time = 0;
#    define CACKEY_DEBUG_PRINTTIME { if (cackey_debug_start_time == 0) { cackey_debug_start_time = time(NULL); }; fprintf(stderr, "[%lu]: ", (unsigned long) (time(NULL) - cackey_debug_start_time)); }
#  else
#    define CACKEY_DEBUG_PRINTTIME /**/
#  endif

#  define CACKEY_DEBUG_PRINTF(x...) { CACKEY_DEBUG_PRINTTIME; fprintf(stderr, "%s():%i: ", __func__, __LINE__); fprintf(stderr, x); fprintf(stderr, "\n"); fflush(stderr); }
#  define CACKEY_DEBUG_PRINTBUF(f, x, y) { unsigned char *TMPBUF; unsigned long idx; TMPBUF = (unsigned char *) (x); CACKEY_DEBUG_PRINTTIME; fprintf(stderr, "%s():%i: %s  (%s/%lu = {%02x", __func__, __LINE__, f, #x, (unsigned long) (y), TMPBUF[0]); for (idx = 1; idx < (y); idx++) { fprintf(stderr, ", %02x", TMPBUF[idx]); }; fprintf(stderr, "})\n"); fflush(stderr); }
#  define CACKEY_DEBUG_PERROR(x) { fprintf(stderr, "%s():%i: ", __func__, __LINE__); CACKEY_DEBUG_PRINTTIME; perror(x); fflush(stderr); }
#  define free(x) { CACKEY_DEBUG_PRINTF("FREE(%p) (%s)", x, #x); free(x); }

static void *CACKEY_DEBUG_FUNC_MALLOC(size_t size, const char *func, int line) {
	void *retval;

	retval = malloc(size);

	CACKEY_DEBUG_PRINTTIME;
	fprintf(stderr, "%s():%i: ", func, line);
	fprintf(stderr, "MALLOC() = %p", retval);
	fprintf(stderr, "\n");
	fflush(stderr);

	return(retval);
}

static void *CACKEY_DEBUG_FUNC_REALLOC(void *ptr, size_t size, const char *func, int line) {
	void *retval;

	retval = realloc(ptr, size);

	if (retval != ptr) {
		CACKEY_DEBUG_PRINTTIME;
		fprintf(stderr, "%s():%i: ", func, line);
		fprintf(stderr, "REALLOC(%p) = %p", ptr, retval);
		fprintf(stderr, "\n");
		fflush(stderr);
	}

	if (retval == NULL) {
		CACKEY_DEBUG_PRINTF(" *** ERROR *** realloc returned NULL (size = %lu)", (unsigned long) size);
	}

	return(retval);
}

static char *CACKEY_DEBUG_FUNC_STRDUP(const char *ptr, const char *func, int line) {
	char *retval;

	retval = strdup(ptr);

	CACKEY_DEBUG_PRINTTIME;
	fprintf(stderr, "%s():%i: ", func, line);
	fprintf(stderr, "STRDUP_MALLOC() = %p", retval);
	fprintf(stderr, "\n");
	fflush(stderr);

	return(retval);
}
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
		CACKEY_DEBUG_PRINTF("Connection to PC/SC failed, returning in failure");

		return(CACKEY_PCSC_E_GENERIC);
	}

	/* Connect to reader, if needed */
	if (!slot->pcsc_card_connected) {
		slot->protocol = 0;

		CACKEY_DEBUG_PRINTF("SCardConnect(%s) called", slot->pcsc_reader);
		scard_conn_ret = SCardConnect(*cackey_pcsc_handle, slot->pcsc_reader, SCARD_SHARE_SHARED, SCARD_PROTOCOL_T0 | SCARD_PROTOCOL_T1, &slot->pcsc_card, &protocol);

		if (scard_conn_ret == SCARD_E_PROTO_MISMATCH) {
			CACKEY_DEBUG_PRINTF("SCardConnect() returned SCARD_E_PROTO_MISMATCH, trying with just T=0")
			scard_conn_ret = SCardConnect(*cackey_pcsc_handle, slot->pcsc_reader, SCARD_SHARE_SHARED, SCARD_PROTOCOL_T0, &slot->pcsc_card, &protocol);








<
<







900
901
902
903
904
905
906


907
908
909
910
911
912
913
		CACKEY_DEBUG_PRINTF("Connection to PC/SC failed, returning in failure");

		return(CACKEY_PCSC_E_GENERIC);
	}

	/* Connect to reader, if needed */
	if (!slot->pcsc_card_connected) {


		CACKEY_DEBUG_PRINTF("SCardConnect(%s) called", slot->pcsc_reader);
		scard_conn_ret = SCardConnect(*cackey_pcsc_handle, slot->pcsc_reader, SCARD_SHARE_SHARED, SCARD_PROTOCOL_T0 | SCARD_PROTOCOL_T1, &slot->pcsc_card, &protocol);

		if (scard_conn_ret == SCARD_E_PROTO_MISMATCH) {
			CACKEY_DEBUG_PRINTF("SCardConnect() returned SCARD_E_PROTO_MISMATCH, trying with just T=0")
			scard_conn_ret = SCardConnect(*cackey_pcsc_handle, slot->pcsc_reader, SCARD_SHARE_SHARED, SCARD_PROTOCOL_T0, &slot->pcsc_card, &protocol);

1193
1194
1195
1196
1197
1198
1199
1200
1201
1202
1203
1204
1205
1206
1207
		CACKEY_DEBUG_PRINTBUF("Sending APDU:", xmit_buf, xmit_len);
	}

	recv_len = sizeof(recv_buf);
	scard_xmit_ret = SCardTransmit(slot->pcsc_card, pioSendPci, xmit_buf, xmit_len, NULL, recv_buf, &recv_len);

	if (scard_xmit_ret == SCARD_E_NOT_TRANSACTED) {
		CACKEY_DEBUG_PRINTF("Failed to send APDU to card (SCardTransmit() = %s/%lx), will ask calling function to retry...", CACKEY_DEBUG_FUNC_SCARDERR_TO_STR(scard_xmit_ret), (unsigned long) scard_xmit_ret);

		/* Begin Smartcard Transaction */
		cackey_end_transaction(slot);

		return(CACKEY_PCSC_E_RETRY);
	}








|







1201
1202
1203
1204
1205
1206
1207
1208
1209
1210
1211
1212
1213
1214
1215
		CACKEY_DEBUG_PRINTBUF("Sending APDU:", xmit_buf, xmit_len);
	}

	recv_len = sizeof(recv_buf);
	scard_xmit_ret = SCardTransmit(slot->pcsc_card, pioSendPci, xmit_buf, xmit_len, NULL, recv_buf, &recv_len);

	if (scard_xmit_ret == SCARD_E_NOT_TRANSACTED) {
		CACKEY_DEBUG_PRINTF("Failed to send APDU to card (SCardTransmit() = %s/%lx), will ask calling function to retry (not resetting card)...", CACKEY_DEBUG_FUNC_SCARDERR_TO_STR(scard_xmit_ret), (unsigned long) scard_xmit_ret);

		/* Begin Smartcard Transaction */
		cackey_end_transaction(slot);

		return(CACKEY_PCSC_E_RETRY);
	}

2386
2387
2388
2389
2390
2391
2392


















2393
2394
2395
2396
2397
2398
2399
		CACKEY_DEBUG_PRINTF("Unable to connect to card, returning token absent");

		return(CACKEY_PCSC_E_TOKENABSENT);
	}

	atr_len = sizeof(atr);
	status_ret = SCardStatus(slot->pcsc_card, NULL, &reader_len, &state, &protocol, atr, &atr_len);


















	if (status_ret != SCARD_S_SUCCESS) {
		slot->slot_reset = 1;
		slot->token_flags = CKF_LOGIN_REQUIRED;

		if (status_ret == SCARD_W_RESET_CARD) {
			CACKEY_DEBUG_PRINTF("Reset required, please hold...");








>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>







2394
2395
2396
2397
2398
2399
2400
2401
2402
2403
2404
2405
2406
2407
2408
2409
2410
2411
2412
2413
2414
2415
2416
2417
2418
2419
2420
2421
2422
2423
2424
2425
		CACKEY_DEBUG_PRINTF("Unable to connect to card, returning token absent");

		return(CACKEY_PCSC_E_TOKENABSENT);
	}

	atr_len = sizeof(atr);
	status_ret = SCardStatus(slot->pcsc_card, NULL, &reader_len, &state, &protocol, atr, &atr_len);

	if (status_ret == SCARD_E_INVALID_HANDLE) {
		CACKEY_DEBUG_PRINTF("SCardStatus() returned SCARD_E_INVALID_HANDLE, marking is not already connected and trying again");
		slot->pcsc_card_connected = 0;
		slot->slot_reset = 1;
		slot->token_flags = CKF_LOGIN_REQUIRED;

		pcsc_connect_ret = cackey_connect_card(slot);
		if (pcsc_connect_ret != CACKEY_PCSC_S_OK) {
			CACKEY_DEBUG_PRINTF("Unable to connect to card, returning token absent");

			return(CACKEY_PCSC_E_TOKENABSENT);
		}

		atr_len = sizeof(atr);
		status_ret = SCardStatus(slot->pcsc_card, NULL, &reader_len, &state, &protocol, atr, &atr_len);
	}

	if (status_ret != SCARD_S_SUCCESS) {
		slot->slot_reset = 1;
		slot->token_flags = CKF_LOGIN_REQUIRED;

		if (status_ret == SCARD_W_RESET_CARD) {
			CACKEY_DEBUG_PRINTF("Reset required, please hold...");

4508
4509
4510
4511
4512
4513
4514

4515
4516
4517
4518
4519
4520
4521

		if (cackey_slots[slotID].label != NULL) {
			free(cackey_slots[slotID].label);
			cackey_slots[slotID].label = NULL;
		}

		cackey_slots[slotID].slot_reset = 0;

		cackey_slots[slotID].token_flags = CKF_LOGIN_REQUIRED;
	}

	if (cackey_sessions[hSession].identities == NULL) {
		cackey_sessions[hSession].identities = cackey_read_identities(&cackey_slots[slotID], &cackey_sessions[hSession].identities_count);
	}








>







4534
4535
4536
4537
4538
4539
4540
4541
4542
4543
4544
4545
4546
4547
4548

		if (cackey_slots[slotID].label != NULL) {
			free(cackey_slots[slotID].label);
			cackey_slots[slotID].label = NULL;
		}

		cackey_slots[slotID].slot_reset = 0;
		cackey_slots[slotID].pcsc_card_connected = 0;
		cackey_slots[slotID].token_flags = CKF_LOGIN_REQUIRED;
	}

	if (cackey_sessions[hSession].identities == NULL) {
		cackey_sessions[hSession].identities = cackey_read_identities(&cackey_slots[slotID], &cackey_sessions[hSession].identities_count);
	}

Modified configure.ac from [7e15536eaa] to [1ed71809e2].

22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
AC_CHECK_TOOL(AR, ar)
AC_CHECK_TOOL(RANLIB, ranlib)

dnl Determine how to strip executables
AC_CHECK_TOOL(STRIP, strip)

dnl Check for all required headers
AC_CHECK_HEADERS(arpa/inet.h inttypes.h stdarg.h stdint.h stdio.h stdlib.h string.h sys/socket.h sys/types.h sys/un.h unistd.h pthread.h zlib.h limits.h,,[
	AC_WARN([Required header missing, compilation will likely fail.])
], [
#ifdef HAVE_ARPA_INET_H
#  include <arpa/inet.h>
#endif
#ifdef HAVE_INTTYPES_H
#  include <inttypes.h>







|







22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
AC_CHECK_TOOL(AR, ar)
AC_CHECK_TOOL(RANLIB, ranlib)

dnl Determine how to strip executables
AC_CHECK_TOOL(STRIP, strip)

dnl Check for all required headers
AC_CHECK_HEADERS(arpa/inet.h inttypes.h stdarg.h stdint.h stdio.h stdlib.h string.h sys/socket.h sys/types.h sys/un.h time.h unistd.h pthread.h zlib.h limits.h,,[
	AC_WARN([Required header missing, compilation will likely fail.])
], [
#ifdef HAVE_ARPA_INET_H
#  include <arpa/inet.h>
#endif
#ifdef HAVE_INTTYPES_H
#  include <inttypes.h>
58
59
60
61
62
63
64



65
66
67
68
69
70
71
#endif
#ifdef HAVE_SYS_UN_H
#  include <sys/un.h>
#endif
#ifdef HAVE_UNISTD_H
#  include <unistd.h>
#endif



#ifdef HAVE_PTHREAD_H
#  include <pthread.h>
#endif
#ifdef HAVE_LIMITS_H
#  include <limits.h>
#endif
#ifdef HAVE_ZLIB_H







>
>
>







58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
#endif
#ifdef HAVE_SYS_UN_H
#  include <sys/un.h>
#endif
#ifdef HAVE_UNISTD_H
#  include <unistd.h>
#endif
#ifdef HAVE_TIME_H
#  include <time.h>
#endif
#ifdef HAVE_PTHREAD_H
#  include <pthread.h>
#endif
#ifdef HAVE_LIMITS_H
#  include <limits.h>
#endif
#ifdef HAVE_ZLIB_H