protect access to global logging calls with a mutex

rclpy/CMakeLists.txt

@@ -102,9 +102,11 @@ install(TARGETS rclpy_common
   RUNTIME DESTINATION bin
 )
 
-add_library(
-  rclpy
-  SHARED src/rclpy/_rclpy.c
+add_library(rclpy SHARED
+  src/rclpy/_rclpy.c
+  src/rclpy/detail/execute_with_logging_mutex.cpp
+  src/rclpy/detail/logging_mutex.cpp
+  src/rclpy/detail/thread_safe_logging_output_handler.cpp
 )
 target_link_libraries(rclpy
   rclpy_common

rclpy/src/rclpy/_rclpy.c

@@ -42,6 +42,8 @@
 #include <rmw/validate_node_name.h>
 #include <rosidl_runtime_c/message_type_support_struct.h>
 
+#include "./detail/thread_safe_logging_output_handler.h"
+#include "./detail/execute_with_logging_mutex.h"
 #include "rclpy_common/common.h"
 #include "rclpy_common/handle.h"
 
@@ -640,7 +642,7 @@ rclpy_init(PyObject * Py_UNUSED(self), PyObject * args)
  * Raises RuntimeError if rcl logging could not be initialized
  */
 static PyObject *
-rclpy_logging_configure(PyObject * Py_UNUSED(self), PyObject * args)
+rclpy_logging_configure_impl(PyObject * Py_UNUSED(self), PyObject * args)
 {
   // Expect one argument, a context.
   PyObject * pycontext;
@@ -653,23 +655,33 @@ rclpy_logging_configure(PyObject * Py_UNUSED(self), PyObject * args)
     return NULL;
   }
   rcl_allocator_t allocator = rcl_get_default_allocator();
-  rcl_ret_t ret = rcl_logging_configure(
-    &context->global_arguments, &allocator);
+  rcl_ret_t ret = rcl_logging_configure_with_output_handler(
+    &context->global_arguments,
+    &allocator,
+    rclpy_detail_thread_safe_logging_output_handler);
   if (RCL_RET_OK != ret) {
     PyErr_Format(
       RCLError,
       "Failed to initialize logging: %s", rcl_get_error_string().str);
+    rcl_reset_error();
     return NULL;
   }
   Py_RETURN_NONE;
 }
 
+/// See rclpy_logging_configure_impl above.
+static PyObject *
+rclpy_logging_configure(PyObject * self, PyObject * args)
+{
+  return rclpy_detail_execute_with_logging_mutex(rclpy_logging_configure_impl, self, args);
+}
+
 /// Finalize rcl logging
 /**
- * Raises RuntimeError if rcl logging could not be finalized
+ * Produces a RuntimeWarning if rcl logging could not be finalized
  */
 static PyObject *
-rclpy_logging_fini(PyObject * Py_UNUSED(self), PyObject * Py_UNUSED(args))
+rclpy_logging_fini_impl(PyObject * Py_UNUSED(self), PyObject * Py_UNUSED(args))
 {
   rcl_ret_t ret = rcl_logging_fini();
   if (RCL_RET_OK != ret) {
@@ -679,14 +691,22 @@ rclpy_logging_fini(PyObject * Py_UNUSED(self), PyObject * Py_UNUSED(args))
       stack_level,
       "Failed to fini logging: %s",
       rcl_get_error_string().str);
+    rcl_reset_error();
     return NULL;
   }
   Py_RETURN_NONE;
 }
 
+/// See rclpy_logging_fini_impl above.
+static PyObject *
+rclpy_logging_fini(PyObject * self, PyObject * args)
+{
+  return rclpy_detail_execute_with_logging_mutex(rclpy_logging_fini_impl, self, args);
+}
+
 /// Handle destructor for node
 static void
