From 0dd99c0d95f41be3b5831e0a4ccf0d1b0dad76c6 Mon Sep 17 00:00:00 2001 From: Romain Reignier Date: Fri, 22 May 2026 17:04:40 +0200 Subject: [PATCH] Add support for logging services Fixes #642 Signed-off-by: Romain Reignier Assisted-by: Claude:claude-4.7-opus --- rclrs/src/logging.rs | 5 + rclrs/src/logging/log_params.rs | 89 ++++- rclrs/src/logging/logging_configuration.rs | 2 +- rclrs/src/logging/service.rs | 391 +++++++++++++++++++++ rclrs/src/node.rs | 14 + rclrs/src/node/node_options.rs | 24 ++ 6 files changed, 511 insertions(+), 14 deletions(-) create mode 100644 rclrs/src/logging/service.rs diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index d5cd989c5..e4ba70c90 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -20,6 +20,11 @@ pub use log_params::*; mod logger; pub use logger::*; +#[cfg(not(ros_distro = "humble"))] +mod service; +#[cfg(not(ros_distro = "humble"))] +pub(crate) use service::LoggingService; + /// log a message to rosout /// /// # Examples diff --git a/rclrs/src/logging/log_params.rs b/rclrs/src/logging/log_params.rs index 99eed7cab..ab4fe3a84 100644 --- a/rclrs/src/logging/log_params.rs +++ b/rclrs/src/logging/log_params.rs @@ -218,24 +218,43 @@ impl LogSeverity { LogSeverity::Fatal => RCUTILS_LOG_SEVERITY_FATAL, } } +} + +impl TryFrom for LogSeverity { + type Error = InvalidLogSeverity; - /// This is only used by the log output handler during testing, so it will - /// not be compiled when testing is not configured - #[cfg(test)] - pub(crate) fn from_native(native: i32) -> Self { + fn try_from(value: i32) -> Result { use crate::rcl_bindings::rcl_log_severity_t::*; - match native { - _ if native == RCUTILS_LOG_SEVERITY_UNSET as i32 => LogSeverity::Unset, - _ if native == RCUTILS_LOG_SEVERITY_DEBUG as i32 => LogSeverity::Debug, - _ if native == RCUTILS_LOG_SEVERITY_INFO as i32 => LogSeverity::Info, - _ if native == RCUTILS_LOG_SEVERITY_WARN as i32 => LogSeverity::Warn, - _ if native == RCUTILS_LOG_SEVERITY_ERROR as i32 => LogSeverity::Error, - _ if native == RCUTILS_LOG_SEVERITY_FATAL as i32 => LogSeverity::Fatal, - _ => panic!("Invalid native severity received: {}", native), - } + Ok(match value { + v if v == RCUTILS_LOG_SEVERITY_UNSET as i32 => LogSeverity::Unset, + v if v == RCUTILS_LOG_SEVERITY_DEBUG as i32 => LogSeverity::Debug, + v if v == RCUTILS_LOG_SEVERITY_INFO as i32 => LogSeverity::Info, + v if v == RCUTILS_LOG_SEVERITY_WARN as i32 => LogSeverity::Warn, + v if v == RCUTILS_LOG_SEVERITY_ERROR as i32 => LogSeverity::Error, + v if v == RCUTILS_LOG_SEVERITY_FATAL as i32 => LogSeverity::Fatal, + _ => return Err(InvalidLogSeverity { value }), + }) + } +} + +/// The error returned when an integer value does not correspond to a defined +/// [`LogSeverity`] variant. +#[doc(hidden)] +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub struct InvalidLogSeverity { + /// The offending raw value, as received from rcutils or from a + /// `LoggerLevel` message. + pub value: i32, +} + +impl std::fmt::Display for InvalidLogSeverity { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "Invalid logger severity value {}", self.value) } } +impl std::error::Error for InvalidLogSeverity {} + impl Default for LogSeverity { fn default() -> Self { Self::Info @@ -291,3 +310,47 @@ impl<'a> ToLogParams<'a> for LogParams<'a> { self } } + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn log_severity_try_from_accepts_all_variants() { + assert_eq!(LogSeverity::try_from(0), Ok(LogSeverity::Unset)); + assert_eq!(LogSeverity::try_from(10), Ok(LogSeverity::Debug)); + assert_eq!(LogSeverity::try_from(20), Ok(LogSeverity::Info)); + assert_eq!(LogSeverity::try_from(30), Ok(LogSeverity::Warn)); + assert_eq!(LogSeverity::try_from(40), Ok(LogSeverity::Error)); + assert_eq!(LogSeverity::try_from(50), Ok(LogSeverity::Fatal)); + } + + #[test] + fn log_severity_try_from_rejects_unknown_values() { + assert_eq!( + LogSeverity::try_from(99), + Err(InvalidLogSeverity { value: 99 }) + ); + assert_eq!( + LogSeverity::try_from(-1), + Err(InvalidLogSeverity { value: -1 }) + ); + } + + #[test] + fn log_severity_try_from_round_trips_through_as_native() { + for severity in [ + LogSeverity::Unset, + LogSeverity::Debug, + LogSeverity::Info, + LogSeverity::Warn, + LogSeverity::Error, + LogSeverity::Fatal, + ] { + assert_eq!( + LogSeverity::try_from(severity.as_native() as i32), + Ok(severity) + ); + } + } +} diff --git a/rclrs/src/logging/logging_configuration.rs b/rclrs/src/logging/logging_configuration.rs index 4353f1d30..0b04b1e00 100644 --- a/rclrs/src/logging/logging_configuration.rs +++ b/rclrs/src/logging/logging_configuration.rs @@ -170,7 +170,7 @@ pub(crate) mod log_handler { ), line_number: (*raw_location).line_number, }; - let severity = LogSeverity::from_native(raw_severity); + let severity = LogSeverity::try_from(raw_severity).unwrap(); let logger_name = Cow::Borrowed(CStr::from_ptr(raw_logger_name).to_str().unwrap()); let timestamp: i64 = raw_timestamp; diff --git a/rclrs/src/logging/service.rs b/rclrs/src/logging/service.rs new file mode 100644 index 000000000..11de15421 --- /dev/null +++ b/rclrs/src/logging/service.rs @@ -0,0 +1,391 @@ +#![cfg(not(ros_distro = "humble"))] + +use ros_env::rcl_interfaces::{msg::rmw::*, srv::rmw::*}; + +use crate::{ + error::ToResult, + rcl_bindings::{rcutils_logging_get_logger_level, rcutils_logging_set_logger_level}, + IntoPrimitiveOptions, LogSeverity, Node, QoSProfile, RclrsError, Service, + ENTITY_LIFECYCLE_MUTEX, +}; + +// The variables only exist to keep a strong reference to the services and are technically unused. +pub(crate) struct LoggingService { + #[allow(dead_code)] + get_logger_levels_service: Service, + #[allow(dead_code)] + set_logger_levels_service: Service, +} + +impl LoggingService { + pub(crate) fn new(node: &Node) -> Result { + let fqn = node.fully_qualified_name(); + let get_logger_levels_service = node.create_service( + (fqn.clone() + "/get_logger_levels").qos(QoSProfile::parameter_services_default()), + |req: GetLoggerLevels_Request| get_logger_levels(req), + )?; + let set_logger_levels_service = node.create_service( + (fqn + "/set_logger_levels").qos(QoSProfile::parameter_services_default()), + |req: SetLoggerLevels_Request| set_logger_levels(req), + )?; + Ok(Self { + get_logger_levels_service, + set_logger_levels_service, + }) + } +} + +fn get_logger_levels(req: GetLoggerLevels_Request) -> GetLoggerLevels_Response { + let levels = req + .names + .into_iter() + .map(|name| { + let raw_level = { + let c_name = name.to_cstr(); + let _lifecycle = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); + // SAFETY: The precondition are: + // - we are passing in a valid CString, borrowed from the request String + // - not thread-safe, so we lock the global mutex before calling this + unsafe { rcutils_logging_get_logger_level(c_name.as_ptr()) } + }; + let level = LogSeverity::try_from(raw_level) + .map(|severity| severity.as_native() as u32) + .unwrap_or(u32::from(LoggerLevel::LOG_LEVEL_UNKNOWN)); + LoggerLevel { name, level } + }) + .collect(); + GetLoggerLevels_Response { levels } +} + +fn set_logger_levels(req: SetLoggerLevels_Request) -> SetLoggerLevels_Response { + let results = req + .levels + .into_iter() + .map(|entry| { + let severity = match LogSeverity::try_from(entry.level as i32) { + Ok(severity) => severity, + Err(err) => { + return SetLoggerLevelsResult { + successful: false, + reason: err.to_string().into(), + }; + } + }; + let result = { + let c_name = entry.name.to_cstr(); + let _lifecycle = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); + // SAFETY: The preconditions are: + // - we are passing in a valid CString, borrowed from the request String + // - the severity level is a known LogSeverity variant, checked above + // - not thread-safe, so we lock the global mutex before calling this + unsafe { + rcutils_logging_set_logger_level(c_name.as_ptr(), severity.as_native() as i32) + } + .ok() + }; + match result { + Ok(()) => SetLoggerLevelsResult { + successful: true, + reason: Default::default(), + }, + Err(err) => { + let reason = match &err { + RclrsError::RclError { msg: Some(m), .. } + | RclrsError::UnknownRclError { msg: Some(m), .. } => m.to_string(), + other => other.to_string(), + }; + SetLoggerLevelsResult { + successful: false, + reason: reason.into(), + } + } + } + }) + .collect(); + SetLoggerLevels_Response { results } +} + +#[cfg(test)] +mod tests { + use std::{ + sync::{ + atomic::{AtomicBool, Ordering}, + Arc, + }, + time::Duration, + }; + + use ros_env::rcl_interfaces::{msg::rmw::*, srv::rmw::*}; + use rosidl_runtime_rs::{seq, Sequence}; + + use crate::*; + + /// Builds an executor with a node that advertises the logger services and + /// a client node, both under the given namespace. + fn build_test_pair(ns: &str, enable: bool) -> (Executor, Node, Node) { + let mut options = NodeOptions::new("node").namespace(ns); + if enable { + options = options.enable_logger_service(true); + } + let executor = Context::default().create_basic_executor(); + let server = executor.create_node(options).unwrap(); + let client = executor + .create_node(NodeOptions::new("client").namespace(ns)) + .unwrap(); + (executor, server, client) + } + + #[test] + fn services_round_trip_when_enabled() -> Result<(), RclrsError> { + let (mut executor, _server, client) = build_test_pair("logger_svc_round_trip", true); + let set_client = client + .create_client::("/logger_svc_round_trip/node/set_logger_levels")?; + let get_client = client + .create_client::("/logger_svc_round_trip/node/get_logger_levels")?; + + let set_inner = Arc::clone(&set_client); + let get_inner = Arc::clone(&get_client); + let clients_ready = client + .notify_on_graph_change_with_period(Duration::from_millis(1), move || { + set_inner.service_is_ready().unwrap() && get_inner.service_is_ready().unwrap() + }); + executor + .spin( + SpinOptions::default() + .until_promise_resolved(clients_ready) + .timeout(Duration::from_secs(2)), + ) + .first_error()?; + + // Use a name unique to this test to avoid clashes with other tests + // that mutate the global rcutils logger map. + let logger_name = "rclrs.logger_svc.round_trip"; + + let set_request = SetLoggerLevels_Request { + levels: seq![LoggerLevel { + name: logger_name.into(), + level: u32::from(LoggerLevel::LOG_LEVEL_WARN), + }], + }; + let set_done = Arc::new(AtomicBool::new(false)); + let set_done_inner = Arc::clone(&set_done); + let set_promise = set_client + .call_then(&set_request, move |response: SetLoggerLevels_Response| { + assert_eq!(response.results.len(), 1); + assert!( + response.results[0].successful, + "Set failed: {}", + response.results[0].reason + ); + set_done_inner.store(true, Ordering::Release); + }) + .unwrap(); + executor + .spin( + SpinOptions::default() + .until_promise_resolved(set_promise) + .timeout(Duration::from_secs(2)), + ) + .first_error()?; + assert!(set_done.load(Ordering::Acquire)); + + let get_request = GetLoggerLevels_Request { + names: seq![logger_name.into()], + }; + let get_done = Arc::new(AtomicBool::new(false)); + let get_done_inner = Arc::clone(&get_done); + let get_promise = get_client + .call_then(&get_request, move |response: GetLoggerLevels_Response| { + assert_eq!(response.levels.len(), 1); + assert_eq!(response.levels[0].name.to_string(), logger_name); + assert_eq!( + response.levels[0].level, + u32::from(LoggerLevel::LOG_LEVEL_WARN) + ); + get_done_inner.store(true, Ordering::Release); + }) + .unwrap(); + executor + .spin( + SpinOptions::default() + .until_promise_resolved(get_promise) + .timeout(Duration::from_secs(2)), + ) + .first_error()?; + assert!(get_done.load(Ordering::Acquire)); + + Ok(()) + } + + #[test] + fn unknown_logger_returns_unknown_level() -> Result<(), RclrsError> { + let (mut executor, _server, client) = build_test_pair("logger_svc_unknown", true); + let get_client = client + .create_client::("/logger_svc_unknown/node/get_logger_levels")?; + + let get_inner = Arc::clone(&get_client); + let ready = client + .notify_on_graph_change_with_period(Duration::from_millis(1), move || { + get_inner.service_is_ready().unwrap() + }); + executor + .spin( + SpinOptions::default() + .until_promise_resolved(ready) + .timeout(Duration::from_secs(2)), + ) + .first_error()?; + + let request = GetLoggerLevels_Request { + names: seq!["rclrs.logger_svc.never_set".into()], + }; + let done = Arc::new(AtomicBool::new(false)); + let done_inner = Arc::clone(&done); + let promise = get_client + .call_then(&request, move |response: GetLoggerLevels_Response| { + assert_eq!(response.levels.len(), 1); + assert_eq!( + response.levels[0].level, + u32::from(LoggerLevel::LOG_LEVEL_UNKNOWN) + ); + done_inner.store(true, Ordering::Release); + }) + .unwrap(); + executor + .spin( + SpinOptions::default() + .until_promise_resolved(promise) + .timeout(Duration::from_secs(2)), + ) + .first_error()?; + assert!(done.load(Ordering::Acquire)); + + Ok(()) + } + + #[test] + fn services_absent_by_default() -> Result<(), RclrsError> { + let (mut executor, server, _client) = build_test_pair("logger_svc_absent", false); + + // Give time for discovery; the services should never appear. + executor + .spin(SpinOptions::default().timeout(Duration::from_millis(500))) + .timeout_ok() + .first_error()?; + + let names_and_types = server.get_service_names_and_types().unwrap(); + assert!( + !names_and_types.contains_key("/logger_svc_absent/node/get_logger_levels"), + "get_logger_levels service should not be advertised by default" + ); + assert!( + !names_and_types.contains_key("/logger_svc_absent/node/set_logger_levels"), + "set_logger_levels service should not be advertised by default" + ); + + Ok(()) + } + + #[test] + fn invalid_severity_rejected() -> Result<(), RclrsError> { + let (mut executor, _server, client) = build_test_pair("logger_svc_invalid", true); + let set_client = client + .create_client::("/logger_svc_invalid/node/set_logger_levels")?; + + let set_inner = Arc::clone(&set_client); + let ready = client + .notify_on_graph_change_with_period(Duration::from_millis(1), move || { + set_inner.service_is_ready().unwrap() + }); + executor + .spin( + SpinOptions::default() + .until_promise_resolved(ready) + .timeout(Duration::from_secs(2)), + ) + .first_error()?; + + let request = SetLoggerLevels_Request { + levels: seq![LoggerLevel { + name: "rclrs.logger_svc.invalid".into(), + level: 99, + }], + }; + let done = Arc::new(AtomicBool::new(false)); + let done_inner = Arc::clone(&done); + let promise = set_client + .call_then(&request, move |response: SetLoggerLevels_Response| { + assert_eq!(response.results.len(), 1); + assert!(!response.results[0].successful); + let reason = response.results[0].reason.to_string(); + assert!( + reason.contains("99"), + "Expected reason to mention offending value 99, got: {reason}" + ); + done_inner.store(true, Ordering::Release); + }) + .unwrap(); + executor + .spin( + SpinOptions::default() + .until_promise_resolved(promise) + .timeout(Duration::from_secs(2)), + ) + .first_error()?; + assert!(done.load(Ordering::Acquire)); + + Ok(()) + } + + #[test] + fn unset_severity_accepted() -> Result<(), RclrsError> { + let (mut executor, _server, client) = build_test_pair("logger_svc_unset", true); + let set_client = + client.create_client::("/logger_svc_unset/node/set_logger_levels")?; + + let set_inner = Arc::clone(&set_client); + let ready = client + .notify_on_graph_change_with_period(Duration::from_millis(1), move || { + set_inner.service_is_ready().unwrap() + }); + executor + .spin( + SpinOptions::default() + .until_promise_resolved(ready) + .timeout(Duration::from_secs(2)), + ) + .first_error()?; + + // Level 0 maps to LogSeverity::Unset, which rcutils treats as + // "inherit from parent" — a valid configuration. + let request = SetLoggerLevels_Request { + levels: seq![LoggerLevel { + name: "rclrs.logger_svc.unset".into(), + level: u32::from(LoggerLevel::LOG_LEVEL_UNKNOWN), + }], + }; + let done = Arc::new(AtomicBool::new(false)); + let done_inner = Arc::clone(&done); + let promise = set_client + .call_then(&request, move |response: SetLoggerLevels_Response| { + assert_eq!(response.results.len(), 1); + assert!( + response.results[0].successful, + "Setting level 0 should succeed; got reason: {}", + response.results[0].reason + ); + done_inner.store(true, Ordering::Release); + }) + .unwrap(); + executor + .spin( + SpinOptions::default() + .until_promise_resolved(promise) + .timeout(Duration::from_secs(2)), + ) + .first_error()?; + assert!(done.load(Ordering::Acquire)); + + Ok(()) + } +} diff --git a/rclrs/src/node.rs b/rclrs/src/node.rs index 8fdccad79..f97aca428 100644 --- a/rclrs/src/node.rs +++ b/rclrs/src/node.rs @@ -30,6 +30,8 @@ use async_std::future::timeout; use rosidl_runtime_rs::{Action, Message}; +#[cfg(not(ros_distro = "humble"))] +use crate::LoggingService; use crate::{ dynamic_message::{ DynamicMessage, DynamicPublisher, DynamicPublisherState, DynamicSubscription, @@ -106,6 +108,8 @@ pub struct NodeState { time_source: TimeSource, parameter: ParameterInterface, logger: Logger, + #[cfg(not(ros_distro = "humble"))] + logger_service: Mutex>, commands: Arc, graph_change_action: UnboundedSender, handle: Arc, @@ -1511,6 +1515,16 @@ impl NodeState { pub(crate) fn handle(&self) -> &Arc { &self.handle } + + /// Creates the logger configuration services associated with this Node. + /// + /// Called at most once from [`NodeOptions::build`] when + /// [`IntoNodeOptions::enable_logger_service`] is set to `true`. + #[cfg(not(ros_distro = "humble"))] + pub(crate) fn create_logger_service(self: &Arc) -> Result<(), RclrsError> { + *self.logger_service.lock().unwrap() = Some(LoggingService::new(self)?); + Ok(()) + } } impl<'a> ToLogParams<'a> for &'a NodeState { diff --git a/rclrs/src/node/node_options.rs b/rclrs/src/node/node_options.rs index 62855d240..266027662 100644 --- a/rclrs/src/node/node_options.rs +++ b/rclrs/src/node/node_options.rs @@ -166,6 +166,18 @@ pub trait IntoNodeOptions<'a>: Sized { options } + /// Enables or disables the logger configuration services. + /// + /// When enabled, the node exposes `~/get_logger_levels` and + /// `~/set_logger_levels` services that allow external nodes to query and + /// change logger severity levels at runtime. Disabled by default. + #[cfg(not(ros_distro = "humble"))] + fn enable_logger_service(self, enable: bool) -> NodeOptions<'a> { + let mut options = self.into_node_options(); + options.enable_logger_service = enable; + options + } + /// Sets the node's clock type. fn clock_type(self, clock_type: ClockType) -> NodeOptions<'a> { let mut options = self.into_node_options(); @@ -192,6 +204,7 @@ pub trait IntoNodeOptions<'a>: Sized { /// - `arguments: []` /// - `enable_rosout: true` /// - `start_parameter_services: true` +/// - `enable_logger_service: false` /// - `clock_type: ClockType::RosTime` /// - `clock_qos: QOS_PROFILE_CLOCK` /// @@ -233,6 +246,8 @@ pub struct NodeOptions<'a> { arguments: Vec, enable_rosout: bool, start_parameter_services: bool, + #[cfg(not(ros_distro = "humble"))] + enable_logger_service: bool, clock_type: ClockType, clock_qos: QoSProfile, } @@ -279,6 +294,8 @@ impl<'a> NodeOptions<'a> { arguments: vec![], enable_rosout: true, start_parameter_services: true, + #[cfg(not(ros_distro = "humble"))] + enable_logger_service: false, clock_type: ClockType::RosTime, clock_qos: QOS_PROFILE_CLOCK, } @@ -418,6 +435,8 @@ impl<'a> NodeOptions<'a> { .build(), parameter, logger: Logger::new(logger_name)?, + #[cfg(not(ros_distro = "humble"))] + logger_service: Mutex::new(None), graph_change_action, commands: Arc::clone(&commands), handle, @@ -428,6 +447,11 @@ impl<'a> NodeOptions<'a> { node.parameter.create_services(&node)?; } + #[cfg(not(ros_distro = "humble"))] + if self.enable_logger_service { + node.create_logger_service()?; + } + Ok(node) }