fix: do not run logging tests in parallel

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" }

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 {
@@ -495,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();
 
@@ -549,15 +546,16 @@ 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");
         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 {
@@ -616,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);
 
@@ -646,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",
@@ -681,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"
@@ -715,12 +716,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 +740,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::<Vec<_>>(),
         );
 
         // Verify all messages were received with correct severity levels