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

Implement thread-safe logging. #427

Draft
wants to merge 2 commits into
base: rolling
Choose a base branch
from
Draft
Show file tree
Hide file tree
Changes from all 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
15 changes: 15 additions & 0 deletions CMakeLists.txt
Original file line number Diff line number Diff line change
Expand Up @@ -42,10 +42,24 @@ if(NOT WIN32)
add_compile_options(-Wall -Wextra -Wconversion -Wno-sign-conversion -Wpedantic)
endif()

option(FORCE_STUB_RWLOCK "Force the use of a 'stub' rwlock implementation, which makes logging slower and inherently racy." OFF)

if(WIN32)
set(time_impl_c src/time_win32.c)
set(rwlock_impl_c src/rwlock_win32.c)
else()
set(time_impl_c src/time_unix.c)
find_package(Threads QUIET)
if(Threads_FOUND)
set(rwlock_impl_c src/rwlock_pthread.c)
else()
if(FORCE_STUB_RWLOCK)
set(rwlock_impl_c src/rwlock_stub.c)
add_definitions(-DRWLOCK_STUB)
else()
message(FATAL "No valid rwlock implementation found!")
endif()
endif()
endif()

set(rcutils_sources
Expand All @@ -63,6 +77,7 @@ set(rcutils_sources
src/process.c
src/qsort.c
src/repl_str.c
${rwlock_impl_c}
src/sha256.c
src/shared_library.c
src/snprintf.c
Expand Down
82 changes: 68 additions & 14 deletions src/logging.c
Original file line number Diff line number Diff line change
Expand Up @@ -49,6 +49,8 @@
#include "rcutils/time.h"
#include "rcutils/types/hash_map.h"

#include "./rwlock.h"


#define RCUTILS_LOGGING_SEPARATOR_CHAR '.'

Expand Down Expand Up @@ -90,6 +92,7 @@ static const char * g_rcutils_logging_default_output_format =
static rcutils_allocator_t g_rcutils_logging_allocator;

static rcutils_logging_output_handler_t g_rcutils_logging_output_handler = NULL;
static rcutils_rwlock_t g_rcutils_logging_map_lock;
static rcutils_hash_map_t g_rcutils_logging_severities_map;

// If this is false, attempts to use the severities map will be skipped.
Expand Down Expand Up @@ -645,6 +648,17 @@ rcutils_ret_t rcutils_logging_initialize_with_allocator(rcutils_allocator_t allo
return RCUTILS_RET_ERROR;
}

g_rcutils_logging_map_lock = rcutils_get_zero_initialized_rwlock();

if (rcutils_rwlock_init(&g_rcutils_logging_map_lock, allocator) != RCUTILS_RET_OK) {
RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING(
"Failed to initialize rwlock for logger severities [%s].", rcutils_get_error_string().str);
if (rcutils_hash_map_fini(&g_rcutils_logging_severities_map) != RCUTILS_RET_OK) {
RCUTILS_SAFE_FWRITE_TO_STDERR("Additionally, failed to free memory when cleaning up\n");
}
return RCUTILS_RET_ERROR;
}

parse_and_create_handlers_list();

g_rcutils_logging_severities_map_valid = true;
Expand All @@ -665,6 +679,7 @@ rcutils_ret_t rcutils_logging_shutdown(void)
// Iterate over the map, getting every key so we can free it
char * key = NULL;
int level;
rcutils_rwlock_write_lock(&g_rcutils_logging_map_lock);
rcutils_ret_t hash_map_ret = rcutils_hash_map_get_next_key_and_data(
&g_rcutils_logging_severities_map, NULL, &key, &level);
while (RCUTILS_RET_OK == hash_map_ret) {
Expand All @@ -688,6 +703,9 @@ rcutils_ret_t rcutils_logging_shutdown(void)
rcutils_get_error_string().str);
ret = RCUTILS_RET_LOGGING_SEVERITY_MAP_INVALID;
}
rcutils_rwlock_write_unlock(&g_rcutils_logging_map_lock);
rcutils_rwlock_fini(&g_rcutils_logging_map_lock);

g_rcutils_logging_severities_map_valid = false;
}
g_num_log_msg_handlers = 0;
Expand Down Expand Up @@ -775,6 +793,18 @@ static rcutils_ret_t add_key_to_hash_map(const char * name, int level, bool set_
// Check if key already exists, to avoid extra memory allocation
// If the key already exists, then rcutils_hash_map_set will not maintain the key we give it,
// so we do not need to copy the name
if (set_by_user) {
rcutils_rwlock_write_lock(&g_rcutils_logging_map_lock);
} else {
// In the specific case where this is not being set by the user, we know
// that this is a cache set. Just try to get the lock here; if we fail,
// the worst case is that we don't cache this in the map and we'll try
// again next time.
rcutils_ret_t lockret = rcutils_rwlock_write_trylock(&g_rcutils_logging_map_lock);
if (lockret != RCUTILS_RET_OK) {
return RCUTILS_RET_OK;
}
}
bool already_exists = rcutils_hash_map_key_exists(&g_rcutils_logging_severities_map, &copy_name);

if (!already_exists) {
Expand All @@ -783,6 +813,7 @@ static rcutils_ret_t add_key_to_hash_map(const char * name, int level, bool set_
if (copy_name == NULL) {
// Don't report an error to the error handling machinery; some uses of this function are for
// caching so this is not necessarily fatal.
rcutils_rwlock_write_unlock(&g_rcutils_logging_map_lock);
return RCUTILS_RET_ERROR;
}
}
Expand All @@ -800,16 +831,21 @@ static rcutils_ret_t add_key_to_hash_map(const char * name, int level, bool set_
RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING(
"Error setting severity level for logger named '%s': %s",
name, rcutils_get_error_string().str);
rcutils_rwlock_write_unlock(&g_rcutils_logging_map_lock);
return RCUTILS_RET_ERROR;
}

rcutils_rwlock_write_unlock(&g_rcutils_logging_map_lock);

return RCUTILS_RET_OK;
}

static rcutils_ret_t get_severity_level(const char * name, int * severity)
{
rcutils_rwlock_read_lock(&g_rcutils_logging_map_lock);
rcutils_ret_t ret =
rcutils_hash_map_get(&g_rcutils_logging_severities_map, &name, severity);
rcutils_rwlock_read_unlock(&g_rcutils_logging_map_lock);
if (ret != RCUTILS_RET_OK) {
// One possible response is RCUTILS_RET_NOT_FOUND, but the higher layers may be OK with that.
return ret;
Expand Down Expand Up @@ -845,7 +881,9 @@ int rcutils_logging_get_logger_leveln(const char * name, size_t name_length)
}

int severity;
rcutils_rwlock_read_lock(&g_rcutils_logging_map_lock);
rcutils_ret_t ret = get_severity_level(short_name, &severity);
rcutils_rwlock_read_unlock(&g_rcutils_logging_map_lock);
g_rcutils_logging_allocator.deallocate(short_name, g_rcutils_logging_allocator.state);
if (ret != RCUTILS_RET_OK) {
// The error message was already set by get_severity_level
Expand All @@ -863,8 +901,10 @@ int rcutils_logging_get_logger_effective_level(const char * name)
}

size_t hash_map_size;
rcutils_rwlock_read_lock(&g_rcutils_logging_map_lock);
rcutils_ret_t hash_map_ret = rcutils_hash_map_get_size(
&g_rcutils_logging_severities_map, &hash_map_size);
rcutils_rwlock_read_unlock(&g_rcutils_logging_map_lock);
if (hash_map_ret != RCUTILS_RET_OK) {
RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING(
"Error getting severity level for logger named '%s': %s",
Expand Down Expand Up @@ -943,20 +983,24 @@ int rcutils_logging_get_logger_effective_level(const char * name)
severity = g_rcutils_logging_default_logger_level;
}

// 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");
// }
// }
#if !defined(RWLOCK_STUB)
// If the RWLOCK implementation is a stub, this will definitely cause corruption, even between get
// calls, so we skip it (the consequence is that log level lookups are slower). With a stub
// RWLOCK there is still a race between get and set, but that is less common.

// 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");
}
}
#endif

return severity;
}
Expand Down Expand Up @@ -990,6 +1034,13 @@ rcutils_ret_t rcutils_logging_set_logger_level(const char * name, int level)