-_rclpy_destroy_node(void * p)
+_rclpy_destroy_node_impl(void * p)
 {
   rcl_node_t * node = p;
   if (!node) {
@@ -708,6 +728,13 @@ _rclpy_destroy_node(void * p)
   PyMem_Free(node);
 }
 
+/// See _rclpy_destroy_node_impl above.
+static void
+_rclpy_destroy_node(void * p)
+{
+  rclpy_detail_execute_with_logging_mutex2(_rclpy_destroy_node_impl, p);
+}
+
 /// Create a node
 /**
  * Raises ValueError if the node name or namespace is invalid
@@ -720,7 +747,7 @@ _rclpy_destroy_node(void * p)
  * \return NULL on failure
  */
 static PyObject *
-rclpy_create_node(PyObject * Py_UNUSED(self), PyObject * args)
+rclpy_create_node_impl(PyObject * Py_UNUSED(self), PyObject * args)
 {
   rcl_ret_t ret;
   const char * node_name;
@@ -827,6 +854,13 @@ rclpy_create_node(PyObject * Py_UNUSED(self), PyObject * args)
   return node_capsule;
 }
 
+/// See rclpy_create_node_impl above.
+static PyObject *
+rclpy_create_node(PyObject * self, PyObject * args)
+{
+  return rclpy_detail_execute_with_logging_mutex(rclpy_create_node_impl, self, args);
+}
+
 /// Get the name of a node.
 /**
  * Raises ValueError if pynode is not a node capsule

rclpy/src/rclpy/detail/execute_with_logging_mutex.cpp

@@ -0,0 +1,72 @@
+// Copyright 2020 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 "./execute_with_logging_mutex.h"  // NOLINT(build/include)
+
+// Must be before Python.h; makes #-formats use ssize_t instead of int
+#define PY_SSIZE_T_CLEAN
+#include <Python.h>
+
+#include "rcutils/logging.h"
+#include "rcutils/visibility_control_macros.h"
+
+#include "./logging_mutex.hpp"
+
+extern "C"
+{
+PyObject *
+rclpy_detail_execute_with_logging_mutex(
+  rclpy_detail_execute_with_logging_mutex_sig function,
+  PyObject * self,
+  PyObject * args)
+{
+  try {
+    std::lock_guard<std::recursive_mutex> guard(rclpy::detail::get_global_logging_mutex());
+    return function(self, args);
+  } catch (std::exception & ex) {
+    PyErr_Format(
+      PyExc_RuntimeError,
+      "Failed to acquire logging mutex: %s", ex.what());
+    return NULL;
+  } catch (...) {
+    PyErr_Format(
+      PyExc_RuntimeError,
+      "Failed to acquire logging mutex");
+    return NULL;
+  }
+}
+
+void
+rclpy_detail_execute_with_logging_mutex2(
+  rclpy_detail_execute_with_logging_mutex_sig2 function,
+  void * arg)
+{
+  try {
+    std::lock_guard<std::recursive_mutex> guard(rclpy::detail::get_global_logging_mutex());
+    function(arg);
+  } catch (std::exception & ex) {
+    // Warning should use line number of the current stack frame
+    int stack_level = 1;
+    PyErr_WarnFormat(
+      PyExc_RuntimeWarning, stack_level,
+      "Failed to acquire logging mutex: %s", ex.what());
+  } catch (...) {
+    // Warning should use line number of the current stack frame
+    int stack_level = 1;
+    PyErr_WarnFormat(
+      PyExc_RuntimeWarning, stack_level,
+      "Failed to acquire logging mutex");
+  }
+}
+}  // extern "C"

rclpy/src/rclpy/detail/execute_with_logging_mutex.h

@@ -0,0 +1,56 @@
+// Copyright 2020 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 RCLPY__DETAIL__EXECUTE_WITH_LOGGING_MUTEX_H_
+#define RCLPY__DETAIL__EXECUTE_WITH_LOGGING_MUTEX_H_
+
+// Must be before Python.h; makes #-formats use ssize_t instead of int
+#define PY_SSIZE_T_CLEAN
+#include <Python.h>
+
+#include "rcutils/logging.h"
+#include "rcutils/visibility_control_macros.h"
+
+#ifdef __cplusplus
+extern "C"
+{
+#endif
+
+typedef PyObject * (* rclpy_detail_execute_with_logging_mutex_sig)(PyObject *, PyObject *);
+
+/// Execute the given function pointer after acquiring the logging mutex.
+RCUTILS_LOCAL
+PyObject *
+rclpy_detail_execute_with_logging_mutex(
+  rclpy_detail_execute_with_logging_mutex_sig function,
+  PyObject * self,
+  PyObject * args);
+
+typedef void (* rclpy_detail_execute_with_logging_mutex_sig2)(void *);
+
+/// Execute the given function pointer after acquiring the logging mutex.
+/**
+ * This version has a slightly different signature which is used when destroying a node.
+ */
+RCUTILS_LOCAL
+void
+rclpy_detail_execute_with_logging_mutex2(
+  rclpy_detail_execute_with_logging_mutex_sig2 function,
+  void * arg);
+
+#ifdef __cplusplus
+}  // extern "C"
+#endif
+
+#endif  // RCLPY__DETAIL__EXECUTE_WITH_LOGGING_MUTEX_H_

