From 3ec882cd2db97d84330197bb946bd31572215489 Mon Sep 17 00:00:00 2001 From: mschickler Date: Tue, 28 Jan 2020 12:08:00 -0500 Subject: [PATCH] Allow node clock use in logging macros (#969) (#970) Capturing a cached reference allows a clock object that is not a local (e.g. the one returned by Node::get_clock()) to be passed to the throttle logging macro. Signed-off-by: Matt Schickler Co-Authored-By: Ivan Santiago Paunovic --- rclcpp/resource/logging.hpp.em | 4 ++-- rclcpp/test/test_logging.cpp | 39 +++++++++++++++++++++++++++++++++- 2 files changed, 40 insertions(+), 3 deletions(-) diff --git a/rclcpp/resource/logging.hpp.em b/rclcpp/resource/logging.hpp.em index 7cab4b3..3e99619 100644 --- a/rclcpp/resource/logging.hpp.em +++ b/rclcpp/resource/logging.hpp.em @@ -129,9 +129,9 @@ def get_rclcpp_suffix_from_features(features): typename ::rclcpp::Logger>::value, \ "First argument to logging macros must be an rclcpp::Logger"); \ @[ if 'throttle' in feature_combination]@ \ - auto get_time_point = [&clock](rcutils_time_point_value_t * time_point) -> rcutils_ret_t { \ + auto get_time_point = [&c=clock](rcutils_time_point_value_t * time_point) -> rcutils_ret_t { \ try { \ - *time_point = clock.now().nanoseconds(); \ + *time_point = c.now().nanoseconds(); \ } catch (...) { \ RCUTILS_SAFE_FWRITE_TO_STDERR( \ "[rclcpp|logging.hpp] RCLCPP_@(severity)@(suffix) could not get current time stamp\n"); \ diff --git a/rclcpp/test/test_logging.cpp b/rclcpp/test/test_logging.cpp index f66851b..cc8bd62 100644 --- a/rclcpp/test/test_logging.cpp +++ b/rclcpp/test/test_logging.cpp @@ -77,16 +77,33 @@ public: } }; +class DummyNode +{ +public: + DummyNode() + { + clock_ = rclcpp::Clock::make_shared(RCL_ROS_TIME); + } + rclcpp::Clock::SharedPtr get_clock() + { + return clock_; + } + +private: + rclcpp::Clock::SharedPtr clock_; +}; + TEST_F(TestLoggingMacros, test_logging_named) { for (int i : {1, 2, 3}) { RCLCPP_DEBUG(g_logger, "message %d", i); } + size_t expected_location = __LINE__ - 2u; EXPECT_EQ(3u, g_log_calls); EXPECT_TRUE(g_last_log_event.location != NULL); if (g_last_log_event.location) { EXPECT_STREQ("TestBody", g_last_log_event.location->function_name); EXPECT_THAT(g_last_log_event.location->file_name, EndsWith("test_logging.cpp")); - EXPECT_EQ(82u, g_last_log_event.location->line_number); + EXPECT_EQ(expected_location, g_last_log_event.location->line_number); } EXPECT_EQ(RCUTILS_LOG_SEVERITY_DEBUG, g_last_log_event.level); EXPECT_EQ("name", g_last_log_event.name); @@ -210,6 +227,26 @@ TEST_F(TestLoggingMacros, test_throttle) { EXPECT_EQ(6u, g_log_calls); } } + DummyNode node; + rcl_clock_t * node_clock = node.get_clock()->get_clock_handle(); + ASSERT_TRUE(node_clock); + ASSERT_EQ(RCL_RET_OK, rcl_enable_ros_time_override(node_clock)); + EXPECT_EQ(6u, g_log_calls); + EXPECT_EQ(RCL_RET_OK, rcl_set_ros_time_override(node_clock, RCUTILS_MS_TO_NS(10))); + for (uint64_t i = 0; i < 3; ++i) { + RCLCPP_DEBUG_THROTTLE(g_logger, *node.get_clock(), 10, "Throttling"); + if (i == 0) { + EXPECT_EQ(7u, g_log_calls); + rcl_time_point_value_t clock_ns = node.get_clock()->now().nanoseconds() + RCUTILS_MS_TO_NS(5); + EXPECT_EQ(RCL_RET_OK, rcl_set_ros_time_override(node_clock, clock_ns)); + } else if (i == 1) { + EXPECT_EQ(7u, g_log_calls); + rcl_time_point_value_t clock_ns = node.get_clock()->now().nanoseconds() + RCUTILS_MS_TO_NS(5); + EXPECT_EQ(RCL_RET_OK, rcl_set_ros_time_override(node_clock, clock_ns)); + } else { + EXPECT_EQ(8u, g_log_calls); + } + } } bool log_function(rclcpp::Logger logger)