size_t name_length = strlen(name);

// TODO(clalancette): We could *almost* make this a read lock, except for the fact that the loop
// below might unset keys. If we find that this write lock is a bottleneck, we could split
// that unsetting of keys into a separate function which acquires the write lock itself.
// However, don't forget that when unlocking as read and relocking as write, you have to
// double-check that the thing you were operating on still exists (since it may have been
// changed in the meantime).
rcutils_rwlock_write_lock(&g_rcutils_logging_map_lock);
if (rcutils_hash_map_key_exists(&g_rcutils_logging_severities_map, &name)) {
// Iterate over the entire contents of the severities map, looking for entries that start with
// this key name. For any ones that match, check whether the user explicitly set them. If the
Expand Down Expand Up @@ -1029,6 +1080,7 @@ rcutils_ret_t rcutils_logging_set_logger_level(const char * name, int level)
RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING(
"Error accessing hash map when setting logger level for '%s': %s",
name, rcutils_get_error_string().str);
rcutils_rwlock_write_unlock(&g_rcutils_logging_map_lock);
return hash_map_ret;
}

Expand All @@ -1042,12 +1094,14 @@ rcutils_ret_t rcutils_logging_set_logger_level(const char * name, int level)
RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING(
"Error clearing old severity level for logger named '%s': %s",
name, rcutils_get_error_string().str);
rcutils_rwlock_write_unlock(&g_rcutils_logging_map_lock);
return unset_ret;
}
g_rcutils_logging_allocator.deallocate(previous_key, g_rcutils_logging_allocator.state);
}
}
}
rcutils_rwlock_write_unlock(&g_rcutils_logging_map_lock);

