diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index d5cd989c..437452b3 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -341,35 +341,28 @@ pub unsafe fn impl_log( #[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(), - ); - } + // Always call rcutils_log the safe way ("%s" + message), so the record + // can be forwarded to the default rcl handler (console/`/rosout`) + // without printf-interpreting any `%` in the message. When the custom + // capture handler is active we additionally stash the finished message + // in a per-thread slot so the handler can read it back without parsing + // the C `va_list`. The stash is cleared after the call. + let using_custom_handler = log_handler::is_using_custom_handler(); + if using_custom_handler { + log_handler::stash_current_message(message.as_c_str()); + } + 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(), + ); + } + if using_custom_handler { + log_handler::clear_current_message(); } } diff --git a/rclrs/src/logging/logging_configuration.rs b/rclrs/src/logging/logging_configuration.rs index 4353f1d3..4a979065 100644 --- a/rclrs/src/logging/logging_configuration.rs +++ b/rclrs/src/logging/logging_configuration.rs @@ -69,6 +69,36 @@ pub(crate) mod log_handler { }; use crate::{rcl_bindings::*, LogSeverity, ENTITY_LIFECYCLE_MUTEX}; + use std::{cell::RefCell, ffi::CString, thread::ThreadId}; + + thread_local! { + /// The fully-formatted message for the log record currently being emitted + /// on this thread. `impl_log` stashes it here right before calling + /// `rcutils_log` so the capture handler can read the finished string + /// without parsing the C `va_list` (the messy problem noted above). Only + /// read on the capture thread; cleared by `impl_log` after each record. + static CURRENT_MESSAGE: RefCell> = const { RefCell::new(None) }; + } + + /// The thread that installed the capture handler (the logging test's thread). + /// The custom handler captures only records emitted on this thread, so logs + /// from concurrently-running tests don't pollute the captured output. + static CAPTURE_THREAD: OnceLock = OnceLock::new(); + + /// Stash the formatted message for the current log record (called by + /// `impl_log` before `rcutils_log`). + pub(crate) fn stash_current_message(message: &std::ffi::CStr) { + CURRENT_MESSAGE.with(|m| *m.borrow_mut() = Some(message.to_owned())); + } + + /// Clear the stashed message (called by `impl_log` after `rcutils_log`). + pub(crate) fn clear_current_message() { + CURRENT_MESSAGE.with(|m| *m.borrow_mut() = None); + } + + fn current_message() -> Option { + CURRENT_MESSAGE.with(|m| m.borrow().clone()) + } /// Global variable that allows a custom log handler to be set. This log /// handler will be applied throughout the entire application and cannot be @@ -148,12 +178,12 @@ pub(crate) mod log_handler { 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_format: *const std::os::raw::c_char, + // We read the finished message from the per-thread stash set by + // `impl_log` (see `stash_current_message`) rather than from the + // format string + `va_list`, which avoids parsing C varargs in + // Rust. The raw format/args are forwarded to the default rcl + // handler separately (in the trampoline) so /rosout still works. _raw_formatting_arguments: *mut va_list| { unsafe { // NOTE: We use .unwrap() extensively inside this function because @@ -174,7 +204,13 @@ pub(crate) mod log_handler { 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()); + let message = Cow::Owned( + current_message() + .unwrap_or_default() + .to_str() + .unwrap() + .to_owned(), + ); handler(LogEntry { location, severity, @@ -196,6 +232,9 @@ pub(crate) mod log_handler { LOGGING_OUTPUT_HANDLER .set(handler) .map_err(|_| OutputHandlerAlreadySet)?; + // Records are captured only when emitted on the thread that installed the + // handler, so concurrent tests' logs don't pollute the captured output. + let _ = CAPTURE_THREAD.set(std::thread::current().id()); let _lifecycle = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); unsafe { // SAFETY: @@ -225,6 +264,26 @@ pub(crate) mod log_handler { message: *const std::os::raw::c_char, logging_output: *mut va_list, ) { + // Chain to the default rcl handler so console/file/`/rosout` output keeps + // working while our capture handler is installed. Our custom handler used + // to *replace* this, which silently disabled `/rosout` publishing + // process-wide for the duration — breaking concurrently-running tests that + // rely on `/rosout`. The format string and `va_list` are passed through + // unchanged (`impl_log` uses a safe `"%s"` + message form), so this is + // printf-safe. + rcl_logging_multiple_output_handler( + location, + severity, + logger_name, + timestamp, + message, + logging_output, + ); + + // Capture only records emitted on the thread that installed the handler. + if Some(std::thread::current().id()) != CAPTURE_THREAD.get().copied() { + return; + } let handler = LOGGING_OUTPUT_HANDLER.get().unwrap(); (*handler)( location,