[proxy,channels] refactor dynamic channel

* Split DynvcTrackerPeekFn into smaller fragments each handling one kind of packet * Unify logging with a custom logger function to have unified log entries with appropriate data logged.
2026-04-14 00:14:11 +09:00 · 2025-08-25 09:34:35 +02:00
parent 1fa47ce716
commit dc463e1fcd
1 changed files with 427 additions and 268 deletions
--- a/server/proxy/channels/pf_channel_drdynvc.c
+++ b/server/proxy/channels/pf_channel_drdynvc.c
@@ -29,6 +29,11 @@

 #define DTAG PROXY_TAG("drdynvc")

+#define Stream_CheckAndLogRequiredLengthWLogWithBackend(log, s, nmemb, backdata)                 \
+	Stream_CheckAndLogRequiredLengthWLogEx(log, WLOG_WARN, s, nmemb, 1, "%s(%s:%" PRIuz ")[%s]", \
+	                                       __func__, __FILE__, (size_t)__LINE__,                 \
+	                                       getDirection(backdata))
+
 /** @brief channel opened status */
 typedef enum
 {
@@ -103,6 +108,43 @@ static const char* openstatus2str(PfDynChannelOpenStatus status)
 	}
 }

+#define DynvcTrackerLog(log, level, dynChannel, cmd, isBackData, ...)                         \
+	dyn_log_((log), (level), (dynChannel), (cmd), (isBackData), __func__, __FILE__, __LINE__, \
+	         __VA_ARGS__)
+
+static const char* getDirection(BOOL isBackData)
+{
+	return isBackData ? "B->F" : "F->B";
+}
+
+static void dyn_log_(wLog* log, DWORD level, const pServerDynamicChannelContext* dynChannel,
+                     BYTE cmd, BOOL isBackData, const char* fkt, const char* file, size_t line,
+                     const char* fmt, ...)
+{
+	if (!WLog_IsLevelActive(log, level))
+		return;
+
+	char* prefix = NULL;
+	char* msg = NULL;
+	size_t prefixlen = 0;
+	size_t msglen = 0;
+
+	uint32_t channelId = dynChannel ? dynChannel->channelId : UINT32_MAX;
+	const char* channelName = dynChannel ? dynChannel->channelName : "<NULL>";
+	(void)winpr_asprintf(&prefix, &prefixlen, "DynvcTracker[%s](%s [%s:%" PRIu32 "])",
+	                     getDirection(isBackData), channelName, drdynvc_get_packet_type(cmd),
+	                     channelId);
+
+	va_list ap;
+	va_start(ap, fmt);
+	(void)winpr_vasprintf(&msg, &msglen, fmt, ap);
+	va_end(ap);
+
+	WLog_PrintTextMessage(log, level, line, file, fkt, "%s: %s", prefix, msg);
+	free(prefix);
+	free(msg);
+}
+
 static PfChannelResult data_cb(pServerContext* ps, pServerDynamicChannelContext* channel,
                               BOOL isBackData, ChannelStateTracker* tracker, BOOL firstPacket,
                               BOOL lastPacket)
@@ -229,6 +271,194 @@ static DynvcReadResult dynvc_read_varInt(wLog* log, wStream* s, size_t len, UINT
 	return DYNCVC_READ_OK;
 }