rcutils_ret_t add_key_ret = add_key_to_hash_map(name, level, true);
if (add_key_ret != RCUTILS_RET_OK) {
Expand Down
70 changes: 70 additions & 0 deletions src/rwlock.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,70 @@
// Copyright 2023 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 RWLOCK_H_
#define RWLOCK_H_

#ifdef __cplusplus
extern "C"
{
#endif

#include "rcutils/allocator.h"
#include "rcutils/types/rcutils_ret.h"
#include "rcutils/visibility_control.h"

struct rcutils_rwlock_impl_s;

typedef struct rwlock_s
{
struct rcutils_rwlock_impl_s * impl;
} rcutils_rwlock_t;

RCUTILS_PUBLIC
rcutils_rwlock_t
rcutils_get_zero_initialized_rwlock(void);

RCUTILS_PUBLIC
rcutils_ret_t
rcutils_rwlock_init(rcutils_rwlock_t * lock, rcutils_allocator_t allocator);

RCUTILS_PUBLIC
rcutils_ret_t
rcutils_rwlock_read_lock(rcutils_rwlock_t * lock);

RCUTILS_PUBLIC
rcutils_ret_t
rcutils_rwlock_read_unlock(rcutils_rwlock_t * lock);

RCUTILS_PUBLIC
rcutils_ret_t
rcutils_rwlock_write_lock(rcutils_rwlock_t * lock);

RCUTILS_PUBLIC
rcutils_ret_t
rcutils_rwlock_write_trylock(rcutils_rwlock_t * lock);

RCUTILS_PUBLIC
rcutils_ret_t
rcutils_rwlock_write_unlock(rcutils_rwlock_t * lock);

RCUTILS_PUBLIC
rcutils_ret_t
rcutils_rwlock_fini(rcutils_rwlock_t * lock);

#ifdef __cplusplus
}
#endif

#endif // RWLOCK_H_
Loading