rclpy/src/rclpy/detail/logging_mutex.cpp

@@ -0,0 +1,27 @@
+// Copyright 2020 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 "./logging_mutex.hpp"
+
+#include <memory>
+#include <mutex>
+
+#include "rcutils/macros.h"
+
+std::recursive_mutex &
+rclpy::detail::get_global_logging_mutex()
+{
+  static std::recursive_mutex mutex;
+  return mutex;
+}

rclpy/src/rclpy/detail/logging_mutex.hpp

@@ -0,0 +1,47 @@
+// Copyright 2020 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 RCLPY__DETAIL__LOGGING_MUTEX_HPP_
+#define RCLPY__DETAIL__LOGGING_MUTEX_HPP_
+
+#include <memory>
+#include <mutex>
+
+#include "rcutils/visibility_control_macros.h"
+
+namespace rclpy
+{
+namespace detail
+{
+
+/// Global logging mutex
+/**
+ * This mutex is locked in the following situations:
+ *   - In initialization/destruction of contexts.
+ *   - In initialization/destruction of nodes.
+ *   - In the rcl logging output handler installed by rclpy,
+ *     i.e.: in all calls to the logger macros, including RCUTILS_* ones.
+ */
+// Implementation detail:
+// A shared pointer to the mutex is used, so that objects that need to use
+// it at destruction time can keep it alive.
+// In that way, a destruction ordering problem between static objects is avoided.
+RCUTILS_LOCAL
+std::recursive_mutex &
+get_global_logging_mutex();
+
+}  // namespace detail
+}  // namespace rclpy
+
+#endif  // RCLPY__DETAIL__LOGGING_MUTEX_HPP_

rclpy/src/rclpy/detail/thread_safe_logging_output_handler.cpp

@@ -0,0 +1,43 @@
+// Copyright 2020 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 "./thread_safe_logging_output_handler.h"  // NOLINT(build/include)
+
+#include "rcl/logging.h"
+
+#include "./logging_mutex.hpp"
+
+extern "C"
+{
+void
+rclpy_detail_thread_safe_logging_output_handler(
+  const rcutils_log_location_t * location,
+  int severity,
+  const char * name,
+  rcutils_time_point_value_t timestamp,
+  const char * format,
+  va_list * args)
+{
+  try {
+    std::lock_guard<std::recursive_mutex> guard(rclpy::detail::get_global_logging_mutex());
+    rcl_logging_multiple_output_handler(location, severity, name, timestamp, format, args);
+  } catch (std::exception & ex) {
+    RCUTILS_SAFE_FWRITE_TO_STDERR("rclpy failed to get the global logging mutex: ");
+    RCUTILS_SAFE_FWRITE_TO_STDERR(ex.what());
+    RCUTILS_SAFE_FWRITE_TO_STDERR("\n");
+  } catch (...) {
+    RCUTILS_SAFE_FWRITE_TO_STDERR("rclpy failed to get the global logging mutex\n");
+  }
+}
+}  // extern "C"