From 6563bc28c42c8ffeb8f22747a91cca64d790bf5b Mon Sep 17 00:00:00 2001 From: David Fort Date: Thu, 23 May 2019 12:15:26 +0200 Subject: [PATCH] rail: added verbose logs (#5402) * rail: added verbose logs * rail: fix buffer initialisation in debug message --- channels/rail/client/rail_orders.c | 6 +- libfreerdp/core/update.c | 34 +++---- libfreerdp/core/window.c | 191 ++++++++++++++++++++++++++++++++++--- 3 files changed, 193 insertions(+), 38 deletions(-) diff --git a/channels/rail/client/rail_orders.c b/channels/rail/client/rail_orders.c index 98834e6..da92707 100644 --- a/channels/rail/client/rail_orders.c +++ b/channels/rail/client/rail_orders.c @@ -153,8 +153,7 @@ static UINT rail_read_server_exec_result_order(wStream* s, RAIL_EXEC_RESULT_ORDE Stream_Read_UINT16(s, execResult->execResult); /* execResult (2 bytes) */ Stream_Read_UINT32(s, execResult->rawResult); /* rawResult (4 bytes) */ Stream_Seek_UINT16(s); /* padding (2 bytes) */ - return rail_read_unicode_string(s, - &execResult->exeOrFile) ? CHANNEL_RC_OK : ERROR_INTERNAL_ERROR; /* exeOrFile */ + return rail_read_unicode_string(s, &execResult->exeOrFile) ? CHANNEL_RC_OK : ERROR_INTERNAL_ERROR; /* exeOrFile */ } /** @@ -269,8 +268,7 @@ static UINT rail_read_server_get_appid_resp_order(wStream* s, } Stream_Read_UINT32(s, getAppidResp->windowId); /* windowId (4 bytes) */ - Stream_Read(s, (BYTE*) & (getAppidResp->applicationId), - 512); /* applicationId (256 UNICODE chars) */ + Stream_Read(s, (BYTE*) & (getAppidResp->applicationId), 512); /* applicationId (256 UNICODE chars) */ return CHANNEL_RC_OK; } diff --git a/libfreerdp/core/update.c b/libfreerdp/core/update.c index bcf2d51..9d904c6 100644 --- a/libfreerdp/core/update.c +++ b/libfreerdp/core/update.c @@ -174,13 +174,10 @@ static BOOL update_write_bitmap_data(rdpUpdate* update, wStream* s, { if (!(bitmapData->flags & NO_BITMAP_COMPRESSION_HDR)) { - Stream_Write_UINT16(s, - bitmapData->cbCompFirstRowSize); /* cbCompFirstRowSize (2 bytes) */ - Stream_Write_UINT16(s, - bitmapData->cbCompMainBodySize); /* cbCompMainBodySize (2 bytes) */ + Stream_Write_UINT16(s, bitmapData->cbCompFirstRowSize); /* cbCompFirstRowSize (2 bytes) */ + Stream_Write_UINT16(s, bitmapData->cbCompMainBodySize); /* cbCompMainBodySize (2 bytes) */ Stream_Write_UINT16(s, bitmapData->cbScanWidth); /* cbScanWidth (2 bytes) */ - Stream_Write_UINT16(s, - bitmapData->cbUncompressedSize); /* cbUncompressedSize (2 bytes) */ + Stream_Write_UINT16(s, bitmapData->cbUncompressedSize); /* cbUncompressedSize (2 bytes) */ } Stream_Write(s, bitmapData->bitmapDataStream, bitmapData->bitmapLength); @@ -387,10 +384,8 @@ static BOOL _update_read_pointer_color(wStream* s, POINTER_COLOR_UPDATE* pointer if ((pointer_color->width > 96) || (pointer_color->height > 96)) goto fail; - Stream_Read_UINT16(s, - pointer_color->lengthAndMask); /* lengthAndMask (2 bytes) */ - Stream_Read_UINT16(s, - pointer_color->lengthXorMask); /* lengthXorMask (2 bytes) */ + Stream_Read_UINT16(s, pointer_color->lengthAndMask); /* lengthAndMask (2 bytes) */ + Stream_Read_UINT16(s, pointer_color->lengthXorMask); /* lengthXorMask (2 bytes) */ /** * There does not seem to be any documentation on why @@ -458,7 +453,7 @@ static BOOL _update_read_pointer_color(wStream* s, POINTER_COLOR_UPDATE* pointer if (scanlineSize * pointer_color->height != pointer_color->lengthAndMask) { - WLog_ERR(TAG, "invalid lengthAndMask: %"PRIu32" instead of %"PRIu32"", + WLog_ERR(TAG, "invalid lengthAndMask: %"PRIu32" instead of %"PRIu32"", pointer_color->lengthAndMask, scanlineSize * pointer_color->height); goto fail; } @@ -510,7 +505,7 @@ POINTER_NEW_UPDATE* update_read_pointer_new(rdpUpdate* update, wStream* s) if ((pointer_new->xorBpp < 1) || (pointer_new->xorBpp > 32)) { - WLog_ERR(TAG, "invalid xorBpp %"PRIu32"", pointer_new->xorBpp); + WLog_ERR(TAG, "invalid xorBpp %"PRIu32"", pointer_new->xorBpp); goto fail; } @@ -810,9 +805,8 @@ static BOOL _update_end_paint(rdpContext* context) if (update->numberOrders > 0) { - WLog_DBG(TAG, "sending %"PRIu16" orders", update->numberOrders); - fastpath_send_update_pdu(context->rdp->fastpath, FASTPATH_UPDATETYPE_ORDERS, s, - FALSE); + WLog_DBG(TAG, "sending %"PRIu16" orders", update->numberOrders); + fastpath_send_update_pdu(context->rdp->fastpath, FASTPATH_UPDATETYPE_ORDERS, s, FALSE); } update->combineUpdates = FALSE; @@ -1011,8 +1005,7 @@ static BOOL update_send_refresh_rect(rdpContext* context, BYTE count, return TRUE; } -static void update_write_suppress_output(wStream* s, BYTE allow, - const RECTANGLE_16* area) +static void update_write_suppress_output(wStream* s, BYTE allow, const RECTANGLE_16* area) { Stream_Write_UINT8(s, allow); /* allowDisplayUpdates (1 byte) */ /* Use zeros for padding (like mstsc) for compatibility with legacy servers */ @@ -1247,6 +1240,7 @@ static BOOL update_send_play_sound(rdpContext* context, Stream_Write_UINT32(s, play_sound->frequency); return rdp_send_data_pdu(rdp, s, DATA_PDU_TYPE_PLAY_SOUND, rdp->mcs->userId); } + /** * Primary Drawing Orders */ @@ -1260,8 +1254,7 @@ static BOOL update_send_dstblt(rdpContext* context, ORDER_INFO orderInfo; int inf; rdpUpdate* update = context->update; - headerLength = update_prepare_order_info(context, &orderInfo, - ORDER_TYPE_DSTBLT); + headerLength = update_prepare_order_info(context, &orderInfo, ORDER_TYPE_DSTBLT); inf = update_approximate_dstblt_order(&orderInfo, dstblt); update_check_flush(context, headerLength + inf); s = update->us; @@ -1500,8 +1493,7 @@ static BOOL update_send_cache_bitmap(rdpContext* context, em = Stream_GetPosition(s); orderLength = (em - bm) - 13; Stream_SetPosition(s, bm); - Stream_Write_UINT8(s, ORDER_STANDARD | - ORDER_SECONDARY); /* controlFlags (1 byte) */ + Stream_Write_UINT8(s, ORDER_STANDARD | ORDER_SECONDARY); /* controlFlags (1 byte) */ Stream_Write_UINT16(s, orderLength); /* orderLength (2 bytes) */ Stream_Write_UINT16(s, extraFlags); /* extraFlags (2 bytes) */ Stream_Write_UINT8(s, orderType); /* orderType (1 byte) */ diff --git a/libfreerdp/core/window.c b/libfreerdp/core/window.c index fa9ee3c..9e555ac 100644 --- a/libfreerdp/core/window.c +++ b/libfreerdp/core/window.c @@ -461,8 +461,7 @@ static BOOL update_read_window_cached_icon_order(wStream* s, WINDOW_ORDER_INFO* WINDOW_CACHED_ICON_ORDER* window_cached_icon) { WINPR_UNUSED(orderInfo); - return update_read_cached_icon_info(s, - &window_cached_icon->cachedIcon); /* cachedIcon (CACHED_ICON_INFO) */ + return update_read_cached_icon_info(s, &window_cached_icon->cachedIcon); /* cachedIcon (CACHED_ICON_INFO) */ } static void update_read_window_delete_order(wStream* s, WINDOW_ORDER_INFO* orderInfo) @@ -498,6 +497,148 @@ static BOOL window_order_supported(const rdpSettings* settings, UINT32 fieldFlag } } + +#define DUMP_APPEND(...) do { \ + _snprintf(tmpBuffer, sizeof(tmpBuffer), __VA_ARGS__); \ + strncat(buffer, tmpBuffer, rem); \ + rem -= strlen(tmpBuffer); \ + } while(0) + + +static void dump_window_state_order(wLog *log, const char *msg, const WINDOW_ORDER_INFO* order, const WINDOW_STATE_ORDER *state) +{ + char buffer[3000]; + char tmpBuffer[100]; + size_t rem = sizeof(buffer) - 1; + + _snprintf(buffer, sizeof(buffer), "%s windowId=0x%"PRIu32"", msg, order->windowId); + rem -= strlen(msg); + + if (order->fieldFlags & WINDOW_ORDER_FIELD_OWNER) + DUMP_APPEND(" owner=0x%"PRIx32"", state->ownerWindowId); + if (order->fieldFlags & WINDOW_ORDER_FIELD_STYLE) + { + DUMP_APPEND(" [ex]style=<0x%"PRIx32", 0x%"PRIx32"", state->style, state->extendedStyle); + if (state->style & WS_POPUP) + DUMP_APPEND(" popup"); + if (state->style & WS_VISIBLE) + DUMP_APPEND(" visible"); + if (state->style & WS_THICKFRAME) + DUMP_APPEND(" thickframe"); + if (state->style & WS_BORDER) + DUMP_APPEND(" border"); + if (state->style & WS_CAPTION) + DUMP_APPEND(" caption"); + + if (state->extendedStyle & WS_EX_NOACTIVATE) + DUMP_APPEND(" noactivate"); + if (state->extendedStyle & WS_EX_TOOLWINDOW) + DUMP_APPEND(" toolWindow"); + if (state->extendedStyle & WS_EX_TOPMOST) + DUMP_APPEND(" topMost"); + + DUMP_APPEND(">"); + } + + if (order->fieldFlags & WINDOW_ORDER_FIELD_SHOW) + { + const char *showStr; + switch(state->showState) + { + case 0: showStr = "hidden"; break; + case 2: showStr = "minimized"; break; + case 3: showStr = "maximized"; break; + case 5: showStr = "current"; break; + default: showStr = ""; break; + } + DUMP_APPEND(" show=%s", showStr); + } + + if (order->fieldFlags & WINDOW_ORDER_FIELD_TITLE) + DUMP_APPEND(" title"); + if (order->fieldFlags & WINDOW_ORDER_FIELD_CLIENT_AREA_OFFSET) + DUMP_APPEND(" clientOffsetX=%"PRId32" clientOffsetY=%"PRId32"", + state->clientOffsetX, state->clientOffsetY); + if (order->fieldFlags & WINDOW_ORDER_FIELD_CLIENT_AREA_SIZE) + DUMP_APPEND(" clientAreaWidth=%"PRIu32" clientAreaHeight=%"PRIu32"", + state->clientAreaWidth, state->clientAreaHeight); + if (order->fieldFlags & WINDOW_ORDER_FIELD_RESIZE_MARGIN_X) + DUMP_APPEND(" resizeMarginLeft=%"PRIu32" resizeMarginRight=%"PRIu32"", + state->resizeMarginLeft, state->resizeMarginRight); + if (order->fieldFlags & WINDOW_ORDER_FIELD_RESIZE_MARGIN_Y) + DUMP_APPEND(" resizeMarginTop=%"PRIu32" resizeMarginBottom=%"PRIu32"", + state->resizeMarginTop, state->resizeMarginBottom); + if (order->fieldFlags & WINDOW_ORDER_FIELD_RP_CONTENT) + DUMP_APPEND(" rpContent=0x%"PRIx8"", state->RPContent); + if (order->fieldFlags & WINDOW_ORDER_FIELD_ROOT_PARENT) + DUMP_APPEND(" rootParent=0x%"PRIx32"", state->rootParentHandle); + if (order->fieldFlags & WINDOW_ORDER_FIELD_WND_OFFSET) + DUMP_APPEND(" windowOffsetX=%"PRId32" windowOffsetY=%"PRId32"", state->windowOffsetX, state->windowOffsetY); + if (order->fieldFlags & WINDOW_ORDER_FIELD_WND_CLIENT_DELTA) + DUMP_APPEND(" windowClientDeltaX=%"PRId32" windowClientDeltaY=%"PRId32"", + state->windowClientDeltaX, state->windowClientDeltaY); + if (order->fieldFlags & WINDOW_ORDER_FIELD_WND_SIZE) + DUMP_APPEND(" windowWidth=%"PRIu32" windowHeight=%"PRIu32"", state->windowWidth, state->windowHeight); + + if (order->fieldFlags & WINDOW_ORDER_FIELD_WND_RECTS) + { + UINT32 i; + DUMP_APPEND(" windowRects=("); + for(i = 0; i < state->numWindowRects; i++) + { + DUMP_APPEND("(%"PRIu16",%"PRIu16",%"PRIu16",%"PRIu16")", + state->windowRects[i].left, state->windowRects[i].top, + state->windowRects[i].right, state->windowRects[i].bottom); + } + DUMP_APPEND(")"); + } + + if (order->fieldFlags & WINDOW_ORDER_FIELD_VIS_OFFSET) + DUMP_APPEND(" visibleOffsetX=%"PRId32" visibleOffsetY=%"PRId32"", state->visibleOffsetX, state->visibleOffsetY); + + if (order->fieldFlags & WINDOW_ORDER_FIELD_VISIBILITY) + { + UINT32 i; + DUMP_APPEND(" visibilityRects=("); + for(i = 0; i < state->numVisibilityRects; i++) + { + DUMP_APPEND("(%"PRIu16",%"PRIu16",%"PRIu16",%"PRIu16")", + state->visibilityRects[i].left, state->visibilityRects[i].top, + state->visibilityRects[i].right, state->visibilityRects[i].bottom); + } + DUMP_APPEND(")"); + } + + if (order->fieldFlags & WINDOW_ORDER_FIELD_OVERLAY_DESCRIPTION) + DUMP_APPEND(" overlayDescr"); + + if (order->fieldFlags & WINDOW_ORDER_FIELD_ICON_OVERLAY_NULL) + DUMP_APPEND(" iconOverlayNull"); + + if (order->fieldFlags & WINDOW_ORDER_FIELD_TASKBAR_BUTTON) + DUMP_APPEND(" taskBarButton=0x%"PRIx8"", state->TaskbarButton); + + if (order->fieldFlags & WINDOW_ORDER_FIELD_ENFORCE_SERVER_ZORDER) + DUMP_APPEND(" enforceServerZOrder=0x%"PRIx8"", state->EnforceServerZOrder); + if (order->fieldFlags & WINDOW_ORDER_FIELD_APPBAR_STATE) + DUMP_APPEND(" appBarState=0x%"PRIx8"", state->AppBarState); + if (order->fieldFlags & WINDOW_ORDER_FIELD_APPBAR_EDGE) + { + const char *appBarEdgeStr; + switch (state->AppBarEdge) + { + case 0: appBarEdgeStr = "left"; break; + case 1: appBarEdgeStr = "top"; break; + case 2: appBarEdgeStr = "right"; break; + case 3: appBarEdgeStr = "bottom"; break; + default: appBarEdgeStr = ""; break; + } + DUMP_APPEND(" appBarEdge=%s", appBarEdgeStr); + } + + WLog_Print(log, WLOG_DEBUG, buffer); +} + static BOOL update_recv_window_info_order(rdpUpdate* update, wStream* s, WINDOW_ORDER_INFO* orderInfo) { @@ -517,7 +658,7 @@ static BOOL update_recv_window_info_order(rdpUpdate* update, wStream* s, if (result) { - WLog_Print(update->log, WLOG_DEBUG, "WindowIcon"); + WLog_Print(update->log, WLOG_DEBUG, "WindowIcon windowId=0x%"PRIx32"", orderInfo->windowId); IFCALLRET(window->WindowIcon, result, context, orderInfo, &window_icon); } @@ -531,14 +672,14 @@ static BOOL update_recv_window_info_order(rdpUpdate* update, wStream* s, if (result) { - WLog_Print(update->log, WLOG_DEBUG, "WindowCachedIcon"); + WLog_Print(update->log, WLOG_DEBUG, "WindowCachedIcon windowId=0x%"PRIx32"", orderInfo->windowId); IFCALLRET(window->WindowCachedIcon, result, context, orderInfo, &window_cached_icon); } } else if (orderInfo->fieldFlags & WINDOW_ORDER_STATE_DELETED) { update_read_window_delete_order(s, orderInfo); - WLog_Print(update->log, WLOG_DEBUG, "WindowDelete"); + WLog_Print(update->log, WLOG_DEBUG, "WindowDelete windowId=0x%"PRIx32"", orderInfo->windowId); IFCALLRET(window->WindowDelete, result, context, orderInfo); } else @@ -550,12 +691,12 @@ static BOOL update_recv_window_info_order(rdpUpdate* update, wStream* s, { if (orderInfo->fieldFlags & WINDOW_ORDER_STATE_NEW) { - WLog_Print(update->log, WLOG_DEBUG, "WindowCreate"); + dump_window_state_order(update->log, "WindowCreate", orderInfo, &windowState); IFCALLRET(window->WindowCreate, result, context, orderInfo, &windowState); } else { - WLog_Print(update->log, WLOG_DEBUG, "WindowUpdate"); + dump_window_state_order(update->log, "WindowUpdate", orderInfo, &windowState); IFCALLRET(window->WindowUpdate, result, context, orderInfo, &windowState); } @@ -594,8 +735,7 @@ static BOOL update_read_notification_icon_state_order(wStream* s, WINDOW_ORDER_I if (orderInfo->fieldFlags & WINDOW_ORDER_FIELD_NOTIFY_INFO_TIP) { - if (!update_read_notify_icon_infotip(s, - ¬ify_icon_state->infoTip)) /* infoTip (NOTIFY_ICON_INFOTIP) */ + if (!update_read_notify_icon_infotip(s, ¬ify_icon_state->infoTip)) /* infoTip (NOTIFY_ICON_INFOTIP) */ return FALSE; } @@ -615,8 +755,7 @@ static BOOL update_read_notification_icon_state_order(wStream* s, WINDOW_ORDER_I if (orderInfo->fieldFlags & WINDOW_ORDER_CACHED_ICON) { - if (!update_read_cached_icon_info(s, - ¬ify_icon_state->cachedIcon)) /* cachedIcon (CACHED_ICON_INFO) */ + if (!update_read_cached_icon_info(s, ¬ify_icon_state->cachedIcon)) /* cachedIcon (CACHED_ICON_INFO) */ return FALSE; } @@ -728,6 +867,32 @@ static void update_read_desktop_non_monitored_order(wStream* s, WINDOW_ORDER_INF /* non-monitored desktop notification event */ } +static void dump_monitored_desktop(wLog *log, const char *msg, const WINDOW_ORDER_INFO* orderInfo, + const MONITORED_DESKTOP_ORDER *monitored) +{ + char buffer[1000] = {0}; + char tmpBuffer[1000]; + size_t rem = sizeof(buffer) - 1; + + DUMP_APPEND(msg); + + if (orderInfo->fieldFlags & WINDOW_ORDER_FIELD_DESKTOP_ACTIVE_WND) + DUMP_APPEND(" activeWindowId=0x%"PRIx32"", monitored->activeWindowId); + + if (orderInfo->fieldFlags & WINDOW_ORDER_FIELD_DESKTOP_ZORDER) + { + UINT32 i; + + DUMP_APPEND(" windows=("); + for (i = 0; i < monitored->numWindowIds; i++) + { + DUMP_APPEND("0x%"PRIx32",", monitored->windowIds[i]); + } + DUMP_APPEND(")"); + } + WLog_Print(log, WLOG_DEBUG, buffer); +} + static BOOL update_recv_desktop_info_order(rdpUpdate* update, wStream* s, WINDOW_ORDER_INFO* orderInfo) { @@ -738,7 +903,7 @@ static BOOL update_recv_desktop_info_order(rdpUpdate* update, wStream* s, if (orderInfo->fieldFlags & WINDOW_ORDER_FIELD_DESKTOP_NONE) { update_read_desktop_non_monitored_order(s, orderInfo); - WLog_Print(update->log, WLOG_DEBUG, "NonMonitoredDesktop"); + WLog_Print(update->log, WLOG_DEBUG, "NonMonitoredDesktop, windowId=0x%"PRIx32"", orderInfo->windowId); IFCALLRET(window->NonMonitoredDesktop, result, context, orderInfo); } else @@ -748,7 +913,7 @@ static BOOL update_recv_desktop_info_order(rdpUpdate* update, wStream* s, if (result) { - WLog_Print(update->log, WLOG_DEBUG, "ActivelyMonitoredDesktop"); + dump_monitored_desktop(update->log, "ActivelyMonitoredDesktop", orderInfo, &monitored_desktop); IFCALLRET(window->MonitoredDesktop, result, context, orderInfo, &monitored_desktop); } -- 2.7.4