From 34724ab51bc5898189d200895e13035c87720cff Mon Sep 17 00:00:00 2001 From: Chris Lalancette Date: Tue, 16 Aug 2022 12:01:52 +0000 Subject: [PATCH 1/7] Add in tests for changing ancestor severity level. Signed-off-by: Chris Lalancette --- test/test_logging.cpp | 88 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 88 insertions(+) diff --git a/test/test_logging.cpp b/test/test_logging.cpp index 50cc5aed..9309e598 100644 --- a/test/test_logging.cpp +++ b/test/test_logging.cpp @@ -321,3 +321,91 @@ TEST(TestLogging, test_logger_severity_hierarchy) { rcutils_test_logging_cpp_dot_severity, rcutils_logging_get_logger_effective_level("rcutils_test_logging_cpp..")); } + +TEST(TestLogging, test_logger_unset_change_ancestor) { + ASSERT_EQ(RCUTILS_RET_OK, rcutils_logging_initialize()); + OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT( + { + EXPECT_EQ(RCUTILS_RET_OK, rcutils_logging_shutdown()); + }); + + // check resolving of effective thresholds in hierarchy of loggers + rcutils_logging_set_default_logger_level(RCUTILS_LOG_SEVERITY_INFO); + + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + "rcutils_test_logging_cpp", RCUTILS_LOG_SEVERITY_WARN)); + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + "rcutils_test_logging_cpp.x", RCUTILS_LOG_SEVERITY_UNSET)); + + EXPECT_EQ( + RCUTILS_LOG_SEVERITY_WARN, + rcutils_logging_get_logger_effective_level("rcutils_test_logging_cpp")); + EXPECT_EQ( + RCUTILS_LOG_SEVERITY_WARN, + rcutils_logging_get_logger_effective_level( + "rcutils_test_logging_cpp.x")); + + // Now change the logger level of the ancestor. This should cause the + // higher-level one to change as well (since it is unset). + + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + "rcutils_test_logging_cpp", RCUTILS_LOG_SEVERITY_DEBUG)); + + EXPECT_EQ( + RCUTILS_LOG_SEVERITY_DEBUG, + rcutils_logging_get_logger_effective_level("rcutils_test_logging_cpp")); + EXPECT_EQ( + RCUTILS_LOG_SEVERITY_DEBUG, + rcutils_logging_get_logger_effective_level( + "rcutils_test_logging_cpp.x")); +} + +TEST(TestLogging, test_logger_set_change_ancestor) { + ASSERT_EQ(RCUTILS_RET_OK, rcutils_logging_initialize()); + OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT( + { + EXPECT_EQ(RCUTILS_RET_OK, rcutils_logging_shutdown()); + }); + + // check resolving of effective thresholds in hierarchy of loggers + rcutils_logging_set_default_logger_level(RCUTILS_LOG_SEVERITY_INFO); + + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + "rcutils_test_logging_cpp", RCUTILS_LOG_SEVERITY_WARN)); + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + "rcutils_test_logging_cpp.x", RCUTILS_LOG_SEVERITY_FATAL)); + + EXPECT_EQ( + RCUTILS_LOG_SEVERITY_WARN, + rcutils_logging_get_logger_effective_level("rcutils_test_logging_cpp")); + EXPECT_EQ( + RCUTILS_LOG_SEVERITY_FATAL, + rcutils_logging_get_logger_effective_level( + "rcutils_test_logging_cpp.x")); + + // Now change the logger level of the ancestor. This should not change + // the level of the descendant, since it was set separately. + + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + "rcutils_test_logging_cpp", RCUTILS_LOG_SEVERITY_DEBUG)); + + EXPECT_EQ( + RCUTILS_LOG_SEVERITY_DEBUG, + rcutils_logging_get_logger_effective_level("rcutils_test_logging_cpp")); + EXPECT_EQ( + RCUTILS_LOG_SEVERITY_FATAL, + rcutils_logging_get_logger_effective_level( + "rcutils_test_logging_cpp.x")); +} From 28fe626924ef4c498a42f8fa22ee2fce3e906f1a Mon Sep 17 00:00:00 2001 From: Chris Lalancette Date: Wed, 17 Aug 2022 18:11:13 +0000 Subject: [PATCH 2/7] Revamp error handling in parse_and_create_handlers_list. This makes the code shorter and much more consistent. Signed-off-by: Chris Lalancette --- src/logging.c | 60 ++++++++++++++++++++------------------------------- 1 file changed, 23 insertions(+), 37 deletions(-) diff --git a/src/logging.c b/src/logging.c index 00e1853e..63f5e073 100644 --- a/src/logging.c +++ b/src/logging.c @@ -414,6 +414,21 @@ static const char * copy_from_orig( return logging_output->buffer; } +static bool add_handler(token_handler handler, size_t start_offset, size_t end_offset) +{ + g_handlers[g_num_log_msg_handlers].handler = handler; + g_handlers[g_num_log_msg_handlers].start_offset = start_offset; + g_handlers[g_num_log_msg_handlers].end_offset = end_offset; + if (g_num_log_msg_handlers >= sizeof(g_handlers) - 1) { + RCUTILS_SET_ERROR_MSG("Too many substitutions in the logging output format string; truncating"); + return false; + } + + g_num_log_msg_handlers++; + + return true; +} + static void parse_and_create_handlers_list(void) { // Process the format string looking for known tokens. @@ -435,17 +450,10 @@ static void parse_and_create_handlers_list(void) if (chars_to_start_delim > 0) { // there is stuff before a token start delimiter size_t chars_to_copy = chars_to_start_delim > remaining_chars ? remaining_chars : chars_to_start_delim; - g_handlers[g_num_log_msg_handlers].handler = copy_from_orig; - g_handlers[g_num_log_msg_handlers].start_offset = i; - g_handlers[g_num_log_msg_handlers].end_offset = i + chars_to_copy; - if (g_num_log_msg_handlers >= sizeof(g_handlers) - 1) { - RCUTILS_SAFE_FWRITE_TO_STDERR( - "Too many substitutions in the logging output format string; truncating"); - rcutils_reset_error(); - RCUTILS_SAFE_FWRITE_TO_STDERR("\n"); + if (!add_handler(copy_from_orig, i, i + chars_to_copy)) { + // The error was already set by add_handler return; } - g_num_log_msg_handlers++; i += chars_to_copy; if (i >= size) { // perhaps no start delimiter was found @@ -466,17 +474,10 @@ static void parse_and_create_handlers_list(void) if (chars_to_end_delim > remaining_chars) { // No end delimiters found in the remainder of the format string; // there won't be any more tokens so shortcut the rest of the checking. - g_handlers[g_num_log_msg_handlers].handler = copy_from_orig; - g_handlers[g_num_log_msg_handlers].start_offset = i; - g_handlers[g_num_log_msg_handlers].end_offset = i + remaining_chars; - if (g_num_log_msg_handlers >= sizeof(g_handlers) - 1) { - RCUTILS_SAFE_FWRITE_TO_STDERR( - "Too many substitutions in the logging output format string; truncating"); - rcutils_reset_error(); - RCUTILS_SAFE_FWRITE_TO_STDERR("\n"); + if (!add_handler(copy_from_orig, i, i + remaining_chars)) { + // The error was already set by add_handler return; } - g_num_log_msg_handlers++; break; } @@ -490,33 +491,18 @@ static void parse_and_create_handlers_list(void) if (!expand_token) { // This wasn't a token; print the start delimiter and continue the search as usual // (the substring might contain more start delimiters). - g_handlers[g_num_log_msg_handlers].handler = copy_from_orig; - g_handlers[g_num_log_msg_handlers].start_offset = i; - g_handlers[g_num_log_msg_handlers].end_offset = i + 1; - if (g_num_log_msg_handlers >= sizeof(g_handlers) - 1) { - RCUTILS_SAFE_FWRITE_TO_STDERR( - "Too many substitutions in the logging output format string; truncating"); - rcutils_reset_error(); - RCUTILS_SAFE_FWRITE_TO_STDERR("\n"); + if (!add_handler(copy_from_orig, i, i + 1)) { + // The error was already set by add_handler return; } - g_num_log_msg_handlers++; i++; continue; } - g_handlers[g_num_log_msg_handlers].handler = expand_token; - // These are unused when using a token expander - g_handlers[g_num_log_msg_handlers].start_offset = 0; - g_handlers[g_num_log_msg_handlers].end_offset = 0; - if (g_num_log_msg_handlers >= sizeof(g_handlers) - 1) { - RCUTILS_SAFE_FWRITE_TO_STDERR( - "Too many substitutions in the logging output format string; truncating"); - rcutils_reset_error(); - RCUTILS_SAFE_FWRITE_TO_STDERR("\n"); + if (!add_handler(expand_token, 0, 0)) { + // The error was already set by add_handler return; } - g_num_log_msg_handlers++; // Skip ahead to avoid re-processing the token characters (including the 2 delimiters). i += token_len + 2; From 236c12f7b288d951fff8beb395ec72dc324a2314 Mon Sep 17 00:00:00 2001 From: Chris Lalancette Date: Thu, 4 Aug 2022 21:52:43 +0000 Subject: [PATCH 3/7] Optimize rcutils_logging_get_logger_effective_level(). This function is the most expensive part of rcutils_logging_logger_is_enabled_for(), which is called on every RCUTILS_LOG_* invocation. We notice a couple of things: 1. The current name -> logger level lookup is using a "string map" structure. A "string map" isn't a map at all, but is really a linear array of strings. Thus searching it can be slow when there are a lot of strings in the map. Since this is a global map, this can happen when many ROS 2 nodes are loaded in to the same process. 2. When looking up the severity of a particular name, we need to check the full name, plus any ancestors (separated by '.') to find the severity level. This requires a bunch of work, including copying a string, running strlen on it, searching through it for periods, etc. This can be expensive, and in the common case it isn't needed; the fully-qualified string is usually in the map already. To fix both of these, we switch to a hash map, and look up the current logger level via the hash map. If the full logger name isn't in the hash map, we fall back to the slow path where we do the additional work of finding the severity via the hierarchy. Note that even in this slow path, once we've computed the severity level we place that in the map as well so that subsequent lookups will take the fast path. The benchmarks I ran on this change give very good improvements for most cases. For cases where there are multiple set logger names, and those logger names have ancestors, this change is ~9x faster than the current implementation. For cases where there are multiple set logger names and those logger names have no ancestors (one of the most common cases in ROS 2), this change is ~3x faster than the current implementation. For cases where we have a single logger name (another common case), this change is ~2x faster than the current implementation. Finally, note that rcutils_logging_set_logger_level() is more expensive than before, due to having to traverse the hash map to find other logger names in the hierarchy. Since we don't expect users to change logger levels often, this tradeoff seems worth it to speed up lookups (which are called for every log message). Signed-off-by: Chris Lalancette --- src/logging.c | 283 +++++++++++++++++++++++++++++++++++------- test/test_logging.cpp | 31 ++++- 2 files changed, 268 insertions(+), 46 deletions(-) diff --git a/src/logging.c b/src/logging.c index 63f5e073..266f8d7c 100644 --- a/src/logging.c +++ b/src/logging.c @@ -47,7 +47,7 @@ #include "rcutils/strdup.h" #include "rcutils/strerror.h" #include "rcutils/time.h" -#include "rcutils/types/string_map.h" +#include "rcutils/types/hash_map.h" #define RCUTILS_LOGGING_SEPARATOR_CHAR '.' @@ -90,7 +90,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_string_map_t g_rcutils_logging_severities_map; +static rcutils_hash_map_t g_rcutils_logging_severities_map; // If this is false, attempts to use the severities map will be skipped. // This can happen if allocation of the map fails at initialization. @@ -631,16 +631,17 @@ rcutils_ret_t rcutils_logging_initialize_with_allocator(rcutils_allocator_t allo memcpy(g_rcutils_logging_output_format_string, output_format, chars_to_copy); g_rcutils_logging_output_format_string[chars_to_copy] = '\0'; - g_rcutils_logging_severities_map = rcutils_get_zero_initialized_string_map(); - rcutils_ret_t string_map_ret = rcutils_string_map_init( - &g_rcutils_logging_severities_map, 0, g_rcutils_logging_allocator); - if (string_map_ret != RCUTILS_RET_OK) { - // If an error message was set it will have been overwritten by rcutils_string_map_init. + g_rcutils_logging_severities_map = rcutils_get_zero_initialized_hash_map(); + rcutils_ret_t hash_map_ret = rcutils_hash_map_init( + &g_rcutils_logging_severities_map, 2, sizeof(const char *), sizeof(int), + rcutils_hash_map_string_hash_func, rcutils_hash_map_string_cmp_func, &allocator); + if (hash_map_ret != RCUTILS_RET_OK) { + // If an error message was set it will have been overwritten by rcutils_hash_map_init. RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING( "Failed to initialize map for logger severities [%s]. Severities will not be configurable.", rcutils_get_error_string().str); g_rcutils_logging_severities_map_valid = false; - return RCUTILS_RET_STRING_MAP_INVALID; + return RCUTILS_RET_ERROR; } parse_and_create_handlers_list(); @@ -657,10 +658,30 @@ rcutils_ret_t rcutils_logging_shutdown(void) if (!g_rcutils_logging_initialized) { return RCUTILS_RET_OK; } + rcutils_ret_t ret = RCUTILS_RET_OK; if (g_rcutils_logging_severities_map_valid) { - rcutils_ret_t string_map_ret = rcutils_string_map_fini(&g_rcutils_logging_severities_map); - if (string_map_ret != RCUTILS_RET_OK) { + // Iterate over the map, getting every key so we can free it + char * key = NULL; + int level; + 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) { + hash_map_ret = rcutils_hash_map_unset(&g_rcutils_logging_severities_map, &key); + if (hash_map_ret != RCUTILS_RET_OK) { + RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING( + "Failed to clear out logger severities [%s] during shutdown; memory will be leaked.", + rcutils_get_error_string().str); + break; + } + g_rcutils_logging_allocator.deallocate(key, g_rcutils_logging_allocator.state); + + hash_map_ret = rcutils_hash_map_get_next_key_and_data( + &g_rcutils_logging_severities_map, NULL, &key, &level); + } + + hash_map_ret = rcutils_hash_map_fini(&g_rcutils_logging_severities_map); + if (hash_map_ret != RCUTILS_RET_OK) { RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING( "Failed to finalize map for logger severities: %s", rcutils_get_error_string().str); @@ -747,6 +768,51 @@ int rcutils_logging_get_logger_level(const char * name) return rcutils_logging_get_logger_leveln(name, strlen(name)); } +static rcutils_ret_t add_key_to_hash_map(const char * name, int level, bool set_by_user) +{ + // Copy the name that we will store, as there is no guarantee that the caller will keep it around. + + char * copy_name = rcutils_strdup(name, g_rcutils_logging_allocator); + 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. + return RCUTILS_RET_ERROR; + } + + if (set_by_user) { + // If the level was set by the user (rather than optimistically cached by the implementation), + // mark it here. When we purge the cache, we'll make sure not to purge these. The mark we + // use is setting the bottom bit; since our levels are 0, 10, 20, 30, 40, and 50, this works. + level |= 0x1; + } + + rcutils_ret_t hash_map_ret = + rcutils_hash_map_set(&g_rcutils_logging_severities_map, ©_name, &level); + if (hash_map_ret != RCUTILS_RET_OK) { + RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING( + "Error setting severity level for logger named '%s': %s", + name, rcutils_get_error_string().str); + return RCUTILS_RET_ERROR; + } + + return RCUTILS_RET_OK; +} + +static rcutils_ret_t get_severity_level(const char * name, int * severity) +{ + rcutils_ret_t ret = + rcutils_hash_map_get(&g_rcutils_logging_severities_map, &name, severity); + if (ret != RCUTILS_RET_OK) { + // One possible response is RCUTILS_RET_NOT_FOUND, but the higher layers may be OK with that. + return ret; + } + + // See the comment in add_key_to_hash_map() on why we remove the bottom bit. + (*severity) &= ~(0x1); + + return RCUTILS_RET_OK; +} + int rcutils_logging_get_logger_leveln(const char * name, size_t name_length) { RCUTILS_LOGGING_AUTOINIT; @@ -763,25 +829,21 @@ int rcutils_logging_get_logger_leveln(const char * name, size_t name_length) return RCUTILS_LOG_SEVERITY_UNSET; } - // TODO(dhood): replace string map with int map. - const char * severity_string = rcutils_string_map_getn( - &g_rcutils_logging_severities_map, name, name_length); - if (NULL == severity_string) { - if (rcutils_string_map_key_existsn(&g_rcutils_logging_severities_map, name, name_length)) { - // The level has been specified but couldn't be retrieved. - return -1; - } - return RCUTILS_LOG_SEVERITY_UNSET; + char * short_name = rcutils_strndup(name, name_length, g_rcutils_logging_allocator); + if (short_name == NULL) { + RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING( + "Failed to allocate memory when looking up logger level for '%s'", name); + return -1; } int severity; - rcutils_ret_t ret = rcutils_logging_severity_level_from_string( - severity_string, g_rcutils_logging_allocator, &severity); - if (RCUTILS_RET_OK != ret) { - RCUTILS_SAFE_FWRITE_TO_STDERR_WITH_FORMAT_STRING( - "Logger has an invalid severity level: %s\n", severity_string); - return -1; + rcutils_ret_t ret = get_severity_level(short_name, &severity); + 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 + return RCUTILS_LOG_SEVERITY_UNSET; } + return severity; } @@ -791,30 +853,102 @@ int rcutils_logging_get_logger_effective_level(const char * name) if (NULL == name) { return -1; } - size_t substring_length = strlen(name); - while (true) { - int severity = rcutils_logging_get_logger_leveln(name, substring_length); - if (-1 == severity) { - RCUTILS_SAFE_FWRITE_TO_STDERR_WITH_FORMAT_STRING( - "Error getting effective level of logger '%s'\n", name); - return -1; - } + + size_t hash_map_size; + rcutils_ret_t hash_map_ret = rcutils_hash_map_get_size( + &g_rcutils_logging_severities_map, &hash_map_size); + if (hash_map_ret != RCUTILS_RET_OK) { + RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING( + "Error getting severity level for logger named '%s': %s", + name, rcutils_get_error_string().str); + return -1; + } + + if (hash_map_size == 0) { + // The reason we do this extra check here is a bit tricky. The call to get_severity_level() + // below calls rcutils_hash_map_get(), which already has an optimization to return early if + // there are no entries in the map. However, the rest of this function doesn't know how to + // disambiguate between not finding this particular name in the map and there being no items in + // the map. In the former case, we need to do the additional work of looking through the + // hierarchy of loggers, while in the latter case we can short-circuit. To keep this function + // fast in the latter case, we do the disambiguation here. + return g_rcutils_logging_default_logger_level; + } + + // Start by trying to find the exact name. + int severity; + rcutils_ret_t ret = get_severity_level(name, &severity); + if (ret == RCUTILS_RET_OK) { if (severity != RCUTILS_LOG_SEVERITY_UNSET) { return severity; } + // If the severity is UNSET, then we go through the slow path and try to find a parent logger + // that is set. Failing that, we fall back to the default logger level. + } else if (ret != RCUTILS_RET_NOT_FOUND) { + // The error message was already set by get_severity_level + return -1; + } + + // Since we didn't find the name in the fast path, fall back to the slow path where we break the + // string into substrings based on dots and look for any part that matches. + + size_t substring_length = strlen(name); + char * tmp_name = rcutils_strdup(name, g_rcutils_logging_allocator); + if (tmp_name == NULL) { + RCUTILS_SAFE_FWRITE_TO_STDERR_WITH_FORMAT_STRING( + "Error copying string '%s'\n", name); + return -1; + } + + severity = RCUTILS_LOG_SEVERITY_UNSET; + + while (true) { // Determine the next ancestor's FQN by removing the child's name. size_t index_last_separator = rcutils_find_lastn( name, RCUTILS_LOGGING_SEPARATOR_CHAR, substring_length); if (SIZE_MAX == index_last_separator) { - // There are no more separators in the substring. - // The name we just checked was the last that we needed to, and it was unset. + // There are no more separators in the substring, so this is the last name we needed to check. break; } - // Shorten the substring to be the name of the ancestor (excluding the separator). + substring_length = index_last_separator; + + // Shorten the substring to be the name of the ancestor (excluding the separator). + tmp_name[index_last_separator] = '\0'; + + rcutils_ret_t ret = get_severity_level(tmp_name, &severity); + if (ret == RCUTILS_RET_OK) { + if (severity != RCUTILS_LOG_SEVERITY_UNSET) { + break; + } + } else if (ret != RCUTILS_RET_NOT_FOUND) { + // The error message was already set by get_severity_level + g_rcutils_logging_allocator.deallocate(tmp_name, g_rcutils_logging_allocator.state); + return -1; + } } - // Neither the logger nor its ancestors have had their level specified. - return g_rcutils_logging_default_logger_level; + + g_rcutils_logging_allocator.deallocate(tmp_name, g_rcutils_logging_allocator.state); + + if (severity == RCUTILS_LOG_SEVERITY_UNSET) { + // Neither the logger nor its ancestors have had their level specified. + 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"); + } + } + + return severity; } rcutils_ret_t rcutils_logging_set_logger_level(const char * name, int level) @@ -824,7 +958,9 @@ rcutils_ret_t rcutils_logging_set_logger_level(const char * name, int level) RCUTILS_SET_ERROR_MSG("Invalid logger name"); return RCUTILS_RET_INVALID_ARGUMENT; } - if (strlen(name) == 0) { + + size_t name_length = strlen(name); + if (name_length == 0) { g_rcutils_logging_default_logger_level = level; return RCUTILS_RET_OK; } @@ -834,7 +970,6 @@ rcutils_ret_t rcutils_logging_set_logger_level(const char * name, int level) } // Convert the severity value into a string for storage. - // TODO(dhood): replace string map with int map. if (level < 0 || level >= (int)(sizeof(g_rcutils_log_severity_names) / sizeof(g_rcutils_log_severity_names[0]))) @@ -847,15 +982,73 @@ rcutils_ret_t rcutils_logging_set_logger_level(const char * name, int level) RCUTILS_SET_ERROR_MSG("Unable to determine severity_string for severity"); return RCUTILS_RET_INVALID_ARGUMENT; } - rcutils_ret_t string_map_ret = rcutils_string_map_set( - &g_rcutils_logging_severities_map, name, severity_string); - if (string_map_ret != RCUTILS_RET_OK) { + + 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 + // user did not set it, then we cached it and so we can throw it away. + + char * key = NULL; + int tmp_level; + + rcutils_ret_t hash_map_ret = rcutils_hash_map_get_next_key_and_data( + &g_rcutils_logging_severities_map, NULL, &key, &tmp_level); + while (RCUTILS_RET_OK == hash_map_ret) { + // Hold onto a reference to the pointer; we'll need it later + char * previous_key = key; + bool free_current_key = false; + if (key != NULL && strncmp(name, key, name_length) == 0) { + // If this is the key we are replacing, unconditionally remove it from the hash map; + // we'll be adding it back as a user-set level anyway + if (key[name_length] == '\0') { + free_current_key = true; + } else { + // Otherwise, this is a descendant; only remove it from the hash map + // if we cached it (the user didn't explicitly set it). + if (!(tmp_level & 0x1)) { + free_current_key = true; + } + } + } + + // Note that we need to get the next key before we free the current + // key so that we can continue iterating over the hash_map + hash_map_ret = rcutils_hash_map_get_next_key_and_data( + &g_rcutils_logging_severities_map, &previous_key, &key, &tmp_level); + if (hash_map_ret != RCUTILS_RET_OK && + hash_map_ret != RCUTILS_RET_HASH_MAP_NO_MORE_ENTRIES && + hash_map_ret != RCUTILS_RET_NOT_FOUND) + { + RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING( + "Error accessing hash map when setting logger level for '%s': %s", + name, rcutils_get_error_string().str); + return hash_map_ret; + } + + if (free_current_key) { + rcutils_ret_t unset_ret = rcutils_hash_map_unset( + &g_rcutils_logging_severities_map, &previous_key); + if (unset_ret != RCUTILS_RET_OK) { + // The only way that hash_map_unset can fail is if there is something wrong with the + // hashmap structure or the key is NULL. Since we don't expect either, report it as an + // error and return. + RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING( + "Error clearing old severity level for logger named '%s': %s", + name, rcutils_get_error_string().str); + return unset_ret; + } + g_rcutils_logging_allocator.deallocate(previous_key, g_rcutils_logging_allocator.state); + } + } + } + + rcutils_ret_t add_key_ret = add_key_to_hash_map(name, level, true); + if (add_key_ret != RCUTILS_RET_OK) { RCUTILS_SET_ERROR_MSG_WITH_FORMAT_STRING( "Error setting severity level for logger named '%s': %s", name, rcutils_get_error_string().str); - return RCUTILS_RET_ERROR; } - return RCUTILS_RET_OK; + return add_key_ret; } bool rcutils_logging_logger_is_enabled_for(const char * name, int severity) diff --git a/test/test_logging.cpp b/test/test_logging.cpp index 9309e598..bbb0a52f 100644 --- a/test/test_logging.cpp +++ b/test/test_logging.cpp @@ -44,7 +44,7 @@ TEST(TestLogging, test_logging_initialization) { // for the string map relating severity level values to string rcutils_allocator_t failing_allocator = get_failing_allocator(); EXPECT_EQ( - RCUTILS_RET_STRING_MAP_INVALID, rcutils_logging_initialize_with_allocator(failing_allocator)); + RCUTILS_RET_ERROR, rcutils_logging_initialize_with_allocator(failing_allocator)); } size_t g_log_calls = 0; @@ -409,3 +409,32 @@ TEST(TestLogging, test_logger_set_change_ancestor) { rcutils_logging_get_logger_effective_level( "rcutils_test_logging_cpp.x")); } + +TEST(TestLogging, test_logger_allocated_names) { + // This tests whether we properly store and free the logger names inside + // of logging implementation. It's best to run this under valgrind to + // see that there are no errors and no leaked memory. + + ASSERT_EQ(RCUTILS_RET_OK, rcutils_logging_initialize()); + OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT( + { + EXPECT_EQ(RCUTILS_RET_OK, rcutils_logging_shutdown()); + }); + + rcutils_logging_set_default_logger_level(RCUTILS_LOG_SEVERITY_INFO); + + const char * allocated_name = strdup("rcutils_test_loggers"); + + // check setting of acceptable severities + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + allocated_name, RCUTILS_LOG_SEVERITY_WARN)); + + free(const_cast(allocated_name)); + + ASSERT_EQ( + RCUTILS_LOG_SEVERITY_WARN, + rcutils_logging_get_logger_level("rcutils_test_loggers")); + rcutils_reset_error(); +} From 585eb7442fa7e43d88d4fc4cfe79d96d4c4c433c Mon Sep 17 00:00:00 2001 From: Chris Lalancette Date: Mon, 29 Aug 2022 18:47:40 +0000 Subject: [PATCH 4/7] Fix a bug introduced by the optimizations. Also add in a test. Signed-off-by: Chris Lalancette --- src/logging.c | 13 ++++++++----- test/test_logging.cpp | 44 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 52 insertions(+), 5 deletions(-) diff --git a/src/logging.c b/src/logging.c index 266f8d7c..6b46f24f 100644 --- a/src/logging.c +++ b/src/logging.c @@ -959,11 +959,6 @@ rcutils_ret_t rcutils_logging_set_logger_level(const char * name, int level) return RCUTILS_RET_INVALID_ARGUMENT; } - size_t name_length = strlen(name); - if (name_length == 0) { - g_rcutils_logging_default_logger_level = level; - return RCUTILS_RET_OK; - } if (!g_rcutils_logging_severities_map_valid) { RCUTILS_SET_ERROR_MSG("Logger severity level map is invalid"); return RCUTILS_RET_LOGGING_SEVERITY_MAP_INVALID; @@ -983,6 +978,8 @@ rcutils_ret_t rcutils_logging_set_logger_level(const char * name, int level) return RCUTILS_RET_INVALID_ARGUMENT; } + size_t name_length = strlen(name); + 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 @@ -1048,6 +1045,12 @@ rcutils_ret_t rcutils_logging_set_logger_level(const char * name, int level) "Error setting severity level for logger named '%s': %s", name, rcutils_get_error_string().str); } + + if (name_length == 0) { + // If the name was empty, this also means we should update the default logger level + g_rcutils_logging_default_logger_level = level; + } + return add_key_ret; } diff --git a/test/test_logging.cpp b/test/test_logging.cpp index bbb0a52f..6cd439b7 100644 --- a/test/test_logging.cpp +++ b/test/test_logging.cpp @@ -438,3 +438,47 @@ TEST(TestLogging, test_logger_allocated_names) { rcutils_logging_get_logger_level("rcutils_test_loggers")); rcutils_reset_error(); } + +TEST(TestLogging, test_root_logger_after_nonexistent) +{ + // This tests whether the root logger remains unset after setting the logger name for a + // non-existent logger. + + ASSERT_EQ(RCUTILS_RET_OK, rcutils_logging_initialize()); + OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT( + { + EXPECT_EQ(RCUTILS_RET_OK, rcutils_logging_shutdown()); + }); + + int original_severity = rcutils_logging_get_logger_effective_level("my_internal_logger_name"); + + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + "my_internal_logger_name", RCUTILS_LOG_SEVERITY_DEBUG)); + + EXPECT_EQ( + RCUTILS_LOG_SEVERITY_DEBUG, + rcutils_logging_get_logger_effective_level("my_internal_logger_name")); + + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + "my_internal_logger_name", original_severity)); + + int original_root_severity = rcutils_logging_get_logger_effective_level(""); + + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + "", RCUTILS_LOG_SEVERITY_UNSET)); + + EXPECT_EQ( + RCUTILS_LOG_SEVERITY_UNSET, + rcutils_logging_get_logger_effective_level("")); + + ASSERT_EQ( + RCUTILS_RET_OK, + rcutils_logging_set_logger_level( + "", original_root_severity)); +} From 0a49cdb7f39659334905786c98e12e860c9ace83 Mon Sep 17 00:00:00 2001 From: Chris Lalancette Date: Tue, 30 Aug 2022 01:04:34 +0000 Subject: [PATCH 5/7] Fixes for Windows warnings. Signed-off-by: Chris Lalancette --- test/test_logging.cpp | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/test/test_logging.cpp b/test/test_logging.cpp index 6cd439b7..f87d1b01 100644 --- a/test/test_logging.cpp +++ b/test/test_logging.cpp @@ -20,6 +20,7 @@ #include "./allocator_testing_utils.h" #include "osrf_testing_tools_cpp/scope_exit.hpp" #include "rcutils/logging.h" +#include "rcutils/strdup.h" TEST(TestLogging, test_logging_initialization) { EXPECT_FALSE(g_rcutils_logging_initialized); @@ -423,7 +424,9 @@ TEST(TestLogging, test_logger_allocated_names) { rcutils_logging_set_default_logger_level(RCUTILS_LOG_SEVERITY_INFO); - const char * allocated_name = strdup("rcutils_test_loggers"); + rcutils_allocator_t allocator = rcutils_get_default_allocator(); + + const char * allocated_name = rcutils_strdup("rcutils_test_loggers", allocator); // check setting of acceptable severities ASSERT_EQ( @@ -431,7 +434,7 @@ TEST(TestLogging, test_logger_allocated_names) { rcutils_logging_set_logger_level( allocated_name, RCUTILS_LOG_SEVERITY_WARN)); - free(const_cast(allocated_name)); + allocator.deallocate(const_cast(allocated_name), allocator.state); ASSERT_EQ( RCUTILS_LOG_SEVERITY_WARN, From 14b87abc6cdf063daa1c2ed0d772311b6328259f Mon Sep 17 00:00:00 2001 From: Chris Lalancette Date: Tue, 6 Sep 2022 12:47:05 +0000 Subject: [PATCH 6/7] Fix up error checking for tokens. Signed-off-by: Chris Lalancette --- src/logging.c | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/logging.c b/src/logging.c index 6b46f24f..1374ddc5 100644 --- a/src/logging.c +++ b/src/logging.c @@ -416,14 +416,15 @@ static const char * copy_from_orig( static bool add_handler(token_handler handler, size_t start_offset, size_t end_offset) { - g_handlers[g_num_log_msg_handlers].handler = handler; - g_handlers[g_num_log_msg_handlers].start_offset = start_offset; - g_handlers[g_num_log_msg_handlers].end_offset = end_offset; - if (g_num_log_msg_handlers >= sizeof(g_handlers) - 1) { + if (g_num_log_msg_handlers >= (sizeof(g_handlers) / sizeof(g_handlers[0]))) { RCUTILS_SET_ERROR_MSG("Too many substitutions in the logging output format string; truncating"); return false; } + g_handlers[g_num_log_msg_handlers].handler = handler; + g_handlers[g_num_log_msg_handlers].start_offset = start_offset; + g_handlers[g_num_log_msg_handlers].end_offset = end_offset; + g_num_log_msg_handlers++; return true; From 15757738384214d4631a924da75e1607798f618a Mon Sep 17 00:00:00 2001 From: Chris Lalancette Date: Tue, 6 Sep 2022 12:50:00 +0000 Subject: [PATCH 7/7] Add in a note about the LSB of the logging levels. Signed-off-by: Chris Lalancette --- include/rcutils/logging.h | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/include/rcutils/logging.h b/include/rcutils/logging.h index 32a75c90..97ff97e2 100644 --- a/include/rcutils/logging.h +++ b/include/rcutils/logging.h @@ -164,6 +164,10 @@ typedef struct rcutils_log_location_s } rcutils_log_location_t; /// The severity levels of log messages / loggers. +/** + * Note: all logging levels have their Least Significant Bit as 0, which is used as an + * optimization. If adding new logging levels, ensure that the new levels keep this property. + */ enum RCUTILS_LOG_SEVERITY { RCUTILS_LOG_SEVERITY_UNSET = 0, ///< The unset log level