rail: added verbose logs (#5402)

* rail: added verbose logs

* rail: fix buffer initialisation in debug message
This commit is contained in:
David Fort 2019-05-23 12:15:26 +02:00 committed by akallabeth
parent 789ed72021
commit 6563bc28c4
3 changed files with 193 additions and 38 deletions

View File

@ -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;
}

View File

@ -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) */

View File

@ -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 = "<unknown>"; 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 = "<unknown>"; 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,
&notify_icon_state->infoTip)) /* infoTip (NOTIFY_ICON_INFOTIP) */
if (!update_read_notify_icon_infotip(s, &notify_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,
&notify_icon_state->cachedIcon)) /* cachedIcon (CACHED_ICON_INFO) */
if (!update_read_cached_icon_info(s, &notify_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);
}