Log requests on dead objects

To make it possible to understand that something got discarded,
print a message saying so inside when `WAYLAND_DEBUG` is enabled.

This also changes how timestamps are computed for `WAYLAND_DEBUG` log
so they align with `libwayland-client` to look into logs using both
at the same time more accessible. The `[rs]` particle was added to
the log to give a hint which library was used, which could
be helpful when looking into random logs.

wayland-backend/src/rs/debug.rs → wayland-backend/src/debug.rs

@@ -8,6 +8,11 @@ use std::{
 
 use crate::protocol::Argument;
 
+/// The `WAYLAND_DEBUG` env variable is set to debug client.
+pub fn has_debug_client_env() -> bool {
+    matches!(std::env::var_os("WAYLAND_DEBUG"), Some(str) if str == "1" || str == "client")
+}
+
 /// Print the dispatched message to stderr in a following format:
 ///
 /// [timestamp] <- [email protected]_name(args)
@@ -36,11 +41,16 @@ pub fn print_send_message<Id: Display, Fd: AsRawFd>(
     id: u32,
     msg_name: &str,
     args: &[Argument<Id, Fd>],
+    discarded: bool,
 ) {
     // Add timestamp to output.
     print_timestamp();
 
-    eprint!(" -> {}@{}.{} ({})", interface, id, msg_name, DisplaySlice(args));
+    if discarded {
+        eprint!("[discarded]");
+    }
+
+    eprint!(" -> {}@{}.{}({})", interface, id, msg_name, DisplaySlice(args));
 
     // Add a new line.
     eprintln!();
@@ -66,8 +76,10 @@ impl<'a, D: Display> Display for DisplaySlice<'a, D> {
 #[cfg_attr(coverage, coverage(off))]
 fn print_timestamp() {
     if let Ok(timestamp) = SystemTime::now().duration_since(UNIX_EPOCH) {
-        let sc = timestamp.as_secs();
-        let ms = timestamp.subsec_micros();
-        eprint!("[{}.{:06}]", sc, ms);
+        // NOTE this is all to make timestamps the same with libwayland, so the log doesn't look
+        // out of place when sys tries to log on their own.
+        let time = (timestamp.as_secs() * 1000000 + timestamp.subsec_nanos() as u64 / 1000) as u32;
+        // NOTE annotate timestamp so we know which library emmited the log entry.
+        eprint!("[{:7}.{:03}][rs]", time / 1000, time % 1000);
     }
 }

wayland-backend/src/lib.rs

@@ -91,6 +91,7 @@ pub use sys::server;
 mod test;
 
 mod core_interfaces;
+mod debug;
 pub mod protocol;
 mod types;
 

wayland-backend/src/rs/client_impl/mod.rs

@@ -12,6 +12,7 @@ use std::{
 
 use crate::{
     core_interfaces::WL_DISPLAY_INTERFACE,
+    debug,
     protocol::{
         check_for_signature, same_interface, same_interface_or_anonymous, AllowNull, Argument,
         ArgumentType, Interface, Message, ObjectInfo, ProtocolError, ANONYMOUS_INTERFACE,
@@ -161,8 +162,7 @@ impl InnerBackend {
         )
         .unwrap();
 
-        let debug =
-            matches!(std::env::var_os("WAYLAND_DEBUG"), Some(str) if str == "1" || str == "client");
+        let debug = debug::has_debug_client_env();
 
         Ok(Self {
             state: Arc::new(ConnectionState {
@@ -301,9 +301,6 @@ impl InnerBackend {
     ) -> Result<ObjectId, InvalidId> {
         let mut guard = self.state.lock_protocol();
         let object = guard.get_object(id.clone())?;
-        if object.data.client_destroyed {
-            return Err(InvalidId);
-        }
 
         let message_desc = match object.interface.requests.get(opcode as usize) {
             Some(msg) => msg,
@@ -312,6 +309,13 @@ impl InnerBackend {
             }
         };
 
+        if object.data.client_destroyed {
+            if guard.debug {
+                debug::print_send_message(id.interface.name, id.id, message_desc.name, &args, true);
+            }
+            return Err(InvalidId);
+        }
+
         if !check_for_signature(message_desc.signature, &args) {
             panic!(
                 "Unexpected signature for request {}@{}.{}: expected {:?}, got {:?}.",
@@ -409,20 +413,16 @@ impl InnerBackend {
         }).collect::<SmallVec<[_; INLINE_ARGS]>>();
 
         if guard.debug {
-            super::debug::print_send_message(
+            debug::print_send_message(
                 object.interface.name,
                 id.id,
                 message_desc.name,
                 &args,
+                false,
             );
         }
         #[cfg(feature = "log")]
-        crate::log_debug!(
-            "Sending {}.{} ({})",
-            id,
-            message_desc.name,
-            super::debug::DisplaySlice(&args)
-        );
+        crate::log_debug!("Sending {}.{} ({})", id, message_desc.name, debug::DisplaySlice(&args));
 
         // Send the message
 
@@ -549,7 +549,7 @@ impl ProtocolState {
 
     fn handle_display_event(&mut self, message: Message<u32, OwnedFd>) -> Result<(), WaylandError> {
         if self.debug {
-            super::debug::print_dispatched_message(
+            debug::print_dispatched_message(
                 "wl_display",
                 message.sender_id,
                 if message.opcode == 0 { "error" } else { "delete_id" },
@@ -748,7 +748,7 @@ fn dispatch_events(state: Arc<ConnectionState>) -> Result<usize, WaylandError> {
         }
 
         if guard.debug {
-            super::debug::print_dispatched_message(
+            debug::print_dispatched_message(
                 receiver.interface.name,
                 message.sender_id,
                 message_desc.name,
@@ -775,7 +775,7 @@ fn dispatch_events(state: Arc<ConnectionState>) -> Result<usize, WaylandError> {
             "Dispatching {}.{} ({})",
             id,
             receiver.version,
-            super::debug::DisplaySlice(&args)
+            debug::DisplaySlice(&args)
         );
         let ret = receiver
             .data

wayland-backend/src/rs/mod.rs

@@ -3,7 +3,6 @@
 mod client_impl;
 mod server_impl;
 
-mod debug;
 mod map;
 pub(crate) mod socket;
 mod wire;

wayland-backend/src/rs/server_impl/client.rs

@@ -7,6 +7,7 @@ use std::{
 
 use crate::{
     core_interfaces::{WL_CALLBACK_INTERFACE, WL_DISPLAY_INTERFACE, WL_REGISTRY_INTERFACE},
+    debug,
     protocol::{
         check_for_signature, same_interface, same_interface_or_anonymous, AllowNull, Argument,
         ArgumentType, Interface, Message, ObjectInfo, ProtocolError, ANONYMOUS_INTERFACE,
@@ -135,11 +136,12 @@ impl<D> Client<D> {
         }
 
         if self.debug {
-            crate::rs::debug::print_send_message(
+            debug::print_send_message(
                 object.interface.name,
                 object_id.id.id,
                 message_desc.name,
                 &args,
+                false,
             );
         }
 
@@ -362,7 +364,7 @@ impl<D> Client<D> {
             let obj = self.map.find(msg.sender_id).unwrap();
 
             if self.debug {
-                super::super::debug::print_dispatched_message(
+                debug::print_dispatched_message(
                     obj.interface.name,
                     msg.sender_id,
                     obj.interface.requests.get(msg.opcode as usize).unwrap().name,

wayland-backend/src/rs/server_impl/mod.rs

@@ -10,6 +10,7 @@ mod common_poll;
 mod handle;
 mod registry;
 
+pub use crate::types::server::Credentials;
 pub use common_poll::InnerBackend;
 pub use handle::{InnerHandle, WeakInnerHandle};
 

wayland-backend/src/sys/client_impl/mod.rs

@@ -17,6 +17,8 @@ use std::{
 
 use crate::{
     core_interfaces::WL_DISPLAY_INTERFACE,
+    debug,
+    debug::has_debug_client_env,
     protocol::{
         check_for_signature, same_interface, AllowNull, Argument, ArgumentType, Interface, Message,
         ObjectInfo, ProtocolError, ANONYMOUS_INTERFACE,
@@ -184,6 +186,7 @@ struct Dispatcher;
 struct Inner {
     state: Mutex<ConnectionState>,
     dispatch_lock: Mutex<Dispatcher>,
+    debug: bool,
 }
 
 #[derive(Clone, Debug)]
@@ -254,6 +257,7 @@ impl InnerBackend {
                     last_error: None,
                     known_proxies: HashSet::new(),
                 }),
+                debug: has_debug_client_env(),
                 dispatch_lock: Mutex::new(Dispatcher),
             }),
         })
@@ -276,6 +280,7 @@ impl InnerBackend {
                     last_error: None,
                     known_proxies: HashSet::new(),
                 }),
+                debug: has_debug_client_env(),
                 dispatch_lock: Mutex::new(Dispatcher),
             }),
         }
@@ -512,22 +517,28 @@ impl InnerBackend {
         child_spec: Option<(&'static Interface, u32)>,
     ) -> Result<ObjectId, InvalidId> {
         let mut guard = self.lock_state();
+        // check that the argument list is valid
+        let message_desc = match id.interface.requests.get(opcode as usize) {
+            Some(msg) => msg,
+            None => {
+                panic!("Unknown opcode {} for object {}@{}.", opcode, id.interface.name, id.id);
+            }
+        };
+
         if !id.alive.as_ref().map(|a| a.load(Ordering::Acquire)).unwrap_or(true) || id.ptr.is_null()
         {
+            if self.inner.debug {
+                debug::print_send_message(id.interface.name, id.id, message_desc.name, &args, true);
+            }
             return Err(InvalidId);
         }
+
         let parent_version = if id.id == 1 {
             1
         } else {
             unsafe { ffi_dispatch!(wayland_client_handle(), wl_proxy_get_version, id.ptr) }
         };
-        // check that the argument list is valid
-        let message_desc = match id.interface.requests.get(opcode as usize) {
-            Some(msg) => msg,
-            None => {
-                panic!("Unknown opcode {} for object {}@{}.", opcode, id.interface.name, id.id);
-            }
-        };
+
         if !check_for_signature(message_desc.signature, &args) {
             panic!(
                 "Unexpected signature for request {}@{}.{}: expected {:?}, got {:?}.",