From ada25fbd526dec116026cb2567a912b47890ad05 Mon Sep 17 00:00:00 2001 From: Manuel Stoeckl Date: Sat, 26 Sep 2020 21:14:16 -0400 Subject: [PATCH] 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 --- src/connection.c | 6 ++++-- src/wayland-client.c | 28 +++++++++++++++++++++++----- src/wayland-private.h | 2 +- src/wayland-server.c | 2 +- 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;