Cleaner logging tests

rclrs/src/logging.rs

@@ -209,7 +209,16 @@ macro_rules! log_unconditional {
         // Only allocate a CString for the function name once per call to this macro.
         static FUNCTION_NAME: OnceLock<CString> = OnceLock::new();
         let function_name = FUNCTION_NAME.get_or_init(|| {
-            CString::new($crate::function!()).unwrap_or(
+            // This call to function! is nested within two layers of closures,
+            // so we need to strip away those suffixes or else users will be
+            // misled. If we ever restructure these macros or if Rust changes
+            // the way it names closures, this implementation detail may need to
+            // change.
+            let function_name = $crate::function!()
+                .strip_suffix("::{{closure}}::{{closure}}")
+                .unwrap();
+
+            CString::new(function_name).unwrap_or(
                 CString::new("<invalid name>").unwrap()
             )
         });
@@ -278,21 +287,60 @@ pub unsafe fn impl_log(
             file_name: file.as_ptr(),
             line_number: line as usize,
         };
-        static FORMAT_CSTR: OnceLock<CString> = OnceLock::new();
-        let format_cstr = FORMAT_CSTR.get_or_init(|| CString::new("%s").unwrap());
+
+        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 _lifecycle = ENTITY_LIFECYCLE_MUTEX.lock().unwrap();
-        // SAFETY: Global variables are protected via ENTITY_LIFECYCLE_MUTEX, no other preconditions are required
-        unsafe {
-            rcutils_log(
-                &location,
-                severity as i32,
-                logger_name.as_ptr(),
-                format_cstr.as_ptr(),
-                message.as_ptr(),
-            );
+
+        #[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))]
+        {
+            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(),
+                );
+            }
         }
     };
 
@@ -380,25 +428,121 @@ macro_rules! function {
 
 #[cfg(test)]
 mod tests {
-    use crate::{test_helpers::*, *};
+    use crate::{log_handler::*, test_helpers::*, *};
+    use std::sync::Mutex;
 
     #[test]
     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
+        // particular do not use C-style formatting strings, but rcutils expects
+        // to receive C-style formatting strings alongside variadic arguments
+        // that describe how to fill in the formatting.
+        //
+        // If we pass the final string into rcutils as the format with no
+        // variadic arguments, then it may trigger a crash or undefined behavior
+        // if the message happens to contain any % symbols. In particular %n
+        // will trigger a crash when no variadic arguments are given because it
+        // attempts to write to a buffer. If no buffer is given, a seg fault
+        // happens.
+        log!("please do not crash", "%n");
+
         let graph = construct_test_graph("test_logging_macros")?;
+
+        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());
+        })
+        .unwrap();
+
+        let last_logger_name = || {
+            log_collection
+                .lock()
+                .unwrap()
+                .last()
+                .unwrap()
+                .logger_name
+                .clone()
+        };
+
+        let last_message = || {
+            log_collection
+                .lock()
+                .unwrap()
+                .last()
+                .unwrap()
+                .message
+                .clone()
+        };
+
+        let last_location = || {
+            log_collection
+                .lock()
+                .unwrap()
+                .last()
+                .unwrap()
+                .location
+                .clone()
+        };
+
+        let last_severity = || log_collection.lock().unwrap().last().unwrap().severity;
+
+        let count_message = |message: &str| {
+            let mut count = 0;
+            for log in log_collection.lock().unwrap().iter() {
+                if log.message == message {
+                    count += 1;
+                }
+            }
+            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!(
+            last_location().function_name,
+            "rclrs::logging::tests::test_logging_macros",
+        );
 
         for _ in 0..10 {
             log!(node.once(), "Logging once");
         }
+        assert_eq!(count_message("Logging once"), 1);
+        assert_eq!(last_severity(), LogSeverity::Info);
 
         log!(node.logger(), "Logging with node logger");
+        assert_eq!(last_message(), "Logging with node logger");
+        assert_eq!(last_severity(), LogSeverity::Info);
+
         log!(node.debug(), "Debug from node");
+        // The default severity level is Info so we should not see the last message
+        assert_ne!(last_message(), "Debug from node");
+        assert_ne!(last_severity(), LogSeverity::Debug);
+
         log!(node.info(), "Info from node");
+        assert_eq!(last_message(), "Info from node");
+        assert_eq!(last_severity(), LogSeverity::Info);
+
         log!(node.warn(), "Warn from node");
+        assert_eq!(last_message(), "Warn from node");
+        assert_eq!(last_severity(), LogSeverity::Warn);
+
         log!(node.error(), "Error from node");
+        assert_eq!(last_message(), "Error from node");
+        assert_eq!(last_severity(), LogSeverity::Error);
+
         log!(node.fatal(), "Fatal from node");
+        assert_eq!(last_message(), "Fatal from node");
+        assert_eq!(last_severity(), LogSeverity::Fatal);
 
         log_debug!(node.logger(), "log_debug macro");
         log_info!(node.logger(), "log_info macro");
@@ -412,26 +556,44 @@ mod tests {
         for i in 0..3 {
             log!(node.warn().skip_first(), "Formatted warning #{}", i);
         }
+        assert_eq!(count_message("Formatted warning #0"), 0);
+        assert_eq!(count_message("Formatted warning #1"), 1);
+        assert_eq!(count_message("Formatted warning #2"), 1);
 
         node.logger().set_level(LogSeverity::Debug).unwrap();
         log_debug!(node.logger(), "This debug message appears");
+        assert_eq!(last_message(), "This debug message appears");
+        assert_eq!(last_severity(), LogSeverity::Debug);
+
         node.logger().set_level(LogSeverity::Info).unwrap();
-        log_debug!(node.logger(), "This debug message does not");
+        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");
+        assert_eq!(last_message(), "message for custom logger");
+
         for _ in 0..3 {
             log!(
-                "custom logger name".once(),
-                "one-time message for custom logger"
+                "custom logger name once".once(),
+                "one-time message for custom logger",
             );
         }
+        assert_eq!(last_logger_name(), "custom logger name once");
+        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".error().skip_first(),
+                "custom logger name skip".error().skip_first(),
                 "error for custom logger",
             );
         }