+static PfChannelResult DynvcTrackerPeekHandleByMode(ChannelStateTracker* tracker,
+                                                    DynChannelTrackerState* trackerState,
+                                                    pServerDynamicChannelContext* dynChannel,
+                                                    BYTE cmd, BOOL firstPacket, BOOL lastPacket)
+{
+	WINPR_ASSERT(tracker);
+	WINPR_ASSERT(trackerState);
+	WINPR_ASSERT(dynChannel);
+	PfChannelResult result = PF_CHANNEL_RESULT_ERROR;
+
+	DynChannelContext* dynChannelContext =
+	    (DynChannelContext*)channelTracker_getCustomData(tracker);
+	WINPR_ASSERT(dynChannelContext);
+
+	proxyData* pdata = channelTracker_getPData(tracker);
+	WINPR_ASSERT(pdata);
+
+	const BOOL isBackData = (tracker == dynChannelContext->backTracker);
+	switch (dynChannel->channelMode)
+	{
+		case PF_UTILS_CHANNEL_PASSTHROUGH:
+			result = channelTracker_flushCurrent(tracker, firstPacket, lastPacket, !isBackData);
+			break;
+		case PF_UTILS_CHANNEL_BLOCK:
+			channelTracker_setMode(tracker, CHANNEL_TRACKER_DROP);
+			result = PF_CHANNEL_RESULT_DROP;
+			break;
+		case PF_UTILS_CHANNEL_INTERCEPT:
+			if (trackerState->dataCallback)
+			{
+				result = trackerState->dataCallback(pdata->ps, dynChannel, isBackData, tracker,
+				                                    firstPacket, lastPacket);
+			}
+			else
+			{
+				DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+				                "no intercept callback for channel, dropping packet");
+				result = PF_CHANNEL_RESULT_DROP;
+			}
+			break;
+		default:
+			DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+			                "unknown channel mode %u", dynChannel->channelMode);
+			result = PF_CHANNEL_RESULT_ERROR;
+			break;
+	}
+
+	if (!trackerState->currentDataLength ||
+	    (trackerState->CurrentDataReceived == trackerState->currentDataLength))
+	{
+		trackerState->currentDataLength = 0;
+		trackerState->CurrentDataFragments = 0;
+		trackerState->CurrentDataReceived = 0;
+
+		if (dynChannel->packetReassembly && trackerState->currentPacket)
+			Stream_SetPosition(trackerState->currentPacket, 0);
+	}
+
+	return result;
+}
+
+static PfChannelResult DynvcTrackerHandleClose(ChannelStateTracker* tracker,
+                                               pServerDynamicChannelContext* dynChannel,
+                                               DynChannelContext* dynChannelContext,
+                                               BOOL firstPacket, BOOL lastPacket)
+{
+	WINPR_ASSERT(dynChannel);
+	WINPR_ASSERT(dynChannelContext);
+
+	const BOOL isBackData = (tracker == dynChannelContext->backTracker);
+
+	if (!lastPacket)
+		return PF_CHANNEL_RESULT_DROP;
+
+	DynvcTrackerLog(dynChannelContext->log, WLOG_DEBUG, dynChannel, CLOSE_REQUEST_PDU, isBackData,
+	                "Close request");
+	channelTracker_setMode(tracker, CHANNEL_TRACKER_PASS);
+	if (dynChannel->openStatus != CHANNEL_OPENSTATE_OPENED)
+	{
+		DynvcTrackerLog(dynChannelContext->log, WLOG_DEBUG, dynChannel, CLOSE_REQUEST_PDU,
+		                isBackData, "is in state %s, expected %s",
+		                openstatus2str(dynChannel->openStatus),
+		                openstatus2str(CHANNEL_OPENSTATE_OPENED));
+	}
+	dynChannel->openStatus = CHANNEL_OPENSTATE_CLOSED;
+	return channelTracker_flushCurrent(tracker, firstPacket, lastPacket, !isBackData);
+}
+
+static PfChannelResult DynvcTrackerHandleCreateBack(ChannelStateTracker* tracker, wStream* s,
+                                                    DWORD flags, proxyData* pdata,
+                                                    pServerDynamicChannelContext* dynChannel,
+                                                    DynChannelContext* dynChannelContext,
+                                                    UINT64 dynChannelId)
+{
+	proxyChannelDataEventInfo dev = { 0 };
+	const char* name = Stream_ConstPointer(s);
+	const size_t nameLen = Stream_GetRemainingLength(s);
+	const size_t len = strnlen(name, nameLen);
+	const BOOL isBackData = (tracker == dynChannelContext->backTracker);
+	const BYTE cmd = CREATE_REQUEST_PDU;
+
+	if ((len == 0) || (len == nameLen) || (dynChannelId > UINT16_MAX))
+	{
+		char namebuffer[64] = { 0 };
+		(void)_snprintf(namebuffer, sizeof(namebuffer) - 1, "%s", name);
+
+		DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+		                "channel id %" PRIu64 ", name=%s [%" PRIuz "|%" PRIuz "], status=%s",
+		                dynChannelId, namebuffer, len, nameLen,
+		                openstatus2str(dynChannel->openStatus));
+		return PF_CHANNEL_RESULT_ERROR;
+	}
+
+	wStream* currentPacket = channelTracker_getCurrentPacket(tracker);
+	dev.channel_id = (UINT16)dynChannelId;
+	dev.channel_name = name;
+	dev.data = Stream_Buffer(s);
+	dev.data_len = Stream_GetPosition(currentPacket);
+	dev.flags = flags;
+	dev.total_size = Stream_GetPosition(currentPacket);
+
+	if (dynChannel)
+	{
+		DynvcTrackerLog(dynChannelContext->log, WLOG_WARN, dynChannel, cmd, isBackData,
+		                "Reusing channel id, now %s", name);
+
+		HashTable_Remove(dynChannelContext->channels, &dynChannel->channelId);
+	}
+
+	if (!pf_modules_run_filter(pdata->module, FILTER_TYPE_CLIENT_PASSTHROUGH_DYN_CHANNEL_CREATE,
+	                           pdata, &dev))
+		return PF_CHANNEL_RESULT_DROP; /* Silently drop */
+
+	dynChannel =
+	    DynamicChannelContext_new(dynChannelContext->log, pdata->ps, name, (UINT32)dynChannelId);
+	if (!dynChannel)
+	{
+		DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+		                "unable to create dynamic channel context data");
+		return PF_CHANNEL_RESULT_ERROR;
+	}
+
+	DynvcTrackerLog(dynChannelContext->log, WLOG_DEBUG, dynChannel, cmd, isBackData,
+	                "Adding channel");
+	if (!HashTable_Insert(dynChannelContext->channels, &dynChannel->channelId, dynChannel))
+	{
+		DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+		                "unable register dynamic channel context data");
+		DynamicChannelContext_free(dynChannel);
+		return PF_CHANNEL_RESULT_ERROR;
+	}
+
+	dynChannel->openStatus = CHANNEL_OPENSTATE_WAITING_OPEN_STATUS;
+
+	const BOOL firstPacket = (flags & CHANNEL_FLAG_FIRST) ? TRUE : FALSE;
+	const BOOL lastPacket = (flags & CHANNEL_FLAG_LAST) ? TRUE : FALSE;
+
+	// NOLINTNEXTLINE(clang-analyzer-unix.Malloc): HashTable_Insert owns dynChannel
+	return channelTracker_flushCurrent(tracker, firstPacket, lastPacket, FALSE);
+}
+
+static PfChannelResult DynvcTrackerHandleCreateFront(ChannelStateTracker* tracker, wStream* s,
+                                                     DWORD flags,
+                                                     WINPR_ATTR_UNUSED proxyData* pdata,
+                                                     pServerDynamicChannelContext* dynChannel,
+                                                     DynChannelContext* dynChannelContext,
+                                                     UINT64 dynChannelId)
+{
+	const BOOL isBackData = (tracker == dynChannelContext->backTracker);
+	const BYTE cmd = CREATE_REQUEST_PDU;
+
+	/* CREATE_REQUEST_PDU response */
+	if (!Stream_CheckAndLogRequiredLengthWLogWithBackend(dynChannelContext->log, s, 4, FALSE))
+		return PF_CHANNEL_RESULT_ERROR;
+
+	const UINT32 creationStatus = Stream_Get_UINT32(s);
+	DynvcTrackerLog(dynChannelContext->log, WLOG_DEBUG, dynChannel, cmd, isBackData,
+	                "CREATE_RESPONSE openStatus=%" PRIu32, creationStatus);
+
+	if (creationStatus == 0)
+		dynChannel->openStatus = CHANNEL_OPENSTATE_OPENED;
+
+	const BOOL firstPacket = (flags & CHANNEL_FLAG_FIRST) ? TRUE : FALSE;
+	const BOOL lastPacket = (flags & CHANNEL_FLAG_LAST) ? TRUE : FALSE;
+
+	return channelTracker_flushCurrent(tracker, firstPacket, lastPacket, TRUE);
+}
+
 static PfChannelResult DynvcTrackerHandleCreate(ChannelStateTracker* tracker, wStream* s,
                                                DWORD flags,
                                                pServerDynamicChannelContext* dynChannel,
@@ -242,10 +472,7 @@ static PfChannelResult DynvcTrackerHandleCreate(ChannelStateTracker* tracker, wS
 	WINPR_ASSERT(dynChannelContext);

 	const BOOL lastPacket = (flags & CHANNEL_FLAG_LAST) ? TRUE : FALSE;
-	const BOOL firstPacket = (flags & CHANNEL_FLAG_FIRST) ? TRUE : FALSE;
 	const BOOL isBackData = (tracker == dynChannelContext->backTracker);
-	const char* direction = isBackData ? "B->F" : "F->B";
-	UINT32 creationStatus = 0;

 	proxyData* pdata = channelTracker_getPData(tracker);
 	WINPR_ASSERT(pdata);
@@ -255,83 +482,204 @@ static PfChannelResult DynvcTrackerHandleCreate(ChannelStateTracker* tracker, wS
 		return PF_CHANNEL_RESULT_DROP;

 	if (isBackData)
+		return DynvcTrackerHandleCreateBack(tracker, s, flags, pdata, dynChannel, dynChannelContext,
+		                                    dynChannelId);
+
+	return DynvcTrackerHandleCreateFront(tracker, s, flags, pdata, dynChannel, dynChannelContext,
+	                                     dynChannelId);
+}
+
+static PfChannelResult DynvcTrackerHandleCmdDATA(ChannelStateTracker* tracker,
+                                                 pServerDynamicChannelContext* dynChannel,
+                                                 wStream* s, BYTE cmd, UINT64 Length,
+                                                 BOOL firstPacket, BOOL lastPacket)
+{
+	WINPR_ASSERT(tracker);
+	WINPR_ASSERT(dynChannel);
+	WINPR_ASSERT(s);
+
+	DynChannelContext* dynChannelContext =
+	    (DynChannelContext*)channelTracker_getCustomData(tracker);
+	WINPR_ASSERT(dynChannelContext);
+
+	const BOOL isBackData = (tracker == dynChannelContext->backTracker);
+
+	DynChannelTrackerState* trackerState =
+	    isBackData ? &dynChannel->backTracker : &dynChannel->frontTracker;
+	if (dynChannel->openStatus != CHANNEL_OPENSTATE_OPENED)
 	{
-		proxyChannelDataEventInfo dev = { 0 };
-		const char* name = Stream_ConstPointer(s);
-		const size_t nameLen = Stream_GetRemainingLength(s);
-
-		const size_t len = strnlen(name, nameLen);
-		if ((len == 0) || (len == nameLen) || (dynChannelId > UINT16_MAX))
-			return PF_CHANNEL_RESULT_ERROR;
-
-		wStream* currentPacket = channelTracker_getCurrentPacket(tracker);
-		dev.channel_id = (UINT16)dynChannelId;
-		dev.channel_name = name;
-		dev.data = Stream_Buffer(s);
-		dev.data_len = Stream_GetPosition(currentPacket);
-		dev.flags = flags;
-		dev.total_size = Stream_GetPosition(currentPacket);
-
-		if (dynChannel)
-		{
-			WLog_Print(dynChannelContext->log, WLOG_WARN,
-			           "Reusing channel id %" PRIu32 ", previously %s [state %s, mode %s], now %s",
-			           dynChannel->channelId, dynChannel->channelName,
-			           openstatus2str(dynChannel->openStatus),
-			           pf_utils_channel_mode_string(dynChannel->channelMode), dev.channel_name);
-
-			HashTable_Remove(dynChannelContext->channels, &dynChannel->channelId);
-		}
-
-		if (!pf_modules_run_filter(pdata->module, FILTER_TYPE_CLIENT_PASSTHROUGH_DYN_CHANNEL_CREATE,
-		                           pdata, &dev))
-			return PF_CHANNEL_RESULT_DROP; /* Silently drop */
-
-		dynChannel = DynamicChannelContext_new(dynChannelContext->log, pdata->ps, name,
-		                                       (UINT32)dynChannelId);
-		if (!dynChannel)
-		{
-			WLog_Print(dynChannelContext->log, WLOG_ERROR,
-			           "unable to create dynamic channel context data");
-			return PF_CHANNEL_RESULT_ERROR;
-		}
-
-		WLog_Print(dynChannelContext->log, WLOG_DEBUG, "Adding channel '%s'[%" PRIu32 "]",
-		           dynChannel->channelName, dynChannel->channelId);
-		if (!HashTable_Insert(dynChannelContext->channels, &dynChannel->channelId, dynChannel))
-		{
-			WLog_Print(dynChannelContext->log, WLOG_ERROR,
-			           "unable register dynamic channel context data");
-			DynamicChannelContext_free(dynChannel);
-			return PF_CHANNEL_RESULT_ERROR;
-		}
-
-		dynChannel->openStatus = CHANNEL_OPENSTATE_WAITING_OPEN_STATUS;
-
-		// NOLINTNEXTLINE(clang-analyzer-unix.Malloc): HashTable_Insert owns dynChannel
-		return channelTracker_flushCurrent(tracker, firstPacket, lastPacket, FALSE);
+		DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+		                "channel is not opened");
+		return PF_CHANNEL_RESULT_ERROR;
 	}

-	/* CREATE_REQUEST_PDU response */
-	if (!Stream_CheckAndLogRequiredLengthWLog(dynChannelContext->log, s, 4))
-		return PF_CHANNEL_RESULT_ERROR;
+	switch (cmd)
+	{
+		case DATA_FIRST_PDU:
+		case DATA_FIRST_COMPRESSED_PDU:
+		{
+			DynvcTrackerLog(dynChannelContext->log, WLOG_DEBUG, dynChannel, cmd, isBackData,
+			                "DATA_FIRST currentPacketLength=%" PRIu64 "", Length);
+			if (Length > UINT32_MAX)
+			{
+				DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+				                "Length out of bounds: %" PRIu64, Length);
+				return PF_CHANNEL_RESULT_ERROR;
+			}
+			trackerState->currentDataLength = (UINT32)Length;
+			trackerState->CurrentDataReceived = 0;
+			trackerState->CurrentDataFragments = 0;

-	Stream_Read_UINT32(s, creationStatus);
-	WLog_Print(dynChannelContext->log, WLOG_DEBUG,
-	           "DynvcTracker(%" PRIu64 ",%s): %s CREATE_RESPONSE openStatus=%" PRIu32, dynChannelId,
-	           dynChannel->channelName, direction, creationStatus);
+			if (dynChannel->packetReassembly)
+			{
+				if (trackerState->currentPacket)
+					Stream_SetPosition(trackerState->currentPacket, 0);
+			}
+		}
+		break;
+		default:
+			break;
+	}

-	if (creationStatus == 0)
-		dynChannel->openStatus = CHANNEL_OPENSTATE_OPENED;
+	switch (cmd)
+	{
+		case DATA_PDU:
+		case DATA_FIRST_PDU:
+		{
+			size_t extraSize = Stream_GetRemainingLength(s);

-	return channelTracker_flushCurrent(tracker, firstPacket, lastPacket, TRUE);
+			trackerState->CurrentDataFragments++;
+			trackerState->CurrentDataReceived += WINPR_ASSERTING_INT_CAST(uint32_t, extraSize);
+
+			if (dynChannel->packetReassembly)
+			{
+				if (!trackerState->currentPacket)
+				{
+					trackerState->currentPacket = Stream_New(NULL, 1024);
+					if (!trackerState->currentPacket)
+					{
+						DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd,
+						                isBackData, "unable to create current packet",
+						                getDirection(isBackData), dynChannel->channelName,
+						                drdynvc_get_packet_type(cmd));
+						return PF_CHANNEL_RESULT_ERROR;
+					}
+				}
+
+				if (!Stream_EnsureRemainingCapacity(trackerState->currentPacket, extraSize))
+				{
+					DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+					                "unable to grow current packet", getDirection(isBackData),
+					                dynChannel->channelName, drdynvc_get_packet_type(cmd));
+					return PF_CHANNEL_RESULT_ERROR;
+				}
+
+				Stream_Write(trackerState->currentPacket, Stream_ConstPointer(s), extraSize);
+			}
+			DynvcTrackerLog(dynChannelContext->log, WLOG_DEBUG, dynChannel, cmd, isBackData,
+			                "frags=%" PRIu32 " received=%" PRIu32 "(%" PRIu32 ")",
+			                trackerState->CurrentDataFragments, trackerState->CurrentDataReceived,
+			                trackerState->currentDataLength);
+		}
+		break;
+		default:
+			break;
+	}
+
+	switch (cmd)
+	{
+		case DATA_PDU:
+		{
+			if (trackerState->currentDataLength)
+			{
+				if (trackerState->CurrentDataReceived > trackerState->currentDataLength)
+				{
+					DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+					                "reassembled packet (%" PRIu32
+					                ") is bigger than announced length (%" PRIu32 ")",
+					                trackerState->CurrentDataReceived,
+					                trackerState->currentDataLength);
+					return PF_CHANNEL_RESULT_ERROR;
+				}
+			}
+			else
+			{
+				trackerState->CurrentDataFragments = 0;
+				trackerState->CurrentDataReceived = 0;
+			}
+		}
+		break;
+		default:
+			break;
+	}
+
+	return DynvcTrackerPeekHandleByMode(tracker, trackerState, dynChannel, cmd, firstPacket,
+	                                    lastPacket);
+}
+
+static PfChannelResult DynvcTrackerHandleCmd(ChannelStateTracker* tracker,
+                                             pServerDynamicChannelContext* dynChannel, wStream* s,
+                                             BYTE cmd, UINT32 flags, UINT64 Length,
+                                             UINT64 dynChannelId, BOOL firstPacket, BOOL lastPacket)
+{
+	WINPR_ASSERT(tracker);
+	WINPR_ASSERT(s);
+
+	DynChannelContext* dynChannelContext =
+	    (DynChannelContext*)channelTracker_getCustomData(tracker);
+	WINPR_ASSERT(dynChannelContext);
+
+	const BOOL isBackData = (tracker == dynChannelContext->backTracker);
+	switch (cmd)
+	{
+		case CAPABILITY_REQUEST_PDU:
+			DynvcTrackerLog(dynChannelContext->log, WLOG_DEBUG, dynChannel, cmd, isBackData,
+			                "CAPABILITY_%s", isBackData ? "REQUEST" : "RESPONSE");
+			channelTracker_setMode(tracker, CHANNEL_TRACKER_PASS);
+			return PF_CHANNEL_RESULT_PASS;
+
+		case CREATE_REQUEST_PDU:
+			return DynvcTrackerHandleCreate(tracker, s, flags, dynChannel, dynChannelId);
+
+		case CLOSE_REQUEST_PDU:
+			return DynvcTrackerHandleClose(tracker, dynChannel, dynChannelContext, firstPacket,
+			                               lastPacket);
+
+		case SOFT_SYNC_REQUEST_PDU:
+			/* just pass then as is for now */
+			DynvcTrackerLog(dynChannelContext->log, WLOG_DEBUG, dynChannel, cmd, isBackData,
+			                "SOFT_SYNC_REQUEST_PDU");
+			channelTracker_setMode(tracker, CHANNEL_TRACKER_PASS);
+			/*TODO: return pf_treat_softsync_req(pdata, s);*/
+			return PF_CHANNEL_RESULT_PASS;
+
+		case SOFT_SYNC_RESPONSE_PDU:
+			/* just pass then as is for now */
+			DynvcTrackerLog(dynChannelContext->log, WLOG_DEBUG, dynChannel, cmd, isBackData,
+			                "SOFT_SYNC_RESPONSE_PDU");
+			channelTracker_setMode(tracker, CHANNEL_TRACKER_PASS);
+			return PF_CHANNEL_RESULT_PASS;
+
+		case DATA_FIRST_PDU:
+		case DATA_PDU:
+			return DynvcTrackerHandleCmdDATA(tracker, dynChannel, s, cmd, Length, firstPacket,
+			                                 lastPacket);
+
+		case DATA_FIRST_COMPRESSED_PDU:
+		case DATA_COMPRESSED_PDU:
+			DynvcTrackerLog(dynChannelContext->log, WLOG_DEBUG, dynChannel, cmd, isBackData,
+			                "TODO: compressed data packets, pass them as is for now");
+			channelTracker_setMode(tracker, CHANNEL_TRACKER_PASS);
+			return channelTracker_flushCurrent(tracker, firstPacket, lastPacket, !isBackData);
+
+		default:
+			return PF_CHANNEL_RESULT_ERROR;
+	}
 }

 static PfChannelResult DynvcTrackerPeekFn(ChannelStateTracker* tracker, BOOL firstPacket,
                                          BOOL lastPacket)
 {
-	BYTE cmd = 0;
-	BYTE byte0 = 0;
 	wStream* s = NULL;
 	wStream sbuffer;
 	BOOL haveChannelId = 0;
@@ -346,8 +694,7 @@ static PfChannelResult DynvcTrackerPeekFn(ChannelStateTracker* tracker, BOOL fir
 	    (DynChannelContext*)channelTracker_getCustomData(tracker);
 	WINPR_ASSERT(dynChannelContext);

-	BOOL isBackData = (tracker == dynChannelContext->backTracker);
-	DynChannelTrackerState* trackerState = NULL;
+	const BOOL isBackData = (tracker == dynChannelContext->backTracker);

 	UINT32 flags = lastPacket ? CHANNEL_FLAG_LAST : 0;
 	if (firstPacket)
@@ -355,19 +702,17 @@ static PfChannelResult DynvcTrackerPeekFn(ChannelStateTracker* tracker, BOOL fir
 	proxyData* pdata = channelTracker_getPData(tracker);
 	WINPR_ASSERT(pdata);

-	const char* direction = isBackData ? "B->F" : "F->B";
-
 	{
 		wStream* currentPacket = channelTracker_getCurrentPacket(tracker);
 		s = Stream_StaticConstInit(&sbuffer, Stream_Buffer(currentPacket),
 		                           Stream_GetPosition(currentPacket));
 	}

-	if (!Stream_CheckAndLogRequiredLengthWLog(dynChannelContext->log, s, 1))
+	if (!Stream_CheckAndLogRequiredLengthWLogWithBackend(dynChannelContext->log, s, 1, isBackData))
 		return PF_CHANNEL_RESULT_ERROR;

-	Stream_Read_UINT8(s, byte0);
-	cmd = byte0 >> 4;
+	const BYTE byte0 = Stream_Get_UINT8(s);
+	const BYTE cmd = byte0 >> 4;

 	switch (cmd)
 	{
@@ -401,8 +746,8 @@ static PfChannelResult DynvcTrackerPeekFn(ChannelStateTracker* tracker, BOOL fir
 				return PF_CHANNEL_RESULT_DROP;
 			case DYNCVC_READ_ERROR:
 			default:
-				WLog_Print(dynChannelContext->log, WLOG_ERROR,
-				           "DynvcTrackerPeekFn: invalid channelId field");
+				DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+				                "invalid channelId field");
 				return PF_CHANNEL_RESULT_ERROR;
 		}

@@ -434,200 +779,14 @@ static PfChannelResult DynvcTrackerPeekFn(ChannelStateTracker* tracker, BOOL fir
 				return PF_CHANNEL_RESULT_DROP;
 			case DYNCVC_READ_ERROR:
 			default:
-				WLog_Print(dynChannelContext->log, WLOG_ERROR,
-				           "DynvcTrackerPeekFn: invalid length field");
+				DynvcTrackerLog(dynChannelContext->log, WLOG_ERROR, dynChannel, cmd, isBackData,
+				                "invalid length field");
 				return PF_CHANNEL_RESULT_ERROR;
 		}
 	}

-	switch (cmd)
-	{
-		case CAPABILITY_REQUEST_PDU:
-			WLog_Print(dynChannelContext->log, WLOG_DEBUG, "DynvcTracker: %s CAPABILITY_%s",
-			           direction, isBackData ? "REQUEST" : "RESPONSE");
-			channelTracker_setMode(tracker, CHANNEL_TRACKER_PASS);
-			return PF_CHANNEL_RESULT_PASS;
-
-		case CREATE_REQUEST_PDU:
-			return DynvcTrackerHandleCreate(tracker, s, flags, dynChannel, dynChannelId);
-
-		case CLOSE_REQUEST_PDU:
-			if (!lastPacket)
-				return PF_CHANNEL_RESULT_DROP;
-
-			WLog_Print(dynChannelContext->log, WLOG_DEBUG,
-			           "DynvcTracker(%s): %s Close request on channel", dynChannel->channelName,
-			           direction);
-			channelTracker_setMode(tracker, CHANNEL_TRACKER_PASS);
-			if (dynChannel->openStatus != CHANNEL_OPENSTATE_OPENED)
-			{
-				WLog_Print(dynChannelContext->log, WLOG_WARN,
-				           "DynvcTracker(%s): is in state %s, expected %s", dynChannel->channelName,
-				           openstatus2str(dynChannel->openStatus),
-				           openstatus2str(CHANNEL_OPENSTATE_OPENED));
-			}
-			dynChannel->openStatus = CHANNEL_OPENSTATE_CLOSED;
-			return channelTracker_flushCurrent(tracker, firstPacket, lastPacket, !isBackData);
-
-		case SOFT_SYNC_REQUEST_PDU:
-			/* just pass then as is for now */
-			WLog_Print(dynChannelContext->log, WLOG_DEBUG, "SOFT_SYNC_REQUEST_PDU");
-			channelTracker_setMode(tracker, CHANNEL_TRACKER_PASS);
-			/*TODO: return pf_treat_softsync_req(pdata, s);*/
-			return PF_CHANNEL_RESULT_PASS;
-
-		case SOFT_SYNC_RESPONSE_PDU:
-			/* just pass then as is for now */
-			WLog_Print(dynChannelContext->log, WLOG_DEBUG, "SOFT_SYNC_RESPONSE_PDU");
-			channelTracker_setMode(tracker, CHANNEL_TRACKER_PASS);
-			return PF_CHANNEL_RESULT_PASS;
-
-		case DATA_FIRST_PDU:
-		case DATA_PDU:
-			/* treat these below */
-			trackerState = isBackData ? &dynChannel->backTracker : &dynChannel->frontTracker;
-			break;
-
-		case DATA_FIRST_COMPRESSED_PDU:
-		case DATA_COMPRESSED_PDU:
-			WLog_Print(dynChannelContext->log, WLOG_DEBUG,
-			           "TODO: compressed data packets, pass them as is for now");
-			channelTracker_setMode(tracker, CHANNEL_TRACKER_PASS);
-			return channelTracker_flushCurrent(tracker, firstPacket, lastPacket, !isBackData);
-
-		default:
-			return PF_CHANNEL_RESULT_ERROR;
-	}
-
-	if (dynChannel->openStatus != CHANNEL_OPENSTATE_OPENED)
-	{
-		WLog_Print(dynChannelContext->log, WLOG_ERROR,
-		           "DynvcTracker(%s [%s]): channel is not opened {state %s}",
-		           dynChannel->channelName, drdynvc_get_packet_type(cmd),
-		           openstatus2str(dynChannel->openStatus));
-		return PF_CHANNEL_RESULT_ERROR;
-	}
-
-	if ((cmd == DATA_FIRST_PDU) || (cmd == DATA_FIRST_COMPRESSED_PDU))
-	{
-		WLog_Print(dynChannelContext->log, WLOG_DEBUG,
-		           "DynvcTracker(%s [%s]): %s DATA_FIRST currentPacketLength=%" PRIu64 "",
-		           dynChannel->channelName, drdynvc_get_packet_type(cmd), direction, Length);
-		if (Length > UINT32_MAX)
-			return PF_CHANNEL_RESULT_ERROR;
-		trackerState->currentDataLength = (UINT32)Length;
-		trackerState->CurrentDataReceived = 0;
-		trackerState->CurrentDataFragments = 0;
-
-		if (dynChannel->packetReassembly)
-		{
-			if (trackerState->currentPacket)
-				Stream_SetPosition(trackerState->currentPacket, 0);
-		}
-	}
-
-	if (cmd == DATA_PDU || cmd == DATA_FIRST_PDU)
-	{
-		size_t extraSize = Stream_GetRemainingLength(s);
-
-		trackerState->CurrentDataFragments++;
-		trackerState->CurrentDataReceived += WINPR_ASSERTING_INT_CAST(uint32_t, extraSize);
-
-		if (dynChannel->packetReassembly)
-		{
-			if (!trackerState->currentPacket)
-			{
-				trackerState->currentPacket = Stream_New(NULL, 1024);
-				if (!trackerState->currentPacket)
-				{
-					WLog_Print(dynChannelContext->log, WLOG_ERROR,
-					           "unable to create current packet");
-					return PF_CHANNEL_RESULT_ERROR;
-				}
-			}
-
-			if (!Stream_EnsureRemainingCapacity(trackerState->currentPacket, extraSize))
-			{
-				WLog_Print(dynChannelContext->log, WLOG_ERROR, "unable to grow current packet");
-				return PF_CHANNEL_RESULT_ERROR;
-			}
-
-			Stream_Write(trackerState->currentPacket, Stream_ConstPointer(s), extraSize);
-		}
-		WLog_Print(dynChannelContext->log, WLOG_DEBUG,
-		           "DynvcTracker(%s [%s]{state %s}): %s frags=%" PRIu32 " received=%" PRIu32
-		           "(%" PRIu32 ")",
-		           dynChannel->channelName, drdynvc_get_packet_type(cmd),
-		           openstatus2str(dynChannel->openStatus), direction,
-		           trackerState->CurrentDataFragments, trackerState->CurrentDataReceived,
-		           trackerState->currentDataLength);
-	}
-
-	if (cmd == DATA_PDU)
-	{
-		if (trackerState->currentDataLength)
-		{
-			if (trackerState->CurrentDataReceived > trackerState->currentDataLength)
-			{
-				WLog_Print(dynChannelContext->log, WLOG_ERROR,
-				           "DynvcTracker (%s  [%s]{stte %s}): reassembled packet (%" PRIu32
-				           ") is bigger than announced length (%" PRIu32 ")",
-				           dynChannel->channelName, drdynvc_get_packet_type(cmd),
-				           openstatus2str(dynChannel->openStatus),
-				           trackerState->CurrentDataReceived, trackerState->currentDataLength);
-				return PF_CHANNEL_RESULT_ERROR;
-			}
-		}
-		else
-		{
-			trackerState->CurrentDataFragments = 0;
-			trackerState->CurrentDataReceived = 0;
-		}
-	}
-
-	PfChannelResult result = PF_CHANNEL_RESULT_ERROR;
-	switch (dynChannel->channelMode)
-	{
-		case PF_UTILS_CHANNEL_PASSTHROUGH:
-			result = channelTracker_flushCurrent(tracker, firstPacket, lastPacket, !isBackData);
-			break;
-		case PF_UTILS_CHANNEL_BLOCK:
-			channelTracker_setMode(tracker, CHANNEL_TRACKER_DROP);
-			result = PF_CHANNEL_RESULT_DROP;
-			break;
-		case PF_UTILS_CHANNEL_INTERCEPT:
-			if (trackerState->dataCallback)
-			{
-				result = trackerState->dataCallback(pdata->ps, dynChannel, isBackData, tracker,
-				                                    firstPacket, lastPacket);
-			}
-			else
-			{
-				WLog_Print(dynChannelContext->log, WLOG_ERROR,
-				           "no intercept callback for channel %s(fromBack=%d), dropping packet",
-				           dynChannel->channelName, isBackData);
-				result = PF_CHANNEL_RESULT_DROP;
-			}
-			break;
-		default:
-			WLog_Print(dynChannelContext->log, WLOG_ERROR, "unknown channel mode %u",
-			           dynChannel->channelMode);
-			result = PF_CHANNEL_RESULT_ERROR;
-			break;
-	}
-
-	if (!trackerState->currentDataLength ||
-	    (trackerState->CurrentDataReceived == trackerState->currentDataLength))
-	{
-		trackerState->currentDataLength = 0;
-		trackerState->CurrentDataFragments = 0;
-		trackerState->CurrentDataReceived = 0;
-
-		if (dynChannel->packetReassembly && trackerState->currentPacket)
-			Stream_SetPosition(trackerState->currentPacket, 0);
-	}
-
-	return result;
+	return DynvcTrackerHandleCmd(tracker, dynChannel, s, cmd, flags, Length, dynChannelId,
+	                             firstPacket, lastPacket);
 }

 static void DynChannelContext_free(void* context)