channels/rdpsnd: add wlog debug output

channels/rdpsnd/client/rdpsnd_main.c

@@ -33,6 +33,7 @@
 #include <string.h>
 
 #include <winpr/crt.h>
+#include <winpr/wlog.h>
 #include <winpr/synch.h>
 #include <winpr/print.h>
 #include <winpr/thread.h>
@@ -62,6 +63,7 @@ struct rdpsnd_plugin
 	UINT32 OpenHandle;
 	wMessagePipe* MsgPipe;
 
+	wLog* log;
 	HANDLE ScheduleThread;
 
 	BYTE cBlockNo;
@@ -92,7 +94,7 @@ struct rdpsnd_plugin
 	rdpsndDevicePlugin* device;
 };
 
-static void rdpsnd_send_wave_confirm_pdu(rdpsndPlugin* rdpsnd, UINT16 wTimeStamp, BYTE cConfirmedBlockNo);
+static void rdpsnd_confirm_wave(rdpsndPlugin* rdpsnd, RDPSND_WAVE* wave);
 
 static void* rdpsnd_schedule_thread(void* arg)
 {
@@ -124,9 +126,10 @@ static void* rdpsnd_schedule_thread(void* arg)
 			Sleep(wTimeDiff);
 		}
 
-		rdpsnd_send_wave_confirm_pdu(rdpsnd, wave->wTimeStampB, wave->cBlockNo);
+		rdpsnd_confirm_wave(rdpsnd, wave);
-		free(wave);
+
 		message.wParam = NULL;
+		free(wave);
 	}
 
 	return NULL;
@@ -143,6 +146,8 @@ void rdpsnd_send_quality_mode_pdu(rdpsndPlugin* rdpsnd)
 	Stream_Write_UINT16(pdu, rdpsnd->wQualityMode); /* wQualityMode */
 	Stream_Write_UINT16(pdu, 0); /* Reserved */
 
+	WLog_Print(rdpsnd->log, WLOG_DEBUG, "QualityMode: %d", rdpsnd->wQualityMode);
+
 	rdpsnd_virtual_channel_write(rdpsnd, pdu);
 }
 
@@ -259,6 +264,8 @@ void rdpsnd_send_client_audio_formats(rdpsndPlugin* rdpsnd)
 			Stream_Write(pdu, clientFormat->data, clientFormat->cbSize);
 	}
 
+	WLog_Print(rdpsnd->log, WLOG_DEBUG, "Client Audio Formats");
+
 	rdpsnd_virtual_channel_write(rdpsnd, pdu);
 }
 
@@ -311,6 +318,8 @@ void rdpsnd_recv_server_audio_formats_pdu(rdpsndPlugin* rdpsnd, wStream* s)
 
 	rdpsnd_select_supported_audio_formats(rdpsnd);
 
+	WLog_Print(rdpsnd->log, WLOG_DEBUG, "Server Audio Formats");
+
 	rdpsnd_send_client_audio_formats(rdpsnd);
 
 	if (wVersion >= 6)
@@ -331,6 +340,9 @@ void rdpsnd_send_training_confirm_pdu(rdpsndPlugin* rdpsnd, UINT16 wTimeStamp, U
 	Stream_Write_UINT16(pdu, wTimeStamp);
 	Stream_Write_UINT16(pdu, wPackSize);
 
+	WLog_Print(rdpsnd->log, WLOG_DEBUG, "Training Response: wTimeStamp: %d wPackSize: %d",
+			wTimeStamp, wPackSize);
+
 	rdpsnd_virtual_channel_write(rdpsnd, pdu);
 }
 
@@ -342,6 +354,9 @@ static void rdpsnd_recv_training_pdu(rdpsndPlugin* rdpsnd, wStream* s)
 	Stream_Read_UINT16(s, wTimeStamp);
 	Stream_Read_UINT16(s, wPackSize);
 
+	WLog_Print(rdpsnd->log, WLOG_DEBUG, "Training Request: wTimeStamp: %d wPackSize: %d",
+			wTimeStamp, wPackSize);
+
 	rdpsnd_send_training_confirm_pdu(rdpsnd, wTimeStamp, wPackSize);
 }
 
