Merge branch 'feat-logging-pid-timestamp' into 'main'

logging: Add PID, ClientName for debug logging

See merge request wayland/wayland!478

meson.build

@@ -46,6 +46,7 @@ have_funcs = [
 	'memfd_create',
 	'mremap',
 	'strndup',
+	'getpid',
 ]
 foreach f: have_funcs
 	config_h.set('HAVE_' + f.underscorify().to_upper(), cc.has_function(f))

src/connection.c

@@ -1493,28 +1493,43 @@ wl_closure_queue(struct wl_closure *closure, struct wl_connection *connection)
 
 void
 wl_closure_print(struct wl_closure *closure, struct wl_object *target,
-		 int send, int discarded, uint32_t (*n_parse)(union wl_argument *arg),
-		 const char *queue_name, int color)
+		 int send, int discarded, pid_t client_pid,
+		 uint32_t (*n_parse)(union wl_argument *arg), const char *queue_name, int color)
 {
 	int i;
 	struct argument_details arg;
 	const char *signature = closure->message->signature;
-	struct timespec tp;
-	unsigned int time;
 	uint32_t nval;
 	FILE *f;
 	char *buffer;
 	size_t buffer_length;
+	char time_str[20];
 
 	f = open_memstream(&buffer, &buffer_length);
 	if (f == NULL)
 		return;
 
-	clock_gettime(CLOCK_REALTIME, &tp);
-	time = (tp.tv_sec * 1000000L) + (tp.tv_nsec / 1000);
-	fprintf(f, "%s[%7u.%03u] ",
+	if (wl_time_fmt == WL_TIME_FORMAT_EPOCH) {
+		struct timespec tp;
+		clock_gettime(CLOCK_REALTIME, &tp);
+		unsigned int time = (tp.tv_sec * 1000000L) + (tp.tv_nsec / 1000);
+		sprintf(time_str, "%7u.%03u", time / 1000, time % 1000);
+	} else {
+		time_t rawtime;
+		time(&rawtime);
+		struct tm *info = localtime(&rawtime);
+		strftime(time_str, 20, "%Y-%m-%d %H:%M:%S", info);
+	}
+
+	fprintf(f, "%s[%s] ",
 		color ? WL_DEBUG_COLOR_GREEN : "",
-		time / 1000, time % 1000);
+		time_str);
+
+	if (!send && client_pid != -1) {
+		char proc_name[50];
+		wl_get_name_by_pid(client_pid, proc_name);
+		fprintf(f, "[PID:%d%s] ", client_pid, proc_name);
+	}
 
 	if (queue_name) {
 		fprintf(f, "%s{%s} ",

src/wayland-client.c

@@ -26,6 +26,8 @@
 
 #define _GNU_SOURCE
 
+#include "../config.h"
+
 #include <stdlib.h>
 #include <stdint.h>
 #include <stddef.h>
@@ -34,6 +36,7 @@
 #include <errno.h>
 #include <string.h>
 #include <unistd.h>
+#include <time.h>
 #include <sys/socket.h>
 #include <sys/un.h>
 #include <ctype.h>
@@ -49,6 +52,8 @@
 
 /** \cond */
 
+extern int debug_with_pid;
+
 enum wl_proxy_flag {
 	WL_PROXY_FLAG_ID_DELETED = (1 << 0),
 	WL_PROXY_FLAG_DESTROYED = (1 << 1),
@@ -929,6 +934,12 @@ wl_proxy_marshal_array_flags(struct wl_proxy *proxy, uint32_t opcode,
 	}
 
 	if (debug_client) {
+		pid_t pid = -1;
+#if defined(HAVE_GETPID)
+		if (debug_with_pid)
+			pid = getpid();
+#endif // defined(HAVE_GETPID)
+
 		struct wl_event_queue *queue;
 		const char *queue_name = NULL;
 
@@ -936,7 +947,7 @@ wl_proxy_marshal_array_flags(struct wl_proxy *proxy, uint32_t opcode,
 		if (queue)
 			queue_name = wl_event_queue_get_name(queue);
 
-		wl_closure_print(closure, &proxy->object, true, false, NULL,
+		wl_closure_print(closure, &proxy->object, true, false, pid, NULL,
 				 queue_name, debug_color);
 	}
 
@@ -1238,6 +1249,8 @@ wl_display_connect_to_fd(int fd)
 	debug = getenv("WAYLAND_DEBUG");
 	if (debug && (strstr(debug, "client") || strstr(debug, "1"))) {
 		debug_client = 1;
+		if (strstr(debug, "pid"))
+			debug_with_pid = 1;
 		if (isatty(fileno(stderr)))
 			debug_color = 1;
 	}
@@ -1570,9 +1583,8 @@ queue_event(struct wl_display *display, int len)
 	struct wl_closure *closure;
 	const struct wl_message *message;
 	struct wl_event_queue *queue;
-	struct timespec tp;
-	unsigned int time;
 	int num_zombie_fds;
+	char time_str[20];
 
 	wl_connection_copy(display->connection, p, sizeof p);
 	id = p[0];
@@ -1612,12 +1624,33 @@ queue_event(struct wl_display *display, int len)
 			zombie->fd_count[opcode] : 0;
 
 		if (debug_client) {
-			clock_gettime(CLOCK_REALTIME, &tp);
-			time = (tp.tv_sec * 1000000L) + (tp.tv_nsec / 1000);
-			fprintf(stderr, "%s[%7u.%03u] %sdiscarded %s[%s]%s#%u%s.[event %d]%s"
+			if (wl_time_fmt == WL_TIME_FORMAT_EPOCH) {
+				struct timespec tp;
+				clock_gettime(CLOCK_REALTIME, &tp);
+				unsigned int time = (tp.tv_sec * 1000000L) + (tp.tv_nsec / 1000);
+				sprintf(time_str, "%7u.%03u", time / 1000, time % 1000);
+			} else {
+				time_t rawtime;
+				time(&rawtime);
+				struct tm *info = localtime(&rawtime);
+				strftime(time_str, 20, "%Y-%m-%d %H:%M:%S", info);
+			}
+
+			fprintf(stderr, "%s[%s] ",
+				debug_color ? WL_DEBUG_COLOR_BLUE : "",
+				time_str);
+
+#if defined(HAVE_GETPID)
+			if (debug_with_pid) {
+				pid_t pid = getpid();
+				char proc_name[50];
+				wl_get_name_by_pid(pid, proc_name);
+				fprintf(stderr, "[PID:%d%s] ", pid, proc_name);
+			}
+#endif // defined(HAVE_GETPID)
+
+			fprintf(stderr, "%sdiscarded %s[%s]%s#%u%s.[event %d]%s"
 				"(%d fd, %d byte)\n",
-				debug_color ? WL_DEBUG_COLOR_GREEN : "",
-				time / 1000, time % 1000,
 				debug_color ? WL_DEBUG_COLOR_RED : "",
 				debug_color ? WL_DEBUG_COLOR_BLUE : "",
 				zombie ? "zombie" : "unknown",
@@ -1706,8 +1739,14 @@ dispatch_event(struct wl_display *display, struct wl_event_queue *queue)
 	if (debug_client) {
 		bool discarded = proxy_destroyed ||
 				 !(proxy->dispatcher || proxy->object.implementation);
+		pid_t pid = -1;
+#if defined(HAVE_GETPID)
+			if (debug_with_pid)
+				pid = getpid();
+#endif // defined(HAVE_GETPID)
 
-		wl_closure_print(closure, &proxy->object, false, discarded,
+
+		wl_closure_print(closure, &proxy->object, false, discarded, pid,
 				 id_from_object, queue->name, debug_color);
 	}
 
@@ -1719,9 +1758,29 @@ dispatch_event(struct wl_display *display, struct wl_event_queue *queue)
 	pthread_mutex_unlock(&display->mutex);
 
 	if (proxy->dispatcher) {
+		if (debug_client) {
+			pid_t pid = -1;
+#if defined(HAVE_GETPID)
+			if (debug_with_pid)
+				pid = getpid();
+#endif // defined(HAVE_GETPID)
+			wl_closure_print(closure, &proxy->object, false, false, pid,
+				id_from_object, queue->name, debug_color);
+		}
+
 		wl_closure_dispatch(closure, proxy->dispatcher,
 				    &proxy->object, opcode);
 	} else if (proxy->object.implementation) {
+		if (debug_client) {
+			pid_t pid = -1;
+#if defined(HAVE_GETPID)
+			if (debug_with_pid)
+				pid = getpid();
+#endif // defined(HAVE_GETPID)
+			wl_closure_print(closure, &proxy->object, false, false, pid,
+				id_from_object, queue->name, debug_color);
+		}
+
 		wl_closure_invoke(closure, WL_CLOSURE_INVOKE_CLIENT,
 				  &proxy->object, opcode, proxy->user_data);
 	}

src/wayland-private.h

@@ -240,7 +240,7 @@ wl_closure_queue(struct wl_closure *closure, struct wl_connection *connection);
 void
 wl_closure_print(struct wl_closure *closure,
 		 struct wl_object *target, int send, int discarded,
-		 uint32_t (*n_parse)(union wl_argument *arg),
+		 pid_t client_pid, uint32_t (*n_parse)(union wl_argument *arg),
 		 const char *queue_name, int color);
 
 void
@@ -248,6 +248,8 @@ wl_closure_destroy(struct wl_closure *closure);
 
 extern wl_log_func_t wl_log_handler;
 
+extern enum wl_time_format wl_time_fmt;
+
 void wl_log(const char *fmt, ...);
 void wl_abort(const char *fmt, ...);
 

src/wayland-server.c

@@ -34,6 +34,7 @@
 #include <errno.h>
 #include <string.h>
 #include <unistd.h>
+#include <time.h>
 #include <sys/socket.h>
 #include <sys/un.h>
 #include <dlfcn.h>
@@ -60,6 +61,8 @@
 #define LOCK_SUFFIX	".lock"
 #define LOCK_SUFFIXLEN	5
 
+extern int debug_with_pid;
+
 struct wl_socket {
 	int fd;
 	int fd_lock;
@@ -161,7 +164,7 @@ log_closure(struct wl_resource *resource,
 	struct wl_protocol_logger_message message;
 
 	if (debug_server)
-		wl_closure_print(closure, object, send, false, NULL, NULL, debug_color);
+		wl_closure_print(closure, object, send, false, debug_with_pid ? resource->client->pid : -1, NULL, NULL, debug_color);
 
 	if (!wl_list_empty(&display->protocol_loggers)) {
 		message.resource = resource;
@@ -1200,6 +1203,8 @@ wl_display_create(void)
 	debug = getenv("WAYLAND_DEBUG");
 	if (debug && (strstr(debug, "server") || strstr(debug, "1"))) {
 		debug_server = 1;
+		if (strstr(debug, "pid"))
+			debug_with_pid = 1;
 		if (isatty(fileno(stderr)))
 			debug_color = 1;
 	}

src/wayland-util.c

@@ -30,6 +30,8 @@
 #include <stdio.h>
 #include <string.h>
 #include <stdarg.h>
+#include <fcntl.h>
+#include <limits.h>
 
 #include "wayland-util.h"
 #include "wayland-private.h"
@@ -476,4 +478,32 @@ wl_abort(const char *fmt, ...)
 	abort();
 }
 
+int debug_with_pid = 0;
+
+#define STAT_SIZE 256
+
+void
+wl_get_name_by_pid(pid_t pid, char* process_name)
+{
+	char buf[STAT_SIZE];
+	char proc_pid_path[PATH_MAX];
+	sprintf(proc_pid_path, "/proc/%d/stat", pid);
+	FILE* fp = fopen(proc_pid_path, "r");
+    if (fp) {
+		if(fgets(buf, STAT_SIZE - 1, fp)){
+			sscanf(buf, "%*s %s", process_name);
+		}
+		fclose(fp);
+	}
+}
+
+enum wl_time_format wl_time_fmt = WL_TIME_FORMAT_LOCAL;
+
+WL_EXPORT void
+wl_set_time_format(enum wl_time_format fmt)
+{
+	wl_time_fmt = fmt;
+}
+
+
 /** \endcond */

src/wayland-util.h

@@ -35,6 +35,7 @@
 #include <stddef.h>
 #include <inttypes.h>
 #include <stdarg.h>
+#include <sys/types.h>
 
 #ifdef  __cplusplus
 extern "C" {
@@ -761,6 +762,25 @@ enum wl_iterator_result {
 	WL_ITERATOR_CONTINUE
 };
 
+void
+wl_get_name_by_pid(pid_t pid, char* process_name);
+
+enum wl_time_format {
+	WL_TIME_FORMAT_EPOCH,
+	WL_TIME_FORMAT_LOCAL,
+};
+
+/**
+ * Set System-Wide time format for wayland logging
+ *
+ * \note Default format is WL_TIME_FORMAT_LOCAL
+ *
+ * \param fmt Time format
+ * \sa wl_time_format
+ */
+void
+wl_set_time_format(enum wl_time_format fmt);
+
 #ifdef  __cplusplus
 }
 #endif