From 31cc817c17f92e2f0c880f8e7f73b21ae556dfaf Mon Sep 17 00:00:00 2001 From: Kirill Chibisov Date: Thu, 9 Nov 2023 22:12:07 +0400 Subject: [PATCH] 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 | 20 ++++++++++--- wayland-backend/src/lib.rs | 1 + wayland-backend/src/rs/client_impl/mod.rs | 30 ++++++++++---------- wayland-backend/src/rs/mod.rs | 1 - wayland-backend/src/rs/server_impl/client.rs | 6 ++-- wayland-backend/src/rs/server_impl/mod.rs | 1 + wayland-backend/src/sys/client_impl/mod.rs | 25 +++++++++++----- 7 files changed, 55 insertions(+), 29 deletions(-) rename wayland-backend/src/{rs => }/debug.rs (69%) diff --git a/wayland-backend/src/rs/debug.rs b/wayland-backend/src/debug.rs similarity index 69% rename from wayland-backend/src/rs/debug.rs rename to wayland-backend/src/debug.rs index c02a5dc0cc7..9c713bf4451 100644 --- a/wayland-backend/src/rs/debug.rs +++ b/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] <- interface@id.msg_name(args) @@ -36,11 +41,16 @@ pub fn print_send_message( id: u32, msg_name: &str, args: &[Argument], + 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); } } diff --git a/wayland-backend/src/lib.rs b/wayland-backend/src/lib.rs index 3b3bb41a450..5ebf661d8ba 100644 --- a/wayland-backend/src/lib.rs +++ b/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; diff --git a/wayland-backend/src/rs/client_impl/mod.rs b/wayland-backend/src/rs/client_impl/mod.rs index 97047f44585..ba10fbb27ae 100644 --- a/wayland-backend/src/rs/client_impl/mod.rs +++ b/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 { 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::>(); 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) -> 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) -> Result { } 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) -> Result { "Dispatching {}.{} ({})", id, receiver.version, - super::debug::DisplaySlice(&args) + debug::DisplaySlice(&args) ); let ret = receiver .data diff --git a/wayland-backend/src/rs/mod.rs b/wayland-backend/src/rs/mod.rs index e44ef4ecea7..dfc727be593 100644 --- a/wayland-backend/src/rs/mod.rs +++ b/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; diff --git a/wayland-backend/src/rs/server_impl/client.rs b/wayland-backend/src/rs/server_impl/client.rs index b324d5fb09c..44c216db6de 100644 --- a/wayland-backend/src/rs/server_impl/client.rs +++ b/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 Client { } 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 Client { 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, diff --git a/wayland-backend/src/rs/server_impl/mod.rs b/wayland-backend/src/rs/server_impl/mod.rs index 22269f605f3..51db3633b41 100644 --- a/wayland-backend/src/rs/server_impl/mod.rs +++ b/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}; diff --git a/wayland-backend/src/sys/client_impl/mod.rs b/wayland-backend/src/sys/client_impl/mod.rs index 824b910a907..88c64277b91 100644 --- a/wayland-backend/src/sys/client_impl/mod.rs +++ b/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, dispatch_lock: Mutex, + 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 { 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 {:?}.",