From ca2e578acc2e27fa96a7cf4c36e25c1b7088ec87 Mon Sep 17 00:00:00 2001 From: Kobi Mizrachi Date: Thu, 26 Dec 2019 10:25:13 +0200 Subject: [PATCH] server: proxy: add a unique id to each session and improve logs --- server/proxy/pf_channels.c | 8 +++---- server/proxy/pf_channels.h | 4 ++-- server/proxy/pf_client.c | 39 +++++++++++++++--------------- server/proxy/pf_context.c | 28 ++++++++++++++++++++++ server/proxy/pf_context.h | 4 ++++ server/proxy/pf_log.h | 21 ++++++++++++++++ server/proxy/pf_server.c | 49 ++++++++++++++++++-------------------- 7 files changed, 102 insertions(+), 51 deletions(-) diff --git a/server/proxy/pf_channels.c b/server/proxy/pf_channels.c index fd184536d..073380b36 100644 --- a/server/proxy/pf_channels.c +++ b/server/proxy/pf_channels.c @@ -52,11 +52,11 @@ static void pf_channels_wait_for_server_dynvc(pServerContext* ps) WLog_DBG(TAG, "pf_channels_wait_for_server_dynvc(): server's drdynvc is ready!"); } -void pf_OnChannelConnectedEventHandler(void* data, ChannelConnectedEventArgs* e) +void pf_channels_on_client_channel_connect(void* data, ChannelConnectedEventArgs* e) { pClientContext* pc = (pClientContext*)data; pServerContext* ps = pc->pdata->ps; - WLog_INFO(TAG, "Channel connected: %s", e->name); + LOG_INFO(TAG, pc, "Channel connected: %s", e->name); if (strcmp(e->name, RDPEI_DVC_CHANNEL_NAME) == 0) { @@ -139,12 +139,12 @@ void pf_OnChannelConnectedEventHandler(void* data, ChannelConnectedEventArgs* e) } } -void pf_OnChannelDisconnectedEventHandler(void* data, ChannelDisconnectedEventArgs* e) +void pf_channels_on_client_channel_disconnect(void* data, ChannelDisconnectedEventArgs* e) { rdpContext* context = (rdpContext*)data; pClientContext* pc = (pClientContext*)context; pServerContext* ps = pc->pdata->ps; - WLog_INFO(TAG, "Channel disconnected: %s", e->name); + LOG_INFO(TAG, pc, "Channel disconnected: %s", e->name); if (strcmp(e->name, RDPEI_DVC_CHANNEL_NAME) == 0) { diff --git a/server/proxy/pf_channels.h b/server/proxy/pf_channels.h index f7663f20e..5f6805a9f 100644 --- a/server/proxy/pf_channels.h +++ b/server/proxy/pf_channels.h @@ -27,8 +27,8 @@ #include "pf_context.h" -void pf_OnChannelConnectedEventHandler(void* context, ChannelConnectedEventArgs* e); -void pf_OnChannelDisconnectedEventHandler(void* context, ChannelDisconnectedEventArgs* e); +void pf_channels_on_client_channel_connect(void* context, ChannelConnectedEventArgs* e); +void pf_channels_on_client_channel_disconnect(void* context, ChannelDisconnectedEventArgs* e); BOOL pf_server_channels_init(pServerContext* ps); void pf_server_channels_free(pServerContext* ps); diff --git a/server/proxy/pf_client.c b/server/proxy/pf_client.c index 25ab03f90..8c9f8731a 100644 --- a/server/proxy/pf_client.c +++ b/server/proxy/pf_client.c @@ -69,7 +69,7 @@ static BOOL proxy_server_reactivate(rdpContext* ps, const rdpContext* pc) return TRUE; } -static void pf_OnErrorInfo(void* ctx, ErrorInfoEventArgs* e) +static void pf_client_on_error_info(void* ctx, ErrorInfoEventArgs* e) { pClientContext* pc = (pClientContext*)ctx; pServerContext* ps = pc->pdata->ps; @@ -77,8 +77,8 @@ static void pf_OnErrorInfo(void* ctx, ErrorInfoEventArgs* e) if (e->code == ERRINFO_NONE) return; - WLog_WARN(TAG, "received error info code: 0x%08" PRIu32 ", msg: %s", e->code, - freerdp_get_error_info_string(e->code)); + LOG_WARN(TAG, pc, "received ErrorInfo PDU. code=0x%08" PRIu32 ", message: %s", e->code, + freerdp_get_error_info_string(e->code)); /* forward error back to client */ freerdp_set_error_info(ps->context.rdp, e->code); @@ -155,10 +155,11 @@ static BOOL pf_client_pre_connect(freerdp* instance) * Register the channel listeners. * They are required to set up / tear down channels if they are loaded. */ - PubSub_SubscribeChannelConnected(instance->context->pubSub, pf_OnChannelConnectedEventHandler); + PubSub_SubscribeChannelConnected(instance->context->pubSub, + pf_channels_on_client_channel_connect); PubSub_SubscribeChannelDisconnected(instance->context->pubSub, - pf_OnChannelDisconnectedEventHandler); - PubSub_SubscribeErrorInfo(instance->context->pubSub, pf_OnErrorInfo); + pf_channels_on_client_channel_disconnect); + PubSub_SubscribeErrorInfo(instance->context->pubSub, pf_client_on_error_info); /** * Load all required plugins / channels / libraries specified by current @@ -168,7 +169,7 @@ static BOOL pf_client_pre_connect(freerdp* instance) if (!pf_client_load_rdpsnd(pc, config)) { - WLog_ERR(TAG, "Failed to load rdpsnd client!"); + LOG_ERR(TAG, pc, "Failed to load rdpsnd client"); return FALSE; } @@ -210,11 +211,11 @@ static BOOL pf_client_post_connect(freerdp* instance) { if (!pf_capture_create_session_directory(pc)) { - WLog_ERR(TAG, "pf_capture_create_session_directory failed!"); + LOG_ERR(TAG, pc, "pf_capture_create_session_directory failed!"); return FALSE; } - WLog_INFO(TAG, "frames dir created: %s", pc->frames_dir); + LOG_ERR(TAG, pc, "frames dir created: %s", pc->frames_dir); } if (!gdi_init(instance, PIXEL_FORMAT_BGRA32)) @@ -227,7 +228,7 @@ static BOOL pf_client_post_connect(freerdp* instance) { if (!pf_register_graphics(context->graphics)) { - WLog_ERR(TAG, "failed to register graphics"); + LOG_ERR(TAG, pc, "failed to register graphics"); return FALSE; } @@ -267,10 +268,10 @@ static void pf_client_post_disconnect(freerdp* instance) pdata = context->pdata; PubSub_UnsubscribeChannelConnected(instance->context->pubSub, - pf_OnChannelConnectedEventHandler); + pf_channels_on_client_channel_connect); PubSub_UnsubscribeChannelDisconnected(instance->context->pubSub, - pf_OnChannelDisconnectedEventHandler); - PubSub_UnsubscribeErrorInfo(instance->context->pubSub, pf_OnErrorInfo); + pf_channels_on_client_channel_disconnect); + PubSub_UnsubscribeErrorInfo(instance->context->pubSub, pf_client_on_error_info); gdi_free(instance); /* Only close the connection if NLA fallback process is done */ @@ -341,11 +342,11 @@ static BOOL pf_client_connect(freerdp* instance) if (!retry) goto out; - WLog_ERR(TAG, "failed to connect with NLA. retrying to connect without NLA"); + LOG_ERR(TAG, pc, "failed to connect with NLA. retrying to connect without NLA"); if (!pf_client_connect_without_nla(pc)) { - WLog_ERR(TAG, "pf_client_connect_without_nla failed!"); + LOG_ERR(TAG, pc, "pf_client_connect_without_nla failed!"); goto out; } } @@ -398,7 +399,7 @@ static DWORD WINAPI pf_client_thread_proc(LPVOID arg) if (nCount == 0) { - WLog_ERR(TAG, "%s: freerdp_get_event_handles failed", __FUNCTION__); + LOG_ERR(TAG, ps, "freerdp_get_event_handles failed!"); break; } @@ -539,7 +540,7 @@ static int pf_client_client_stop(rdpContext* context) pClientContext* pc = (pClientContext*)context; proxyData* pdata = pc->pdata; - WLog_DBG(TAG, "aborting client connection"); + LOG_DBG(TAG, pc, "aborting client connection"); proxy_data_abort_connect(pdata); freerdp_abort_connect(context->instance); @@ -549,9 +550,9 @@ static int pf_client_client_stop(rdpContext* context) * Wait for client thread to finish. No need to call CloseHandle() here, as * it is the responsibility of `proxy_data_free`. */ - WLog_DBG(TAG, "pf_client_client_stop(): waiting for thread to finish"); + LOG_DBG(TAG, pc, "waiting for client thread to finish"); WaitForSingleObject(pdata->client_thread, INFINITE); - WLog_DBG(TAG, "pf_client_client_stop(): thread finished"); + LOG_DBG(TAG, pc, "thread finished"); } return 0; diff --git a/server/proxy/pf_context.c b/server/proxy/pf_context.c index b31836df1..56cb67156 100644 --- a/server/proxy/pf_context.c +++ b/server/proxy/pf_context.c @@ -19,6 +19,9 @@ * limitations under the License. */ +#include +#include + #include "pf_client.h" #include "pf_context.h" @@ -160,6 +163,7 @@ error: proxyData* proxy_data_new(void) { + BYTE temp[16]; proxyData* pdata = calloc(1, sizeof(proxyData)); if (pdata == NULL) @@ -179,9 +183,30 @@ proxyData* proxy_data_new(void) return NULL; } + winpr_RAND((BYTE*)&temp, 16); + if (!(pdata->session_id = winpr_BinToHexString(temp, 16, FALSE))) + { + proxy_data_free(pdata); + return NULL; + } + return pdata; } +/* updates circular pointers between proxyData and pClientContext instances */ +void proxy_data_set_client_context(proxyData* pdata, pClientContext* context) +{ + pdata->pc = context; + context->pdata = pdata; +} + +/* updates circular pointers between proxyData and pServerContext instances */ +void proxy_data_set_server_context(proxyData* pdata, pServerContext* context) +{ + pdata->ps = context; + context->pdata = pdata; +} + void proxy_data_free(proxyData* pdata) { if (pdata->abort_event) @@ -202,6 +227,9 @@ void proxy_data_free(proxyData* pdata) pdata->gfx_server_ready = NULL; } + if (pdata->session_id) + free(pdata->session_id); + free(pdata); } diff --git a/server/proxy/pf_context.h b/server/proxy/pf_context.h index c4c92067b..201e406e8 100644 --- a/server/proxy/pf_context.h +++ b/server/proxy/pf_context.h @@ -108,6 +108,8 @@ struct proxy_data HANDLE abort_event; HANDLE client_thread; HANDLE gfx_server_ready; + + char* session_id; }; BOOL pf_context_copy_settings(rdpSettings* dst, const rdpSettings* src); @@ -115,6 +117,8 @@ BOOL pf_context_init_server_context(freerdp_peer* client); pClientContext* pf_context_create_client_context(rdpSettings* clientSettings); proxyData* proxy_data_new(void); +void proxy_data_set_client_context(proxyData* pdata, pClientContext* context); +void proxy_data_set_server_context(proxyData* pdata, pServerContext* context); void proxy_data_free(proxyData* pdata); BOOL proxy_data_shall_disconnect(proxyData* pdata); diff --git a/server/proxy/pf_log.h b/server/proxy/pf_log.h index 4376a882f..0bbd1557d 100644 --- a/server/proxy/pf_log.h +++ b/server/proxy/pf_log.h @@ -26,4 +26,25 @@ #define PROXY_TAG(tag) "proxy." tag +/* + * log format in proxy is: + * "[SessionID=%s] - [__FUNCTION__]: Log message" + * both SessionID and __FUNCTION__ are optional, but if they should be written to the log, + * that's the format. + */ + +/* log macros that prepends session id and function name tp the log message */ +#define LOG_INFO(_tag, _context, _format, ...) \ + WLog_INFO(TAG, "[SessionID=%s][%s]: " _format, _context->pdata->session_id, __FUNCTION__, \ + ##__VA_ARGS__) +#define LOG_ERR(_tag, _context, _format, ...) \ + WLog_ERR(TAG, "[SessionID=%s][%s]: " _format, _context->pdata->session_id, __FUNCTION__, \ + ##__VA_ARGS__) +#define LOG_DBG(_tag, _context, _format, ...) \ + WLog_DBG(TAG, "[SessionID=%s][%s]: " _format, _context->pdata->session_id, __FUNCTION__, \ + ##__VA_ARGS__) +#define LOG_WARN(_tag, _context, _format, ...) \ + WLog_WARN(TAG, "[SessionID=%s][%s]: " _format, _context->pdata->session_id, __FUNCTION__, \ + ##__VA_ARGS__) + #endif /* FREERDP_SERVER_PROXY_PFLOG_H */ \ No newline at end of file diff --git a/server/proxy/pf_server.c b/server/proxy/pf_server.c index c9f0fa287..10e8c054e 100644 --- a/server/proxy/pf_server.c +++ b/server/proxy/pf_server.c @@ -61,9 +61,10 @@ static BOOL pf_server_parse_target_from_routing_token(rdpContext* context, char* #define ROUTING_TOKEN_PREFIX "Cookie: msts=" char* colon; size_t len; - const size_t prefix_len = strnlen(ROUTING_TOKEN_PREFIX, sizeof(ROUTING_TOKEN_PREFIX)); DWORD routing_token_length; + const size_t prefix_len = strnlen(ROUTING_TOKEN_PREFIX, sizeof(ROUTING_TOKEN_PREFIX)); const char* routing_token = freerdp_nego_get_routing_token(context, &routing_token_length); + pServerContext* ps = (pServerContext*)context; if (routing_token == NULL) { @@ -73,11 +74,7 @@ static BOOL pf_server_parse_target_from_routing_token(rdpContext* context, char* if ((routing_token_length <= prefix_len) || (routing_token_length >= TARGET_MAX)) { - WLog_ERR( - TAG, - "pf_server_parse_target_from_routing_token(): invalid routing token length: %" PRIu32 - "", - routing_token_length); + LOG_ERR(TAG, ps, "invalid routing token length: %" PRIu32 "", routing_token_length); return FALSE; } @@ -112,8 +109,10 @@ static BOOL pf_server_parse_target_from_routing_token(rdpContext* context, char* static BOOL pf_server_get_target_info(rdpContext* context, rdpSettings* settings, proxyConfig* config) { - WLog_INFO(TAG, "pf_server_get_target_info(): fetching target from %s", - config->UseLoadBalanceInfo ? "load-balance-info" : "config"); + pServerContext* ps = (pServerContext*)context; + + LOG_INFO(TAG, ps, "fetching target from %s", + config->UseLoadBalanceInfo ? "load-balance-info" : "config"); if (config->UseLoadBalanceInfo) return pf_server_parse_target_from_routing_token(context, &settings->ServerHostname, @@ -122,7 +121,7 @@ static BOOL pf_server_get_target_info(rdpContext* context, rdpSettings* settings /* use hardcoded target info from configuration */ if (!(settings->ServerHostname = _strdup(config->TargetHost))) { - WLog_DBG(TAG, "pf_server_get_target_info(): strdup failed!"); + LOG_ERR(TAG, ps, "strdup failed!"); return FALSE; } @@ -149,42 +148,42 @@ static BOOL pf_server_post_connect(freerdp_peer* peer) if (pdata->config->SessionCapture && !peer->settings->SupportGraphicsPipeline) { - WLog_ERR(TAG, "Session capture feature is enabled, only accepting connections with GFX"); + LOG_ERR(TAG, ps, "Session capture feature is enabled, only accepting connections with GFX"); return FALSE; } pc = pf_context_create_client_context(peer->settings); if (pc == NULL) { - WLog_ERR(TAG, "pf_server_post_connect(): pf_context_create_client_context failed!"); + LOG_ERR(TAG, ps, "[%s]: pf_context_create_client_context failed!"); return FALSE; } client_settings = pc->context.settings; /* keep both sides of the connection in pdata */ - pc->pdata = ps->pdata; - pdata->pc = pc; + proxy_data_set_client_context(pdata, pc); if (!pf_server_get_target_info(peer->context, client_settings, pdata->config)) { - WLog_ERR(TAG, "pf_server_post_connect(): pf_server_get_target_info failed!"); + + LOG_INFO(TAG, ps, "pf_server_get_target_info failed!"); return FALSE; } - WLog_INFO(TAG, "pf_server_post_connect(): target == %s:%" PRIu16 "", - client_settings->ServerHostname, client_settings->ServerPort); + LOG_INFO(TAG, ps, "remote target is %s:%" PRIu16 "", client_settings->ServerHostname, + client_settings->ServerPort); if (!pf_server_channels_init(ps)) { - WLog_ERR(TAG, "pf_server_post_connect(): failed to initialize server's channels!"); + LOG_INFO(TAG, ps, "failed to initialize server's channels!"); return FALSE; } /* Start a proxy's client in it's own thread */ if (!(pdata->client_thread = CreateThread(NULL, 0, pf_client_start, pc, 0, NULL))) { - WLog_ERR(TAG, "CreateThread failed!"); + LOG_ERR(TAG, ps, "failed to create client thread"); return FALSE; } @@ -336,8 +335,7 @@ static DWORD WINAPI pf_server_handle_peer(LPVOID arg) /* only disconnect after checking client's and vcm's file descriptors */ if (proxy_data_shall_disconnect(pdata)) { - WLog_INFO(TAG, "abort_event is set, closing connection with client %s", - client->hostname); + WLog_INFO(TAG, "abort event is set, closing connection with peer %s", client->hostname); break; } @@ -371,13 +369,12 @@ static DWORD WINAPI pf_server_handle_peer(LPVOID arg) fail: pc = (rdpContext*)pdata->pc; - WLog_INFO(TAG, "pf_server_handle_client(): starting shutdown of connection (client %s)", - client->hostname); - WLog_INFO(TAG, "pf_server_handle_client(): stopping proxy's client"); + LOG_INFO(TAG, ps, "starting shutdown of connection"); + LOG_INFO(TAG, ps, "stopping proxy's client"); freerdp_client_stop(pc); - WLog_INFO(TAG, "pf_server_handle_client(): freeing server's channels"); + LOG_INFO(TAG, ps, "freeing server's channels"); pf_server_channels_free(ps); - WLog_INFO(TAG, "pf_server_handle_client(): freeing proxy data"); + LOG_INFO(TAG, ps, "freeing proxy data"); proxy_data_free(pdata); freerdp_client_context_free(pc); client->Close(client); @@ -393,7 +390,7 @@ static BOOL pf_server_peer_accepted(freerdp_listener* listener, freerdp_peer* cl HANDLE hThread; client->ContextExtra = listener->info; - if (!(hThread = CreateThread(NULL, 0, pf_server_handle_client, (void*)client, 0, NULL))) + if (!(hThread = CreateThread(NULL, 0, pf_server_handle_peer, (void*)client, 0, NULL))) return FALSE; CloseHandle(hThread);