+        assert_eq!(last_logger_name(), "custom logger name skip");
+        assert_eq!(last_severity(), LogSeverity::Error);
+        assert_eq!(count_message("error for custom logger"), 2);
+
+        reset_logging_output_handler();
 
         Ok(())
     }

rclrs/src/logging/log_params.rs

@@ -162,8 +162,13 @@ pub enum LoggerName<'a> {
 }
 
 /// Logging severity.
+//
+// TODO(@mxgrey): Consider whether this is redundant with RCUTILS_LOG_SEVERITY.
+// Perhaps we can customize the output of bindgen to automatically change the name
+// of RCUTILS_LOG_SEVERITY to just LogSeverity so it's more idiomatic and then
+// export it from the rclrs module.
 #[doc(hidden)]
-#[derive(Debug, Clone, Copy)]
+#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
 pub enum LogSeverity {
     /// Use the severity level of the parent logger (or the root logger if the
     /// current logger has no parent)
@@ -199,6 +204,22 @@ impl LogSeverity {
             LogSeverity::Fatal => RCUTILS_LOG_SEVERITY_FATAL,
         }
     }
+
+    /// This is only used by the log output handler during testing, so it will
+    /// not be compiled when testing is not configured
+    #[cfg(test)]
+    pub(crate) fn from_native(native: i32) -> Self {
+        use crate::rcl_bindings::rcl_log_severity_t::*;
+        match native {
+            _ if native == RCUTILS_LOG_SEVERITY_UNSET as i32 => LogSeverity::Unset,
+            _ if native == RCUTILS_LOG_SEVERITY_DEBUG as i32 => LogSeverity::Debug,
+            _ if native == RCUTILS_LOG_SEVERITY_INFO as i32 => LogSeverity::Info,
+            _ if native == RCUTILS_LOG_SEVERITY_WARN as i32 => LogSeverity::Warn,
+            _ if native == RCUTILS_LOG_SEVERITY_ERROR as i32 => LogSeverity::Error,
+            _ if native == RCUTILS_LOG_SEVERITY_FATAL as i32 => LogSeverity::Fatal,
+            _ => panic!("Invalid native severity received: {}", native),
+        }
+    }
 }
 
 impl Default for LogSeverity {