mirrors
/
FreeRDP
mirror of https://github.com/FreeRDP/FreeRDP
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

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

This commit is contained in:
Kobi Mizrachi 2019-12-26 10:25:13 +02:00 committed by akallabeth
parent ab3a72f825
commit ca2e578acc
7 changed files with 102 additions and 51 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
server/proxy/pf_channels.c
View File

@ -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)
{

4
server/proxy/pf_channels.h
View File

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

39
server/proxy/pf_client.c
View File

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

28
server/proxy/pf_context.c
View File

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

4
server/proxy/pf_context.h
View File

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

21
server/proxy/pf_log.h
View File

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

49
server/proxy/pf_server.c
View File

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