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>

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

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

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

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;