client: print discarded events in debug log

Before this patch, setting WAYLAND_DEBUG=1 or WAYLAND_DEBUG=client made
a program log all requests sent and events that it processes. However,
some events received are not processed. This can happen when a Wayland
server sends an event to an object that does not exist, or was recently
destroyed by the client program (either before the event was decoded,
or after being decoded but before being dispatched.)

This commit prints all discarded messages in the debug log, producing
lines like:

[1234567.890] discarded [unknown]@42.[event 0](0 fd, 12 byte)
[1234567.890] discarded wl_callback@3.done(34567)
[1234567.890] discarded [zombie]@13.[event 1](3 fd, 8 byte)

The first indicates an event to an object that does not exist; the
second, an event to an object that was deleted after decoding, but
before dispatch; the third, an event to an object that left a
'zombie' marker behind to indicate which events have associated
file descriptors.

Signed-off-by: Manuel Stoeckl <code@mstoeckl.com>

4 files changed, 29 insertions, 9 deletions

diff --git a/src/connection.c b/src/connection.c
index ccbb972..91d00c5 100644
--- a/src/connection.c
+++ b/src/connection.c
@@ -1263,7 +1263,8 @@ 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)
+wl_closure_print(struct wl_closure *closure, struct wl_object *target,
+		 int send, int discarded)
 {
 	int i;
 	struct argument_details arg;
@@ -1274,8 +1275,9 @@ wl_closure_print(struct wl_closure *closure, struct wl_object *target, int send)
 	clock_gettime(CLOCK_REALTIME, &tp);
 	time = (tp.tv_sec * 1000000L) + (tp.tv_nsec / 1000);
 
-	fprintf(stderr, "[%10.3f] %s%s@%u.%s(",
+	fprintf(stderr, "[%10.3f] %s%s%s@%u.%s(",
 		time / 1000.0,
+		discarded ? "discarded " : "",
 		send ? " -> " : "",
 		target->interface->name, target->id,
 		closure->message->name);
diff --git a/src/wayland-client.c b/src/wayland-client.c
index 58531eb..3bf659c 100644
--- a/src/wayland-client.c
+++ b/src/wayland-client.c
@@ -752,7 +752,7 @@ wl_proxy_marshal_array_constructor_versioned(struct wl_proxy *proxy,
 	}
 
 	if (debug_client)
-		wl_closure_print(closure, &proxy->object, true);
+		wl_closure_print(closure, &proxy->object, true, false);
 
 	if (wl_closure_send(closure, proxy->display->connection)) {
 		wl_log("Error sending request: %s\n", strerror(errno));
@@ -1358,6 +1358,9 @@ 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;
 
 	wl_connection_copy(display->connection, p, sizeof p);
 	id = p[0];
@@ -1371,10 +1374,23 @@ queue_event(struct wl_display *display, int len)
 	proxy = wl_map_lookup(&display->objects, id);
 	if (!proxy || wl_object_is_zombie(&display->objects, id)) {
 		struct wl_zombie *zombie = wl_map_lookup(&display->objects, id);
+		num_zombie_fds = (zombie && opcode < zombie->event_count) ?
+			zombie->fd_count[opcode] : 0;
 
-		if (zombie && zombie->fd_count[opcode])
+		if (debug_client) {
+			clock_gettime(CLOCK_REALTIME, &tp);
+			time = (tp.tv_sec * 1000000L) + (tp.tv_nsec / 1000);
+
+			fprintf(stderr, "[%10.3f] discarded [%s]@%d.[event %d]"
+				"(%d fd, %d byte)\n",
+				time / 1000.0,
+				zombie ? "zombie" : "unknown",
+				id, opcode,
+				num_zombie_fds, size);
+		}
+		if (num_zombie_fds > 0)
 			wl_connection_close_fds_in(display->connection,
-						   zombie->fd_count[opcode]);
+						   num_zombie_fds);
 
 		wl_connection_consume(display->connection, size);
 		return size;
@@ -1433,6 +1449,8 @@ dispatch_event(struct wl_display *display, struct wl_event_queue *queue)
 	proxy = closure->proxy;
 	proxy_destroyed = !!(proxy->flags & WL_PROXY_FLAG_DESTROYED);
 	if (proxy_destroyed) {
+		if (debug_client)
+			wl_closure_print(closure, &proxy->object, false, true);
 		destroy_queued_closure(closure);
 		return;
 	}
@@ -1441,13 +1459,13 @@ dispatch_event(struct wl_display *display, struct wl_event_queue *queue)
 
 	if (proxy->dispatcher) {
 		if (debug_client)
-			wl_closure_print(closure, &proxy->object, false);
+			wl_closure_print(closure, &proxy->object, false, false);
 
 		wl_closure_dispatch(closure, proxy->dispatcher,
 				    &proxy->object, opcode);
 	} else if (proxy->object.implementation) {
 		if (debug_client)
-			wl_closure_print(closure, &proxy->object, false);
+			wl_closure_print(closure, &proxy->object, false, false);
 
 		wl_closure_invoke(closure, WL_CLOSURE_INVOKE_CLIENT,
 				  &proxy->object, opcode, proxy->user_data);
diff --git a/src/wayland-private.h b/src/wayland-private.h
index 9bf8cb7..493e1be 100644
--- a/src/wayland-private.h
+++ b/src/wayland-private.h
@@ -211,7 +211,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);
+		 struct wl_object *target, int send, int discarded);
 
 void
 wl_closure_destroy(struct wl_closure *closure);
diff --git a/src/wayland-server.c b/src/wayland-server.c
index 0120326..db734ee 100644
--- a/src/wayland-server.c
+++ b/src/wayland-server.c
@@ -150,7 +150,7 @@ log_closure(struct wl_resource *resource,
 	struct wl_protocol_logger_message message;
 
 	if (debug_server)
-		wl_closure_print(closure, object, send);
+		wl_closure_print(closure, object, send, false);
 
 	if (!wl_list_empty(&display->protocol_loggers)) {
 		message.resource = resource;