rdp: Improved rdp logging infrastructure

Add some logging helper functions along with two log scopes for debug
and extremely verbose debugging information.

Also add tangentially related logging for the synchronize event, so
the debug stream isn't empty right now. The vast majority of verbose
usage will come later.

Co-authored-by: Steve Pronovost <spronovo@microsoft.com>
Co-authored-by: Brenton DeGeer <brdegeer@microsoft.com>
Signed-off-by: Hideyuki Nagase <hideyukn@microsoft.com>
Signed-off-by: Steve Pronovost <spronovo@microsoft.com>
Signed-off-by: Brenton DeGeer <brdegeer@microsoft.com>

libweston/backend-rdp/meson.build

@@ -19,9 +19,14 @@ deps_rdp = [
 	dep_frdp,
 	dep_wpr,
 ]
+srcs_rdp = [
+        'rdp.c',
+        'rdputil.c',
+]
+
 plugin_rdp = shared_library(
 	'rdp-backend',
-	'rdp.c',
+	srcs_rdp,
 	include_directories: common_inc,
 	dependencies: deps_rdp,
 	name_prefix: '',

libweston/backend-rdp/rdp.c

@@ -307,6 +307,7 @@ static int
 rdp_switch_mode(struct weston_output *output, struct weston_mode *target_mode)
 {
 	struct rdp_output *rdpOutput = container_of(output, struct rdp_output, base);
+	struct rdp_backend *rdpBackend = to_rdp_backend(output->compositor);
 	struct rdp_peers_item *rdpPeer;
 	rdpSettings *settings;
 	pixman_image_t *new_shadow_buffer;
@@ -315,7 +316,7 @@ rdp_switch_mode(struct weston_output *output, struct weston_mode *target_mode)
 
 	local_mode = ensure_matching_mode(output, target_mode);
 	if (!local_mode) {
-		weston_log("mode %dx%d not available\n", target_mode->width, target_mode->height);
+		rdp_debug(rdpBackend, "mode %dx%d not available\n", target_mode->width, target_mode->height);
 		return -ENOENT;
 	}
 
@@ -524,6 +525,16 @@ rdp_destroy(struct weston_compositor *ec)
 		if (b->listener_events[i])
 			wl_event_source_remove(b->listener_events[i]);
 
+	if (b->debug) {
+		weston_log_scope_destroy(b->debug);
+		b->debug = NULL;
+	}
+
+	if (b->verbose) {
+		weston_log_scope_destroy(b->verbose);
+		b->verbose = NULL;
+	}
+
 	weston_compositor_shutdown(ec);
 
 	wl_list_for_each_safe(base, next, &ec->head_list, compositor_link)
@@ -824,7 +835,7 @@ xf_peer_activate(freerdp_peer* client)
 	}
 
 	if (b->force_no_compression && settings->CompressionEnabled) {
-		weston_log("Forcing compression off\n");
+		rdp_debug(b, "Forcing compression off\n");
 		settings->CompressionEnabled = FALSE;
 	}
 
@@ -867,7 +878,7 @@ xf_peer_activate(freerdp_peer* client)
 		return TRUE;
 
 	/* when here it's the first reactivation, we need to setup a little more */
-	weston_log("kbd_layout:0x%x kbd_type:0x%x kbd_subType:0x%x kbd_functionKeys:0x%x\n",
+	rdp_debug(b, "kbd_layout:0x%x kbd_type:0x%x kbd_subType:0x%x kbd_functionKeys:0x%x\n",
 			settings->KeyboardLayout, settings->KeyboardType, settings->KeyboardSubType,
 			settings->KeyboardFunctionKey);
 
@@ -1021,10 +1032,18 @@ xf_input_synchronize_event(rdpInput *input, UINT32 flags)
 {
 	freerdp_peer *client = input->context->peer;
 	RdpPeerContext *peerCtx = (RdpPeerContext *)input->context;
+	struct rdp_backend *b = peerCtx->rdpBackend;
 	struct rdp_output *output = peerCtx->rdpBackend->output;
 	pixman_box32_t box;
 	pixman_region32_t damage;
 
+        rdp_debug_verbose(b, "RDP backend: %s ScrLk:%d, NumLk:%d, CapsLk:%d, KanaLk:%d\n",
+			  __func__,
+			  flags & KBD_SYNC_SCROLL_LOCK ? 1 : 0,
+			  flags & KBD_SYNC_NUM_LOCK ? 1 : 0,
+			  flags & KBD_SYNC_CAPS_LOCK ? 1 : 0,
+			  flags & KBD_SYNC_KANA_LOCK ? 1 : 0);
+
 	/* sends a full refresh */
 	box.x1 = 0;
 	box.y1 = 0;
@@ -1083,7 +1102,11 @@ xf_input_keyboard_event(rdpInput *input, UINT16 flags, UINT16 code)
 static BOOL
 xf_input_unicode_keyboard_event(rdpInput *input, UINT16 flags, UINT16 code)
 {
-	weston_log("Client sent a unicode keyboard event (flags:0x%X code:0x%X)\n", flags, code);
+	RdpPeerContext *peerContext = (RdpPeerContext *)input->context;
+	struct rdp_backend *b = peerContext->rdpBackend;
+
+	rdp_debug(b, "Client sent a unicode keyboard event (flags:0x%X code:0x%X)\n", flags, code);
+
 	return TRUE;
 }
 
@@ -1222,6 +1245,17 @@ rdp_backend_create(struct weston_compositor *compositor,
 	b->force_no_compression = config->force_no_compression;
 	b->remotefx_codec = config->remotefx_codec;
 
+	b->debug = weston_compositor_add_log_scope(compositor,
+						   "rdp-backend",
+						   "Debug messages from RDP backend\n",
+						   NULL, NULL, NULL);
+	b->verbose = weston_compositor_add_log_scope(compositor,
+						     "rdp-backend-verbose",
+						     "Verbose debug messages from RDP backend\n",
+						     NULL, NULL, NULL);
+
+	/* After here, rdp_debug() is ready to be used */
+
 	compositor->backend = &b->base;
 
 	/* activate TLS only if certificate/key are available */
@@ -1291,6 +1325,10 @@ err_compositor:
 
 	weston_compositor_shutdown(compositor);
 err_free_strings:
+	if (b->debug)
+		weston_log_scope_destroy(b->debug);
+	if (b->verbose)
+		weston_log_scope_destroy(b->verbose);
 	free(b->rdp_key);
 	free(b->server_cert);
 	free(b->server_key);

libweston/backend-rdp/rdp.h

@@ -45,6 +45,7 @@
 #include "backend.h"
 
 #include "shared/helpers.h"
+#include "shared/string-helpers.h"
 
 #define MAX_FREERDP_FDS 32
 #define DEFAULT_AXIS_STEP_DISTANCE 10
@@ -60,6 +61,8 @@ struct rdp_backend {
 	freerdp_listener *listener;
 	struct wl_event_source *listener_events[MAX_FREERDP_FDS];
 	struct rdp_output *output;
+	struct weston_log_scope *debug;
+	struct weston_log_scope *verbose;
 
 	char *server_cert;
 	char *server_key;
@@ -109,6 +112,19 @@ struct rdp_peer_context {
 };
 typedef struct rdp_peer_context RdpPeerContext;
 
+#define rdp_debug_verbose(b, ...) \
+	rdp_debug_print(b->verbose, false, __VA_ARGS__)
+#define rdp_debug_verbose_continue(b, ...) \
+	rdp_debug_print(b->verbose, true,  __VA_ARGS__)
+#define rdp_debug(b, ...) \
+	rdp_debug_print(b->debug, false, __VA_ARGS__)
+#define rdp_debug_continue(b, ...) \
+	rdp_debug_print(b->debug, true,  __VA_ARGS__)
+
+/* rdputil.c */
+void
+rdp_debug_print(struct weston_log_scope *log_scope, bool cont, char *fmt, ...);
+
 static inline struct rdp_head *
 to_rdp_head(struct weston_head *base)
 {

libweston/backend-rdp/rdputil.c

@@ -0,0 +1,77 @@
+/*
+ * Copyright © 2020 Microsoft
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining
+ * a copy of this software and associated documentation files (the
+ * "Software"), to deal in the Software without restriction, including
+ * without limitation the rights to use, copy, modify, merge, publish,
+ * distribute, sublicense, and/or sell copies of the Software, and to
+ * permit persons to whom the Software is furnished to do so, subject to
+ * the following conditions:
+ *
+ * The above copyright notice and this permission notice (including the
+ * next paragraph) shall be included in all copies or substantial
+ * portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
+ * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
+ * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
+ * NONINFRINGEMENT.  IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS
+ * BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN
+ * ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN
+ * CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+#include "config.h"
+
+#include <assert.h>
+#include <stdint.h>
+#include <stdlib.h>
+#include <string.h>
+#include <unistd.h>
+#include <pthread.h>
+#include <sys/mman.h>
+#include <sys/syscall.h>
+#include <sys/types.h>
+#include <sys/eventfd.h>
+#include <sys/time.h>
+#include <sys/stat.h>
+#include <fcntl.h>
+
+#include "rdp.h"
+
+static int cached_tm_mday = -1;
+
+void rdp_debug_print(struct weston_log_scope *log_scope, bool cont, char *fmt, ...)
+{
+	char timestr[128];
+	int len_va;
+	char *str;
+
+	if (!log_scope || !weston_log_scope_is_enabled(log_scope))
+		return;
+
+	va_list ap;
+	va_start(ap, fmt);
+
+	if (cont) {
+		weston_log_scope_vprintf(log_scope, fmt, ap);
+		goto end;
+	}
+
+	weston_log_timestamp(timestr, sizeof(timestr), &cached_tm_mday);
+	len_va = vasprintf(&str, fmt, ap);
+	if (len_va >= 0) {
+		weston_log_scope_printf(log_scope, "%s %s",
+					timestr, str);
+		free(str);
+	} else {
+		const char *oom = "Out of memory";
+
+		weston_log_scope_printf(log_scope, "%s %s",
+					timestr, oom);
+	}
+end:
+	va_end(ap);
+}