From ac3ad45b7db087612ee8714b884be63fe3061605 Mon Sep 17 00:00:00 2001 From: Esteve Fernandez Date: Sun, 17 May 2026 20:28:53 +0100 Subject: [PATCH 1/3] build: pin ros-env deduplication fix Signed-off-by: Esteve Fernandez --- Cargo.toml | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/Cargo.toml b/Cargo.toml index afac85b2a..7d27a6886 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -3,3 +3,7 @@ members = [ "rclrs", ] resolver = "2" + +# TODO: Remove once ros-env releases duplicate package deduplication. +[patch.crates-io] +ros-env = { git = "https://github.com/esteve/ros-env.git", rev = "ef6507f96ec1dcc122be2604adbfb35b295d9bf3" } From 2e4e969382e097553f9811c2b2e2dbf635af2de5 Mon Sep 17 00:00:00 2001 From: Esteve Fernandez Date: Wed, 15 Apr 2026 12:40:38 +0200 Subject: [PATCH 2/3] fix: do not run logging tests in parallel Signed-off-by: Esteve Fernandez --- rclrs/Cargo.toml | 2 ++ rclrs/src/logging.rs | 42 ++++++++++++++++++++++++++++++++---------- 2 files changed, 34 insertions(+), 10 deletions(-) diff --git a/rclrs/Cargo.toml b/rclrs/Cargo.toml index 05a658f42..2a6a5fe38 100644 --- a/rclrs/Cargo.toml +++ b/rclrs/Cargo.toml @@ -59,6 +59,8 @@ uuid = { version = "1", features = ["v4"] } paste = { version = "1", optional = true} [dev-dependencies] +# Needed for running logging tests serialized +serial_test = "3.4.0" # Needed for e.g. writing yaml files in tests tempfile = "3.3.0" # Needed for parameter service tests diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index d5cd989c5..cb7a4d4e9 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -473,12 +473,14 @@ macro_rules! function { #[cfg(test)] mod tests { use crate::{log_handler::*, test_helpers::*, *}; + use serial_test::serial; use std::{ sync::{Arc, Mutex}, time::Duration, }; #[test] + #[serial] fn test_logging_macros() -> Result<(), RclrsError> { // This test ensures that strings which are being sent to the logger are // being sanitized correctly. Rust generally and our logging macro in @@ -555,9 +557,12 @@ mod tests { assert_eq!(last_logger_name(), node.logger().name()); assert_eq!(last_message(), "Logging with node dereference"); assert_eq!(last_severity(), LogSeverity::Info); - assert_eq!( + assert!( + last_location() + .function_name + .starts_with("rclrs::logging::tests::test_logging_macros"), + "Unexpected function name: {}", last_location().function_name, - "rclrs::logging::tests::test_logging_macros", ); for _ in 0..10 { @@ -669,6 +674,7 @@ mod tests { } #[test] + #[serial] fn test_rosout_publishing_default() -> Result<(), RclrsError> { use crate::rcl_bindings::rcl_logging_rosout_enabled; use ros_env::rcl_interfaces::msg::rmw::Log; @@ -715,12 +721,17 @@ mod tests { )?; // Wait for /rosout subscription to be discovered by the publisher - spin_until_condition( - &mut executor, - || node.count_subscriptions("/rosout").unwrap_or(0) > 0, - Duration::from_millis(500), + assert!( + spin_until_condition( + &mut executor, + || node.count_subscriptions("/rosout").unwrap_or(0) > 0, + Duration::from_secs(2), + ), + "Timed out waiting for /rosout subscription discovery" ); + executor.spin(SpinOptions::spin_once().timeout(Duration::from_millis(100))); + // Log messages at all severity levels (except debug) with unique identifiers let test_id = line!(); let info_msg = format!("Info rosout default test {}", test_id); @@ -734,10 +745,20 @@ mod tests { log!(node.fatal(), "{}", fatal_msg); // Spin until all 4 messages are received (INFO, WARN, ERROR, FATAL) - spin_until_condition( - &mut executor, - || received_logs.lock().unwrap().len() >= 4, - Duration::from_secs(5), + assert!( + spin_until_condition( + &mut executor, + || received_logs.lock().unwrap().len() >= 4, + Duration::from_secs(5), + ), + "Timed out waiting for rosout messages. Received {} messages: {:?}", + received_logs.lock().unwrap().len(), + received_logs + .lock() + .unwrap() + .iter() + .map(|l| l.msg.to_string()) + .collect::>(), ); // Verify all messages were received with correct severity levels @@ -793,6 +814,7 @@ mod tests { } #[test] + #[serial] fn test_rosout_disabled() -> Result<(), RclrsError> { use ros_env::rcl_interfaces::msg::rmw::Log; use std::sync::{ From 3138c2f5a1b4793ad3dc7296208f4373f9cac6c7 Mon Sep 17 00:00:00 2001 From: Esteve Fernandez Date: Sun, 17 May 2026 18:37:12 +0100 Subject: [PATCH 3/3] fix: make logging tests parallel-safe Signed-off-by: Esteve Fernandez --- rclrs/Cargo.toml | 2 - rclrs/src/logging.rs | 110 ++++++++------- rclrs/src/logging/logging_configuration.rs | 148 +++++++++------------ rclrs/src/node/node_options.rs | 5 +- 4 files changed, 116 insertions(+), 149 deletions(-) diff --git a/rclrs/Cargo.toml b/rclrs/Cargo.toml index 2a6a5fe38..05a658f42 100644 --- a/rclrs/Cargo.toml +++ b/rclrs/Cargo.toml @@ -59,8 +59,6 @@ uuid = { version = "1", features = ["v4"] } paste = { version = "1", optional = true} [dev-dependencies] -# Needed for running logging tests serialized -serial_test = "3.4.0" # Needed for e.g. writing yaml files in tests tempfile = "3.3.0" # Needed for parameter service tests diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index cb7a4d4e9..92e430320 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -335,57 +335,37 @@ pub unsafe fn impl_log( static FORMAT_STRING: OnceLock = OnceLock::new(); let format_string = FORMAT_STRING.get_or_init(|| CString::new("%s").unwrap()); - let severity = severity.as_native(); + let severity = severity.as_native() as i32; let _lifecycle = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); #[cfg(test)] - { - // If we are compiling for testing purposes, when the default log - // output handler is being used we need to use the format_string, - // but when our custom log output handler is being used we need to - // pass the raw message string so that it can be viewed by the - // custom log output handler, allowing us to use it for test assertions. - if log_handler::is_using_custom_handler() { - // We are using the custom log handler that is only used during - // logging tests, so pass the raw message as the format string. - unsafe { - // SAFETY: The global mutex is locked as _lifecycle - rcutils_log( - &location, - severity as i32, - logger_name.as_ptr(), - message.as_ptr(), - ); - } - } else { - // We are using the normal log handler so call rcutils_log the normal way. - unsafe { - // SAFETY: The global mutex is locked as _lifecycle - rcutils_log( - &location, - severity as i32, - logger_name.as_ptr(), - format_string.as_ptr(), - message.as_ptr(), - ); - } - } - } - - #[cfg(not(test))] + if log_handler::is_using_custom_handler() + && unsafe { rcutils_logging_logger_is_enabled_for(logger_name.as_ptr(), severity) } { unsafe { - // SAFETY: The global mutex is locked as _lifecycle - rcutils_log( + // SAFETY: The global mutex is locked as _lifecycle and the pointers are valid for + // the duration of this call. + log_handler::dispatch_logging_output_handler( &location, - severity as i32, + severity, logger_name.as_ptr(), - format_string.as_ptr(), + log_handler::null_timestamp(), message.as_ptr(), ); } } + + unsafe { + // SAFETY: The global mutex is locked as _lifecycle + rcutils_log( + &location, + severity, + logger_name.as_ptr(), + format_string.as_ptr(), + message.as_ptr(), + ); + } }; match logger_name { @@ -473,14 +453,12 @@ macro_rules! function { #[cfg(test)] mod tests { use crate::{log_handler::*, test_helpers::*, *}; - use serial_test::serial; use std::{ sync::{Arc, Mutex}, time::Duration, }; #[test] - #[serial] fn test_logging_macros() -> Result<(), RclrsError> { // This test ensures that strings which are being sent to the logger are // being sanitized correctly. Rust generally and our logging macro in @@ -497,15 +475,32 @@ mod tests { log!("please do not crash", "%n"); let graph = construct_test_graph("test_logging_macros")?; + let node = graph.node1; + let node_logger_name = node.logger().name().to_owned(); + + let custom_logger_name = "test_logging_macros_custom"; + let once_logger_name = "test_logging_macros_once"; + let skip_logger_name = "test_logging_macros_skip"; + let throttle_logger_name = "test_logging_macros_throttle"; let log_collection: Arc>>> = Arc::new(Mutex::new(Vec::new())); let inner_log_collection = log_collection.clone(); log_handler::set_logging_output_handler(move |log_entry: log_handler::LogEntry| { - inner_log_collection - .lock() - .unwrap() - .push(log_entry.into_owned()); + if [ + node_logger_name.as_str(), + custom_logger_name, + once_logger_name, + skip_logger_name, + throttle_logger_name, + ] + .contains(&log_entry.logger_name.as_ref()) + { + inner_log_collection + .lock() + .unwrap() + .push(log_entry.into_owned()); + } }) .unwrap(); @@ -551,8 +546,6 @@ mod tests { count }; - let node = graph.node1; - log!(&*node, "Logging with node dereference"); assert_eq!(last_logger_name(), node.logger().name()); assert_eq!(last_message(), "Logging with node dereference"); @@ -621,27 +614,27 @@ mod tests { log_debug!(node.logger(), "This debug message does not appear"); assert_ne!(last_message(), "This debug message does not appear"); - log!("custom logger name", "message for custom logger"); - assert_eq!(last_logger_name(), "custom logger name"); + log!(custom_logger_name, "message for custom logger"); + assert_eq!(last_logger_name(), custom_logger_name); assert_eq!(last_message(), "message for custom logger"); for _ in 0..3 { log!( - "custom logger name once".once(), + once_logger_name.once(), "one-time message for custom logger", ); } - assert_eq!(last_logger_name(), "custom logger name once"); + assert_eq!(last_logger_name(), once_logger_name); assert_eq!(last_severity(), LogSeverity::Info); assert_eq!(count_message("one-time message for custom logger"), 1); for _ in 0..3 { log!( - "custom logger name skip".error().skip_first(), + skip_logger_name.error().skip_first(), "error for custom logger", ); } - assert_eq!(last_logger_name(), "custom logger name skip"); + assert_eq!(last_logger_name(), skip_logger_name); assert_eq!(last_severity(), LogSeverity::Error); assert_eq!(count_message("error for custom logger"), 2); @@ -651,7 +644,7 @@ mod tests { for i in 0..15 { log!( - "logger" + throttle_logger_name .throttle(Duration::from_nanos(10)) .throttle_clock(ThrottleClock::Clock(&clock)), "custom clock throttled message", @@ -674,7 +667,6 @@ mod tests { } #[test] - #[serial] fn test_rosout_publishing_default() -> Result<(), RclrsError> { use crate::rcl_bindings::rcl_logging_rosout_enabled; use ros_env::rcl_interfaces::msg::rmw::Log; @@ -687,8 +679,11 @@ mod tests { .unwrap(); // Check if rosout is enabled at the rcl level - // SAFETY: This is a simple query function with no preconditions - let rosout_enabled = unsafe { rcl_logging_rosout_enabled() }; + let rosout_enabled = { + let _lifecycle_lock = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); + // SAFETY: The entity lifecycle mutex is locked to protect logging's global state. + unsafe { rcl_logging_rosout_enabled() } + }; assert!( rosout_enabled, "rcl_logging_rosout should be enabled for this test" @@ -814,7 +809,6 @@ mod tests { } #[test] - #[serial] fn test_rosout_disabled() -> Result<(), RclrsError> { use ros_env::rcl_interfaces::msg::rmw::Log; use std::sync::{ diff --git a/rclrs/src/logging/logging_configuration.rs b/rclrs/src/logging/logging_configuration.rs index 4353f1d30..ee932a93a 100644 --- a/rclrs/src/logging/logging_configuration.rs +++ b/rclrs/src/logging/logging_configuration.rs @@ -64,34 +64,18 @@ pub(crate) mod log_handler { ffi::CStr, sync::{ atomic::{AtomicBool, Ordering}, - OnceLock, + Mutex, OnceLock, }, }; - use crate::{rcl_bindings::*, LogSeverity, ENTITY_LIFECYCLE_MUTEX}; + use crate::{rcl_bindings::*, LogSeverity}; - /// Global variable that allows a custom log handler to be set. This log - /// handler will be applied throughout the entire application and cannot be - /// replaced with a different custom log handler. If you want to be able to - /// change the log handler over the lifetime of your application, you should - /// design your own custom handler with an Arc> inside that allows - /// its own behavior to be modified. - static LOGGING_OUTPUT_HANDLER: OnceLock = OnceLock::new(); + /// Global variable that allows tests to observe log entries without replacing + /// the process-global rcutils output handler. + static LOGGING_OUTPUT_HANDLER: OnceLock>> = OnceLock::new(); /// Alias for an arbitrary log handler that is compatible with raw rcl types - pub(crate) type RawLogHandler = Box< - dyn Fn( - *const rcutils_log_location_t, // location - std::os::raw::c_int, // severity - *const std::os::raw::c_char, // logger name - rcutils_time_point_value_t, // timestamp - *const std::os::raw::c_char, // format - *mut va_list, // formatting arguments - ) - + 'static - + Send - + Sync, - >; + pub(crate) type RawLogHandler = Box; /// This is an idiomatic representation of all the information for a log entry #[derive(Clone)] @@ -143,65 +127,19 @@ pub(crate) mod log_handler { pub(crate) fn set_logging_output_handler( handler: impl Fn(LogEntry) + 'static + Send + Sync, ) -> Result<(), OutputHandlerAlreadySet> { - let raw_handler = Box::new( - move |raw_location: *const rcutils_log_location_t, - raw_severity: std::os::raw::c_int, - raw_logger_name: *const std::os::raw::c_char, - raw_timestamp: rcutils_time_point_value_t, - raw_format: *const std::os::raw::c_char, - // NOTE: In the rclrs logging test we are choosing to format - // the full message in advance when using the custom handler, - // so the format field always contains the finished formatted - // message. Therefore we can just ignore the raw formatting - // arguments. - _raw_formatting_arguments: *mut va_list| { - unsafe { - // NOTE: We use .unwrap() extensively inside this function because - // it only gets used during tests. We should reconsider this if - // we ever make this public. - let location = LogLocation { - function_name: Cow::Borrowed( - CStr::from_ptr((*raw_location).function_name) - .to_str() - .unwrap(), - ), - file_name: Cow::Borrowed( - CStr::from_ptr((*raw_location).file_name).to_str().unwrap(), - ), - line_number: (*raw_location).line_number, - }; - let severity = LogSeverity::from_native(raw_severity); - let logger_name = - Cow::Borrowed(CStr::from_ptr(raw_logger_name).to_str().unwrap()); - let timestamp: i64 = raw_timestamp; - let message = Cow::Borrowed(CStr::from_ptr(raw_format).to_str().unwrap()); - handler(LogEntry { - location, - severity, - logger_name, - timestamp, - message, - }); - } - }, - ); - - set_raw_logging_output_handler(raw_handler) + set_raw_logging_output_handler(Box::new(handler)) } /// Set the logging output handler directly pub(crate) fn set_raw_logging_output_handler( handler: RawLogHandler, ) -> Result<(), OutputHandlerAlreadySet> { - LOGGING_OUTPUT_HANDLER - .set(handler) - .map_err(|_| OutputHandlerAlreadySet)?; - let _lifecycle = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); - unsafe { - // SAFETY: - // - We have locked the global mutex - rcutils_logging_set_output_handler(Some(rclrs_logging_output_handler)); + let handler_slot = LOGGING_OUTPUT_HANDLER.get_or_init(Default::default); + let mut handler_slot = handler_slot.lock().unwrap(); + if handler_slot.is_some() { + return Err(OutputHandlerAlreadySet); } + *handler_slot = Some(handler); USING_CUSTOM_HANDLER .get_or_init(|| AtomicBool::new(false)) @@ -215,37 +153,73 @@ pub(crate) mod log_handler { .load(Ordering::Acquire) } - /// This function exists so that we can give a raw function pointer to - /// rcutils_logging_set_output_handler, which is needed by its API. - unsafe extern "C" fn rclrs_logging_output_handler( + /// Dispatch a log entry to the active test handler, if one is set. + /// + /// SAFETY: The raw pointers must be valid for the duration of the call. + pub(crate) unsafe fn dispatch_logging_output_handler( location: *const rcutils_log_location_t, severity: std::os::raw::c_int, logger_name: *const std::os::raw::c_char, timestamp: rcutils_time_point_value_t, message: *const std::os::raw::c_char, - logging_output: *mut va_list, ) { - let handler = LOGGING_OUTPUT_HANDLER.get().unwrap(); - (*handler)( + let Some(handler_slot) = LOGGING_OUTPUT_HANDLER.get() else { + return; + }; + let handler_slot = handler_slot.lock().unwrap(); + let Some(handler) = handler_slot.as_ref() else { + return; + }; + + let location = if location.is_null() { + LogLocation { + function_name: Cow::Borrowed(""), + file_name: Cow::Borrowed(""), + line_number: 0, + } + } else { + LogLocation { + function_name: Cow::Borrowed( + CStr::from_ptr((*location).function_name).to_str().unwrap(), + ), + file_name: Cow::Borrowed(CStr::from_ptr((*location).file_name).to_str().unwrap()), + line_number: (*location).line_number, + } + }; + let severity = LogSeverity::from_native(severity); + let logger_name = if logger_name.is_null() { + Cow::Borrowed("") + } else { + Cow::Borrowed(CStr::from_ptr(logger_name).to_str().unwrap()) + }; + let message = if message.is_null() { + Cow::Borrowed("") + } else { + Cow::Borrowed(CStr::from_ptr(message).to_str().unwrap()) + }; + + handler(LogEntry { location, severity, logger_name, timestamp, message, - logging_output, - ); + }); } /// Reset the logging output handler to the default one pub(crate) fn reset_logging_output_handler() { - let _lifecycle = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); - unsafe { - // SAFETY: The global mutex is locked. No other precondition is - // required. - rcutils_logging_set_output_handler(Some(rcl_logging_multiple_output_handler)); + if let Some(handler_slot) = LOGGING_OUTPUT_HANDLER.get() { + *handler_slot.lock().unwrap() = None; } USING_CUSTOM_HANDLER .get_or_init(|| AtomicBool::new(false)) .store(false, Ordering::Release); } + + pub(crate) fn null_timestamp() -> rcutils_time_point_value_t { + // This value is only used by the Rust-side test hook. The real rcutils + // output handler still receives the timestamp produced by rcutils_log. + 0 + } } diff --git a/rclrs/src/node/node_options.rs b/rclrs/src/node/node_options.rs index 62855d240..38ee3ba03 100644 --- a/rclrs/src/node/node_options.rs +++ b/rclrs/src/node/node_options.rs @@ -338,9 +338,10 @@ impl<'a> NodeOptions<'a> { // so we only need to explicitly initialize it on newer distros. #[cfg(not(ros_distro = "humble"))] if self.enable_rosout { - // SAFETY: rcl_logging_rosout_enabled checks if rosout logging is globally enabled. + let _lifecycle_lock = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); + // SAFETY: The entity lifecycle mutex is locked and rcl_logging_rosout_enabled checks + // if rosout logging is globally enabled. if unsafe { rcl_logging_rosout_enabled() } { - let _lifecycle_lock = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); // SAFETY: The node has been successfully initialized and the // entity lifecycle mutex is locked. unsafe {