@@ -362,6 +377,9 @@ static void rdpsnd_recv_wave_info_pdu(rdpsndPlugin* rdpsnd, wStream* s, UINT16 B
 
 	format = &rdpsnd->ClientFormats[wFormatNo];
 
+	WLog_Print(rdpsnd->log, WLOG_DEBUG, "WaveInfo: cBlockNo: %d wFormatNo: %d",
+			rdpsnd->cBlockNo, wFormatNo);
+
 	if (!rdpsnd->isOpen)
 	{
 		rdpsnd->isOpen = TRUE;
@@ -400,6 +418,14 @@ void rdpsnd_send_wave_confirm_pdu(rdpsndPlugin* rdpsnd, UINT16 wTimeStamp, BYTE
 	rdpsnd_virtual_channel_write(rdpsnd, pdu);
 }
 
+void rdpsnd_confirm_wave(rdpsndPlugin* rdpsnd, RDPSND_WAVE* wave)
+{
+	WLog_Print(rdpsnd->log, WLOG_DEBUG, "WaveConfirm: cBlockNo: %d wTimeStamp: %d wTimeDiff: %d",
+			wave->cBlockNo, wave->wTimeStampB, wave->wTimeStampB - wave->wTimeStampA);
+
+	rdpsnd_send_wave_confirm_pdu(rdpsnd, wave->wTimeStampB, wave->cBlockNo);
+}
+
 static void rdpsnd_device_send_wave_confirm_pdu(rdpsndDevicePlugin* device, RDPSND_WAVE* wave)
 {
 	MessageQueue_Post(device->rdpsnd->MsgPipe->Out, NULL, 0, (void*) wave, NULL);
@@ -439,6 +465,9 @@ static void rdpsnd_recv_wave_pdu(rdpsndPlugin* rdpsnd, wStream* s)
 	format = &rdpsnd->ClientFormats[rdpsnd->wCurrentFormatNo];
 	wave->wAudioLength = rdpsnd_compute_audio_time_length(format, size);
 
+	WLog_Print(rdpsnd->log, WLOG_DEBUG, "Wave: cBlockNo: %d wTimeStamp: %d",
+			wave->cBlockNo, wave->wTimeStampA);
+
 	if (!rdpsnd->device)
 	{
 		free(wave);
@@ -469,6 +498,8 @@ static void rdpsnd_recv_wave_pdu(rdpsndPlugin* rdpsnd, wStream* s)
 
 static void rdpsnd_recv_close_pdu(rdpsndPlugin* rdpsnd)
 {
+	WLog_Print(rdpsnd->log, WLOG_DEBUG, "Close");
+
 	if (rdpsnd->device)
 	{
 		IFCALL(rdpsnd->device->Close, rdpsnd->device);
@@ -483,6 +514,8 @@ static void rdpsnd_recv_volume_pdu(rdpsndPlugin* rdpsnd, wStream* s)
 
 	Stream_Read_UINT32(s, dwVolume);
 
+	WLog_Print(rdpsnd->log, WLOG_DEBUG, "Volume: 0x%04X", dwVolume);
+
 	if (rdpsnd->device)
 	{
 		IFCALL(rdpsnd->device->SetVolume, rdpsnd->device, dwVolume);
@@ -1041,6 +1074,9 @@ int VirtualChannelEntry(PCHANNEL_ENTRY_POINTS pEntryPoints)
 
 		CopyMemory(&(rdpsnd->channelEntryPoints), pEntryPoints, pEntryPoints->cbSize);
 
+		rdpsnd->log = WLog_Get("com.freerdp.channels.rdpsnd.client");
+		//WLog_SetLogLevel(rdpsnd->log, WLOG_TRACE);
+
 		rdpsnd->channelEntryPoints.pVirtualChannelInit(&rdpsnd->InitHandle,
 			&rdpsnd->channelDef, 1, VIRTUAL_CHANNEL_VERSION_WIN2000, rdpsnd_virtual_channel_init_event);