Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix thread safety issues related to logging #1125

Merged
merged 7 commits into from
May 22, 2020
Merged
Show file tree
Hide file tree
Changes from 6 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions rclcpp/CMakeLists.txt
Original file line number Diff line number Diff line change
Expand Up @@ -54,6 +54,7 @@ set(${PROJECT_NAME}_SRCS
src/rclcpp/init_options.cpp
src/rclcpp/intra_process_manager.cpp
src/rclcpp/logger.cpp
src/rclcpp/logging_mutex.cpp
src/rclcpp/memory_strategies.cpp
src/rclcpp/memory_strategy.cpp
src/rclcpp/message_info.cpp
Expand Down
4 changes: 2 additions & 2 deletions rclcpp/include/rclcpp/context.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -338,8 +338,8 @@ class Context : public std::enable_shared_from_this<Context>
rclcpp::InitOptions init_options_;
std::string shutdown_reason_;

// Keep shared ownership of global logging configure mutex.
std::shared_ptr<std::mutex> logging_configure_mutex_;
// Keep shared ownership of the global logging mutex.
std::shared_ptr<std::recursive_mutex> logging_mutex_;

std::unordered_map<std::type_index, std::shared_ptr<void>> sub_contexts_;
// This mutex is recursive so that the constructor of a sub context may
Expand Down
64 changes: 42 additions & 22 deletions rclcpp/src/rclcpp/context.cpp
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
// Copyright 2015 Open Source Robotics Foundation, Inc.
// Copyright 2015-2020 Open Source Robotics Foundation, Inc.
wjwwood marked this conversation as resolved.
Show resolved Hide resolved
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
Expand All @@ -23,38 +23,60 @@

#include "rcl/init.h"
#include "rcl/logging.h"

#include "rclcpp/detail/utilities.hpp"
#include "rclcpp/exceptions.hpp"
#include "rclcpp/logging.hpp"

#include "rcutils/error_handling.h"
#include "rcutils/macros.h"

#include "rmw/impl/cpp/demangle.hpp"

#include "./logging_mutex.hpp"

/// Mutex to protect initialized contexts.
static std::mutex g_contexts_mutex;
/// Weak list of context to be shutdown by the signal handler.
static std::vector<std::weak_ptr<rclcpp::Context>> g_contexts;

using rclcpp::Context;

static
std::shared_ptr<std::mutex>
get_global_logging_configure_mutex()
{
static auto mutex = std::make_shared<std::mutex>();
return mutex;
}

static
/// Count of contexts that wanted to initialize the logging system.
size_t &
get_logging_reference_count()
{
static size_t ref_count = 0;
return ref_count;
}

using rclcpp::Context;

extern "C"
{
static
void
rclcpp_logging_output_handler(
ivanpauno marked this conversation as resolved.
Show resolved Hide resolved
const rcutils_log_location_t * location,
int severity, const char * name, rcutils_time_point_value_t timestamp,
const char * format, va_list * args)
{
try {
ivanpauno marked this conversation as resolved.
Show resolved Hide resolved
std::shared_ptr<std::recursive_mutex> logging_mutex;
logging_mutex = get_global_logging_mutex();
std::lock_guard<std::recursive_mutex> guard(*logging_mutex);
return rcl_logging_multiple_output_handler(
location, severity, name, timestamp, format, args);
} catch (std::exception & ex) {
RCUTILS_SAFE_FWRITE_TO_STDERR(ex.what());
ivanpauno marked this conversation as resolved.
Show resolved Hide resolved
} catch (...) {
RCUTILS_SAFE_FWRITE_TO_STDERR("failed to take global rclcpp logging mutex\n");
}
ivanpauno marked this conversation as resolved.
Show resolved Hide resolved
}
} // extern "C"

Context::Context()
: rcl_context_(nullptr),
shutdown_reason_(""),
logging_configure_mutex_(nullptr)
logging_mutex_(nullptr)
{}

Context::~Context()
Expand Down Expand Up @@ -116,16 +138,14 @@ Context::init(
}

if (init_options.auto_initialize_logging()) {
logging_configure_mutex_ = get_global_logging_configure_mutex();
if (!logging_configure_mutex_) {
throw std::runtime_error("global logging configure mutex is 'nullptr'");
}
std::lock_guard<std::mutex> guard(*logging_configure_mutex_);
logging_mutex_ = get_global_logging_mutex();
std::lock_guard<std::recursive_mutex> guard(*logging_mutex_);
size_t & count = get_logging_reference_count();
if (0u == count) {
ret = rcl_logging_configure(
ret = rcl_logging_configure_with_output_handler(
&rcl_context_->global_arguments,
rcl_init_options_get_allocator(init_options_.get_rcl_init_options()));
rcl_init_options_get_allocator(init_options_.get_rcl_init_options()),
rclcpp_logging_output_handler);
if (RCL_RET_OK != ret) {
rcl_context_.reset();
rclcpp::exceptions::throw_from_rcl_error(ret, "failed to configure logging");
Expand Down Expand Up @@ -228,9 +248,9 @@ Context::shutdown(const std::string & reason)
}
}
// shutdown logger
if (logging_configure_mutex_) {
if (logging_mutex_) {
// logging was initialized by this context
std::lock_guard<std::mutex> guard(*logging_configure_mutex_);
std::lock_guard<std::recursive_mutex> guard(*logging_mutex_);
size_t & count = get_logging_reference_count();
if (0u == --count) {
rcl_ret_t rcl_ret = rcl_logging_fini();
Expand Down
28 changes: 28 additions & 0 deletions rclcpp/src/rclcpp/logging_mutex.cpp
Original file line number Diff line number Diff line change
@@ -0,0 +1,28 @@
// 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 <memory>
#include <mutex>

#include "rcutils/macros.h"

std::shared_ptr<std::recursive_mutex>
get_global_logging_mutex()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I just noticed that this does not include the header file that defines this symbol, should it not?

{
static auto mutex = std::make_shared<std::recursive_mutex>();
if (RCUTILS_UNLIKELY(!mutex)) {
throw std::runtime_error("rclcpp global logging mutex is a nullptr");
}
return mutex;
}
39 changes: 39 additions & 0 deletions rclcpp/src/rclcpp/logging_mutex.hpp
Original file line number Diff line number Diff line change
@@ -0,0 +1,39 @@
// 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 RCLCPP__LOGGING_MUTEX_HPP_
#define RCLCPP__LOGGING_MUTEX_HPP_

#include <memory>
#include <mutex>

#include "rclcpp/visibility_control.hpp"

/// 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 rclcpp,
* 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 hold it alive.
// In that way, a destruction ordering problem between static objects is avoided.
wjwwood marked this conversation as resolved.
Show resolved Hide resolved
RCLCPP_LOCAL
std::shared_ptr<std::recursive_mutex>
get_global_logging_mutex();

#endif // RCLCPP__LOGGING_MUTEX_HPP_
23 changes: 18 additions & 5 deletions rclcpp/src/rclcpp/node_interfaces/node_base.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,8 @@
#include "rmw/validate_namespace.h"
#include "rmw/validate_node_name.h"

#include "../logging_mutex.hpp"

using rclcpp::exceptions::throw_from_rcl_error;

using rclcpp::node_interfaces::NodeBase;
Expand Down Expand Up @@ -65,10 +67,17 @@ NodeBase::NodeBase(
// Create the rcl node and store it in a shared_ptr with a custom destructor.
std::unique_ptr<rcl_node_t> rcl_node(new rcl_node_t(rcl_get_zero_initialized_node()));

ret = rcl_node_init(
rcl_node.get(),
node_name.c_str(), namespace_.c_str(),
context_->get_rcl_context().get(), &rcl_node_options);
std::shared_ptr<std::recursive_mutex> logging_mutex = get_global_logging_mutex();
{
std::lock_guard<std::recursive_mutex> guard(*logging_mutex);
// TODO(ivanpauno): Instead of mutually excluding rcl_node_init with the global logger mutex,
// rcl_logging_rosout_init_publisher_for_node could be decoupled from there and be called
// here directly.
ret = rcl_node_init(
rcl_node.get(),
node_name.c_str(), namespace_.c_str(),
context_->get_rcl_context().get(), &rcl_node_options);
}
if (ret != RCL_RET_OK) {
// Finalize the interrupt guard condition.
finalize_notify_guard_condition();
Expand Down Expand Up @@ -123,7 +132,11 @@ NodeBase::NodeBase(

node_handle_.reset(
rcl_node.release(),
[](rcl_node_t * node) -> void {
[logging_mutex](rcl_node_t * node) -> void {
std::lock_guard<std::recursive_mutex> guard(*logging_mutex);
// TODO(ivanpauno): Instead of mutually excluding rcl_node_fini with the global logger mutex,
// rcl_logging_rosout_fini_publisher_for_node could be decoupled from there and be called
// here directly.
if (rcl_node_fini(node) != RCL_RET_OK) {
RCUTILS_LOG_ERROR_NAMED(
"rclcpp",
Expand Down