fix: make logging tests parallel-safe

Signed-off-by: Esteve Fernandez <esteve@apache.org>

Author: esteve

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

rclrs/src/logging.rs

@@ -335,57 +335,37 @@ pub unsafe fn impl_log(
         static FORMAT_STRING: OnceLock<CString> = 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<Mutex<Vec<LogEntry<'static>>>> = 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::{