diff --git a/server/proxy/channels/pf_channel_drdynvc.c b/server/proxy/channels/pf_channel_drdynvc.c index 15c6a0e67..3ee932896 100644 --- 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 : ""; + (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)