From 7b512490365eaaf28aa35a4efaaf4ae386a58bcb Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Mon, 4 Nov 2024 02:37:02 +0800 Subject: [PATCH 01/16] Introduce Logger and LogParams Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 610 ++++++++++++++++++-------------- rclrs/src/logging/log_params.rs | 240 +++++++++++++ rclrs/src/logging/logger.rs | 108 ++++++ rclrs/src/node.rs | 29 +- rclrs/src/node/builder.rs | 18 +- 5 files changed, 717 insertions(+), 288 deletions(-) create mode 100644 rclrs/src/logging/log_params.rs create mode 100644 rclrs/src/logging/logger.rs diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index e4f789c4d..5a08e189d 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -3,198 +3,25 @@ // 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, sync::Mutex, time::Duration}; +use std::{ffi::CString, sync::{LazyLock, Mutex}, collections::HashMap}; -use crate::rcl_bindings::*; +use crate::{ + rcl_bindings::*, + ENTITY_LIFECYCLE_MUTEX, +}; -// Used to protect calls to rcl/rcutils in case those functions manipulate global variables -static LOG_GUARD: Mutex<()> = Mutex::new(()); +mod log_params; +pub use log_params::*; -/// 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 _guard = LOG_GUARD.lock().unwrap(); - // SAFETY: Global variables are protected via LOG_GUARD, 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, -} +mod logger; +pub use logger::*; -/// 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, - } - } - - /// 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, - } - } - - /// 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, AsLogParams}; /// use std::sync::Mutex; /// use std::time::Duration; /// use std::env; @@ -202,141 +29,382 @@ impl LogConditions { /// let context = rclrs::Context::new(env::args()).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`] +/// - [`log_info`] +/// - [`log_warn`] +/// - [`log_error`] +/// - [`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)*) => { + ($as_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, LazyLock, 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::AsLogParams::as_log_params($as_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: LazyLock> = LazyLock::new(|| { + 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)*); + ($as_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::AsLogParams::as_log_params($as_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)*); + ($as_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::AsLogParams::as_log_params($as_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)*); + ($as_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::AsLogParams::as_log_params($as_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)*); + ($as_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::AsLogParams::as_log_params($as_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)*); + ($as_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::AsLogParams::as_log_params($as_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::LazyLock}; + + // Only allocate a CString for the function name once per call to this macro. + let function: LazyLock = LazyLock::new(|| { + CString::new($crate::function!()).unwrap_or( + CString::new("").unwrap() + ) + }); + + // Only allocate a CString for the file name once per call to this macro. + let file: LazyLock = LazyLock::new(|| { + 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, &file, line!()) }; + } + Err(err) => { + let message = CString::new(format!( + "Unable to format log message into a valid c-string. Error: {}", err + )).unwrap(); + + unsafe { + $crate::impl_log( + $crate::LogSeverity::Error, + &$crate::LoggerName::Unvalidated("logger"), + &message, + &function, + &file, + 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, function: &CString, file: &CString, line: u32| { + let location = rcutils_log_location_t { + function_name: function.as_ptr(), + file_name: file.as_ptr(), + line_number: line as usize, + }; + let format: LazyLock = LazyLock::new(|| { + CString::new("%s").unwrap() + }); + + 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(), + ); + } + }; + + 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, function, file, line); + } + 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. + let name_map: LazyLock>> = LazyLock::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, function, file, line); + + // 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(_) => { + let invalid_msg: LazyLock = LazyLock::new(|| { + CString::new( + "Failed to convert logger name into a c-string. \ + Check for null terminators inside the string." + ).unwrap() + }); + let internal_logger_name: LazyLock = LazyLock::new(|| { + CString::new("logger").unwrap() + }); + send_log(severity, &internal_logger_name, &invalid_msg, function, file, line); + return; + } + }; + + 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"); + + Ok(()) + } +} diff --git a/rclrs/src/logging/log_params.rs b/rclrs/src/logging/log_params.rs new file mode 100644 index 000000000..08bf19b5f --- /dev/null +++ b/rclrs/src/logging/log_params.rs @@ -0,0 +1,240 @@ +use std::{time::Duration, borrow::Borrow, ffi::CString}; +use crate::rcl_bindings::RCUTILS_LOG_SEVERITY; + +/// 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 AsLogParams<'a>: Sized { + /// Convert the object into LogParams with default settings + fn as_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.as_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.as_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 `AsLogParams::interval` or `AsLogParams::once` + /// filtering the log. + fn only_if(self, only_if: bool) -> LogParams<'a> { + let mut params = self.as_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.as_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 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, + } + } +} + +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> AsLogParams<'a> for &'a T { + fn as_log_params(self) -> LogParams<'a> { + LogParams::new(LoggerName::Unvalidated(self.borrow())) + } +} + +impl<'a> AsLogParams<'a> for LogParams<'a> { + fn as_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..25f231948 --- /dev/null +++ b/rclrs/src/logging/logger.rs @@ -0,0 +1,108 @@ +use std::{ + ffi::CString, + borrow::Borrow, +}; + +use crate::{ + RclrsError, AsLogParams, LogParams, LoggerName, LogSeverity, ToResult, + ENTITY_LIFECYCLE_MUTEX, + rcl_bindings::{ + rcutils_logging_set_logger_level, + rcutils_logging_set_default_logger_level, + } +}; + +/// 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 [`AsLogParams`] 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.to_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.to_native() as i32); + } + } +} + +impl<'a> AsLogParams<'a> for &'a Logger { + fn as_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/node.rs b/rclrs/src/node.rs index 0d141721c..9cac45b27 100644 --- a/rclrs/src/node.rs +++ b/rclrs/src/node.rs @@ -16,7 +16,7 @@ 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, + TimeSource, ENTITY_LIFECYCLE_MUTEX, Logger, AsLogParams, LogParams, }; // 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 @@ -447,19 +448,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> AsLogParams<'a> for &'a Node { + fn as_log_params(self) -> LogParams<'a> { + self.logger().as_log_params() } } @@ -542,11 +539,11 @@ mod tests { let graph = construct_test_graph("test_topics_graph")?; assert_eq!( - graph.node1.logger_name(), + graph.node1.logger().name(), "test_topics_graph.graph_test_node_1" ); assert_eq!( - graph.node2.logger_name(), + graph.node2.logger().name(), "test_topics_graph.graph_test_node_2" ); diff --git a/rclrs/src/node/builder.rs b/rclrs/src/node/builder.rs index 14d4dae27..01e96d2f0 100644 --- a/rclrs/src/node/builder.rs +++ b/rclrs/src/node/builder.rs @@ -1,11 +1,12 @@ use std::{ - ffi::CString, + ffi::{CString, CStr}, sync::{Arc, Mutex}, }; use crate::{ rcl_bindings::*, ClockType, Context, ContextHandle, Node, NodeHandle, ParameterInterface, QoSProfile, RclrsError, TimeSource, ToResult, ENTITY_LIFECYCLE_MUTEX, QOS_PROFILE_CLOCK, + Logger, }; /// A builder for creating a [`Node`][1]. @@ -308,6 +309,19 @@ 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 { + unsafe { CStr::from_ptr(logger_name_raw_ptr) } + .to_str() + .unwrap_or("") + } + }; + let node = Arc::new(Node { handle, clients_mtx: Mutex::new(vec![]), @@ -318,7 +332,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)?; From d89121be7615a44a9024dc0991e37acb7b8e2e51 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Mon, 4 Nov 2024 02:45:10 +0800 Subject: [PATCH 02/16] Add test for arbitrary string logger name Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index 5a08e189d..9e39a65f0 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -256,7 +256,7 @@ macro_rules! log_unconditional { 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, function: &CString, file: &CString, line: u32| { + 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(), @@ -284,7 +284,7 @@ pub unsafe fn impl_log(severity: LogSeverity, logger_name: &LoggerName, message: 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, function, file, line); + send_log(severity, c_name, message); } LoggerName::Unvalidated(str_name) => { // The name was not validated before being passed in. @@ -306,7 +306,7 @@ pub unsafe fn impl_log(severity: LogSeverity, logger_name: &LoggerName, message: 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, function, file, line); + send_log(severity, c_name, message); // We return right away because the remainder of this // function just allocates and validates a new CString for @@ -329,11 +329,12 @@ pub unsafe fn impl_log(severity: LogSeverity, logger_name: &LoggerName, message: let internal_logger_name: LazyLock = LazyLock::new(|| { CString::new("logger").unwrap() }); - send_log(severity, &internal_logger_name, &invalid_msg, function, file, line); + 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); } } @@ -405,6 +406,8 @@ mod tests { node.logger().set_level(LogSeverity::Info).unwrap(); log_debug!(node.logger(), "This debug message does not"); + log!(&"custom logger name", "message for custom logger"); + Ok(()) } } From 69b43f04ed51e8ca662e18476be87a4380852724 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Mon, 4 Nov 2024 23:32:33 +0800 Subject: [PATCH 03/16] Fix merge Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 3 +++ rclrs/src/node/builder.rs | 2 +- 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index 9e39a65f0..1e25a35cc 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -10,6 +10,9 @@ use crate::{ ENTITY_LIFECYCLE_MUTEX, }; +mod logging_configuration; +pub(crate) use logging_configuration::*; + mod log_params; pub use log_params::*; diff --git a/rclrs/src/node/builder.rs b/rclrs/src/node/builder.rs index 933c9f926..0a67211e9 100644 --- a/rclrs/src/node/builder.rs +++ b/rclrs/src/node/builder.rs @@ -317,7 +317,7 @@ impl NodeBuilder { let logger_name = { let rcl_node = handle.rcl_node.lock().unwrap(); - let logger_name_raw_ptr = unsafe { rcl_node_get_logger_name(&**rcl_node) }; + let logger_name_raw_ptr = unsafe { rcl_node_get_logger_name(&*rcl_node) }; if logger_name_raw_ptr.is_null() { "" } else { From 27f5bc85eb37380772b56c5a487dddf0d73517a1 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Mon, 4 Nov 2024 23:40:25 +0800 Subject: [PATCH 04/16] Add safety comment Signed-off-by: Michael X. Grey --- rclrs/src/node/builder.rs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/rclrs/src/node/builder.rs b/rclrs/src/node/builder.rs index 0a67211e9..f19ffb544 100644 --- a/rclrs/src/node/builder.rs +++ b/rclrs/src/node/builder.rs @@ -321,6 +321,13 @@ impl NodeBuilder { 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("") From 57f879e243f1599054421fbfcc0e64cd5f761d43 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Mon, 4 Nov 2024 23:42:56 +0800 Subject: [PATCH 05/16] Fix formatting Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 58 ++++++++++++++++----------------- rclrs/src/logging/log_params.rs | 2 +- rclrs/src/logging/logger.rs | 23 +++++-------- rclrs/src/node.rs | 8 ++--- rclrs/src/node/builder.rs | 12 +++---- 5 files changed, 48 insertions(+), 55 deletions(-) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index 1e25a35cc..a89e7439e 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -3,13 +3,14 @@ // 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, sync::{LazyLock, Mutex}, collections::HashMap}; - -use crate::{ - rcl_bindings::*, - ENTITY_LIFECYCLE_MUTEX, +use std::{ + collections::HashMap, + ffi::CString, + sync::{LazyLock, Mutex}, }; +use crate::{rcl_bindings::*, ENTITY_LIFECYCLE_MUTEX}; + mod logging_configuration; pub(crate) use logging_configuration::*; @@ -256,7 +257,14 @@ macro_rules! log_unconditional { /// 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) { +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| { @@ -265,9 +273,7 @@ pub unsafe fn impl_log(severity: LogSeverity, logger_name: &LoggerName, message: file_name: file.as_ptr(), line_number: line as usize, }; - let format: LazyLock = LazyLock::new(|| { - CString::new("%s").unwrap() - }); + let format: LazyLock = LazyLock::new(|| CString::new("%s").unwrap()); let severity = severity.to_native(); @@ -326,19 +332,22 @@ pub unsafe fn impl_log(severity: LogSeverity, logger_name: &LoggerName, message: let invalid_msg: LazyLock = LazyLock::new(|| { CString::new( "Failed to convert logger name into a c-string. \ - Check for null terminators inside the string." - ).unwrap() - }); - let internal_logger_name: LazyLock = LazyLock::new(|| { - CString::new("logger").unwrap() + Check for null terminators inside the string.", + ) + .unwrap() }); + let internal_logger_name: LazyLock = + LazyLock::new(|| 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); + name_map + .lock() + .unwrap() + .insert(str_name.to_string(), c_name); } } } @@ -357,12 +366,12 @@ macro_rules! function { } let name = type_name_of(f); name.strip_suffix("::f").unwrap() - }} + }}; } #[cfg(test)] mod tests { - use crate::{*, test_helpers::*}; + use crate::{test_helpers::*, *}; #[test] fn test_logging_macros() -> Result<(), RclrsError> { @@ -388,20 +397,11 @@ mod tests { 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", - ); + 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 - ); + log!(node.warn().skip_first(), "Formatted warning #{}", i); } node.logger().set_level(LogSeverity::Debug).unwrap(); diff --git a/rclrs/src/logging/log_params.rs b/rclrs/src/logging/log_params.rs index 08bf19b5f..8f1d4215e 100644 --- a/rclrs/src/logging/log_params.rs +++ b/rclrs/src/logging/log_params.rs @@ -1,5 +1,5 @@ -use std::{time::Duration, borrow::Borrow, ffi::CString}; 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)] diff --git a/rclrs/src/logging/logger.rs b/rclrs/src/logging/logger.rs index 25f231948..10bcce3fd 100644 --- a/rclrs/src/logging/logger.rs +++ b/rclrs/src/logging/logger.rs @@ -1,15 +1,8 @@ -use std::{ - ffi::CString, - borrow::Borrow, -}; +use std::{borrow::Borrow, ffi::CString}; use crate::{ - RclrsError, AsLogParams, LogParams, LoggerName, LogSeverity, ToResult, - ENTITY_LIFECYCLE_MUTEX, - rcl_bindings::{ - rcutils_logging_set_logger_level, - rcutils_logging_set_default_logger_level, - } + rcl_bindings::{rcutils_logging_set_default_logger_level, rcutils_logging_set_logger_level}, + AsLogParams, LogParams, LogSeverity, LoggerName, RclrsError, ToResult, ENTITY_LIFECYCLE_MUTEX, }; /// Logger can be passed in as the first argument into one of the [logging][1] @@ -40,7 +33,10 @@ impl Logger { 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 }); + return Err(RclrsError::StringContainsNul { + s: name.into_string(), + err, + }); } }; @@ -75,10 +71,7 @@ impl Logger { // - 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.to_native() as i32, - ).ok() + rcutils_logging_set_logger_level(self.c_name.as_ptr(), severity.to_native() as i32).ok() } } diff --git a/rclrs/src/node.rs b/rclrs/src/node.rs index 74a8a267d..89e6d4bd0 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, Logger, AsLogParams, LogParams, + rcl_bindings::*, AsLogParams, Client, ClientBase, Clock, Context, ContextHandle, + GuardCondition, LogParams, Logger, ParameterBuilder, ParameterInterface, ParameterVariant, + Parameters, Publisher, QoSProfile, RclrsError, Service, ServiceBase, Subscription, + SubscriptionBase, SubscriptionCallback, TimeSource, ENTITY_LIFECYCLE_MUTEX, }; // SAFETY: The functions accessing this type, including drop(), shouldn't care about the thread diff --git a/rclrs/src/node/builder.rs b/rclrs/src/node/builder.rs index f19ffb544..1e7a9fc63 100644 --- a/rclrs/src/node/builder.rs +++ b/rclrs/src/node/builder.rs @@ -1,12 +1,12 @@ use std::{ - ffi::{CString, CStr}, + 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, - Logger, + 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]. @@ -329,8 +329,8 @@ impl NodeBuilder { // 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("") + .to_str() + .unwrap_or("") } }; From ef0d0a0429f6a47f938649d3d4507a58aa556198 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Tue, 5 Nov 2024 00:12:40 +0800 Subject: [PATCH 06/16] Allow &str to implement AsLogParams instead of &&str Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 12 +++++++++++- rclrs/src/logging/log_params.rs | 6 ++++++ 2 files changed, 17 insertions(+), 1 deletion(-) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index a89e7439e..4bd685f55 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -409,7 +409,17 @@ mod tests { node.logger().set_level(LogSeverity::Info).unwrap(); log_debug!(node.logger(), "This debug message does not"); - log!(&"custom logger name", "message for custom logger"); + 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(()) } diff --git a/rclrs/src/logging/log_params.rs b/rclrs/src/logging/log_params.rs index 8f1d4215e..d3e0af2a8 100644 --- a/rclrs/src/logging/log_params.rs +++ b/rclrs/src/logging/log_params.rs @@ -233,6 +233,12 @@ impl<'a, T: Borrow> AsLogParams<'a> for &'a T { } } +impl<'a> AsLogParams<'a> for &'a str { + fn as_log_params(self) -> LogParams<'a> { + LogParams::new(LoggerName::Unvalidated(self)) + } +} + impl<'a> AsLogParams<'a> for LogParams<'a> { fn as_log_params(self) -> LogParams<'a> { self From 8451518d083330d1c965a3112ed18cc1e407edb2 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Tue, 5 Nov 2024 00:21:39 +0800 Subject: [PATCH 07/16] Add safety comment Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index 4bd685f55..a01586bad 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -234,6 +234,8 @@ macro_rules! log_unconditional { "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, From 2d169855eeedb8c39fd8041d1c3c75bd5829eba8 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Tue, 5 Nov 2024 00:26:46 +0800 Subject: [PATCH 08/16] Add test for function!() macro Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index a01586bad..b724f5548 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -425,4 +425,9 @@ mod tests { Ok(()) } + + #[test] + fn test_function_macro() { + assert_eq!(function!(), "rclrs::logging::tests::test_function_macro"); + } } From d27b4079e88e4044da57b2427d3b1aede881c50d Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Tue, 5 Nov 2024 13:30:47 +0800 Subject: [PATCH 09/16] Replace all uses of LazyLock with OnceLock to be compatible with 1.75 Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 40 +++++++++++++--------- rclrs/src/logging/logging_configuration.rs | 12 +++---- 2 files changed, 30 insertions(+), 22 deletions(-) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index b724f5548..f9d231a06 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -6,7 +6,7 @@ use std::{ collections::HashMap, ffi::CString, - sync::{LazyLock, Mutex}, + sync::{OnceLock, Mutex}, }; use crate::{rcl_bindings::*, ENTITY_LIFECYCLE_MUTEX}; @@ -80,7 +80,7 @@ macro_rules! log { // 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, LazyLock, Mutex}; + use std::sync::{Once, OnceLock, Mutex}; use std::time::SystemTime; // We wrap the functional body of the macro inside of a closure which @@ -128,13 +128,14 @@ macro_rules! log { // of that interval. let interval = params.get_interval(); if interval > std::time::Duration::ZERO { - static LAST_LOG_TIME: LazyLock> = LazyLock::new(|| { + 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(); + let mut previous = last_log_time.lock().unwrap(); if now >= *previous + interval { *previous = now; } else { @@ -203,17 +204,19 @@ macro_rules! log_fatal { #[macro_export] macro_rules! log_unconditional { ($severity: expr, $logger_name: expr, $($args:tt)*) => {{ - use std::{ffi::CString, sync::LazyLock}; + use std::{ffi::CString, sync::OnceLock}; // Only allocate a CString for the function name once per call to this macro. - let function: LazyLock = LazyLock::new(|| { + 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. - let file: LazyLock = LazyLock::new(|| { + static FILE_NAME: OnceLock = OnceLock::new(); + let file_name = FILE_NAME.get_or_init(|| { CString::new(file!()).unwrap_or( CString::new("").unwrap() ) @@ -227,7 +230,7 @@ macro_rules! log_unconditional { 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, &file, line!()) }; + unsafe { $crate::impl_log($severity, $logger_name, &message, &function_name, &file_name, line!()) }; } Err(err) => { let message = CString::new(format!( @@ -241,8 +244,8 @@ macro_rules! log_unconditional { $crate::LogSeverity::Error, &$crate::LoggerName::Unvalidated("logger"), &message, - &function, - &file, + &function_name, + &file_name, line!(), ); } @@ -275,7 +278,8 @@ pub unsafe fn impl_log( file_name: file.as_ptr(), line_number: line as usize, }; - let format: LazyLock = LazyLock::new(|| CString::new("%s").unwrap()); + static FORMAT_CSTR: OnceLock = OnceLock::new(); + let format_cstr = FORMAT_CSTR.get_or_init(|| CString::new("%s").unwrap()); let severity = severity.to_native(); @@ -286,7 +290,7 @@ pub unsafe fn impl_log( &location, severity as i32, logger_name.as_ptr(), - format.as_ptr(), + format_cstr.as_ptr(), message.as_ptr(), ); } @@ -304,7 +308,8 @@ pub unsafe fn impl_log( // 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. - let name_map: LazyLock>> = LazyLock::default(); + 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 @@ -331,15 +336,18 @@ pub unsafe fn impl_log( let c_name = match CString::new(str_name.to_string()) { Ok(c_name) => c_name, Err(_) => { - let invalid_msg: LazyLock = LazyLock::new(|| { + 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() }); - let internal_logger_name: LazyLock = - LazyLock::new(|| CString::new("logger").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; } diff --git a/rclrs/src/logging/logging_configuration.rs b/rclrs/src/logging/logging_configuration.rs index 21f13987a..84519ac56 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, OnceLock, Mutex, 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); } From 188a33103210a4e76cc76bd3cb992f90353fffa6 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Tue, 5 Nov 2024 18:13:41 +0800 Subject: [PATCH 10/16] Fix formatting Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 12 +++++++----- rclrs/src/logging/logging_configuration.rs | 2 +- 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index f9d231a06..43096841b 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -6,7 +6,7 @@ use std::{ collections::HashMap, ffi::CString, - sync::{OnceLock, Mutex}, + sync::{Mutex, OnceLock}, }; use crate::{rcl_bindings::*, ENTITY_LIFECYCLE_MUTEX}; @@ -345,9 +345,8 @@ pub unsafe fn impl_log( .unwrap() }); static INTERNAL_LOGGER_NAME: OnceLock = OnceLock::new(); - let internal_logger_name = INTERNAL_LOGGER_NAME.get_or_init( - || CString::new("logger").unwrap() - ); + let internal_logger_name = + INTERNAL_LOGGER_NAME.get_or_init(|| CString::new("logger").unwrap()); send_log(severity, &internal_logger_name, &invalid_msg); return; } @@ -421,7 +420,10 @@ mod tests { log!("custom logger name", "message for custom logger"); for _ in 0..3 { - log!("custom logger name".once(), "one-time message for custom logger"); + log!( + "custom logger name".once(), + "one-time message for custom logger" + ); } for _ in 0..3 { diff --git a/rclrs/src/logging/logging_configuration.rs b/rclrs/src/logging/logging_configuration.rs index 84519ac56..2f7014273 100644 --- a/rclrs/src/logging/logging_configuration.rs +++ b/rclrs/src/logging/logging_configuration.rs @@ -1,4 +1,4 @@ -use std::sync::{Arc, OnceLock, Mutex, Weak}; +use std::sync::{Arc, Mutex, OnceLock, Weak}; use crate::{ rcl_bindings::{ From ec91f3dec1cb676d06ff87fb9647f33b4f17040e Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Tue, 5 Nov 2024 19:55:31 +0800 Subject: [PATCH 11/16] Comply with Rust naming conventions Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 28 ++++++++++++++-------------- rclrs/src/logging/log_params.rs | 28 ++++++++++++++-------------- rclrs/src/logging/logger.rs | 12 ++++++------ rclrs/src/node.rs | 8 ++++---- 4 files changed, 38 insertions(+), 38 deletions(-) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index 43096841b..4cda8c6e3 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -25,7 +25,7 @@ pub use logger::*; /// # Examples /// /// ``` -/// use rclrs::{log, AsLogParams}; +/// use rclrs::{log, ToLogParams}; /// use std::sync::Mutex; /// use std::time::Duration; /// use std::env; @@ -75,7 +75,7 @@ macro_rules! log { // ``` // log_error!(, "Log with no params"); // OR // log_error!(, "Log with useful info {}", error_reason); - ($as_log_params: 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, @@ -88,7 +88,7 @@ macro_rules! log { // macro early without causing the calling function to also try to // return early. (|| { - let params = $crate::AsLogParams::as_log_params($as_log_params); + 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 @@ -155,8 +155,8 @@ macro_rules! log { /// Debug log message. See [`log`] for usage. #[macro_export] macro_rules! log_debug { - ($as_log_params: expr, $($args:tt)*) => {{ - let log_params = $crate::AsLogParams::as_log_params($as_log_params); + ($to_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::ToLogParams::to_log_params($to_log_params); $crate::log!(log_params.debug(), $($args)*); }} } @@ -164,8 +164,8 @@ macro_rules! log_debug { /// Info log message. See [`log`] for usage. #[macro_export] macro_rules! log_info { - ($as_log_params: expr, $($args:tt)*) => {{ - let log_params = $crate::AsLogParams::as_log_params($as_log_params); + ($to_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::ToLogParams::to_log_params($to_log_params); $crate::log!(log_params.info(), $($args)*); }} } @@ -173,8 +173,8 @@ macro_rules! log_info { /// Warning log message. See [`log`] for usage. #[macro_export] macro_rules! log_warn { - ($as_log_params: expr, $($args:tt)*) => {{ - let log_params = $crate::AsLogParams::as_log_params($as_log_params); + ($to_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::ToLogParams::to_log_params($to_log_params); $crate::log!(log_params.warn(), $($args)*); }} } @@ -182,8 +182,8 @@ macro_rules! log_warn { /// Error log message. See [`log`] for usage. #[macro_export] macro_rules! log_error { - ($as_log_params: expr, $($args:tt)*) => {{ - let log_params = $crate::AsLogParams::as_log_params($as_log_params); + ($to_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::ToLogParams::to_log_params($to_log_params); $crate::log!(log_params.error(), $($args)*); }} } @@ -191,8 +191,8 @@ macro_rules! log_error { /// Fatal log message. See [`log`] for usage. #[macro_export] macro_rules! log_fatal { - ($as_log_params: expr, $($args:tt)*) => {{ - let log_params = $crate::AsLogParams::as_log_params($as_log_params); + ($to_log_params: expr, $($args:tt)*) => {{ + let log_params = $crate::ToLogParams::to_log_params($to_log_params); $crate::log!(log_params.fatal(), $($args)*); }} } @@ -281,7 +281,7 @@ pub unsafe fn impl_log( static FORMAT_CSTR: OnceLock = OnceLock::new(); let format_cstr = FORMAT_CSTR.get_or_init(|| CString::new("%s").unwrap()); - let severity = severity.to_native(); + 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 diff --git a/rclrs/src/logging/log_params.rs b/rclrs/src/logging/log_params.rs index d3e0af2a8..d8cbc8995 100644 --- a/rclrs/src/logging/log_params.rs +++ b/rclrs/src/logging/log_params.rs @@ -67,9 +67,9 @@ impl<'a> LogParams<'a> { /// /// [1]: Borrow /// [2]: std::borrow::Cow -pub trait AsLogParams<'a>: Sized { +pub trait ToLogParams<'a>: Sized { /// Convert the object into LogParams with default settings - fn as_log_params(self) -> LogParams<'a>; + fn to_log_params(self) -> LogParams<'a>; /// The logging should only happen once fn once(self) -> LogParams<'a> { @@ -83,7 +83,7 @@ pub trait AsLogParams<'a>: Sized { /// Set the occurrence behavior of the log instance fn occurs(self, occurs: LogOccurrence) -> LogParams<'a> { - let mut params = self.as_log_params(); + let mut params = self.to_log_params(); params.occurs = occurs; params } @@ -94,7 +94,7 @@ pub trait AsLogParams<'a>: Sized { /// /// 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.as_log_params(); + let mut params = self.to_log_params(); params.interval = interval; params } @@ -103,10 +103,10 @@ pub trait AsLogParams<'a>: Sized { /// this function. /// /// Other factors may prevent the log from being published if a `true` is - /// passed in, such as `AsLogParams::interval` or `AsLogParams::once` + /// 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.as_log_params(); + let mut params = self.to_log_params(); params.only_if = only_if; params } @@ -140,7 +140,7 @@ pub trait AsLogParams<'a>: Sized { /// 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.as_log_params(); + let mut params = self.to_log_params(); params.severity = severity; params } @@ -188,7 +188,7 @@ pub enum LogSeverity { } impl LogSeverity { - pub(super) fn to_native(&self) -> RCUTILS_LOG_SEVERITY { + 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, @@ -227,20 +227,20 @@ impl Default for LogOccurrence { // 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> AsLogParams<'a> for &'a T { - fn as_log_params(self) -> LogParams<'a> { +impl<'a, T: Borrow> ToLogParams<'a> for &'a T { + fn to_log_params(self) -> LogParams<'a> { LogParams::new(LoggerName::Unvalidated(self.borrow())) } } -impl<'a> AsLogParams<'a> for &'a str { - fn as_log_params(self) -> LogParams<'a> { +impl<'a> ToLogParams<'a> for &'a str { + fn to_log_params(self) -> LogParams<'a> { LogParams::new(LoggerName::Unvalidated(self)) } } -impl<'a> AsLogParams<'a> for LogParams<'a> { - fn as_log_params(self) -> LogParams<'a> { +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 index 10bcce3fd..64f917c81 100644 --- a/rclrs/src/logging/logger.rs +++ b/rclrs/src/logging/logger.rs @@ -2,12 +2,12 @@ use std::{borrow::Borrow, ffi::CString}; use crate::{ rcl_bindings::{rcutils_logging_set_default_logger_level, rcutils_logging_set_logger_level}, - AsLogParams, LogParams, LogSeverity, LoggerName, RclrsError, ToResult, ENTITY_LIFECYCLE_MUTEX, + ToLogParams, LogParams, LogSeverity, LoggerName, RclrsError, 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 [`AsLogParams`] to tweak +/// you can optionally apply any of the methods from [`ToLogParams`] to tweak /// the logging behavior. /// /// You can obtain a Logger in the following ways: @@ -71,7 +71,7 @@ impl Logger { // - 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.to_native() as i32).ok() + rcutils_logging_set_logger_level(self.c_name.as_ptr(), severity.as_native() as i32).ok() } } @@ -83,13 +83,13 @@ impl Logger { // - 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.to_native() as i32); + rcutils_logging_set_default_logger_level(severity.as_native() as i32); } } } -impl<'a> AsLogParams<'a> for &'a Logger { - fn as_log_params(self) -> LogParams<'a> { +impl<'a> ToLogParams<'a> for &'a Logger { + fn to_log_params(self) -> LogParams<'a> { LogParams::new(LoggerName::Validated(&self.c_name)) } } diff --git a/rclrs/src/node.rs b/rclrs/src/node.rs index 89e6d4bd0..5d50b114c 100644 --- a/rclrs/src/node.rs +++ b/rclrs/src/node.rs @@ -13,7 +13,7 @@ use rosidl_runtime_rs::Message; pub use self::{builder::*, graph::*}; use crate::{ - rcl_bindings::*, AsLogParams, Client, ClientBase, Clock, Context, ContextHandle, + rcl_bindings::*, ToLogParams, Client, ClientBase, Clock, Context, ContextHandle, GuardCondition, LogParams, Logger, ParameterBuilder, ParameterInterface, ParameterVariant, Parameters, Publisher, QoSProfile, RclrsError, Service, ServiceBase, Subscription, SubscriptionBase, SubscriptionCallback, TimeSource, ENTITY_LIFECYCLE_MUTEX, @@ -472,9 +472,9 @@ impl Node { } } -impl<'a> AsLogParams<'a> for &'a Node { - fn as_log_params(self) -> LogParams<'a> { - self.logger().as_log_params() +impl<'a> ToLogParams<'a> for &'a Node { + fn to_log_params(self) -> LogParams<'a> { + self.logger().to_log_params() } } From 474e4d2d85edbfc8837c838f1ce01ff881b8529d Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Tue, 5 Nov 2024 19:59:36 +0800 Subject: [PATCH 12/16] Comply with clippy suggestions Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 4 ++-- rclrs/src/subscription.rs | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index 4cda8c6e3..ede331d7d 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -309,7 +309,7 @@ pub unsafe fn impl_log( // 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()); + let name_map = NAME_MAP.get_or_init(Default::default); { // We need to keep name_map locked while we call send_log, but @@ -347,7 +347,7 @@ pub unsafe fn impl_log( 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); + send_log(severity, internal_logger_name, invalid_msg); return; } }; 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"), }]; From 0416551d237ec624631f1c498129f174d6392959 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Tue, 5 Nov 2024 20:21:36 +0800 Subject: [PATCH 13/16] Fix formatting with ToLogParams Signed-off-by: Michael X. Grey --- rclrs/src/logging/logger.rs | 2 +- rclrs/src/node.rs | 8 ++++---- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/rclrs/src/logging/logger.rs b/rclrs/src/logging/logger.rs index 64f917c81..2d55f2d7a 100644 --- a/rclrs/src/logging/logger.rs +++ b/rclrs/src/logging/logger.rs @@ -2,7 +2,7 @@ use std::{borrow::Borrow, ffi::CString}; use crate::{ rcl_bindings::{rcutils_logging_set_default_logger_level, rcutils_logging_set_logger_level}, - ToLogParams, LogParams, LogSeverity, LoggerName, RclrsError, ToResult, ENTITY_LIFECYCLE_MUTEX, + LogParams, LogSeverity, LoggerName, RclrsError, ToLogParams, ToResult, ENTITY_LIFECYCLE_MUTEX, }; /// Logger can be passed in as the first argument into one of the [logging][1] diff --git a/rclrs/src/node.rs b/rclrs/src/node.rs index 5d50b114c..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::*, ToLogParams, Client, ClientBase, Clock, Context, ContextHandle, - GuardCondition, LogParams, Logger, 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 From 3934c3262a45709b15aa8306a8cb8f21bb46f498 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Tue, 5 Nov 2024 22:41:46 +0800 Subject: [PATCH 14/16] Try to help cargo docs resolve macro links Signed-off-by: Michael X. Grey --- rclrs/src/logging.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index ede331d7d..d008e5d66 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -58,11 +58,11 @@ pub use logger::*; /// /// 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`] -/// - [`log_info`] -/// - [`log_warn`] -/// - [`log_error`] -/// - [`log_fatal`] +/// - [`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 /// From a9f5b3f4816589dc270ed96e9c476e7836f548c0 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Tue, 5 Nov 2024 23:50:44 +0800 Subject: [PATCH 15/16] Fork expectations based on distro version Signed-off-by: Michael X. Grey --- rclrs/build.rs | 1 + rclrs/src/node/graph.rs | 35 +++++++++++++++++++++-------------- 2 files changed, 22 insertions(+), 14 deletions(-) diff --git a/rclrs/build.rs b/rclrs/build.rs index 3ac6dc414..0d5f84a87 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\"))"); println!("cargo:rustc-cfg=ros_distro=\"{ros_distro}\""); let mut builder = bindgen::Builder::default() diff --git a/rclrs/src/node/graph.rs b/rclrs/src/node/graph.rs index 6f9e6d866..0f8a9b3fa 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(ros_distro = "jazzy")] + { + 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] From 049a829965f0428ed0cfb5f489735e29e7ada0d1 Mon Sep 17 00:00:00 2001 From: "Michael X. Grey" Date: Wed, 6 Nov 2024 00:32:26 +0800 Subject: [PATCH 16/16] Account for rolling distro Signed-off-by: Michael X. Grey --- rclrs/build.rs | 2 +- rclrs/src/node/graph.rs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/rclrs/build.rs b/rclrs/build.rs index 0d5f84a87..91d0b190f 100644 --- a/rclrs/build.rs +++ b/rclrs/build.rs @@ -35,7 +35,7 @@ fn main() { } }; - println!("cargo:rustc-check-cfg=cfg(ros_distro, values(\"humble\", \"iron\", \"jazzy\"))"); + 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/node/graph.rs b/rclrs/src/node/graph.rs index 0f8a9b3fa..639a38e38 100644 --- a/rclrs/src/node/graph.rs +++ b/rclrs/src/node/graph.rs @@ -500,7 +500,7 @@ mod tests { } // rosout does not automatically show up in jazzy when the graph is empty - #[cfg(ros_distro = "jazzy")] + #[cfg(any(ros_distro = "jazzy", ros_distro = "rolling"))] { assert_eq!(topics.len(), 0); }