diff --git a/rclrs/src/context.rs b/rclrs/src/context.rs index e9b7ad9d5..524169bb2 100644 --- a/rclrs/src/context.rs +++ b/rclrs/src/context.rs @@ -6,7 +6,7 @@ use std::{ vec::Vec, }; -use crate::{rcl_bindings::*, RclrsError, ToResult}; +use crate::{rcl_bindings::*, LoggingLifecycle, RclrsError, ToResult}; /// This is locked whenever initializing or dropping any middleware entity /// because we have found issues in RCL and some RMW implementations that @@ -34,10 +34,6 @@ impl Drop for rcl_context_t { // SAFETY: The entity lifecycle mutex is locked to protect against the risk of // global variables in the rmw implementation being unsafely modified during cleanup. rcl_shutdown(self); - - // SAFETY: No preconditions for rcl_logging_fini - rcl_logging_fini(); - rcl_context_fini(self); } } @@ -76,6 +72,10 @@ pub struct Context { /// bindings in this library. pub(crate) struct ContextHandle { pub(crate) rcl_context: Mutex, + /// This ensures that logging does not get cleaned up until after this ContextHandle + /// has dropped. + #[allow(unused)] + logging: Arc, } impl Context { @@ -150,28 +150,17 @@ impl Context { rcl_init_options_fini(&mut rcl_init_options).ok()?; // Move the check after the last fini() ret?; + } - // TODO: "Auto set-up logging" is forced but should be configurable as per rclcpp and rclpy - // SAFETY: - // * Lock the mutex as we cannot guarantee that rcl_* functions are protecting their global variables - // * Context is validated before we reach this point - // * No other preconditions for calling this function - let ret = { - let _lifecycle_lock = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); - // Note: shadowing the allocator above. The rcutils_get_default_allocator provides us with mechanisms for allocating and freeing - // memory, e.g. calloc/free. As these are function pointers and will be the same each time we call the method, it is safe to - // perform this shadowing - // Alternate is to call rcl_init_options_get_allocator however, we've freed the allocator above and restructuring the call - // sequence is unnecessarily complex - let allocator = rcutils_get_default_allocator(); + // TODO: "Auto set-up logging" is forced but should be configurable as per rclcpp and rclpy + // SAFETY: We created this context a moment ago and verified that it is valid. + // No other conditions are needed. + let logging = unsafe { LoggingLifecycle::configure(&rcl_context)? }; - rcl_logging_configure(&rcl_context.global_arguments, &allocator).ok() - }; - ret? - } Ok(Self { handle: Arc::new(ContextHandle { rcl_context: Mutex::new(rcl_context), + logging, }), }) } diff --git a/rclrs/src/logging.rs b/rclrs/src/logging.rs index e4f789c4d..bfce6ad5b 100644 --- a/rclrs/src/logging.rs +++ b/rclrs/src/logging.rs @@ -5,10 +5,10 @@ use std::{ffi::CString, sync::Mutex, time::Duration}; -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 logging_configuration; +pub(crate) use logging_configuration::*; /// Calls the underlying rclutils logging function /// Don't call this directly, use the logging macros instead. @@ -39,8 +39,8 @@ pub fn log(msg: &str, logger_name: &str, file: &str, line: u32, severity: LogSev .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 + 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, @@ -200,7 +200,7 @@ impl LogConditions { /// use std::env; /// /// let context = rclrs::Context::new(env::args()).unwrap(); -/// let node = rclrs::Node::new(&context, "test_node").unwrap(); +/// let node = rclrs::Node::new(&context, "log_example_node").unwrap(); /// /// log_debug!(&node.name(), "Simple message"); /// let some_variable = 43; diff --git a/rclrs/src/logging/logging_configuration.rs b/rclrs/src/logging/logging_configuration.rs new file mode 100644 index 000000000..b4cfa626b --- /dev/null +++ b/rclrs/src/logging/logging_configuration.rs @@ -0,0 +1,53 @@ +use std::sync::{Mutex, Weak, LazyLock, Arc}; + +use crate::{ + RclrsError, ENTITY_LIFECYCLE_MUTEX, ToResult, + rcl_bindings::{ + rcl_context_t, rcl_arguments_t, rcutils_get_default_allocator, + rcl_logging_configure, rcl_logging_fini, + }, +}; + + +struct LoggingConfiguration { + lifecycle: Mutex>, +} + +pub(crate) struct LoggingLifecycle; + +impl LoggingLifecycle { + fn new(args: &rcl_arguments_t) -> Result { + // SAFETY: + // * Lock the mutex as we cannot guarantee that rcl_* functions are protecting their global variables + // * This is only called by Self::configure, which requires that a valid context was passed to it + // * No other preconditions for calling this function + unsafe { + let allocator = rcutils_get_default_allocator(); + let _lock = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); + rcl_logging_configure(args, &allocator).ok()?; + } + Ok(Self) + } + + /// SAFETY: Ensure rcl_context_t is valid before passing it in. + pub(crate) unsafe fn configure(context: &rcl_context_t) -> Result, RclrsError> { + static CONFIGURATION: LazyLock = LazyLock::new( + || LoggingConfiguration { lifecycle: Mutex::new(Weak::new())} + ); + + let mut lifecycle = CONFIGURATION.lifecycle.lock().unwrap(); + if let Some(arc_lifecycle) = lifecycle.upgrade() { + return Ok(arc_lifecycle); + } + let arc_lifecycle = Arc::new(LoggingLifecycle::new(&context.global_arguments)?); + *lifecycle = Arc::downgrade(&arc_lifecycle); + Ok(arc_lifecycle) + } +} + +impl Drop for LoggingLifecycle { + fn drop(&mut self) { + let _lock = ENTITY_LIFECYCLE_MUTEX.lock().unwrap(); + unsafe { rcl_logging_fini(); } + } +} diff --git a/rclrs/src/node.rs b/rclrs/src/node.rs index 0d141721c..e767911f4 100644 --- a/rclrs/src/node.rs +++ b/rclrs/src/node.rs @@ -539,15 +539,15 @@ mod tests { #[test] fn test_logger_name() -> Result<(), RclrsError> { // Use helper to create 2 nodes for us - let graph = construct_test_graph("test_topics_graph")?; + let graph = construct_test_graph("test_logger_name")?; assert_eq!( graph.node1.logger_name(), - "test_topics_graph.graph_test_node_1" + "test_logger_name.graph_test_node_1" ); assert_eq!( graph.node2.logger_name(), - "test_topics_graph.graph_test_node_2" + "test_logger_name.graph_test_node_2" ); Ok(()) diff --git a/rclrs/src/node/graph.rs b/rclrs/src/node/graph.rs index e18675a21..8b6e6e3db 100644 --- a/rclrs/src/node/graph.rs +++ b/rclrs/src/node/graph.rs @@ -487,12 +487,13 @@ 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 + // Test that the graph has no publishers besides /rosout let names_and_topics = node .get_publisher_names_and_types_by_node(node_name, "") .unwrap(); - assert_eq!(names_and_topics.len(), 0); + assert_eq!(names_and_topics.len(), 1); + assert_eq!(names_and_topics.get("/rosout").unwrap().first().unwrap(), "rcl_interfaces/msg/Log"); let num_publishers = node.count_publishers("/test").unwrap(); @@ -535,10 +536,11 @@ mod tests { assert_eq!(names_and_topics.len(), 0); - // Test that the graph has no topics + // 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(), 0); + assert_eq!(names_and_topics.len(), 1); + assert_eq!(names_and_topics.get("/rosout").unwrap().first().unwrap(), "rcl_interfaces/msg/Log"); } #[test] diff --git a/rclrs/src/parameter.rs b/rclrs/src/parameter.rs index f8427a0cc..5ec75baa5 100644 --- a/rclrs/src/parameter.rs +++ b/rclrs/src/parameter.rs @@ -882,7 +882,7 @@ mod tests { String::from("declared_int:=10"), ]) .unwrap(); - let node = create_node(&ctx, "param_test_node").unwrap(); + let node = create_node(&ctx, &format!("param_test_node_{}", line!())).unwrap(); // Declaring a parameter with a different type than what was overridden should return an // error @@ -940,7 +940,7 @@ mod tests { String::from("non_declared_string:='param'"), ]) .unwrap(); - let node = create_node(&ctx, "param_test_node").unwrap(); + let node = create_node(&ctx, &format!("param_test_node_{}", line!())).unwrap(); let overridden_int = node .declare_parameter("declared_int") @@ -1090,7 +1090,7 @@ mod tests { String::from("declared_int:=10"), ]) .unwrap(); - let node = create_node(&ctx, "param_test_node").unwrap(); + let node = create_node(&ctx, &format!("param_test_node_{}", line!())).unwrap(); // If a parameter was set as an override and as an undeclared parameter, the undeclared // value should get priority node.use_undeclared_parameters() @@ -1112,7 +1112,7 @@ mod tests { String::from("declared_int:=10"), ]) .unwrap(); - let node = create_node(&ctx, "param_test_node").unwrap(); + let node = create_node(&ctx, &format!("param_test_node_{}", line!())).unwrap(); { // Setting a parameter with an override let param = node @@ -1158,7 +1158,7 @@ mod tests { #[test] fn test_parameter_ranges() { let ctx = Context::new([]).unwrap(); - let node = create_node(&ctx, "param_test_node").unwrap(); + let node = create_node(&ctx, &format!("param_test_node_{}", line!())).unwrap(); // Setting invalid ranges should fail let range = ParameterRange { lower: Some(10), @@ -1286,7 +1286,7 @@ mod tests { #[test] fn test_readonly_parameters() { let ctx = Context::new([]).unwrap(); - let node = create_node(&ctx, "param_test_node").unwrap(); + let node = create_node(&ctx, &format!("param_test_node_{}", line!())).unwrap(); let param = node .declare_parameter("int_param") .default(100) @@ -1313,7 +1313,7 @@ mod tests { #[test] fn test_preexisting_value_error() { let ctx = Context::new([]).unwrap(); - let node = create_node(&ctx, "param_test_node").unwrap(); + let node = create_node(&ctx, &format!("param_test_node_{}", line!())).unwrap(); node.use_undeclared_parameters() .set("int_param", 100) .unwrap(); @@ -1366,7 +1366,7 @@ mod tests { #[test] fn test_optional_parameter_apis() { let ctx = Context::new([]).unwrap(); - let node = create_node(&ctx, "param_test_node").unwrap(); + let node = create_node(&ctx, &format!("param_test_node_{}", line!())).unwrap(); node.declare_parameter::("int_param") .optional() .unwrap(); diff --git a/rclrs/src/subscription.rs b/rclrs/src/subscription.rs index 47d93de1a..068c80435 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: String::from("graph_test_node_2"), + node_name: format!("graph_test_node_2"), node_namespace: String::from(namespace), topic_type: String::from("test_msgs/msg/Empty"), }]; diff --git a/rclrs/src/time_source.rs b/rclrs/src/time_source.rs index a6b600800..15d2ca31b 100644 --- a/rclrs/src/time_source.rs +++ b/rclrs/src/time_source.rs @@ -149,7 +149,7 @@ mod tests { #[test] fn time_source_default_clock() { - let node = create_node(&Context::new([]).unwrap(), "test_node").unwrap(); + let node = create_node(&Context::new([]).unwrap(), &format!("time_source_test_node_{}", line!())).unwrap(); // Default clock should be above 0 (use_sim_time is default false) assert!(node.get_clock().now().nsec > 0); } @@ -162,7 +162,7 @@ mod tests { String::from("use_sim_time:=true"), ]) .unwrap(); - let node = create_node(&ctx, "test_node").unwrap(); + let node = create_node(&ctx, &format!("time_source_test_node_{}", line!())).unwrap(); // Default sim time value should be 0 (no message received) assert_eq!(node.get_clock().now().nsec, 0); }