diff --git a/rclrs/build.rs b/rclrs/build.rs index 3ac6dc414..91d0b190f 100644 --- a/rclrs/build.rs +++ b/rclrs/build.rs @@ -35,6 +35,7 @@ fn main() { } }; + println!("cargo:rustc-check-cfg=cfg(ros_distro, values(\"humble\", \"iron\", \"jazzy\", \"rolling\"))"); println!("cargo:rustc-cfg=ros_distro=\"{ros_distro}\""); let mut builder = bindgen::Builder::default() diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index 3943183c7..d008e5d66 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -3,340 +3,441 @@ // Adapted from https://github.com/sequenceplanner/r2r/blob/89cec03d07a1496a225751159cbc7bfb529d9dd1/r2r/src/utils.rs // Further adapted from https://github.com/mvukov/rules_ros2/pull/371 -use std::{ffi::CString, time::Duration}; +use std::{ + collections::HashMap, + ffi::CString, + sync::{Mutex, OnceLock}, +}; use crate::{rcl_bindings::*, ENTITY_LIFECYCLE_MUTEX}; mod logging_configuration; pub(crate) use logging_configuration::*; -/// Calls the underlying rclutils logging function -/// Don't call this directly, use the logging macros instead. -/// -/// # Panics -/// -/// This function might panic in the following scenarios: -/// - A logger_name is provided that is not a valid c-string, e.g. contains extraneous null characters -/// - The user-supplied "msg" is not a valid c-string, e.g. contains extraneous null characters -/// - When called if the lock is already held by the current thread. -/// - If the construction of CString objects used to create the log output fail, -/// although, this highly unlikely to occur in most cases -#[doc(hidden)] -pub fn log(msg: &str, logger_name: &str, file: &str, line: u32, severity: LogSeverity) { - // currently not possible to get function name in rust. - // see https://github.com/rust-lang/rfcs/pull/2818 - let function = CString::new("").unwrap(); - let file = CString::new(file).unwrap(); - let location = rcutils_log_location_t { - function_name: function.as_ptr(), - file_name: file.as_ptr(), - line_number: line as usize, - }; - let format = CString::new("%s").unwrap(); - let logger_name = CString::new(logger_name) - .expect("Logger name is a valid c style string, e.g. check for extraneous null characters"); - let message = CString::new(msg) - .expect("Valid c style string required, e.g. check for extraneous null characters"); - let severity = severity.to_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.as_ptr(), - message.as_ptr(), - ); - } -} - -/// Logging severity -#[doc(hidden)] -pub enum LogSeverity { - Unset, - Debug, - Info, - Warn, - Error, - Fatal, -} - -impl LogSeverity { - fn to_native(&self) -> RCUTILS_LOG_SEVERITY { - use crate::rcl_bindings::rcl_log_severity_t::*; - match self { - LogSeverity::Unset => RCUTILS_LOG_SEVERITY_UNSET, - LogSeverity::Debug => RCUTILS_LOG_SEVERITY_DEBUG, - LogSeverity::Info => RCUTILS_LOG_SEVERITY_INFO, - LogSeverity::Warn => RCUTILS_LOG_SEVERITY_WARN, - LogSeverity::Error => RCUTILS_LOG_SEVERITY_ERROR, - LogSeverity::Fatal => RCUTILS_LOG_SEVERITY_FATAL, - } - } -} - -#[derive(Debug)] -/// Specify when a log message should be published -pub enum LoggingOccurrence { - /// The log message will always be published (assuming all other conditions are met) - Always, - /// The message will only be published on the first occurrence (Note: no other conditions apply) - Once, - /// The log message will not be published on the first occurrence, but will be published on - /// each subsequent occurrence (assuming all other conditions are met) - SkipFirst, -} - -/// Specify conditions that must be met for a log message to be published -/// -/// The struct provides the following convenience functions to construct conditions that match -/// behaviour available in the `rclcpp` and `rclpy` libraries. -/// -/// When will my log message be output? -/// -/// - `Once`: A message with the [`LoggingOccurrence::Once`] value will be published once only -/// regardless of any other conditions -/// - `SkipFirst`: A message with the [`LoggingOccurrence::SkipFirst`] value will never be published -/// on the first encounter regardless of any other conditions. After the first -/// encounter, the behaviour is identical to the [`LoggingOccurrence::Always`] setting. -/// - `Always`: The log message will be output if all additional conditions are true: -/// - The current time + the `publish_interval` > the last time the message was published. -/// - The default value for `publish_interval` is 0, i.e. the interval check will always pass -/// - The `log_if_true` expression evaluates to TRUE. -/// - The default value for the `log_if_true` field is TRUE. -pub struct LogConditions { - /// Specify when a log message should be published (See[`LoggingOccurrence`] above) - pub occurs: LoggingOccurrence, - /// Specify the publication interval of the message. A value of ZERO (0) indicates that the - /// message should be published every time, otherwise, the message will only be published once - /// the specified interval has elapsed. - /// This field is typically used to limit the output from high-frequency messages, e.g. instead - /// of publishing a log message every 10 milliseconds, the `publish_interval` can be configured - /// such that the message is published every 10 seconds. - pub publish_interval: Duration, - /// The log message will only published if the specified expression evaluates to true - pub log_if_true: bool, -} - -impl LogConditions { - /// Default construct an instance - pub fn new() -> Self { - Self { - occurs: LoggingOccurrence::Always, - publish_interval: Duration::ZERO, - log_if_true: true, - } - } - - /// Only publish this message the first time it is encountered - pub fn once() -> Self { - Self { - occurs: LoggingOccurrence::Once, - publish_interval: Duration::ZERO, - log_if_true: true, - } - } +mod log_params; +pub use log_params::*; - /// Do not publish the message the first time it is encountered - pub fn skip_first() -> Self { - Self { - occurs: LoggingOccurrence::SkipFirst, - publish_interval: Duration::ZERO, - log_if_true: true, - } - } - - /// Do not publish the first time this message is encountered and publish - /// at the specified `publish_interval` thereafter - pub fn skip_first_throttle(publish_interval: Duration) -> Self { - Self { - occurs: LoggingOccurrence::SkipFirst, - publish_interval, - log_if_true: true, - } - } - - /// Throttle the message to the supplied publish_interval - /// e.g. set `publish_interval` to 1000ms to limit publishing to once a second - pub fn throttle(publish_interval: Duration) -> Self { - Self { - occurs: LoggingOccurrence::Always, - publish_interval, - log_if_true: true, - } - } +mod logger; +pub use logger::*; - /// Permitting logging if the supplied expression evaluates to true - /// Uses default LoggingOccurrence (Always) and publish_interval (no throttling) - pub fn log_if_true(log_if_true: bool) -> Self { - Self { - occurs: LoggingOccurrence::Always, - publish_interval: Duration::ZERO, - log_if_true, - } - } -} - -/// log_with_conditions -/// Helper macro to log a message using the ROS2 RCUTILS library -/// -/// The macro supports two general calling formats: -/// 1. Plain message string e.g. as per println! macro -/// 2. With calling conditions that provide some restrictions on the output of the message -/// (see [`LogConditions`] above) -/// -/// It is expected that, typically, the macro will be called using one of the wrapper macros, -/// e.g. log_debug!, etc, however, it is relatively straight forward to call the macro directly -/// if you really want to. +/// log a message to rosout /// /// # Examples /// /// ``` -/// use rclrs::{log_debug, log_error, log_fatal, log_info, log_warn, LogConditions, LoggingOccurrence}; +/// use rclrs::{log, ToLogParams}; /// use std::sync::Mutex; /// use std::time::Duration; /// use std::env; /// /// let context = rclrs::Context::new(env::args()).unwrap(); -/// let node = rclrs::Node::new(&context, "log_example_node").unwrap(); +/// let node = rclrs::Node::new(&context, "test_node").unwrap(); /// -/// log_debug!(&node.name(), "Simple message"); +/// log!(node.debug(), "Simple debug message"); /// let some_variable = 43; -/// log_debug!(&node.name(), "Simple message {some_variable}"); -/// log_fatal!(&node.name(), "Simple message from {}", node.name()); -/// log_warn!(&node.name(), LogConditions::once(), "Only log this the first time"); -/// log_error!(&node.name(), -/// LogConditions::skip_first_throttle(Duration::from_millis(1000)), -/// "Noisy error that we expect the first time"); +/// log!(node.debug(), "Formatted debug message: {some_variable}"); +/// log!(node.fatal(), "Fatal message from {}", node.name()); +/// log!(node.warn().once(), "Only log this the first time"); +/// log!( +/// node +/// .error() +/// .skip_first() +/// .interval(Duration::from_millis(1000)), +/// "Noisy error that we expect the first time" +/// ); /// /// let count = 0; -/// log_info!(&node.name(), LogConditions { occurs: LoggingOccurrence::Always, -/// publish_interval: Duration::from_millis(1000), -/// log_if_true: count % 10 == 0, }, -/// "Manually constructed LogConditions"); +/// log!( +/// node +/// .info() +/// .interval(Duration::from_millis(1000)) +/// .only_if(count % 10 == 0), +/// "Manually constructed LogConditions", +/// ); /// ``` /// +/// All of the above examples will also work with the severity-specific log macros, +/// but any severity that gets passed in will be overridden: +/// - [`log_debug`][crate::log_debug] +/// - [`log_info`][crate::log_info] +/// - [`log_warn`][crate::log_warn] +/// - [`log_error`][crate::log_error] +/// - [`log_fatal`][crate::log_fatal] +/// /// # Panics /// /// It is theoretically possible for the call to panic if the Mutex used for the throttling is -/// poisoned although this should not be possible. +/// poisoned although this should never happen. #[macro_export] -macro_rules! log_with_conditions { +macro_rules! log { // The variable args captured by the $(, $($args:tt)*)?)) code allows us to omit (or include) - // parameters in the simple message case, e.g. to write + // formatting parameters in the simple message case, e.g. to write // ``` // log_error!(, "Log with no params"); // OR // log_error!(, "Log with useful info {}", error_reason); - ($severity: expr, $logger_name: expr, $msg_start: literal $(, $($args:tt)*)?) => { - $crate::log(&std::fmt::format(format_args!($msg_start, $($($args)*)?)), $logger_name, file!(), line!(), $severity); - }; - ($severity: expr, $logger_name: expr, $conditions: expr, $($args:tt)*) => { + ($to_log_params: expr, $($args:tt)*) => {{ // Adding these use statements here due an issue like this one: // https://github.com/intellij-rust/intellij-rust/issues/9853 // Note: that issue appears to be specific to jetbrains intellisense however, // observed same/similar behaviour with rust-analyzer/rustc - use std::sync::Once; + use std::sync::{Once, OnceLock, Mutex}; use std::time::SystemTime; - let log_conditions: $crate::LogConditions = $conditions; - let mut allow_logging = true; - match log_conditions.occurs { - // Create the static variables here so we get a per-instance static - $crate::LoggingOccurrence::Once => { - static LOG_ONCE: std::sync::Once = std::sync::Once::new(); - LOG_ONCE.call_once(|| { - $crate::log(&std::fmt::format(format_args!($($args)*)), $logger_name, file!(), line!(), $severity); - }); - allow_logging = false; - } - $crate::LoggingOccurrence::SkipFirst => { - // Noop, just make sure we exit the first time... - static SKIP_FIRST: std::sync::Once = std::sync::Once::new(); - SKIP_FIRST.call_once(|| { - // Only disable logging the first time - allow_logging = false; - }); + // We wrap the functional body of the macro inside of a closure which + // we immediately trigger. This allows us to use `return` to exit the + // macro early without causing the calling function to also try to + // return early. + (|| { + let params = $crate::ToLogParams::to_log_params($to_log_params); + if !params.get_user_filter() { + // The user filter is telling us not to log this time, so exit + // before doing anything else. + return; } - // Drop out - $crate::LoggingOccurrence::Always => (), - } - // If we have a throttle period AND logging has not already been disabled due to SkipFirst settings - if log_conditions.publish_interval > std::time::Duration::ZERO && allow_logging { - let mut ignore_first_timeout = false; - // Need to initialise to a constant - static LAST_LOG_TIME: Mutex = Mutex::new(std::time::SystemTime::UNIX_EPOCH); - - static INIT_LAST_LOG_TIME: std::sync::Once = std::sync::Once::new(); - // Set the last log time to "now", but let us log the message the first time we hit this - // code, i.e. initial behaviour is expired. - // Note: If this is part of a SkipFirst macro call, we will only hit this code on the second iteration. - INIT_LAST_LOG_TIME.call_once(|| { - let mut last_log_time = LAST_LOG_TIME.lock().unwrap(); - *last_log_time = std::time::SystemTime::now(); - ignore_first_timeout = true; - }); - - let mut last_log_time = LAST_LOG_TIME.lock().unwrap(); - if std::time::SystemTime::now() >= *last_log_time + log_conditions.publish_interval { - // Update our time stamp - *last_log_time = std::time::SystemTime::now(); + let mut first_time = false; + static REMEMBER_FIRST_TIME: Once = Once::new(); + REMEMBER_FIRST_TIME.call_once(|| first_time = true); + + let logger_name = params.get_logger_name(); + let severity = params.get_severity(); + + match params.get_occurence() { + // Create the static variables here so we get a per-instance static + $crate::LogOccurrence::Once => { + if first_time { + $crate::log_unconditional!(severity, logger_name, $($args)*); + } + // Since we've already logged once, we should never log again, + // so just exit right now. + return; + } + $crate::LogOccurrence::SkipFirst => { + if first_time { + // This is the first time that we're seeing this log, and we + // were told to skip the first one, so just exit right away. + return; + } + } + // Do nothing + $crate::LogOccurrence::All => (), } - else if !ignore_first_timeout { - // Timer has not expired (and this is not the first time through here) - allow_logging = false; + + // If we have a throttle interval then check if we're inside or outside + // of that interval. + let interval = params.get_interval(); + if interval > std::time::Duration::ZERO { + static LAST_LOG_TIME: OnceLock> = OnceLock::new(); + let last_log_time = LAST_LOG_TIME.get_or_init(|| { + Mutex::new(std::time::SystemTime::now()) + }); + + if !first_time { + let now = std::time::SystemTime::now(); + let mut previous = last_log_time.lock().unwrap(); + if now >= *previous + interval { + *previous = now; + } else { + // We are still inside the throttle interval, so just exit + // here. + return; + } + } } - } - // At this point we've validated the skip/throttle operations, and we now check that any - // expression supplied also evaluates to true, e.g. if timer has expired but expression is - // false, we won't print - if (allow_logging && log_conditions.log_if_true) - { - $crate::log(&std::fmt::format(format_args!($($args)*)), $logger_name, file!(), line!(), $severity); - } - }; + // All filters have been checked, so go ahead and publish the message + $crate::log_unconditional!(severity, logger_name, $($args)*); + })(); + }}; } -/// Debug log message. +/// Debug log message. See [`log`] for usage. #[macro_export] macro_rules! log_debug { - ($logger_name: expr, $($args:tt)*) => {{ - $crate::log_with_conditions!($crate::LogSeverity::Debug, $logger_name, $($args)*); + ($to_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::ToLogParams::to_log_params($to_log_params); + $crate::log!(log_params.debug(), $($args)*); }} } -/// Info log message. +/// Info log message. See [`log`] for usage. #[macro_export] macro_rules! log_info { - ($logger_name: expr, $($args:tt)*) => {{ - $crate::log_with_conditions!($crate::LogSeverity::Info, $logger_name, $($args)*); + ($to_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::ToLogParams::to_log_params($to_log_params); + $crate::log!(log_params.info(), $($args)*); }} } -/// Warning log message. +/// Warning log message. See [`log`] for usage. #[macro_export] macro_rules! log_warn { - ($logger_name: expr, $($args:tt)*) => {{ - $crate::log_with_conditions!($crate::LogSeverity::Warn, $logger_name, $($args)*); + ($to_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::ToLogParams::to_log_params($to_log_params); + $crate::log!(log_params.warn(), $($args)*); }} } -/// Error log message. +/// Error log message. See [`log`] for usage. #[macro_export] macro_rules! log_error { - ($logger_name: expr, $($args:tt)*) => {{ - $crate::log_with_conditions!($crate::LogSeverity::Error, $logger_name, $($args)*); + ($to_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::ToLogParams::to_log_params($to_log_params); + $crate::log!(log_params.error(), $($args)*); }} } -/// Fatal log message. +/// Fatal log message. See [`log`] for usage. #[macro_export] macro_rules! log_fatal { - ($logger_name: expr, $($args:tt)*) => {{ - $crate::log_with_conditions!($crate::LogSeverity::Fatal, $logger_name, $($args)*); + ($to_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::ToLogParams::to_log_params($to_log_params); + $crate::log!(log_params.fatal(), $($args)*); }} } + +/// A logging mechanism that does not have any conditions: It will definitely +/// publish the log. This is only meant for internal use, but needs to be exported +/// in order for [`log`] to work. +#[doc(hidden)] +#[macro_export] +macro_rules! log_unconditional { + ($severity: expr, $logger_name: expr, $($args:tt)*) => {{ + use std::{ffi::CString, sync::OnceLock}; + + // Only allocate a CString for the function name once per call to this macro. + static FUNCTION_NAME: OnceLock = OnceLock::new(); + let function_name = FUNCTION_NAME.get_or_init(|| { + CString::new($crate::function!()).unwrap_or( + CString::new("").unwrap() + ) + }); + + // Only allocate a CString for the file name once per call to this macro. + static FILE_NAME: OnceLock = OnceLock::new(); + let file_name = FILE_NAME.get_or_init(|| { + CString::new(file!()).unwrap_or( + CString::new("").unwrap() + ) + }); + + // We have to allocate a CString for the message every time because the + // formatted data may have changed. We could consider having an alternative + // macro for string literals that only allocates once, but it not obvious + // how to guarantee that the user only passes in an unchanging string literal. + match CString::new(std::fmt::format(format_args!($($args)*))) { + Ok(message) => { + // SAFETY: impl_log is actually completely safe to call, we just + // mark it as unsafe to discourage downstream users from calling it + unsafe { $crate::impl_log($severity, $logger_name, &message, &function_name, &file_name, line!()) }; + } + Err(err) => { + let message = CString::new(format!( + "Unable to format log message into a valid c-string. Error: {}", err + )).unwrap(); + + // SAFETY: impl_log is actually completely safe to call, we just + // mark it as unsafe to discourage downstream users from calling it + unsafe { + $crate::impl_log( + $crate::LogSeverity::Error, + &$crate::LoggerName::Unvalidated("logger"), + &message, + &function_name, + &file_name, + line!(), + ); + } + } + } + }} +} + +/// Calls the underlying rclutils logging function +/// Don't call this directly, use the logging macros instead, i.e. [`log`]. +/// +/// SAFETY: This function is not actually unsafe, but it is not meant to be part of the public +/// API, so we mark it as unsafe to discourage users from trying to use it. They should use +/// one of the of log! macros instead. We can't make it private because it needs to be used +/// by exported macros. +#[doc(hidden)] +pub unsafe fn impl_log( + severity: LogSeverity, + logger_name: &LoggerName, + message: &CString, + function: &CString, + file: &CString, + line: u32, +) { + // We use a closure here because there are several different points in this + // function where we may need to run this same logic. + let send_log = |severity: LogSeverity, logger_name: &CString, message: &CString| { + let location = rcutils_log_location_t { + function_name: function.as_ptr(), + file_name: file.as_ptr(), + line_number: line as usize, + }; + static FORMAT_CSTR: OnceLock = OnceLock::new(); + let format_cstr = FORMAT_CSTR.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(), + ); + } + }; + + match logger_name { + LoggerName::Validated(c_name) => { + // The logger name is pre-validated, so just go ahead and use it. + send_log(severity, c_name, message); + } + LoggerName::Unvalidated(str_name) => { + // The name was not validated before being passed in. + // + // We maintain a hashmap of previously validated loggers so + // we don't need to reallocate the CString on every log instance. + // This is done inside of the function impl_log instead of in a macro + // so that this map is global for the entire application. + static NAME_MAP: OnceLock>> = OnceLock::new(); + let name_map = NAME_MAP.get_or_init(Default::default); + + { + // We need to keep name_map locked while we call send_log, but + // we also need to make sure it gets unlocked right afterward + // if the condition fails, otherwise this function would + // deadlock on itself when handling the error case of the logger + // name being invalid. So we keep name_map_guard in this extra + // scope to isolate its lifespan. + let name_map_guard = name_map.lock().unwrap(); + if let Some(c_name) = name_map_guard.get(*str_name) { + // The map name has been used before, so we just use the + // pre-existing CString + send_log(severity, c_name, message); + + // We return right away because the remainder of this + // function just allocates and validates a new CString for + // the logger name. + return; + } + } + + // The unvalidated logger name has not been used before, so we need + // to convert it and add it to the name_map now. + let c_name = match CString::new(str_name.to_string()) { + Ok(c_name) => c_name, + Err(_) => { + static INVALID_MSG: OnceLock = OnceLock::new(); + let invalid_msg = INVALID_MSG.get_or_init(|| { + CString::new( + "Failed to convert logger name into a c-string. \ + Check for null terminators inside the string.", + ) + .unwrap() + }); + static INTERNAL_LOGGER_NAME: OnceLock = OnceLock::new(); + let internal_logger_name = + INTERNAL_LOGGER_NAME.get_or_init(|| CString::new("logger").unwrap()); + send_log(severity, internal_logger_name, invalid_msg); + return; + } + }; + + send_log(severity, &c_name, message); + name_map + .lock() + .unwrap() + .insert(str_name.to_string(), c_name); + } + } +} + +/// Used internally by logging macros to get the name of the function that called the +/// logging macro. This is not meant for public use, but we need to export it so the +/// other exported macros can use it. We should remove it if an official function! macro +/// is ever offered. +#[macro_export] +#[doc(hidden)] +macro_rules! function { + () => {{ + fn f() {} + fn type_name_of(_: T) -> &'static str { + std::any::type_name::() + } + let name = type_name_of(f); + name.strip_suffix("::f").unwrap() + }}; +} + +#[cfg(test)] +mod tests { + use crate::{test_helpers::*, *}; + + #[test] + fn test_logging_macros() -> Result<(), RclrsError> { + let graph = construct_test_graph("test_logging_macros")?; + let node = graph.node1; + + log!(&*node, "Logging with node dereference"); + + for _ in 0..10 { + log!(node.once(), "Logging once"); + } + + log!(node.logger(), "Logging with node logger"); + log!(node.debug(), "Debug from node"); + log!(node.info(), "Info from node"); + log!(node.warn(), "Warn from node"); + log!(node.error(), "Error from node"); + log!(node.fatal(), "Fatal from node"); + + log_debug!(node.logger(), "log_debug macro"); + log_info!(node.logger(), "log_info macro"); + log_warn!(node.logger(), "log_warn macro"); + log_error!(node.logger(), "log_error macro"); + log_fatal!(node.logger(), "log_fatal macro"); + + log!(node.only_if(false), "This should not be logged",); + log!(node.only_if(true), "This should be logged",); + + for i in 0..3 { + log!(node.warn().skip_first(), "Formatted warning #{}", i); + } + + node.logger().set_level(LogSeverity::Debug).unwrap(); + log_debug!(node.logger(), "This debug message appears"); + node.logger().set_level(LogSeverity::Info).unwrap(); + log_debug!(node.logger(), "This debug message does not"); + + log!("custom logger name", "message for custom logger"); + for _ in 0..3 { + log!( + "custom logger name".once(), + "one-time message for custom logger" + ); + } + + for _ in 0..3 { + log!( + "custom logger name".error().skip_first(), + "error for custom logger", + ); + } + + Ok(()) + } + + #[test] + fn test_function_macro() { + assert_eq!(function!(), "rclrs::logging::tests::test_function_macro"); + } +} diff --git a/rclrs/src/logging/log_params.rs b/rclrs/src/logging/log_params.rs new file mode 100644 index 000000000..d8cbc8995 --- /dev/null +++ b/rclrs/src/logging/log_params.rs @@ -0,0 +1,246 @@ +use crate::rcl_bindings::RCUTILS_LOG_SEVERITY; +use std::{borrow::Borrow, ffi::CString, time::Duration}; + +/// These parameters determine the behavior of an instance of logging. +#[derive(Debug, Clone, Copy)] +pub struct LogParams<'a> { + /// The name of the logger + logger_name: LoggerName<'a>, + /// The severity of the logging instance. + severity: LogSeverity, + /// Specify when a log message should be published (See[`LoggingOccurrence`] above) + occurs: LogOccurrence, + /// Specify the publication interval of the message. A value of ZERO (0) indicates that the + /// message should be published every time, otherwise, the message will only be published once + /// the specified interval has elapsed. + /// This field is typically used to limit the output from high-frequency messages, e.g. instead + /// of publishing a log message every 10 milliseconds, the `publish_interval` can be configured + /// such that the message is published every 10 seconds. + interval: Duration, + /// The log message will only published if the specified expression evaluates to true + only_if: bool, +} + +impl<'a> LogParams<'a> { + /// Create a set of default log parameters, given the name of a logger + pub fn new(logger_name: LoggerName<'a>) -> Self { + Self { + logger_name, + severity: Default::default(), + occurs: Default::default(), + interval: Duration::new(0, 0), + only_if: true, + } + } + + /// Get the logger name + pub fn get_logger_name(&self) -> &LoggerName { + &self.logger_name + } + + /// Get the severity of the log + pub fn get_severity(&self) -> LogSeverity { + self.severity + } + + /// Get the occurrence + pub fn get_occurence(&self) -> LogOccurrence { + self.occurs + } + + /// Get the interval + pub fn get_interval(&self) -> Duration { + self.interval + } + + /// Get the arbitrary filter set by the user + pub fn get_user_filter(&self) -> bool { + self.only_if + } +} + +/// Methods for defining the behavior of a logging instance. +/// +/// This trait is implemented by Logger, Node, and anything that a `&str` can be +/// [borrowed][1] from, such as string literals (`"my_str"`), [`String`], or +/// [`Cow`][2]. +/// +/// [1]: Borrow +/// [2]: std::borrow::Cow +pub trait ToLogParams<'a>: Sized { + /// Convert the object into LogParams with default settings + fn to_log_params(self) -> LogParams<'a>; + + /// The logging should only happen once + fn once(self) -> LogParams<'a> { + self.occurs(LogOccurrence::Once) + } + + /// The first time the logging happens, we should skip it + fn skip_first(self) -> LogParams<'a> { + self.occurs(LogOccurrence::SkipFirst) + } + + /// Set the occurrence behavior of the log instance + fn occurs(self, occurs: LogOccurrence) -> LogParams<'a> { + let mut params = self.to_log_params(); + params.occurs = occurs; + params + } + + /// Set an interval during which this log will not publish. A value of zero + /// will never block the message from being published, and this is the + /// default behavior. + /// + /// A negative duration is not valid, but will be treated as a zero duration. + fn interval(self, interval: Duration) -> LogParams<'a> { + let mut params = self.to_log_params(); + params.interval = interval; + params + } + + /// The log will not be published if a `false` expression is passed into + /// this function. + /// + /// Other factors may prevent the log from being published if a `true` is + /// passed in, such as `ToLogParams::interval` or `ToLogParams::once` + /// filtering the log. + fn only_if(self, only_if: bool) -> LogParams<'a> { + let mut params = self.to_log_params(); + params.only_if = only_if; + params + } + + /// Log as a debug message. + fn debug(self) -> LogParams<'a> { + self.severity(LogSeverity::Debug) + } + + /// Log as an informative message. This is the default, so you don't + /// generally need to use this. + fn info(self) -> LogParams<'a> { + self.severity(LogSeverity::Info) + } + + /// Log as a warning message. + fn warn(self) -> LogParams<'a> { + self.severity(LogSeverity::Warn) + } + + /// Log as an error message. + fn error(self) -> LogParams<'a> { + self.severity(LogSeverity::Error) + } + + /// Log as a fatal message. + fn fatal(self) -> LogParams<'a> { + self.severity(LogSeverity::Fatal) + } + + /// Set the severity for this instance of logging. The default value will be + /// [`LogSeverity::Info`]. + fn severity(self, severity: LogSeverity) -> LogParams<'a> { + let mut params = self.to_log_params(); + params.severity = severity; + params + } +} + +/// This is used to borrow a logger name which might be validated (e.g. came +/// from a [`Logger`][1] struct) or not (e.g. a user-defined `&str`). If an +/// unvalidated logger name is used with one of the logging macros, we will log +/// an error about it, and the original log message will be logged with the +/// default logger. +/// +/// [1]: crate::Logger +#[derive(Debug, Clone, Copy)] +pub enum LoggerName<'a> { + /// The logger name is already available as a valid CString + Validated(&'a CString), + /// The logger name has not been validated yet + Unvalidated(&'a str), +} + +/// Logging severity. +#[doc(hidden)] +#[derive(Debug, Clone, Copy)] +pub enum LogSeverity { + /// Use the severity level of the parent logger (or the root logger if the + /// current logger has no parent) + Unset, + /// For messages that are not needed outside of debugging. + Debug, + /// For messages that provide useful information about the state of the + /// application. + Info, + /// For messages that indicate something unusual or unintended might have happened. + Warn, + /// For messages that indicate an error has occurred which may cause the application + /// to misbehave. + Error, + /// For messages that indicate an error has occurred which is so severe that the + /// application should terminate because it cannot recover. + /// + /// Using this severity level will not automatically cause the application to + /// terminate, the application developer must decide how to do that on a + /// case-by-case basis. + Fatal, +} + +impl LogSeverity { + pub(super) fn as_native(&self) -> RCUTILS_LOG_SEVERITY { + use crate::rcl_bindings::rcl_log_severity_t::*; + match self { + LogSeverity::Unset => RCUTILS_LOG_SEVERITY_UNSET, + LogSeverity::Debug => RCUTILS_LOG_SEVERITY_DEBUG, + LogSeverity::Info => RCUTILS_LOG_SEVERITY_INFO, + LogSeverity::Warn => RCUTILS_LOG_SEVERITY_WARN, + LogSeverity::Error => RCUTILS_LOG_SEVERITY_ERROR, + LogSeverity::Fatal => RCUTILS_LOG_SEVERITY_FATAL, + } + } +} + +impl Default for LogSeverity { + fn default() -> Self { + Self::Info + } +} + +/// Specify when a log message should be published +#[derive(Debug, Clone, Copy)] +pub enum LogOccurrence { + /// Every message will be published if all other conditions are met + All, + /// The message will only be published on the first occurrence (Note: no other conditions apply) + Once, + /// The log message will not be published on the first occurrence, but will be published on + /// each subsequent occurrence (assuming all other conditions are met) + SkipFirst, +} + +impl Default for LogOccurrence { + fn default() -> Self { + Self::All + } +} + +// Anything that we can borrow a string from can be used as if it's a logger and +// turned into LogParams +impl<'a, T: Borrow> ToLogParams<'a> for &'a T { + fn to_log_params(self) -> LogParams<'a> { + LogParams::new(LoggerName::Unvalidated(self.borrow())) + } +} + +impl<'a> ToLogParams<'a> for &'a str { + fn to_log_params(self) -> LogParams<'a> { + LogParams::new(LoggerName::Unvalidated(self)) + } +} + +impl<'a> ToLogParams<'a> for LogParams<'a> { + fn to_log_params(self) -> LogParams<'a> { + self + } +} diff --git a/rclrs/src/logging/logger.rs b/rclrs/src/logging/logger.rs new file mode 100644 index 000000000..2d55f2d7a --- /dev/null +++ b/rclrs/src/logging/logger.rs @@ -0,0 +1,101 @@ +use std::{borrow::Borrow, ffi::CString}; + +use crate::{ + rcl_bindings::{rcutils_logging_set_default_logger_level, rcutils_logging_set_logger_level}, + LogParams, LogSeverity, LoggerName, RclrsError, ToLogParams, ToResult, ENTITY_LIFECYCLE_MUTEX, +}; + +/// Logger can be passed in as the first argument into one of the [logging][1] +/// macros provided by rclrs. When passing it into one of the logging macros, +/// you can optionally apply any of the methods from [`ToLogParams`] to tweak +/// the logging behavior. +/// +/// You can obtain a Logger in the following ways: +/// - Calling [`Node::logger`][2] to get the logger of a Node +/// - Using [`Logger::create_child`] to create a child logger for an existing logger +/// - Using [`Logger::new`] to create a new logger with any name that you'd like +/// - Using [`Logger::default()`] to access the global default logger +/// +/// Note that if you are passing the Logger of a Node into one of the logging macros, +/// then you can choose to simply pass in `&node` instead of `node.logger()`. +/// +/// [1]: crate::log +/// [2]: crate::Node::logger +pub struct Logger { + name: Box, + c_name: CString, +} + +impl Logger { + /// Create a new logger with the given name. + pub fn new(name: impl Borrow) -> Result { + let name: Box = name.borrow().into(); + let c_name = match CString::new(name.clone().into_string()) { + Ok(c_name) => c_name, + Err(err) => { + return Err(RclrsError::StringContainsNul { + s: name.into_string(), + err, + }); + } + }; + + Ok(Self { name, c_name }) + } + + /// Create a new logger which will be a child of this logger. + /// + /// If the name of this logger is `parent_name`, then the name for the new + /// child will be '"parent_name.child_name"`. + /// + /// If this is the default logger (whose name is an empty string), then the + /// name for the new child will simply be the value in `child_name`. + pub fn create_child(&self, child_name: impl Borrow) -> Result { + if self.name.is_empty() { + Self::new(child_name) + } else { + Self::new(format!("{}.{}", &self.name, child_name.borrow())) + } + } + + /// Get the name of this logger + pub fn name(&self) -> &str { + &self.name + } + + /// Set the severity level of this logger + pub fn set_level(&self, severity: LogSeverity) -> Result<(), RclrsError> { + // SAFETY: The precondition are: + // - we are passing in a valid CString, which is already taken care of during construction of the Logger + // - the severity level is a valid value, which is guaranteed by the rigid enum definition + // - not thread-safe, so we lock the global mutex before calling this + let _lifecycle = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); + unsafe { + rcutils_logging_set_logger_level(self.c_name.as_ptr(), severity.as_native() as i32).ok() + } + } + + /// Set the severity level of the default logger which acts as the root ancestor + /// of all other loggers. + pub fn set_default_level(severity: LogSeverity) { + // SAFETY: The preconditions are: + // - the severity level is a valid value, which is guaranteed by the rigid enum definition + // - not thread-safe, so we lock the global mutex before calling this + let _lifecycle = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); + unsafe { + rcutils_logging_set_default_logger_level(severity.as_native() as i32); + } + } +} + +impl<'a> ToLogParams<'a> for &'a Logger { + fn to_log_params(self) -> LogParams<'a> { + LogParams::new(LoggerName::Validated(&self.c_name)) + } +} + +impl Default for Logger { + fn default() -> Self { + Self::new("").unwrap() + } +} diff --git a/rclrs/src/logging/logging_configuration.rs b/rclrs/src/logging/logging_configuration.rs index 21f13987a..2f7014273 100644 --- a/rclrs/src/logging/logging_configuration.rs +++ b/rclrs/src/logging/logging_configuration.rs @@ -1,4 +1,4 @@ -use std::sync::{Arc, LazyLock, Mutex, Weak}; +use std::sync::{Arc, Mutex, OnceLock, Weak}; use crate::{ rcl_bindings::{ @@ -32,12 +32,12 @@ impl LoggingLifecycle { pub(crate) unsafe fn configure( context: &rcl_context_t, ) -> Result, RclrsError> { - static CONFIGURATION: LazyLock = - LazyLock::new(|| LoggingConfiguration { - lifecycle: Mutex::new(Weak::new()), - }); + static CONFIGURATION: OnceLock = OnceLock::new(); + let configuration = CONFIGURATION.get_or_init(|| LoggingConfiguration { + lifecycle: Mutex::new(Weak::new()), + }); - let mut lifecycle = CONFIGURATION.lifecycle.lock().unwrap(); + let mut lifecycle = configuration.lifecycle.lock().unwrap(); if let Some(arc_lifecycle) = lifecycle.upgrade() { return Ok(arc_lifecycle); } diff --git a/rclrs/src/node.rs b/rclrs/src/node.rs index 394c5f740..5afa1fe03 100644 --- a/rclrs/src/node.rs +++ b/rclrs/src/node.rs @@ -13,10 +13,10 @@ use rosidl_runtime_rs::Message; pub use self::{builder::*, graph::*}; use crate::{ - rcl_bindings::*, Client, ClientBase, Clock, Context, ContextHandle, GuardCondition, - ParameterBuilder, ParameterInterface, ParameterVariant, Parameters, Publisher, QoSProfile, - RclrsError, Service, ServiceBase, Subscription, SubscriptionBase, SubscriptionCallback, - TimeSource, ENTITY_LIFECYCLE_MUTEX, + rcl_bindings::*, Client, ClientBase, Clock, Context, ContextHandle, GuardCondition, LogParams, + Logger, ParameterBuilder, ParameterInterface, ParameterVariant, Parameters, Publisher, + QoSProfile, RclrsError, Service, ServiceBase, Subscription, SubscriptionBase, + SubscriptionCallback, TimeSource, ToLogParams, ENTITY_LIFECYCLE_MUTEX, }; // SAFETY: The functions accessing this type, including drop(), shouldn't care about the thread @@ -66,6 +66,7 @@ pub struct Node { time_source: TimeSource, parameter: ParameterInterface, pub(crate) handle: Arc, + logger: Logger, } /// This struct manages the lifetime of an `rcl_node_t`, and accounts for its @@ -465,19 +466,15 @@ impl Node { NodeBuilder::new(context, node_name) } - /// Returns the logger name of the node. - pub fn logger_name(&self) -> &str { - let rcl_node = self.handle.rcl_node.lock().unwrap(); - // SAFETY: No pre-conditions for this function - let name_raw_ptr = unsafe { rcl_node_get_logger_name(&*rcl_node) }; - if name_raw_ptr.is_null() { - return ""; - } - // SAFETY: The returned CStr is immediately converted to a string slice, - // so the lifetime is no issue. The ptr is valid as per the documentation - // of rcl_node_get_logger_name. - let name_cstr = unsafe { CStr::from_ptr(name_raw_ptr) }; - name_cstr.to_str().unwrap_or("") + /// Get the logger associated with this Node. + pub fn logger(&self) -> &Logger { + &self.logger + } +} + +impl<'a> ToLogParams<'a> for &'a Node { + fn to_log_params(self) -> LogParams<'a> { + self.logger().to_log_params() } } @@ -560,11 +557,11 @@ mod tests { let graph = construct_test_graph("test_logger_name")?; assert_eq!( - graph.node1.logger_name(), + graph.node1.logger().name(), "test_logger_name.graph_test_node_1" ); assert_eq!( - graph.node2.logger_name(), + graph.node2.logger().name(), "test_logger_name.graph_test_node_2" ); diff --git a/rclrs/src/node/builder.rs b/rclrs/src/node/builder.rs index f8df82101..1e7a9fc63 100644 --- a/rclrs/src/node/builder.rs +++ b/rclrs/src/node/builder.rs @@ -1,11 +1,12 @@ use std::{ - ffi::CString, + ffi::{CStr, CString}, sync::{atomic::AtomicBool, Arc, Mutex}, }; use crate::{ - rcl_bindings::*, ClockType, Context, ContextHandle, Node, NodeHandle, ParameterInterface, - QoSProfile, RclrsError, TimeSource, ToResult, ENTITY_LIFECYCLE_MUTEX, QOS_PROFILE_CLOCK, + rcl_bindings::*, ClockType, Context, ContextHandle, Logger, Node, NodeHandle, + ParameterInterface, QoSProfile, RclrsError, TimeSource, ToResult, ENTITY_LIFECYCLE_MUTEX, + QOS_PROFILE_CLOCK, }; /// A builder for creating a [`Node`][1]. @@ -313,6 +314,26 @@ impl NodeBuilder { &rcl_context.global_arguments, )? }; + + let logger_name = { + let rcl_node = handle.rcl_node.lock().unwrap(); + let logger_name_raw_ptr = unsafe { rcl_node_get_logger_name(&*rcl_node) }; + if logger_name_raw_ptr.is_null() { + "" + } else { + // SAFETY: rcl_node_get_logger_name will either return a nullptr + // if the provided node was invalid or provide a valid null-terminated + // const char* if the provided node was valid. We have already + // verified that it is not a nullptr. We are also preventing the + // pointed-to value from being modified while we view it by locking + // the mutex of rcl_node while we view it. This means all the + // safety conditions of CStr::from_ptr are met. + unsafe { CStr::from_ptr(logger_name_raw_ptr) } + .to_str() + .unwrap_or("") + } + }; + let node = Arc::new(Node { handle, clients_mtx: Mutex::new(vec![]), @@ -323,7 +344,9 @@ impl NodeBuilder { .clock_qos(self.clock_qos) .build(), parameter, + logger: Logger::new(logger_name)?, }); + node.time_source.attach_node(&node); if self.start_parameter_services { node.parameter.create_services(&node)?; diff --git a/rclrs/src/node/graph.rs b/rclrs/src/node/graph.rs index 6f9e6d866..639a38e38 100644 --- a/rclrs/src/node/graph.rs +++ b/rclrs/src/node/graph.rs @@ -487,16 +487,29 @@ mod tests { .unwrap(); let node_name = "test_publisher_names_and_types"; let node = Node::new(&context, node_name).unwrap(); - // Test that the graph has no publishers besides /rosout + + let check_rosout = |topics: HashMap>| { + // rosout shows up in humble and iron, even if the graph is empty + #[cfg(any(ros_distro = "humble", ros_distro = "iron"))] + { + assert_eq!(topics.len(), 1); + assert_eq!( + topics.get("/rosout").unwrap().first().unwrap(), + "rcl_interfaces/msg/Log" + ); + } + + // rosout does not automatically show up in jazzy when the graph is empty + #[cfg(any(ros_distro = "jazzy", ros_distro = "rolling"))] + { + assert_eq!(topics.len(), 0); + } + }; + let names_and_topics = node .get_publisher_names_and_types_by_node(node_name, "") .unwrap(); - - assert_eq!(names_and_topics.len(), 1); - assert_eq!( - names_and_topics.get("/rosout").unwrap().first().unwrap(), - "rcl_interfaces/msg/Log" - ); + check_rosout(names_and_topics); let num_publishers = node.count_publishers("/test").unwrap(); @@ -539,14 +552,8 @@ mod tests { assert_eq!(names_and_topics.len(), 0); - // Test that the graph has no topics besides /rosout let names_and_topics = node.get_topic_names_and_types().unwrap(); - - assert_eq!(names_and_topics.len(), 1); - assert_eq!( - names_and_topics.get("/rosout").unwrap().first().unwrap(), - "rcl_interfaces/msg/Log" - ); + check_rosout(names_and_topics); } #[test] diff --git a/rclrs/src/subscription.rs b/rclrs/src/subscription.rs index 05b01beb5..36c241d19 100644 --- a/rclrs/src/subscription.rs +++ b/rclrs/src/subscription.rs @@ -381,7 +381,7 @@ mod tests { // Test get_subscriptions_info_by_topic() let expected_subscriptions_info = vec![TopicEndpointInfo { - node_name: format!("graph_test_node_2"), + node_name: String::from("graph_test_node_2"), node_namespace: String::from(namespace), topic_type: String::from("test_msgs/msg/Empty"), }];