diff --git a/src/connection.c b/src/connection.c index 34495211..f8f57aa6 100644 --- a/src/connection.c +++ b/src/connection.c @@ -1488,8 +1488,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), - const char *queue_name) + bool send, const char* discarded_reason, const char *queue_name) { int i; struct argument_details arg; @@ -1508,13 +1507,14 @@ wl_closure_print(struct wl_closure *closure, struct wl_object *target, clock_gettime(CLOCK_REALTIME, &tp); time = (tp.tv_sec * 1000000L) + (tp.tv_nsec / 1000); - fprintf(f, "[%7u.%03u] ", time / 1000, time % 1000); - - if (queue_name) - fprintf(f, "{%s} ", queue_name); - - fprintf(f, "%s%s%s#%u.%s(", - discarded ? "discarded " : "", + fprintf(f, "[%7u.%03u] %s%s%s%s%s%s%s%s#%u.%s(", + time / 1000, time % 1000, + (queue_name != NULL) ? "{" : "", + (queue_name != NULL) ? queue_name : "", + (queue_name != NULL) ? "} " : "", + (discarded_reason != NULL) ? "discarded[" : "", + (discarded_reason != NULL) ? discarded_reason : "", + (discarded_reason != NULL) ? "] " : "", send ? " -> " : "", target->interface->name, target->id, closure->message->name); @@ -1559,10 +1559,7 @@ wl_closure_print(struct wl_closure *closure, struct wl_object *target, fprintf(f, "nil"); break; case WL_ARG_NEW_ID: - if (n_parse) - nval = n_parse(&closure->args[i]); - else - nval = closure->args[i].n; + nval = closure->args[i].n; fprintf(f, "new id %s#", (closure->message->types[i]) ? diff --git a/src/wayland-client-core.h b/src/wayland-client-core.h index a70d4f09..3d968792 100644 --- a/src/wayland-client-core.h +++ b/src/wayland-client-core.h @@ -230,6 +230,9 @@ wl_proxy_set_queue(struct wl_proxy *proxy, struct wl_event_queue *queue); struct wl_event_queue * wl_proxy_get_queue(const struct wl_proxy *proxy); +struct wl_proxy * +wl_proxy_from_object(struct wl_object *object); + const char * wl_event_queue_get_name(const struct wl_event_queue *queue); @@ -313,6 +316,113 @@ void wl_display_set_max_buffer_size(struct wl_display *display, size_t max_buffer_size); +/** + * The message type. + */ +enum wl_client_message_type { + /** The message is a request */ + WL_CLIENT_MESSAGE_REQUEST, + + /** The message is an event */ + WL_CLIENT_MESSAGE_EVENT, +}; + +/** + * The message discard reason codes. + */ +enum wl_client_message_discarded_reason { + /** The message was handled normally, and not discarded. */ + WL_CLIENT_MESSAGE_NOT_DISCARDED = 0, + + /** The target was not alive at dispatch time */ + WL_CLIENT_MESSAGE_DISCARD_DEAD_PROXY_ON_DISPATCH, + + /** The target had no listener or dispatcher */ + WL_CLIENT_MESSAGE_DISCARD_NO_LISTENER_ON_DISPATCH, + + /** The target was not valid when the event was demarshalled */ + WL_CLIENT_MESSAGE_DISCARD_UNKNOWN_ID_ON_DEMARSHAL, +}; + +/** + * The structure used to communicate details about an observed message to the + * registered observers. + */ +struct wl_client_observed_message { + /** The target for the message */ + struct wl_proxy *proxy; + + /** The message opcode */ + int message_opcode; + + /** The protocol message structure */ + const struct wl_message *message; + + /** The count of arguments to the message */ + int arguments_count; + + /** The argument array for the messagge */ + const union wl_argument *arguments; + + /** The discard reason code */ + enum wl_client_message_discarded_reason discarded_reason; + + /** + * The discard reason string, or NULL if the event was not discarded. + * + * This string is only for convenience for a observer that does + * logging. The string values should not be considered stable, and + * are not localized. + */ + const char *discarded_reason_str; + + /** + * The queue name, or NULL if the event is not associated with a + * particular queue. + */ + const char *queue_name; +}; + +/** + * The signature for a client message observer function, as registered with + * wl_display_add_client_observer(). + * + * \param user_data \c user_data pointer given when the observer was + * registered with \c wl_display_create_client_observer + * \param type type of message + * \param message details for the message + */ +typedef void (*wl_client_message_observer_func_t)( + void *user_data, enum wl_client_message_type type, + const struct wl_client_observed_message *message); + +/** \class wl_client_observer + * + * \brief Represents a client message observer + * + * A client observer allows the client to observe all request and event + * message traffic to and from the client. For events, the observer is + * also given a discard reason if the event wasn't handled. + * + * The typical use for the observer is to allow the client implementation to + * do its own debug logging, as the default when setting WAYLAND_DEBUG is to + * log to stderr. + * + * Via the client observer interfaces, the client can also enable and disable + * the observer at any time. + * + * The protocol-logger-test.c file has an example of a logger implementation. + */ +struct wl_client_observer; + +struct wl_client_observer * +wl_display_create_client_observer(struct wl_display *display, + wl_client_message_observer_func_t observer, + void *user_data); + +void +wl_client_observer_destroy(struct wl_client_observer *observer); + #ifdef __cplusplus } #endif diff --git a/src/wayland-client.c b/src/wayland-client.c index 3d0ef7b4..46cc17df 100644 --- a/src/wayland-client.c +++ b/src/wayland-client.c @@ -110,12 +110,188 @@ struct wl_display { int reader_count; uint32_t read_serial; pthread_cond_t reader_cond; + + struct wl_list observers; }; /** \endcond */ +struct wl_client_observer { + struct wl_list link; + struct wl_display *display; + wl_client_message_observer_func_t func; + void *user_data; +}; + static int debug_client = 0; +/** + * This helper function adjusts the closure arguments before they are logged. + * On the client, after the call to create_proxies(), NEW_ID arguments will + * point to a wl_proxy accessible via arg.o instead of being an int32 + * accessible by arg.n, which is what wl_closure_print() attempts to print. + * This helper transforms the argument back into an id, so wl_closure_print() + * doesn't need to handle that as a special case. + * + * \param closure closure to adjust + * \param send if this is closure is for a request + * + */ +static void +adjust_closure_args_for_logging(struct wl_closure *closure, bool send) +{ + int i; + struct argument_details arg; + const struct wl_proxy *proxy; + const char *signature = closure->message->signature; + + // No adjustment needed for a send. + if (send) + return; + + for (i = 0; i < closure->count; i++) { + signature = get_next_argument(signature, &arg); + + switch (arg.type) { + case WL_ARG_NEW_ID: + proxy = (struct wl_proxy *)closure->args[i].o; + closure->args[i].n = proxy ? proxy->object.id : 0; + break; + default: + break; + } + } +} + +/** + * Maps the \c discard_reason to a string suitable for logging. + * + * \param discarded_reason reason for discard + * \return A string describing the reason, or NULL. + * + */ +static const char * +get_discarded_reason_str( + enum wl_client_message_discarded_reason discarded_reason) +{ + switch (discarded_reason) { + case WL_CLIENT_MESSAGE_NOT_DISCARDED: + return NULL; + case WL_CLIENT_MESSAGE_DISCARD_DEAD_PROXY_ON_DISPATCH: + return "dead proxy on dispatch"; + case WL_CLIENT_MESSAGE_DISCARD_NO_LISTENER_ON_DISPATCH: + return "no listener on dispatch"; + case WL_CLIENT_MESSAGE_DISCARD_UNKNOWN_ID_ON_DEMARSHAL: + return "unknown id on demarshal"; + } + return NULL; +} + +/** + * This function helps log closures from the client, assuming logging is + * enabled. + * + * \param closure closure for the message + * \param proxy proxy for the message + * \param send true if this is closure is for a request + * \param discarded_reason reason if the message is being discarded, or + * WL_CLIENT_MESSAGE_NOT_DISCARDED + * \param queue_name name for the queue for the message + * + */ +static void +closure_log(struct wl_closure *closure, struct wl_proxy *proxy, bool send, + enum wl_client_message_discarded_reason discarded_reason, const char *queue_name) +{ + struct wl_display *display = proxy->display; + const char *discarded_reason_str; + struct wl_closure adjusted_closure = { 0 }; + + if (!debug_client && wl_list_empty(&display->observers)) + return; + + // Note: The real closure has extra data (referenced by its args + // immediately following the structure in memory, but we don't + // need to duplicate that. + memcpy(&adjusted_closure, closure, sizeof(struct wl_closure)); + + // Adjust the closure arguments. + adjust_closure_args_for_logging(&adjusted_closure, send); + + discarded_reason_str = get_discarded_reason_str(discarded_reason); + + if (debug_client) + wl_closure_print(&adjusted_closure, &proxy->object, send, + discarded_reason_str, queue_name); + + if (!wl_list_empty(&display->observers)) { + enum wl_client_message_type type = + send ? WL_CLIENT_MESSAGE_REQUEST + : WL_CLIENT_MESSAGE_EVENT; + struct wl_client_observer *observer; + struct wl_client_observed_message message; + + message.proxy = proxy; + message.message_opcode = adjusted_closure.opcode; + message.message = adjusted_closure.message; + message.arguments_count = adjusted_closure.count; + message.arguments = adjusted_closure.args; + message.discarded_reason = discarded_reason; + message.discarded_reason_str = discarded_reason_str; + message.queue_name = queue_name; + wl_list_for_each(observer, &display->observers, link) { + observer->func(observer->user_data, type, &message); + } + } +} + +/** + * This function helps log unknown messages on the client, when logging is + * enabled. + * + * \param display current display + * \param zombie true if there was a zombie for the message target + * \param id id of the proxy this message was meant for + * \param opcode opcode from the message + * \param num_fds number of fd arguments for this message + * \param num_bytes byte size of this message + */ +static void +log_unknown_message(struct wl_display *display, bool zombie, uint32_t id, + int opcode, int num_fds, int num_bytes) +{ + char event_detail[100]; + struct wl_interface unknown_interface = { 0 }; + struct wl_proxy unknown_proxy = { 0 }; + struct wl_message unknown_message = { 0 }; + struct wl_closure unknown_closure = { 0 }; + + if (!debug_client && wl_list_empty(&display->observers)) + return; + + snprintf(event_detail, sizeof event_detail, + "[event %d, %d fds, %d bytes]", opcode, num_fds, num_bytes); + + unknown_interface.name = zombie ? "[zombie]" : "[unknown]"; + + unknown_proxy.object.interface = &unknown_interface; + unknown_proxy.object.id = id; + unknown_proxy.display = display; + unknown_proxy.refcount = -1; + unknown_proxy.flags = WL_PROXY_FLAG_WRAPPER; + + unknown_message.name = event_detail; + unknown_message.signature = ""; + unknown_message.types = NULL; + + unknown_closure.message = &unknown_message; + unknown_closure.opcode = opcode; + unknown_closure.proxy = &unknown_proxy; + + closure_log(&unknown_closure, &unknown_proxy, false, + WL_CLIENT_MESSAGE_DISCARD_UNKNOWN_ID_ON_DEMARSHAL, NULL); +} + /** * This helper function wakes up all threads that are * waiting for display->reader_cond (i. e. when reading is done, @@ -902,6 +1078,8 @@ wl_proxy_marshal_array_flags(struct wl_proxy *proxy, uint32_t opcode, struct wl_proxy *new_proxy = NULL; const struct wl_message *message; struct wl_display *disp = proxy->display; + struct wl_event_queue *queue = NULL; + const char *queue_name = NULL; pthread_mutex_lock(&disp->mutex); @@ -927,17 +1105,12 @@ wl_proxy_marshal_array_flags(struct wl_proxy *proxy, uint32_t opcode, goto err_unlock; } - if (debug_client) { - struct wl_event_queue *queue; - const char *queue_name = NULL; + queue = wl_proxy_get_queue(proxy); + if (queue) + queue_name = wl_event_queue_get_name(queue); - queue = wl_proxy_get_queue(proxy); - if (queue) - queue_name = wl_event_queue_get_name(queue); - - wl_closure_print(closure, &proxy->object, true, false, NULL, - queue_name); - } + closure_log(closure, proxy, true, WL_CLIENT_MESSAGE_NOT_DISCARDED, + queue_name); if (wl_closure_send(closure, proxy->display->connection)) { wl_log("Error sending request for %s.%s: %s\n", @@ -1247,6 +1420,7 @@ wl_display_connect_to_fd(int fd) pthread_mutex_init(&display->mutex, NULL); pthread_cond_init(&display->reader_cond, NULL); display->reader_count = 0; + wl_list_init(&display->observers); if (wl_map_insert_at(&display->objects, 0, 0, NULL) == -1) goto err_connection; @@ -1378,6 +1552,7 @@ wl_display_disconnect(struct wl_display *display) free(display->default_queue.name); wl_event_queue_release(&display->display_queue); free(display->display_queue.name); + wl_list_remove(&display->observers); pthread_mutex_destroy(&display->mutex); pthread_cond_destroy(&display->reader_cond); close(display->fd); @@ -1556,8 +1731,6 @@ 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); @@ -1575,17 +1748,9 @@ queue_event(struct wl_display *display, int len) num_zombie_fds = (zombie && opcode < zombie->event_count) ? zombie->fd_count[opcode] : 0; - if (debug_client) { - clock_gettime(CLOCK_REALTIME, &tp); - time = (tp.tv_sec * 1000000L) + (tp.tv_nsec / 1000); + log_unknown_message(display, !!zombie, id, opcode, + num_zombie_fds, size); - fprintf(stderr, "[%7u.%03u] discarded [%s]#%d.[event %d]" - "(%d fd, %d byte)\n", - time / 1000, time % 1000, - zombie ? "zombie" : "unknown", - id, opcode, - num_zombie_fds, size); - } if (num_zombie_fds > 0) wl_connection_close_fds_in(display->connection, num_zombie_fds); @@ -1632,19 +1797,6 @@ queue_event(struct wl_display *display, int len) return size; } -static uint32_t -id_from_object(union wl_argument *arg) -{ - struct wl_proxy *proxy; - - if (arg->o) { - proxy = (struct wl_proxy *)arg->o; - return proxy->object.id; - } - - return 0; -} - static void dispatch_event(struct wl_display *display, struct wl_event_queue *queue) { @@ -1663,31 +1815,32 @@ dispatch_event(struct wl_display *display, struct wl_event_queue *queue) proxy = closure->proxy; proxy_destroyed = !!(proxy->flags & WL_PROXY_FLAG_DESTROYED); - if (debug_client) { - bool discarded = proxy_destroyed || - !(proxy->dispatcher || proxy->object.implementation); - - wl_closure_print(closure, &proxy->object, false, discarded, - id_from_object, queue->name); - } - if (proxy_destroyed) { - destroy_queued_closure(closure); - return; - } + closure_log(closure, proxy, false, + WL_CLIENT_MESSAGE_DISCARD_DEAD_PROXY_ON_DISPATCH, + queue->name); + } else if (proxy->dispatcher) { + closure_log(closure, proxy, false, + WL_CLIENT_MESSAGE_NOT_DISCARDED, queue->name); - pthread_mutex_unlock(&display->mutex); - - if (proxy->dispatcher) { + pthread_mutex_unlock(&display->mutex); wl_closure_dispatch(closure, proxy->dispatcher, &proxy->object, opcode); + pthread_mutex_lock(&display->mutex); } else if (proxy->object.implementation) { + closure_log(closure, proxy, false, + WL_CLIENT_MESSAGE_NOT_DISCARDED, queue->name); + + pthread_mutex_unlock(&display->mutex); wl_closure_invoke(closure, WL_CLOSURE_INVOKE_CLIENT, &proxy->object, opcode, proxy->user_data); + pthread_mutex_lock(&display->mutex); + } else { + closure_log(closure, proxy, false, + WL_CLIENT_MESSAGE_DISCARD_NO_LISTENER_ON_DISPATCH, + queue->name); } - pthread_mutex_lock(&display->mutex); - destroy_queued_closure(closure); } @@ -2705,8 +2858,91 @@ wl_proxy_wrapper_destroy(void *proxy_wrapper) free(wrapper); } +/** Safely converts an object into its corresponding proxy + * + * \param object object to get the proxy for + * \return A corresponding proxy, or NULL on failure. + * + * Safely converts an object into its corresponding proxy. + * + * This is useful for implementing functions that are given a \c wl_argument + * array, and that need to do further introspection on the ".o" field, as it + * is otherwise an opaque type. + * + * \memberof wl_proxy + */ +WL_EXPORT struct wl_proxy * +wl_proxy_from_object(struct wl_object *object) +{ + struct wl_proxy *proxy; + if (object == NULL) + return NULL; + return wl_container_of(object, proxy, object); +} + WL_EXPORT void wl_log_set_handler_client(wl_log_func_t handler) { wl_log_handler = handler; } + +/** Creates an client message observer. + * + * Note that the observer can potentially start receiving traffic immediately + * after being created, and even before this call returns. + * + * \param display client display to register with + * \param func function to call when client messages are observed + * \param user_data \c user_data pointer to pass to the observer + * + * \return The created observer, or NULL. + * + * \sa wl_client_observer_destroy + * + * \memberof wl_display + */ + +WL_EXPORT struct wl_client_observer * +wl_display_create_client_observer(struct wl_display *display, + wl_client_message_observer_func_t func, + void *user_data) +{ + struct wl_client_observer *observer; + + observer = malloc(sizeof *observer); + if (!observer) + return NULL; + + observer->display = display; + observer->func = func; + observer->user_data = user_data; + + pthread_mutex_lock(&display->mutex); + + wl_list_insert(&display->observers, &observer->link); + + pthread_mutex_unlock(&display->mutex); + + return observer; +} + +/** Destroys a client message obsever. + * + * This function destroys a client message observer, and removes it from the + * display it was added to with \c wl_display_create_client_observer. + * + * \param observer observer to destroy. + * + * \memberof wl_client_observer + */ +WL_EXPORT void +wl_client_observer_destroy(struct wl_client_observer *observer) +{ + pthread_mutex_lock(&observer->display->mutex); + + wl_list_remove(&observer->link); + + pthread_mutex_unlock(&observer->display->mutex); + + free(observer); +} diff --git a/src/wayland-private.h b/src/wayland-private.h index fe9120af..d90080cc 100644 --- a/src/wayland-private.h +++ b/src/wayland-private.h @@ -228,8 +228,9 @@ 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), + struct wl_object *target, + bool send, + const char *discarded_reason, const char *queue_name); void diff --git a/src/wayland-server-core.h b/src/wayland-server-core.h index 15c3b762..94e55263 100644 --- a/src/wayland-server-core.h +++ b/src/wayland-server-core.h @@ -629,6 +629,9 @@ struct wl_listener * wl_resource_get_destroy_listener(struct wl_resource *resource, wl_notify_func_t notify); +struct wl_resource * +wl_resource_from_object(struct wl_object *object); + #define wl_resource_for_each(resource, list) \ for (resource = 0, resource = wl_resource_from_link((list)->next); \ wl_resource_get_link(resource) != (list); \ diff --git a/src/wayland-server.c b/src/wayland-server.c index e5805669..3ab1fe0a 100644 --- a/src/wayland-server.c +++ b/src/wayland-server.c @@ -160,7 +160,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); + wl_closure_print(closure, object, send, NULL, NULL); if (!wl_list_empty(&display->protocol_loggers)) { message.resource = resource; @@ -905,6 +905,28 @@ wl_resource_get_class(const struct wl_resource *resource) return resource->object.interface->name; } +/** Safely converts an object into its corresponding resource + * + * \param object object to get the resource for + * \return A corresponding resource, or NULL on failure + * + * Safely converts an object into its corresponding resource. + * + * This is useful for implementing functions that are given a \c wl_argument + * array, and that need to do further introspection on the ".o" field, as it + * is otherwise an opaque type. + * + * \memberof wl_resource + */ +WL_EXPORT struct wl_resource * +wl_resource_from_object(struct wl_object *object) +{ + struct wl_resource *resource; + if (object == NULL) + return NULL; + return wl_container_of(object, resource, object); +} + /** * Add a listener to be called at the beginning of wl_client destruction * diff --git a/tests/protocol-logger-test.c b/tests/protocol-logger-test.c index a0ebd22a..af64bd0f 100644 --- a/tests/protocol-logger-test.c +++ b/tests/protocol-logger-test.c @@ -29,12 +29,15 @@ #include #include #include +#include #include #include "wayland-client.h" #include "wayland-server.h" #include "test-runner.h" +#define ARRAY_LENGTH(a) (sizeof(a) / sizeof(a)[0]) + /* Ensure the connection doesn't fail due to lack of XDG_RUNTIME_DIR. */ static const char * require_xdg_runtime_dir(void) @@ -45,57 +48,291 @@ require_xdg_runtime_dir(void) return val; } -struct compositor { - struct wl_display *display; - struct wl_event_loop *loop; - int message; - struct wl_client *client; -}; - -struct message { +struct expected_compositor_message { enum wl_protocol_logger_type type; const char *class; int opcode; const char *message_name; int args_count; -} messages[] = { - { - .type = WL_PROTOCOL_LOGGER_REQUEST, - .class = "wl_display", - .opcode = 0, - .message_name = "sync", - .args_count = 1, - }, - { - .type = WL_PROTOCOL_LOGGER_EVENT, - .class = "wl_callback", - .opcode = 0, - .message_name = "done", - .args_count = 1, - }, - { - .type = WL_PROTOCOL_LOGGER_EVENT, - .class = "wl_display", - .opcode = 1, - .message_name = "delete_id", - .args_count = 1, - }, }; +struct compositor { + struct wl_display *display; + struct wl_event_loop *loop; + struct wl_protocol_logger *logger; + + struct expected_compositor_message *expected_msg; + int expected_msg_count; + int actual_msg_count; + struct wl_client *client; +}; + +struct expected_client_message { + enum wl_client_message_type type; + enum wl_client_message_discarded_reason discarded_reason; + const char *queue_name; + const char *class; + int opcode; + const char *message_name; + int args_count; +}; + +struct client { + struct wl_display *display; + struct wl_callback *cb; + struct wl_client_observer *sequence_observer; + struct wl_client_observer *stderr_logger; + + struct expected_client_message *expected_msg; + int expected_msg_count; + int actual_msg_count; +}; + +static int +safe_strcmp(const char *s1, const char *s2) { + if (s1 == NULL && s2 == NULL) + return 0; + if (s1 == NULL && s2 != NULL) + return 1; + if (s1 != NULL && s2 == NULL) + return -1; + return strcmp(s1, s2); +} + +#define ASSERT_LT(arg1, arg2, ...) \ + if (arg1 >= arg2) \ + fprintf(stderr, __VA_ARGS__); \ + assert(arg1 < arg2) + +#define ASSERT_EQ(arg1, arg2, ...) \ + if (arg1 != arg2) \ + fprintf(stderr, __VA_ARGS__); \ + assert(arg1 == arg2) + +#define ASSERT_STR_EQ(arg1, arg2, ...) \ + if (safe_strcmp(arg1, arg2) != 0) \ + fprintf(stderr, __VA_ARGS__); \ + assert(safe_strcmp(arg1, arg2) == 0) + static void -logger_func(void *user_data, enum wl_protocol_logger_type type, - const struct wl_protocol_logger_message *message) +compositor_sequence_observer_func( + void *user_data, enum wl_protocol_logger_type actual_type, + const struct wl_protocol_logger_message *actual_msg) { struct compositor *c = user_data; - struct message *msg = &messages[c->message++]; + struct expected_compositor_message *expected_msg; + int actual_msg_count = c->actual_msg_count++; + char details_msg[256]; - assert(msg->type == type); - assert(strcmp(msg->class, wl_resource_get_class(message->resource)) == 0); - assert(msg->opcode == message->message_opcode); - assert(strcmp(msg->message_name, message->message->name) == 0); - assert(msg->args_count == message->arguments_count); + c->client = wl_resource_get_client(actual_msg->resource); - c->client = wl_resource_get_client(message->resource); + if (!c->expected_msg) + return; + + ASSERT_LT(actual_msg_count, c->expected_msg_count, + "actual count %d exceeds expected count %d\n", + actual_msg_count, c->expected_msg_count); + + expected_msg = &c->expected_msg[actual_msg_count]; + + snprintf(details_msg, sizeof details_msg, + "compositor msg %d of %d actual [%d, '%s', %d, '%s', %d] vs " + "expected [%d, '%s', %d, '%s', %d]\n", + c->actual_msg_count, c->expected_msg_count, actual_type, + wl_resource_get_class(actual_msg->resource), + actual_msg->message_opcode, actual_msg->message->name, + actual_msg->arguments_count, expected_msg->type, + expected_msg->class, expected_msg->opcode, + expected_msg->message_name, expected_msg->args_count); + + ASSERT_EQ(expected_msg->type, actual_type, "type mismatch: %s", + details_msg); + ASSERT_STR_EQ(expected_msg->class, + wl_resource_get_class(actual_msg->resource), + "class mismatch: %s", details_msg); + ASSERT_EQ(expected_msg->opcode, actual_msg->message_opcode, + "opcode mismatch: %s", details_msg); + ASSERT_STR_EQ(expected_msg->message_name, actual_msg->message->name, + "message name mismatch: %s", details_msg); + ASSERT_EQ(expected_msg->args_count, actual_msg->arguments_count, + "arg count mismatch: %s", details_msg); +} + +static void +client_sequence_observer_func( + void *user_data, enum wl_client_message_type actual_type, + const struct wl_client_observed_message *actual_msg) +{ + struct client *c = user_data; + struct expected_client_message *expected_msg; + int actual_msg_count = c->actual_msg_count++; + char details_msg[256]; + + if (!c->expected_msg) + return; + + ASSERT_LT(actual_msg_count, c->expected_msg_count, + "actual count %d exceeds expected count %d\n", + actual_msg_count, c->expected_msg_count); + expected_msg = &c->expected_msg[actual_msg_count]; + + snprintf(details_msg, sizeof details_msg, + "client msg %d of %d actual [%d, %d, '%s', '%s', %d, '%s', %d] vs " + "expected [%d, %d, '%s', '%s', %d, '%s', %d]\n", + c->actual_msg_count, c->expected_msg_count, actual_type, + actual_msg->discarded_reason, + actual_msg->queue_name ? actual_msg->queue_name : "NULL", + wl_proxy_get_class(actual_msg->proxy), + actual_msg->message_opcode, actual_msg->message->name, + actual_msg->arguments_count, expected_msg->type, + expected_msg->discarded_reason, + expected_msg->queue_name ? expected_msg->queue_name : "NULL", + expected_msg->class, expected_msg->opcode, + expected_msg->message_name, expected_msg->args_count); + + ASSERT_EQ(expected_msg->type, actual_type, "type mismatch: %s", + details_msg); + ASSERT_EQ(expected_msg->discarded_reason, actual_msg->discarded_reason, + "discarded reason mismatch: %s", details_msg); + ASSERT_STR_EQ(expected_msg->queue_name, actual_msg->queue_name, + "queue name mismatch: %s", details_msg); + ASSERT_STR_EQ(expected_msg->class, + wl_proxy_get_class(actual_msg->proxy), + "class mismatch: %s", details_msg); + ASSERT_EQ(expected_msg->opcode, actual_msg->message_opcode, + "opcode mismatch: %s", details_msg); + ASSERT_STR_EQ(expected_msg->message_name, actual_msg->message->name, + "message name mismatch: %s", details_msg); + ASSERT_EQ(expected_msg->args_count, actual_msg->arguments_count, + "arg count mismatch: %s", details_msg); +} + +// A slightly simplified version of get_next_argument() from src/connection.c +static const char * +get_next_argument_type(const char *signature, char *type) +{ + for (; *signature; ++signature) { + assert(strchr("iufsonah?", *signature) != NULL); + switch (*signature) { + case 'i': + case 'u': + case 'f': + case 's': + case 'o': + case 'n': + case 'a': + case 'h': + *type = *signature; + return signature + 1; + case '?': + break; + } + } + *type = 0; + return signature; +} + +// This duplicates what the internal wl_closure_print function does, and can be +// used as a starting point for a client or server that wants to log messages. +static void +client_log_to_stderr_demo(void *user_data, enum wl_client_message_type type, + const struct wl_client_observed_message *message) +{ + int i; + char arg_type; + const char *signature = message->message->signature; + const union wl_argument *args = message->arguments; + struct wl_proxy *arg_proxy; + const char *arg_class; + struct timespec tp; + unsigned int time; + FILE *f; + char *buffer; + size_t buffer_length; + + f = open_memstream(&buffer, &buffer_length); + if (f == NULL) + return; + + clock_gettime(CLOCK_REALTIME, &tp); + time = (tp.tv_sec * 1000000L) + (tp.tv_nsec / 1000); + + // Note: server logger will be given message->resource, and should + // use wl_resource_get_class and wl_resource_get_id. + fprintf(f, "[%7u.%03u] %s%s%s%s%s%s%s%s#%u.%s(", time / 1000, time % 1000, + (message->queue_name != NULL) ? "{" : "", + (message->queue_name != NULL) ? message->queue_name : "", + (message->queue_name != NULL) ? "} " : "", + (message->discarded_reason_str ? "discarded[" : ""), + (message->discarded_reason_str ? message->discarded_reason_str + : ""), + (message->discarded_reason_str ? "] " : ""), + (type == WL_CLIENT_MESSAGE_REQUEST) ? " -> " : "", + wl_proxy_get_class(message->proxy), + wl_proxy_get_id(message->proxy), message->message->name); + + for (i = 0; i < message->arguments_count; i++) { + signature = get_next_argument_type(signature, &arg_type); + if (i > 0) + fprintf(f, ", "); + + switch (arg_type) { + case 'u': + fprintf(f, "%u", args[i].u); + break; + case 'i': + fprintf(f, "%d", args[i].i); + break; + case 'f': + fprintf(f, "%f", wl_fixed_to_double(args[i].f)); + break; + case 's': + if (args[i].s) + fprintf(f, "\"%s\"", args[i].s); + else + fprintf(f, "nil"); + break; + case 'o': + if (args[i].o) { + // Note: server logger should instead use + // wl_resource_from_object, and then + // wl_resource_get_class and + // wl_resource_get_id. + arg_proxy = wl_proxy_from_object(args[i].o); + arg_class = wl_proxy_get_class(arg_proxy); + + fprintf(f, "%s#%u", + arg_class ? arg_class : "[unknown]", + wl_proxy_get_id(arg_proxy)); + } else { + fprintf(f, "nil"); + } + break; + case 'n': + fprintf(f, "new id %s#", + (message->message->types[i]) + ? message->message->types[i]->name + : "[unknown]"); + if (args[i].n != 0) + fprintf(f, "%u", args[i].n); + else + fprintf(f, "nil"); + break; + case 'a': + fprintf(f, "array"); + break; + case 'h': + fprintf(f, "fd %d", args[i].h); + break; + } + } + + fprintf(f, ")\n"); + + if (fclose(f) == 0) { + fprintf(stderr, "%s", buffer); + free(buffer); + } } static void @@ -108,41 +345,505 @@ static const struct wl_callback_listener callback_listener = { callback_done, }; +static void +logger_setup(struct compositor *compositor, struct client *client) +{ + const char *socket; + + require_xdg_runtime_dir(); + + compositor->display = wl_display_create(); + compositor->loop = wl_display_get_event_loop(compositor->display); + socket = wl_display_add_socket_auto(compositor->display); + + compositor->logger = wl_display_add_protocol_logger( + compositor->display, compositor_sequence_observer_func, + compositor); + + client->display = wl_display_connect(socket); + client->sequence_observer = wl_display_create_client_observer( + client->display, client_sequence_observer_func, client); + client->stderr_logger = wl_display_create_client_observer( + client->display, client_log_to_stderr_demo, client); +} + +static void +logger_teardown(struct compositor *compositor, struct client *client) +{ + wl_client_observer_destroy(client->sequence_observer); + wl_client_observer_destroy(client->stderr_logger); + wl_display_disconnect(client->display); + + wl_client_destroy(compositor->client); + wl_protocol_logger_destroy(compositor->logger); + wl_display_destroy(compositor->display); +} + TEST(logger) { test_set_timeout(1); - const char *socket; + struct expected_compositor_message compositor_messages[] = { + { + .type = WL_PROTOCOL_LOGGER_REQUEST, + .class = "wl_display", + .opcode = 0, + .message_name = "sync", + .args_count = 1, + }, + { + .type = WL_PROTOCOL_LOGGER_EVENT, + .class = "wl_callback", + .opcode = 0, + .message_name = "done", + .args_count = 1, + }, + { + .type = WL_PROTOCOL_LOGGER_EVENT, + .class = "wl_display", + .opcode = 1, + .message_name = "delete_id", + .args_count = 1, + }, + }; + struct expected_client_message client_messages[] = { + { + .type = WL_CLIENT_MESSAGE_REQUEST, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_display", + .opcode = 0, + .message_name = "sync", + .args_count = 1, + }, + { + .type = WL_CLIENT_MESSAGE_EVENT, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Display Queue", + .class = "wl_display", + .opcode = 1, + .message_name = "delete_id", + .args_count = 1, + }, + { + .type = WL_CLIENT_MESSAGE_EVENT, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_callback", + .opcode = 0, + .message_name = "done", + .args_count = 1, + }, + }; struct compositor compositor = { 0 }; - struct { - struct wl_display *display; - struct wl_callback *cb; - } client; - struct wl_protocol_logger *logger; + struct client client = { 0 }; - require_xdg_runtime_dir(); + logger_setup(&compositor, &client); - compositor.display = wl_display_create(); - compositor.loop = wl_display_get_event_loop(compositor.display); - socket = wl_display_add_socket_auto(compositor.display); + compositor.expected_msg = &compositor_messages[0]; + compositor.expected_msg_count = ARRAY_LENGTH(compositor_messages); - logger = wl_display_add_protocol_logger(compositor.display, - logger_func, &compositor); + client.expected_msg = &client_messages[0]; + client.expected_msg_count = ARRAY_LENGTH(client_messages); - client.display = wl_display_connect(socket); client.cb = wl_display_sync(client.display); wl_callback_add_listener(client.cb, &callback_listener, NULL); wl_display_flush(client.display); - while (compositor.message < 3) { + while (compositor.actual_msg_count < compositor.expected_msg_count) { + wl_event_loop_dispatch(compositor.loop, -1); + wl_display_flush_clients(compositor.display); + } + + while (client.actual_msg_count < client.expected_msg_count) { + wl_display_dispatch(client.display); + } + + logger_teardown(&compositor, &client); +} + +TEST(client_discards_if_dead_on_dispatch) +{ + test_set_timeout(1); + + struct expected_client_message client_messages[] = { + { + .type = WL_CLIENT_MESSAGE_REQUEST, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_display", + .opcode = 0, + .message_name = "sync", + .args_count = 1, + }, + { + .type = WL_CLIENT_MESSAGE_EVENT, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Display Queue", + .class = "wl_display", + .opcode = 1, + .message_name = "delete_id", + .args_count = 1, + }, + { + .type = WL_CLIENT_MESSAGE_EVENT, + .discarded_reason = + WL_CLIENT_MESSAGE_DISCARD_DEAD_PROXY_ON_DISPATCH, + .queue_name = "Default Queue", + .class = "wl_callback", + .opcode = 0, + .message_name = "done", + .args_count = 1, + }, + }; + struct compositor compositor = { 0 }; + struct client client = { 0 }; + + logger_setup(&compositor, &client); + + compositor.expected_msg_count = 3; + + client.expected_msg = &client_messages[0]; + client.expected_msg_count = ARRAY_LENGTH(client_messages); + + client.cb = wl_display_sync(client.display); + wl_callback_add_listener(client.cb, &callback_listener, NULL); + wl_display_flush(client.display); + + while (compositor.actual_msg_count < compositor.expected_msg_count) { + wl_event_loop_dispatch(compositor.loop, -1); + wl_display_flush_clients(compositor.display); + } + + wl_display_prepare_read(client.display); + wl_display_read_events(client.display); + + // To get a WL_CLIENT_MESSAGE_DISCARD_DEAD_PROXY_ON_DISPATCH, we + // destroy the callback after reading client events, but before + // dispatching them. + wl_callback_destroy(client.cb); + + while (client.actual_msg_count < client.expected_msg_count) { + wl_display_dispatch(client.display); + } + + logger_teardown(&compositor, &client); +} + +TEST(client_discards_if_no_listener_on_dispatch) +{ + test_set_timeout(1); + + struct expected_client_message client_messages[] = { + { + .type = WL_CLIENT_MESSAGE_REQUEST, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_display", + .opcode = 0, + .message_name = "sync", + .args_count = 1, + }, + { + .type = WL_CLIENT_MESSAGE_EVENT, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Display Queue", + .class = "wl_display", + .opcode = 1, + .message_name = "delete_id", + .args_count = 1, + }, + { + .type = WL_CLIENT_MESSAGE_EVENT, + .discarded_reason = + WL_CLIENT_MESSAGE_DISCARD_NO_LISTENER_ON_DISPATCH, + .queue_name = "Default Queue", + .class = "wl_callback", + .opcode = 0, + .message_name = "done", + .args_count = 1, + }, + }; + struct compositor compositor = { 0 }; + struct client client = { 0 }; + + logger_setup(&compositor, &client); + + compositor.expected_msg_count = 3; + + client.expected_msg = &client_messages[0]; + client.expected_msg_count = ARRAY_LENGTH(client_messages); + + client.cb = wl_display_sync(client.display); + wl_display_flush(client.display); + + while (compositor.actual_msg_count < compositor.expected_msg_count) { + wl_event_loop_dispatch(compositor.loop, -1); + wl_display_flush_clients(compositor.display); + } + + while (client.actual_msg_count < client.expected_msg_count) { + wl_display_dispatch(client.display); + } + + wl_callback_destroy(client.cb); + + logger_teardown(&compositor, &client); +} + +TEST(client_discards_if_invalid_id_on_demarshal) +{ + test_set_timeout(1); + + struct expected_client_message client_messages[] = { + { + .type = WL_CLIENT_MESSAGE_REQUEST, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_display", + .opcode = 0, + .message_name = "sync", + .args_count = 1, + }, + { + .type = WL_CLIENT_MESSAGE_EVENT, + .discarded_reason = + WL_CLIENT_MESSAGE_DISCARD_UNKNOWN_ID_ON_DEMARSHAL, + .queue_name = NULL, + .class = "[unknown]", + .opcode = 0, + .message_name = "[event 0, 0 fds, 12 bytes]", + .args_count = 0, + }, + { + .type = WL_CLIENT_MESSAGE_EVENT, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Display Queue", + .class = "wl_display", + .opcode = 1, + .message_name = "delete_id", + .args_count = 1, + }, + }; + struct compositor compositor = { 0 }; + struct client client = { 0 }; + + logger_setup(&compositor, &client); + + compositor.expected_msg_count = 3; + + client.expected_msg = &client_messages[0]; + client.expected_msg_count = ARRAY_LENGTH(client_messages); + + client.cb = wl_display_sync(client.display); + wl_display_flush(client.display); + + while (compositor.actual_msg_count < compositor.expected_msg_count) { + wl_event_loop_dispatch(compositor.loop, -1); + wl_display_flush_clients(compositor.display); + } + + // To get a WL_CLIENT_MESSAGE_DISCARD_UNKNOWN_ID_ON_DEMARSHAL, we + // destroy the callback before reading and dispatching client events. + wl_callback_destroy(client.cb); + + while (client.actual_msg_count < client.expected_msg_count) { + wl_display_dispatch(client.display); + } + + logger_teardown(&compositor, &client); +} + +static const struct wl_keyboard_interface keyboard_interface = { 0 }; + +static void +seat_get_pointer(struct wl_client *client, struct wl_resource *resource, + uint32_t id) +{ + assert(false && "Not expected to be called by client."); +} + +static void +seat_get_keyboard(struct wl_client *client, struct wl_resource *resource, + uint32_t id) +{ + struct wl_resource *keyboard_res; + + keyboard_res = + wl_resource_create(client, &wl_keyboard_interface, + wl_resource_get_version(resource), id); + wl_resource_set_implementation(keyboard_res, &keyboard_interface, NULL, + NULL); + + wl_keyboard_send_key(keyboard_res, 0, 0, 0, 0); +} + +static void +seat_get_touch(struct wl_client *client, struct wl_resource *resource, + uint32_t id) +{ + assert(false && "Not expected to be called by client."); +} + +static void +seat_release(struct wl_client *client, struct wl_resource *resource) +{ + wl_resource_destroy(resource); +} + +static const struct wl_seat_interface seat_interface = { + &seat_get_pointer, + &seat_get_keyboard, + &seat_get_touch, + &seat_release, +}; + +static void +bind_seat(struct wl_client *client, void *data, uint32_t vers, uint32_t id) +{ + struct wl_resource *seat_res; + + seat_res = wl_resource_create(client, &wl_seat_interface, vers, id); + wl_resource_set_implementation(seat_res, &seat_interface, NULL, NULL); +} + +static void +registry_seat_listener_handle_global(void *data, struct wl_registry *registry, + uint32_t id, const char *intf, + uint32_t ver) +{ + uint32_t *seat_id_ptr = data; + + if (strcmp(intf, wl_seat_interface.name) == 0) { + *seat_id_ptr = id; + } +} + +static const struct wl_registry_listener registry_seat_listener = { + registry_seat_listener_handle_global, NULL +}; + +TEST(client_discards_if_zombie_on_demarshal) +{ + test_set_timeout(1); + + struct expected_client_message client_messages[] = { + { + .type = WL_CLIENT_MESSAGE_REQUEST, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_display", + .opcode = 1, + .message_name = "get_registry", + .args_count = 1, + }, + { + .type = WL_CLIENT_MESSAGE_EVENT, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_registry", + .opcode = 0, + .message_name = "global", + .args_count = 3, + }, + { + .type = WL_CLIENT_MESSAGE_REQUEST, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_registry", + .opcode = 0, + .message_name = "bind", + .args_count = 4, + }, + { + .type = WL_CLIENT_MESSAGE_REQUEST, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_seat", + .opcode = 1, + .message_name = "get_keyboard", + .args_count = 1, + }, + { + .type = WL_CLIENT_MESSAGE_REQUEST, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_keyboard", + .opcode = 0, + .message_name = "release", + .args_count = 0, + }, + { + .type = WL_CLIENT_MESSAGE_REQUEST, + .discarded_reason = WL_CLIENT_MESSAGE_NOT_DISCARDED, + .queue_name = "Default Queue", + .class = "wl_seat", + .opcode = 3, + .message_name = "release", + .args_count = 0, + }, + { + .type = WL_CLIENT_MESSAGE_EVENT, + .discarded_reason = + WL_CLIENT_MESSAGE_DISCARD_UNKNOWN_ID_ON_DEMARSHAL, + .queue_name = NULL, + .class = "[zombie]", + .opcode = 3, + .message_name = "[event 3, 0 fds, 24 bytes]", + .args_count = 0, + }, + }; + + struct compositor compositor = { 0 }; + struct client client = { 0 }; + struct wl_global *g_keyboard; + struct wl_registry *registry; + struct wl_seat *seat; + struct wl_keyboard *keyboard; + int32_t seat_id; + + logger_setup(&compositor, &client); + + client.expected_msg = &client_messages[0]; + client.expected_msg_count = ARRAY_LENGTH(client_messages); + + g_keyboard = wl_global_create(compositor.display, &wl_seat_interface, + 5, &compositor.display, bind_seat); + + registry = wl_display_get_registry(client.display); + wl_registry_add_listener(registry, ®istry_seat_listener, &seat_id); + wl_display_flush(client.display); + + compositor.actual_msg_count = 0; + compositor.expected_msg_count = 2; + + while (compositor.actual_msg_count < compositor.expected_msg_count) { wl_event_loop_dispatch(compositor.loop, -1); wl_display_flush_clients(compositor.display); } wl_display_dispatch(client.display); - wl_display_disconnect(client.display); - wl_client_destroy(compositor.client); - wl_protocol_logger_destroy(logger); - wl_display_destroy(compositor.display); + seat = wl_registry_bind(registry, seat_id, &wl_seat_interface, 5); + keyboard = wl_seat_get_keyboard(seat); + wl_display_flush(client.display); + + compositor.actual_msg_count = 0; + compositor.expected_msg_count = 3; + + while (compositor.actual_msg_count < compositor.expected_msg_count) { + wl_event_loop_dispatch(compositor.loop, -1); + wl_display_flush_clients(compositor.display); + } + + wl_keyboard_release(keyboard); + wl_seat_release(seat); + + wl_display_dispatch(client.display); + + wl_registry_destroy(registry); + + wl_global_destroy(g_keyboard); + + logger_teardown(&compositor, &client); }