regression of thread-safety for logging macros (ros2#393)

* add regression test for thread-safety of logging macros

Signed-off-by: William Woodall <william@osrfoundation.org>

* remove optimization that regressed thread-safety of logging macros

Signed-off-by: William Woodall <william@osrfoundation.org>

* fix references to issue pr

Signed-off-by: William Woodall <william@osrfoundation.org>

* add documentation about the thread-safety of rcutils_log()

Signed-off-by: William Woodall <william@osrfoundation.org>

Signed-off-by: William Woodall <william@osrfoundation.org>

Author: wjwwood

include/rcutils/logging.h

@@ -486,9 +486,20 @@ RCUTILS_ATTRIBUTE_PRINTF_FORMAT(4, 5)
  * ------------------ | -------------
  * Allocates Memory   | No, for formatted outputs <= 1023 characters
  *                    | Yes, for formatted outputs >= 1024 characters
- * Thread-Safe        | No
+ * Thread-Safe        | Yes, with itself [1]
  * Uses Atomics       | No
  * Lock-Free          | Yes
+ * <i>[1] should be thread-safe with itself but not with other logging functions</i>
+ *
+ * This should be thread-safe with itself, but is not thread-safe with other
+ * logging functions that do things like set logger levels.
+ *
+ * \todo There are no thread-safety gurantees between this function and other
+ *   logging functions in rcutils, even though it is likely users are calling
+ *   them concurrently today.
+ *   We need to revisit these functions with respect to this issue and make
+ *   guarantees where we can, and change functions higher in the stack to
+ *   provide the thread-safety where we cannot.
  *
  * \param[in] location The pointer to the location struct or NULL
  * \param[in] severity The severity level

src/logging.c

@@ -943,18 +943,20 @@ int rcutils_logging_get_logger_effective_level(const char * name)
     severity = g_rcutils_logging_default_logger_level;
   }
 
-  // If the calculated severity is anything but UNSET, we place it into the hashmap for speedier
-  // lookup next time.  If the severity is UNSET, we don't bother because we are going to have to
-  // walk the hierarchy next time anyway.
-  if (severity != RCUTILS_LOG_SEVERITY_UNSET) {
-    ret = add_key_to_hash_map(name, severity, false);
-    if (ret != RCUTILS_RET_OK) {
-      // Continue on if we failed to add the key to the hashmap.
-      // This will affect performance but is not fatal.
-      RCUTILS_SAFE_FWRITE_TO_STDERR(
-        "Failed to cache severity; this is not fatal but will impact performance");
-    }
-  }
+  // TODO(wjwwood): restore or replace this optimization when thread-safety is addressed
+  //   see: https://github.com/ros2/rcutils/pull/393
+  // // If the calculated severity is anything but UNSET, we place it into the hashmap for speedier
+  // // lookup next time.  If the severity is UNSET, we don't bother because we are going to have to
+  // // walk the hierarchy next time anyway.
+  // if (severity != RCUTILS_LOG_SEVERITY_UNSET) {
+  //   ret = add_key_to_hash_map(name, severity, false);
+  //   if (ret != RCUTILS_RET_OK) {
+  //     // Continue on if we failed to add the key to the hashmap.
+  //     // This will affect performance but is not fatal.
+  //     RCUTILS_SAFE_FWRITE_TO_STDERR(
+  //       "Failed to cache severity; this is not fatal but will impact performance\n");
+  //   }
+  // }
 
   return severity;
 }

test/test_logging.cpp

@@ -14,7 +14,9 @@
 
 #include <gtest/gtest.h>
 
+#include <chrono>
 #include <string>
+#include <thread>
 #include <vector>
 
 #include "./allocator_testing_utils.h"
@@ -485,3 +487,52 @@ TEST(TestLogging, test_root_logger_after_nonexistent)
     rcutils_logging_set_logger_level(
       "", original_root_severity));
 }
+
+TEST(TestLogging, test_logging_macro_thread_safety)
+{
+  // This tests whether or not using logging macros from multiple threads is safe or not.
+
+  // This test is based on an issue found in the optimization of the logging macros,
+  // and therefore has a very specific trigger scenario, which is described more
+  // in the steps below.
+  // See: https://github.com/ros2/rcutils/pull/393
+
+  // This test is likely to be flakey false-positive, meaning it's possible that
+  // it will pass even if the macros are not thread-safe and may require running
+  // repeatedly to detect problems.
+
+  ASSERT_EQ(RCUTILS_RET_OK, rcutils_logging_initialize());
+  OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT(
+  {
+    EXPECT_EQ(RCUTILS_RET_OK, rcutils_logging_shutdown());
+  });
+
+  // One of the loggers needs to be set "by the user" to trigger the optimization.
+  ASSERT_EQ(RCUTILS_RET_OK, rcutils_logging_set_logger_level("", RCUTILS_LOG_SEVERITY_DEBUG));
+
+  // In threads, in a loop do a log call on many different logger names.
+  // The message doesn't matter.
+  std::size_t loop_count = 10;
+  auto task = [&loop_count](std::size_t thread_number) {
+      for (std::size_t i = 0; i < loop_count; ++i) {
+        rcutils_log_location_t location = {"func", "file", 42u};
+        rcutils_log(
+          &location,
+          RCUTILS_LOG_SEVERITY_DEBUG,
+          ("some_logger_name" + std::to_string(thread_number * i)).c_str(),
+          "message %d", 11);
+      }
+    };
+
+  // Create many thread to increase the chance of collisions.
+  std::vector<std::thread> threads;
+  std::size_t number_of_threads = std::thread::hardware_concurrency() * 10;
+  for (std::size_t i = 0; i < number_of_threads; ++i) {
+    threads.emplace_back(task, i + 1);
+  }
+
+  // Wait for threads to complete.
+  for (auto & thread : threads) {
+    thread.join();
+  }
+}