Implement rclcpp-specific logging macros [taking name not object] (#389)

rclcpp/CMakeLists.txt

@@ -64,6 +64,28 @@ set(${PROJECT_NAME}_SRCS
   src/rclcpp/utilities.cpp
 )
 
+# "watch" template for changes
+configure_file(
+  "resource/logging.hpp.em"
+  "logging.hpp.em.watch"
+  COPYONLY
+)
+# generate header with logging macros
+set(python_code
+  "import em"
+  "em.invoke(['-o', 'include/rclcpp/logging.hpp', '${CMAKE_CURRENT_SOURCE_DIR}/resource/logging.hpp.em'])")
+string(REPLACE ";" "$<SEMICOLON>" python_code "${python_code}")
+add_custom_command(OUTPUT include/rclcpp/logging.hpp
+  COMMAND ${CMAKE_COMMAND} -E make_directory "include/rclcpp"
+  COMMAND ${PYTHON_EXECUTABLE} ARGS -c "${python_code}"
+  DEPENDS "${CMAKE_CURRENT_BINARY_DIR}/logging.hpp.em.watch"
+  COMMENT "Expanding logging.hpp.em"
+  VERBATIM
+)
+list(APPEND ${PROJECT_NAME}_SRCS
+  include/rclcpp/logging.hpp)
+include_directories("${CMAKE_CURRENT_BINARY_DIR}/include")
+
 add_library(${PROJECT_NAME} SHARED
   ${${PROJECT_NAME}_SRCS})
 ament_target_dependencies(${PROJECT_NAME}
@@ -251,6 +273,9 @@ if(BUILD_TESTING)
       "rcl")
     target_link_libraries(test_time ${PROJECT_NAME})
   endif()
+
+  ament_add_gmock(test_logging test/test_logging.cpp)
+  target_link_libraries(test_logging ${PROJECT_NAME})
 endif()
 
 ament_package(
@@ -263,6 +288,6 @@ install(
 )
 
 install(
-  DIRECTORY include/
+  DIRECTORY include/ ${CMAKE_CURRENT_BINARY_DIR}/include/
   DESTINATION include
 )

rclcpp/Doxyfile

@@ -4,7 +4,12 @@ PROJECT_NAME           = "rclcpp"
 PROJECT_NUMBER         = master
 PROJECT_BRIEF          = "C++ ROS Client Library API"
 
+# Use these lines to include the generated logging.hpp (update install path if needed)
+#INPUT                  = ../../../../install_isolated/rclcpp/include
+#STRIP_FROM_PATH        = /Users/william/ros2_ws/install_isolated/rclcpp/include
+# Otherwise just generate for the local (non-generated header files)
 INPUT                  = ./include
+
 RECURSIVE              = YES
 OUTPUT_DIRECTORY       = doc_output
 

rclcpp/include/rclcpp/macros.hpp

@@ -110,6 +110,4 @@
 #define RCLCPP_STRING_JOIN(arg1, arg2) RCLCPP_DO_STRING_JOIN(arg1, arg2)
 #define RCLCPP_DO_STRING_JOIN(arg1, arg2) arg1 ## arg2
 
-#define RCLCPP_INFO(Args) std::cout << Args << std::endl;
-
 #endif  // RCLCPP__MACROS_HPP_

rclcpp/include/rclcpp/rclcpp.hpp

@@ -110,6 +110,13 @@
  *   - rclcpp::context::Context
  *   - rclcpp/context.hpp
  *   - rclcpp/contexts/default_context.hpp
+ * - Logging macros:
+ *   - Some examples (not exhaustive):
+ *     - RCLCPP_DEBUG()
+ *     - RCLCPP_INFO()
+ *     - RCLCPP_WARN_ONCE()
+ *     - RCLCPP_ERROR_SKIPFIRST()
+ *   - rclcpp/logging.hpp
  * - Various utilities:
  *   - rclcpp/function_traits.hpp
  *   - rclcpp/macros.hpp
@@ -126,6 +133,7 @@
 #include <memory>
 
 #include "rclcpp/executors.hpp"
+#include "rclcpp/logging.hpp"
 #include "rclcpp/node.hpp"
 #include "rclcpp/parameter.hpp"
 #include "rclcpp/parameter_client.hpp"

rclcpp/package.xml

@@ -27,6 +27,7 @@
 
   <exec_depend>ament_cmake</exec_depend>
 
+  <test_depend>ament_cmake_gmock</test_depend>
   <test_depend>ament_cmake_gtest</test_depend>
   <test_depend>ament_lint_auto</test_depend>
   <test_depend>ament_lint_common</test_depend>

rclcpp/resource/logging.hpp.em

@@ -0,0 +1,101 @@
+// generated from rclcpp/resource/logging.hpp.em
+
+// Copyright 2017 Open Source Robotics Foundation, Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#ifndef RCLCPP__LOGGING_HPP_
+#define RCLCPP__LOGGING_HPP_
+
+#include "rcutils/logging_macros.h"
+
+// These are used for compiling out logging macros lower than a minimum severity.
+#define RCLCPP_LOG_MIN_SEVERITY_DEBUG 0
+#define RCLCPP_LOG_MIN_SEVERITY_INFO 1
+#define RCLCPP_LOG_MIN_SEVERITY_WARN 2
+#define RCLCPP_LOG_MIN_SEVERITY_ERROR 3
+#define RCLCPP_LOG_MIN_SEVERITY_FATAL 4
+#define RCLCPP_LOG_MIN_SEVERITY_NONE 5
+
+/**
+ * \def RCLCPP_LOG_MIN_SEVERITY
+ * Define RCLCPP_LOG_MIN_SEVERITY=RCLCPP_LOG_MIN_SEVERITY_[DEBUG|INFO|WARN|ERROR|FATAL]
+ * in your build options to compile out anything below that severity.
+ * Use RCUTILS_LOG_MIN_SEVERITY_NONE to compile out all macros.
+ */
+#ifndef RCLCPP_LOG_MIN_SEVERITY
+#define RCLCPP_LOG_MIN_SEVERITY RCLCPP_LOG_MIN_SEVERITY_DEBUG
+#endif
+
+
+@{
+from rcutils.logging import feature_combinations
+from rcutils.logging import get_macro_parameters
+from rcutils.logging import get_suffix_from_features
+from rcutils.logging import severities
+
+# TODO(dhood): Implement the throttle macro using time sources available in rclcpp
+excluded_features = ['named', 'throttle']
+def is_supported_feature_combination(feature_combination):
+    is_excluded = any([ef in feature_combination for ef in excluded_features])
+    return not is_excluded
+}@
+@[for severity in severities]@
+/** @@name Logging macros for severity @(severity).
+ */
+///@@{
+#if (RCLCPP_LOG_MIN_SEVERITY > RCLCPP_LOG_MIN_SEVERITY_@(severity))
+// empty logging macros for severity @(severity) when being disabled at compile time
+@[ for feature_combination in [fc for fc in feature_combinations if is_supported_feature_combination(fc)]]@
+@{suffix = get_suffix_from_features(feature_combination)}@
+/// Empty logging macro due to the preprocessor definition of RCLCPP_LOG_MIN_SEVERITY.
+#define RCLCPP_@(severity)@(suffix)(...)
+@[ end for]@
+
+#else
+@[ for feature_combination in [fc for fc in feature_combinations if is_supported_feature_combination(fc)]]@
+@{suffix = get_suffix_from_features(feature_combination)}@
+/**
+ * \def RCLCPP_@(severity)@(suffix)
+ * Log a message with severity @(severity)@
+@[ if feature_combinations[feature_combination].doc_lines]@
+ with the following conditions:
+@[ else]@
+.
+@[ end if]@
+@[ for doc_line in feature_combinations[feature_combination].doc_lines]@
+ * @(doc_line)
+@[ end for]@
+ * \param name The name of the logger
+@[ for param_name, doc_line in feature_combinations[feature_combination].params.items()]@
+ * \param @(param_name) @(doc_line)
+@[ end for]@
+ * \param ... The format string, followed by the variable arguments for the format string
+ */
+// TODO(dhood): Replace the name argument with a logger object.
+#define RCLCPP_@(severity)@(suffix)(name, @(''.join([p + ', ' for p in get_macro_parameters(feature_combination).keys()]))...) \
+  RCUTILS_LOG_@(severity)@(suffix)_NAMED( \
+@{params = get_macro_parameters(feature_combination).keys()}@
+@[ if params]@
+@(''.join(['    ' + p + ', \\\n' for p in params]))@
+@[ end if]@
+    std::string(name).c_str(), \
+    __VA_ARGS__)
+
+@[ end for]@
+#endif
+///@@}
+
+@[end for]@
+
+#endif  // RCLCPP__LOGGING_HPP_

rclcpp/test/test_logging.cpp

@@ -0,0 +1,158 @@
+// Copyright 2017 Open Source Robotics Foundation, Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include <gmock/gmock.h>
+
+#include <chrono>
+#include <string>
+#include <thread>
+#include <vector>
+
+#include "rclcpp/logging.hpp"
+#include "rcutils/logging.h"
+#include "rcutils/time.h"
+
+#define RCLCPP_TEST_LOGGING_MACRO_NAME "name"  // Used in testing below
+
+using ::testing::EndsWith;
+
+size_t g_log_calls = 0;
+
+struct LogEvent
+{
+  rcutils_log_location_t * location;
+  int level;
+  std::string name;
+  std::string message;
+};
+LogEvent g_last_log_event;
+
+class TestLoggingMacros : public ::testing::Test
+{
+public:
+  rcutils_logging_output_handler_t previous_output_handler;
+  void SetUp()
+  {
+    g_log_calls = 0;
+    ASSERT_EQ(RCUTILS_RET_OK, rcutils_logging_initialize());
+    rcutils_logging_set_default_severity_threshold(RCUTILS_LOG_SEVERITY_DEBUG);
+
+    auto rcutils_logging_console_output_handler = [](
+      rcutils_log_location_t * location,
+      int level, const char * name, const char * format, va_list * args) -> void
+      {
+        g_log_calls += 1;
+        g_last_log_event.location = location;
+        g_last_log_event.level = level;
+        g_last_log_event.name = name ? name : "";
+        char buffer[1024];
+        vsnprintf(buffer, sizeof(buffer), format, *args);
+        g_last_log_event.message = buffer;
+      };
+
+    this->previous_output_handler = rcutils_logging_get_output_handler();
+    rcutils_logging_set_output_handler(rcutils_logging_console_output_handler);
+  }
+
+  void TearDown()
+  {
+    rcutils_logging_set_output_handler(this->previous_output_handler);
+    g_rcutils_logging_initialized = false;
+    EXPECT_FALSE(g_rcutils_logging_initialized);
+  }
+};
+
+TEST_F(TestLoggingMacros, test_logging_named) {
+  for (int i : {1, 2, 3}) {
+    RCLCPP_DEBUG("name", "message %d", i);
+  }
+  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(78u, 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);
+  EXPECT_EQ("message 3", g_last_log_event.message);
+
+  // Test different name inputs
+  std::string std_string_name = "name";
+  RCLCPP_DEBUG(std_string_name, "message");
+  EXPECT_EQ("name", g_last_log_event.name);
+
+  const char * c_string_name = "name";
+  RCLCPP_DEBUG(c_string_name, "message");
+  EXPECT_EQ("name", g_last_log_event.name);
+
+  RCLCPP_DEBUG(std_string_name + c_string_name, "message");
+  EXPECT_EQ("namename", g_last_log_event.name);
+
+  RCLCPP_DEBUG(RCLCPP_TEST_LOGGING_MACRO_NAME, "message");
+  EXPECT_EQ(RCLCPP_TEST_LOGGING_MACRO_NAME, g_last_log_event.name);
+  RCLCPP_DEBUG(std::string(RCLCPP_TEST_LOGGING_MACRO_NAME) + std_string_name, "message");
+  EXPECT_EQ("namename", g_last_log_event.name);
+}
+
+TEST_F(TestLoggingMacros, test_logging_once) {
+  for (int i : {1, 2, 3}) {
+    RCLCPP_INFO_ONCE("name", "message %d", i);
+  }
+  EXPECT_EQ(1u, g_log_calls);
+  EXPECT_EQ(RCUTILS_LOG_SEVERITY_INFO, g_last_log_event.level);
+  EXPECT_EQ("name", g_last_log_event.name);
+  EXPECT_EQ("message 1", g_last_log_event.message);
+
+  // Check that another instance has a context that's independent to the call above's
+  g_log_calls = 0;
+  for (int i : {1, 2, 3}) {
+    RCLCPP_INFO_ONCE("name", "second message %d", i);
+  }
+  EXPECT_EQ(1u, g_log_calls);
+  EXPECT_EQ(RCUTILS_LOG_SEVERITY_INFO, g_last_log_event.level);
+  EXPECT_EQ("name", g_last_log_event.name);
+  EXPECT_EQ("second message 1", g_last_log_event.message);
+}
+
+TEST_F(TestLoggingMacros, test_logging_expression) {
+  for (int i : {1, 2, 3, 4, 5, 6}) {
+    RCLCPP_INFO_EXPRESSION("name", i % 3, "message %d", i);
+  }
+  EXPECT_EQ(4u, g_log_calls);
+  EXPECT_EQ("message 5", g_last_log_event.message);
+}
+
+int g_counter = 0;
+
+bool mod3()
+{
+  return (g_counter % 3) != 0;
+}
+
+TEST_F(TestLoggingMacros, test_logging_function) {
+  for (int i : {1, 2, 3, 4, 5, 6}) {
+    g_counter = i;
+    RCLCPP_INFO_FUNCTION("name", &mod3, "message %d", i);
+  }
+  EXPECT_EQ(4u, g_log_calls);
+  EXPECT_EQ("message 5", g_last_log_event.message);
+}
+
+TEST_F(TestLoggingMacros, test_logging_skipfirst) {
+  for (uint32_t i : {1, 2, 3, 4, 5}) {
+    RCLCPP_WARN_SKIPFIRST("name", "message %u", i);
+    EXPECT_EQ(i - 1, g_log_calls);
+  }
+}