server: proxy: add a unique id to each session and improve logs

diff --git a/server/proxy/pf_channels.c b/server/proxy/pf_channels.c
index fd18453..073380b 100644 (file)
--- 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 f7663f2..5f6805a 100644 (file)
--- 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 25ab03f..8c9f873 100644 (file)
--- 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 b31836d..56cb671 100644 (file)
--- a/server/proxy/pf_context.c
+++ b/server/proxy/pf_context.c
@@ -19,6 +19,9 @@
  * limitations under the License.
  */
 
+#include <winpr/crypto.h>
+#include <winpr/print.h>
+
 #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 c4c9206..201e406 100644 (file)
--- 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 4376a88..0bbd155 100644 (file)
--- 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 c9f0fa2..10e8c05 100644 (file)
--- 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);