channels/smartcard: added detailed debug tracing

channels/smartcard/client/smartcard_main.c

@@ -255,6 +255,8 @@ int DeviceServiceEntry(PDEVICE_SERVICE_ENTRY_POINTS pEntryPoints)
 
 	smartcard->log = WLog_Get("com.freerdp.channel.smartcard.client");
 
+	WLog_SetLogLevel(smartcard->log, WLOG_DEBUG);
+
 	smartcard->IrpQueue = MessageQueue_New(NULL);
 	smartcard->OutstandingIrps = ListDictionary_New(TRUE);
 

channels/smartcard/client/smartcard_operations.c

@@ -180,13 +180,17 @@ static UINT32 smartcard_EstablishContext(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_establish_context_call(smartcard, irp->input, &call);
 
+	smartcard_trace_establish_context_call(smartcard, &call);
+
 	if (status)
 		return status;
 
 	status = ret.ReturnCode = SCardEstablishContext(call.dwScope, NULL, NULL, &hContext);
 
-	ret.Context.cbContext = sizeof(ULONG_PTR);
 	ret.Context.pbContext = (UINT64) hContext;
+	ret.Context.cbContext = sizeof(ULONG_PTR);
+
+	smartcard_trace_establish_context_return(smartcard, &ret);
 
 	status = smartcard_pack_establish_context_return(smartcard, irp->output, &ret);
 
@@ -205,6 +209,13 @@ static UINT32 smartcard_ReleaseContext(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_context_call(smartcard, irp->input, &call);
 
+	WLog_Print(smartcard->log, WLOG_DEBUG, "ReleaseContext_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d)",
+		call.Context.pbContext, call.Context.cbContext);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+
 	if (status)
 		return status;
 
@@ -224,6 +235,13 @@ static UINT32 smartcard_IsValidContext(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_context_call(smartcard, irp->input, &call);
 
+	WLog_Print(smartcard->log, WLOG_DEBUG, "IsValidContext_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d)",
+		call.Context.pbContext, call.Context.cbContext);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+
 	if (status)
 		return status;
 
@@ -245,6 +263,8 @@ static UINT32 smartcard_ListReadersA(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_list_readers_call(smartcard, irp->input, &call);
 
+	smartcard_trace_list_readers_call(smartcard, &call);
+
 	if (status)
 		return status;
 
@@ -260,6 +280,8 @@ static UINT32 smartcard_ListReadersA(SMARTCARD_DEVICE* smartcard, IRP* irp)
 	if (status)
 		return status;
 
+	smartcard_trace_list_readers_return(smartcard, &ret);
+
 	status = smartcard_pack_list_readers_return(smartcard, irp->output, &ret);
 
 	if (status)
@@ -285,6 +307,8 @@ static UINT32 smartcard_ListReadersW(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_list_readers_call(smartcard, irp->input, &call);
 
+	smartcard_trace_list_readers_call(smartcard, &call);
+
 	if (status)
 		return status;
 
@@ -300,6 +324,8 @@ static UINT32 smartcard_ListReadersW(SMARTCARD_DEVICE* smartcard, IRP* irp)
 	if (status)
 		return status;
 
+	smartcard_trace_list_readers_return(smartcard, &ret);
+
 	status = smartcard_pack_list_readers_return(smartcard, irp->output, &ret);
 
 	if (status)
@@ -325,6 +351,8 @@ static UINT32 smartcard_GetStatusChangeA(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_get_status_change_a_call(smartcard, irp->input, &call);
 
+	smartcard_trace_get_status_change_a_call(smartcard, &call);
+
 	if (status)
 		return status;
 
@@ -346,6 +374,8 @@ static UINT32 smartcard_GetStatusChangeA(SMARTCARD_DEVICE* smartcard, IRP* irp)
 		CopyMemory(&ret.rgReaderStates[index].rgbAtr, &call.rgReaderStates[index].rgbAtr, 32);
 	}
 
+	smartcard_trace_get_status_change_return(smartcard, &ret);
+
 	status = smartcard_pack_get_status_change_return(smartcard, irp->output, &ret);
 
 	if (status)
@@ -379,6 +409,8 @@ static UINT32 smartcard_GetStatusChangeW(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_get_status_change_w_call(smartcard, irp->input, &call);
 
+	smartcard_trace_get_status_change_w_call(smartcard, &call);
+
 	if (status)
 		return status;
 
@@ -400,6 +432,8 @@ static UINT32 smartcard_GetStatusChangeW(SMARTCARD_DEVICE* smartcard, IRP* irp)
 		CopyMemory(&ret.rgReaderStates[index].rgbAtr, &call.rgReaderStates[index].rgbAtr, 32);
 	}
 
+	smartcard_trace_get_status_change_return(smartcard, &ret);
+
 	status = smartcard_pack_get_status_change_return(smartcard, irp->output, &ret);
 
 	if (status)
@@ -431,6 +465,13 @@ static UINT32 smartcard_Cancel(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_context_call(smartcard, irp->input, &call);
 
+	WLog_Print(smartcard->log, WLOG_DEBUG, "Cancel_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d)",
+		call.Context.pbContext, call.Context.cbContext);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+
 	if (status)
 		return status;
 
@@ -453,6 +494,8 @@ UINT32 smartcard_ConnectA(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_connect_a_call(smartcard, irp->input, &call);
 
+	smartcard_trace_connect_a_call(smartcard, &call);
+
 	if (status)
 		return status;
 
@@ -470,11 +513,13 @@ UINT32 smartcard_ConnectA(SMARTCARD_DEVICE* smartcard, IRP* irp)
 	if (status)
 		return status;
 
-	ret.hCard.Context.cbContext = sizeof(ULONG_PTR);
 	ret.hCard.Context.pbContext = (UINT64) hContext;
+	ret.hCard.Context.cbContext = sizeof(ULONG_PTR);
 
-	ret.hCard.cbHandle = sizeof(ULONG_PTR);
 	ret.hCard.pbHandle = (UINT64) hCard;
+	ret.hCard.cbHandle = sizeof(ULONG_PTR);
+
+	smartcard_trace_connect_return(smartcard, &ret);
 
 	status = smartcard_pack_connect_return(smartcard, irp->output, &ret);
 
@@ -499,6 +544,8 @@ UINT32 smartcard_ConnectW(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_connect_w_call(smartcard, irp->input, &call);
 
+	smartcard_trace_connect_w_call(smartcard, &call);
+
 	if (status)
 		return status;
 
@@ -516,11 +563,13 @@ UINT32 smartcard_ConnectW(SMARTCARD_DEVICE* smartcard, IRP* irp)
 	if (status)
 		return status;
 
-	ret.hCard.Context.cbContext = sizeof(ULONG_PTR);
 	ret.hCard.Context.pbContext = (UINT64) hContext;
+	ret.hCard.Context.cbContext = sizeof(ULONG_PTR);
 
-	ret.hCard.cbHandle = sizeof(ULONG_PTR);
 	ret.hCard.pbHandle = (UINT64) hCard;
+	ret.hCard.cbHandle = sizeof(ULONG_PTR);
+
+	smartcard_trace_connect_return(smartcard, &ret);
 
 	status = smartcard_pack_connect_return(smartcard, irp->output, &ret);
 
@@ -573,6 +622,15 @@ static UINT32 smartcard_Disconnect(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_hcard_and_disposition_call(smartcard, irp->input, &call);
 
+	WLog_Print(smartcard->log, WLOG_DEBUG, "Cancel_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d) hCard: 0x%08X (%d)",
+		call.hCard.Context.pbContext, call.hCard.Context.cbContext, call.hCard.pbHandle, call.hCard.pbHandle);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "dwDisposition: 0x%08X", call.dwDisposition);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+
 	if (status)
 		return status;
 
@@ -597,6 +655,15 @@ static UINT32 smartcard_BeginTransaction(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_hcard_and_disposition_call(smartcard, irp->input, &call);
 
+	WLog_Print(smartcard->log, WLOG_DEBUG, "BeginTransaction_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d) hCard: 0x%08X (%d)",
+		call.hCard.Context.pbContext, call.hCard.Context.cbContext, call.hCard.pbHandle, call.hCard.pbHandle);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "dwDisposition: 0x%08X", call.dwDisposition);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+
 	if (status)
 		return status;
 
@@ -621,6 +688,15 @@ static UINT32 smartcard_EndTransaction(SMARTCARD_DEVICE* smartcard, IRP* irp)
 
 	status = smartcard_unpack_hcard_and_disposition_call(smartcard, irp->input, &call);
 
+	WLog_Print(smartcard->log, WLOG_DEBUG, "EndTransaction_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d) hCard: 0x%08X (%d)",
+		call.hCard.Context.pbContext, call.hCard.Context.cbContext, call.hCard.pbHandle, call.hCard.pbHandle);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "dwDisposition: 0x%08X", call.dwDisposition);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+
 	if (status)
 		return status;
 

channels/smartcard/client/smartcard_pack.c

@@ -406,6 +406,18 @@ UINT32 smartcard_unpack_establish_context_call(SMARTCARD_DEVICE* smartcard, wStr
 	return SCARD_S_SUCCESS;
 }
 
+void smartcard_trace_establish_context_call(SMARTCARD_DEVICE* smartcard, EstablishContext_Call* call)
+{
+	if (!WLog_IsLevelActive(smartcard->log, WLOG_DEBUG))
+		return;
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "EstablishContext_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "dwScope: 0x%08X", call->dwScope);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+}
+
 UINT32 smartcard_pack_establish_context_return(SMARTCARD_DEVICE* smartcard, wStream* s, EstablishContext_Return* ret)
 {
 	UINT32 status;
@@ -423,6 +435,21 @@ UINT32 smartcard_pack_establish_context_return(SMARTCARD_DEVICE* smartcard, wStr
 	return SCARD_S_SUCCESS;
 }
 
+void smartcard_trace_establish_context_return(SMARTCARD_DEVICE* smartcard, EstablishContext_Return* ret)
+{
+	if (!WLog_IsLevelActive(smartcard->log, WLOG_DEBUG))
+		return;
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "EstablishContext_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "ReturnCode: 0x%08X", ret->ReturnCode);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d)",
+		ret->Context.pbContext, ret->Context.cbContext);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+}
+
 UINT32 smartcard_unpack_context_call(SMARTCARD_DEVICE* smartcard, wStream* s, Context_Call* call)
 {
 	UINT32 status;
@@ -513,6 +540,34 @@ UINT32 smartcard_unpack_list_readers_call(SMARTCARD_DEVICE* smartcard, wStream*
 	return SCARD_S_SUCCESS;
 }
 
+void smartcard_trace_list_readers_call(SMARTCARD_DEVICE* smartcard, ListReaders_Call* call)
+{
+	BOOL unicode;
+	char* mszGroupsA = NULL;
+
+	if (!WLog_IsLevelActive(smartcard->log, WLOG_DEBUG))
+		return;
+
+	unicode = ((call->cBytes > 2) && !call->mszGroups[1]) ? TRUE : FALSE;
+
+	if (unicode)
+		ConvertFromUnicode(CP_UTF8, 0, (WCHAR*) call->mszGroups, call->cBytes / 2, &mszGroupsA, 0, NULL, NULL);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "ListReaders_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d)",
+		call->Context.pbContext, call->Context.cbContext);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG,
+		"cBytes: %d mszGroups: %s fmszReadersIsNULL: %d cchReaders: 0x%08X",
+		call->cBytes, mszGroupsA, call->fmszReadersIsNULL, call->cchReaders);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+
+	if (unicode)
+		free(mszGroupsA);
+}
+
 UINT32 smartcard_pack_list_readers_return(SMARTCARD_DEVICE* smartcard, wStream* s, ListReaders_Return* ret)
 {
 	UINT32 mszNdrPtr;
@@ -537,6 +592,47 @@ UINT32 smartcard_pack_list_readers_return(SMARTCARD_DEVICE* smartcard, wStream*
 	return SCARD_S_SUCCESS;
 }
 
+void smartcard_trace_list_readers_return(SMARTCARD_DEVICE* smartcard, ListReaders_Return* ret)
+{
+	int index;
+	int length;
+	BOOL unicode;
+	char* mszA = NULL;
+
+	if (!WLog_IsLevelActive(smartcard->log, WLOG_DEBUG))
+		return;
+
+	unicode = ((ret->cBytes > 2) && !ret->msz[1]) ? TRUE : FALSE;
+
+	if (unicode)
+	{
+		length = ret->cBytes / 2;
+		ConvertFromUnicode(CP_UTF8, 0, (WCHAR*) ret->msz, length, &mszA, 0, NULL, NULL);
+	}
+	else
+	{
+		length = ret->cBytes;
+		mszA = (char*) malloc(length);
+		CopyMemory(mszA, ret->msz, ret->cBytes);
+	}
+
+	for (index = 0; index < length - 2; index++)
+	{
+		if (mszA[index] == '\0')
+			mszA[index] = ',';
+	}
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "ListReaders_Return {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG,
+		"ReturnCode: 0x%08X cBytes: %d msz: %s",
+		ret->ReturnCode, ret->cBytes, mszA);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+
+	free(mszA);
+}
+
 UINT32 smartcard_unpack_connect_common(SMARTCARD_DEVICE* smartcard, wStream* s, Connect_Common* common)
 {
 	UINT32 status;
@@ -586,7 +682,7 @@ UINT32 smartcard_unpack_connect_a_call(SMARTCARD_DEVICE* smartcard, wStream* s,
 	Stream_Seek_UINT32(s); /* NdrOffset (4 bytes) */
 	Stream_Read_UINT32(s, count); /* NdrActualCount (4 bytes) */
 
-	call->szReader = malloc(count + 1);
+	call->szReader = (unsigned char*) malloc(count + 1);
 	Stream_Read(s, call->szReader, count);
 	smartcard_unpack_read_size_align(smartcard, s, count, 4);
 	call->szReader[count] = '\0';
@@ -596,6 +692,22 @@ UINT32 smartcard_unpack_connect_a_call(SMARTCARD_DEVICE* smartcard, wStream* s,
 	return SCARD_S_SUCCESS;
 }
 
+void smartcard_trace_connect_a_call(SMARTCARD_DEVICE* smartcard, ConnectA_Call* call)
+{
+	if (!WLog_IsLevelActive(smartcard->log, WLOG_DEBUG))
+		return;
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "ConnectA_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d)",
+		call->Common.Context.pbContext, call->Common.Context.cbContext);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "szReader: %s dwShareMode: 0x%08X dwPreferredProtocols: 0x%08X",
+		call->szReader, call->Common.dwShareMode, call->Common.dwPreferredProtocols);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+}
+
 UINT32 smartcard_unpack_connect_w_call(SMARTCARD_DEVICE* smartcard, wStream* s, ConnectW_Call* call)
 {
 	UINT32 status;
@@ -623,7 +735,7 @@ UINT32 smartcard_unpack_connect_w_call(SMARTCARD_DEVICE* smartcard, wStream* s,
 	Stream_Seek_UINT32(s); /* NdrOffset (4 bytes) */
 	Stream_Read_UINT32(s, count); /* NdrActualCount (4 bytes) */
 
-	call->szReader = malloc((count + 1) * 2);
+	call->szReader = (WCHAR*) malloc((count + 1) * 2);
 	Stream_Read(s, call->szReader, (count * 2));
 	smartcard_unpack_read_size_align(smartcard, s, (count * 2), 4);
 	call->szReader[count] = '\0';
@@ -633,6 +745,28 @@ UINT32 smartcard_unpack_connect_w_call(SMARTCARD_DEVICE* smartcard, wStream* s,
 	return SCARD_S_SUCCESS;
 }
 
+void smartcard_trace_connect_w_call(SMARTCARD_DEVICE* smartcard, ConnectW_Call* call)
+{
+	char* szReaderA = NULL;
+
+	if (!WLog_IsLevelActive(smartcard->log, WLOG_DEBUG))
+		return;
+
+	ConvertFromUnicode(CP_UTF8, 0, call->szReader, -1, &szReaderA, 0, NULL, NULL);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "ConnectA_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d)",
+		call->Common.Context.pbContext, call->Common.Context.cbContext);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "szReader: %s dwShareMode: 0x%08X dwPreferredProtocols: %d",
+		szReaderA, call->Common.dwShareMode, call->Common.dwPreferredProtocols);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+
+	free(szReaderA);
+}
+
 UINT32 smartcard_pack_connect_return(SMARTCARD_DEVICE* smartcard, wStream* s, Connect_Return* ret)
 {
 	UINT32 status;
@@ -652,6 +786,22 @@ UINT32 smartcard_pack_connect_return(SMARTCARD_DEVICE* smartcard, wStream* s, Co
 	return SCARD_S_SUCCESS;
 }
 
+void smartcard_trace_connect_return(SMARTCARD_DEVICE* smartcard, Connect_Return* ret)
+{
+	if (!WLog_IsLevelActive(smartcard->log, WLOG_DEBUG))
+		return;
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "Connect_Return {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d) hCard: 0x%08X (%d)",
+		ret->hCard.Context.pbContext, ret->hCard.Context.cbContext, ret->hCard.pbHandle, ret->hCard.cbHandle);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "dwActiveProtocol: 0x%08X",
+		ret->dwActiveProtocol);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+}
+
 UINT32 smartcard_unpack_reconnect_call(SMARTCARD_DEVICE* smartcard, wStream* s, Reconnect_Call* call)
 {
 	UINT32 status;
@@ -830,6 +980,35 @@ UINT32 smartcard_unpack_get_status_change_a_call(SMARTCARD_DEVICE* smartcard, wS
 	return SCARD_S_SUCCESS;
 }
 
+void smartcard_trace_get_status_change_a_call(SMARTCARD_DEVICE* smartcard, GetStatusChangeA_Call* call)
+{
+	UINT32 index;
+	LPSCARD_READERSTATEA readerState;
+
+	if (!WLog_IsLevelActive(smartcard->log, WLOG_DEBUG))
+		return;
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "GetStatusChangeA_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d)",
+		call->Context.pbContext, call->Context.cbContext);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "dwTimeOut: 0x%08X cReaders: %d",
+		call->dwTimeOut, call->cReaders);
+
+	for (index = 0; index < call->cReaders; index++)
+	{
+		readerState = &call->rgReaderStates[index];
+
+		WLog_Print(smartcard->log, WLOG_DEBUG,
+			"\t[%d]: szReader: %s dwCurrentState: 0x%08X dwEventState: 0x%08X cbAtr: %d",
+			index, readerState->szReader, readerState->dwCurrentState,
+			readerState->dwEventState, readerState->cbAtr);
+	}
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+}
+
 UINT32 smartcard_unpack_get_status_change_w_call(SMARTCARD_DEVICE* smartcard, wStream* s, GetStatusChangeW_Call* call)
 {
 	UINT32 index;
@@ -939,6 +1118,41 @@ UINT32 smartcard_unpack_get_status_change_w_call(SMARTCARD_DEVICE* smartcard, wS
 	return SCARD_S_SUCCESS;
 }
 
+void smartcard_trace_get_status_change_w_call(SMARTCARD_DEVICE* smartcard, GetStatusChangeW_Call* call)
+{
+	UINT32 index;
+	LPSCARD_READERSTATEW readerState;
+
+	if (!WLog_IsLevelActive(smartcard->log, WLOG_DEBUG))
+		return;
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "GetStatusChangeW_Call {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "hContext: 0x%08X (%d)",
+		call->Context.pbContext, call->Context.cbContext);
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "dwTimeOut: 0x%08X cReaders: %d",
+		call->dwTimeOut, call->cReaders);
+
+	for (index = 0; index < call->cReaders; index++)
+	{
+		char* szReaderA = NULL;
+
+		readerState = &call->rgReaderStates[index];
+
+		ConvertFromUnicode(CP_UTF8, 0, readerState->szReader, -1, &szReaderA, 0, NULL, NULL);
+
+		WLog_Print(smartcard->log, WLOG_DEBUG,
+			"\t[%d]: szReader: %s dwCurrentState: 0x%08X dwEventState: 0x%08X cbAtr: %d",
+			index, szReaderA, readerState->dwCurrentState,
+			readerState->dwEventState, readerState->cbAtr);
+
+		free(szReaderA);
+	}
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+}
+
 UINT32 smartcard_pack_get_status_change_return(SMARTCARD_DEVICE* smartcard, wStream* s, GetStatusChange_Return* ret)
 {
 	UINT32 index;
@@ -961,6 +1175,31 @@ UINT32 smartcard_pack_get_status_change_return(SMARTCARD_DEVICE* smartcard, wStr
 	return SCARD_S_SUCCESS;
 }
 
+void smartcard_trace_get_status_change_return(SMARTCARD_DEVICE* smartcard, GetStatusChange_Return* ret)
+{
+	UINT32 index;
+	ReaderState_Return* rgReaderState;
+
+	if (!WLog_IsLevelActive(smartcard->log, WLOG_DEBUG))
+		return;
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "GetStatusChange_Return {");
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "ReturnCode: 0x%08X cReaders: %d",
+		ret->ReturnCode, ret->cReaders);
+
+	for (index = 0; index < ret->cReaders; index++)
+	{
+		rgReaderState = &(ret->rgReaderStates[index]);
+
+		WLog_Print(smartcard->log, WLOG_DEBUG,
+			"\t[%d]: dwCurrentState: 0x%08X dwEventState: 0x%08X cbAtr: %d",
+			index, rgReaderState->dwCurrentState, rgReaderState->dwEventState, rgReaderState->cbAtr);
+	}
+
+	WLog_Print(smartcard->log, WLOG_DEBUG, "}");
+}
+
 UINT32 smartcard_unpack_state_call(SMARTCARD_DEVICE* smartcard, wStream* s, State_Call* call)
 {
 	UINT32 status;

channels/smartcard/client/smartcard_pack.h

@@ -445,17 +445,27 @@ UINT32 smartcard_unpack_redir_scard_handle_ref(SMARTCARD_DEVICE* smartcard, wStr
 UINT32 smartcard_pack_redir_scard_handle_ref(SMARTCARD_DEVICE* smartcard, wStream* s, REDIR_SCARDHANDLE* handle);
 
 UINT32 smartcard_unpack_establish_context_call(SMARTCARD_DEVICE* smartcard, wStream* s, EstablishContext_Call* call);
+void smartcard_trace_establish_context_call(SMARTCARD_DEVICE* smartcard, EstablishContext_Call* call);
+
 UINT32 smartcard_pack_establish_context_return(SMARTCARD_DEVICE* smartcard, wStream* s, EstablishContext_Return* ret);
+void smartcard_trace_establish_context_return(SMARTCARD_DEVICE* smartcard, EstablishContext_Return* ret);
 
 UINT32 smartcard_unpack_context_call(SMARTCARD_DEVICE* smartcard, wStream* s, Context_Call* call);
 
 UINT32 smartcard_unpack_list_readers_call(SMARTCARD_DEVICE* smartcard, wStream* s, ListReaders_Call* call);
+void smartcard_trace_list_readers_call(SMARTCARD_DEVICE* smartcard, ListReaders_Call* call);
+
 UINT32 smartcard_pack_list_readers_return(SMARTCARD_DEVICE* smartcard, wStream* s, ListReaders_Return* ret);
+void smartcard_trace_list_readers_return(SMARTCARD_DEVICE* smartcard, ListReaders_Return* ret);
 
 UINT32 smartcard_unpack_connect_a_call(SMARTCARD_DEVICE* smartcard, wStream* s, ConnectA_Call* call);
+void smartcard_trace_connect_a_call(SMARTCARD_DEVICE* smartcard, ConnectA_Call* call);
+
 UINT32 smartcard_unpack_connect_w_call(SMARTCARD_DEVICE* smartcard, wStream* s, ConnectW_Call* call);
+void smartcard_trace_connect_w_call(SMARTCARD_DEVICE* smartcard, ConnectW_Call* call);
 
 UINT32 smartcard_pack_connect_return(SMARTCARD_DEVICE* smartcard, wStream* s, Connect_Return* ret);
+void smartcard_trace_connect_return(SMARTCARD_DEVICE* smartcard, Connect_Return* ret);
 
 UINT32 smartcard_unpack_reconnect_call(SMARTCARD_DEVICE* smartcard, wStream* s, Reconnect_Call* call);
 UINT32 smartcard_pack_reconnect_return(SMARTCARD_DEVICE* smartcard, wStream* s, Reconnect_Return* ret);
@@ -463,8 +473,13 @@ UINT32 smartcard_pack_reconnect_return(SMARTCARD_DEVICE* smartcard, wStream* s,
 UINT32 smartcard_unpack_hcard_and_disposition_call(SMARTCARD_DEVICE* smartcard, wStream* s, HCardAndDisposition_Call* call);
 
 UINT32 smartcard_unpack_get_status_change_a_call(SMARTCARD_DEVICE* smartcard, wStream* s, GetStatusChangeA_Call* call);
+void smartcard_trace_get_status_change_a_call(SMARTCARD_DEVICE* smartcard, GetStatusChangeA_Call* call);
+
 UINT32 smartcard_unpack_get_status_change_w_call(SMARTCARD_DEVICE* smartcard, wStream* s, GetStatusChangeW_Call* call);
+void smartcard_trace_get_status_change_w_call(SMARTCARD_DEVICE* smartcard, GetStatusChangeW_Call* call);
+
 UINT32 smartcard_pack_get_status_change_return(SMARTCARD_DEVICE* smartcard, wStream* s, GetStatusChange_Return* ret);
+void smartcard_trace_get_status_change_return(SMARTCARD_DEVICE* smartcard, GetStatusChange_Return* ret);
 
 UINT32 smartcard_unpack_state_call(SMARTCARD_DEVICE* smartcard, wStream* s, State_Call* call);
 UINT32 smartcard_pack_state_return(SMARTCARD_DEVICE* smartcard, wStream* s, State_Return* ret);

winpr/include/winpr/wlog.h

@@ -246,6 +246,9 @@ WINPR_API void WLog_PrintMessage(wLog* log, wLogMessage* message, ...);
 		WLog_PrintMessage(_log, &(_log_message), ## __VA_ARGS__ ); \
 	}
 
+#define WLog_IsLevelActive(_log, _log_level) \
+	(_log_level >= WLog_GetLogLevel(_log))
+
 WINPR_API DWORD WLog_GetLogLevel(wLog* log);
 WINPR_API void WLog_SetLogLevel(wLog* log, DWORD logLevel);