Fix logging lifecycles and clean up tests

Signed-off-by: Michael X. Grey <[email protected]>

Author: mxgrey

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<rcl_context_t>,
+    /// This ensures that logging does not get cleaned up until after this ContextHandle
+    /// has dropped.
+    #[allow(unused)]
+    logging: Arc<LoggingLifecycle>,
 }
 
 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,
             }),
         })
     }

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;

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<Weak<LoggingLifecycle>>,
+}
+
+pub(crate) struct LoggingLifecycle;
+
+impl LoggingLifecycle {
+    fn new(args: &rcl_arguments_t) -> Result<Self, RclrsError> {
+        // 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<Arc<LoggingLifecycle>, RclrsError> {
+        static CONFIGURATION: LazyLock<LoggingConfiguration> = 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(); }
+    }
+}

rclrs/src/node.rs

@@ -557,15 +557,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(())

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]

rclrs/src/parameter.rs

@@ -885,7 +885,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
@@ -943,7 +943,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")
@@ -1093,7 +1093,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()
@@ -1115,7 +1115,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
@@ -1161,7 +1161,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),
@@ -1289,7 +1289,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)
@@ -1316,7 +1316,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();
@@ -1369,7 +1369,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::<i64>("int_param")
             .optional()
             .unwrap();

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"),
         }];

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);
     }