diff --git a/include/rcutils/logging.h b/include/rcutils/logging.h index 61fe07e6..bafb3571 100644 --- a/include/rcutils/logging.h +++ b/include/rcutils/logging.h @@ -243,6 +243,36 @@ rcutils_logging_output_handler_t rcutils_logging_get_output_handler(); RCUTILS_PUBLIC void rcutils_logging_set_output_handler(rcutils_logging_output_handler_t function); +/// Formats a log message according to RCUTILS_CONSOLE_OUTPUT_FORMAT +/** + * A formatter that is meant to be used by an output handler to format a log message to the match + * the format specified in RCUTILS_CONSOLE_OUTPUT_FORMAT by performing token replacement. + * + *
+ * Attribute | Adherence + * ------------------ | ------------- + * Allocates Memory | Yes + * Thread-Safe | No + * Uses Atomics | No + * Lock-Free | Yes + * + * \return `RCUTILS_RET_OK` if successful. + * \return `RCUTILS_RET_BAD_ALLOC` if memory allocation error occured + * \param location The location information about where the log came from + * \param severity The severity of the log message expressed as an integer + * \param name The name of the logger that this message came from + * \param timestamp The time at which the log message was generated + * \param msg The message being logged + * \param args The list of arguments to insert into the formatted log messgae + * \param[out] logging_output An output buffer for the formatted message + */ +RCUTILS_PUBLIC +RCUTILS_WARN_UNUSED +rcutils_ret_t rcutils_logging_format_message( + const rcutils_log_location_t * location, + int severity, const char * name, rcutils_time_point_value_t timestamp, + const char * msg, rcutils_char_array_t * logging_output); + /// The default severity level for loggers. /** * This level is used for (1) nameless log calls and (2) named log @@ -418,7 +448,8 @@ int rcutils_logging_get_logger_effective_level(const char * name); *
* Attribute | Adherence * ------------------ | ------------- - * Allocates Memory | No + * Allocates Memory | No, for formatted outputs <= 1023 characters + * | Yes, for formatted outputs >= 1024 characters * Thread-Safe | No * Uses Atomics | No * Lock-Free | Yes @@ -449,8 +480,7 @@ void rcutils_log( *
* Attribute | Adherence * ------------------ | ------------- - * Allocates Memory | No, for formatted outputs <= 1023 characters - * | Yes, for formatted outputs >= 1024 characters + * Allocates Memory | No * Thread-Safe | Yes, if the underlying *printf functions are * Uses Atomics | No * Lock-Free | Yes @@ -459,8 +489,7 @@ void rcutils_log( * \param severity The severity level * \param name The name of the logger, must be null terminated c string * \param timestamp The timestamp for when the log message was made - * \param format The format string for the message contents - * \param args The variable argument list for the message format string + * \param log_str The string to be logged */ RCUTILS_PUBLIC void rcutils_logging_console_output_handler( diff --git a/include/rcutils/macros.h b/include/rcutils/macros.h index db705703..b2a9a477 100644 --- a/include/rcutils/macros.h +++ b/include/rcutils/macros.h @@ -62,6 +62,7 @@ extern "C" #define RCUTILS_STRINGIFY_IMPL(x) #x #define RCUTILS_STRINGIFY(x) RCUTILS_STRINGIFY_IMPL(x) +#define RCUTILS_UNUSED(x) (void)(x) #ifdef __cplusplus } diff --git a/include/rcutils/types/char_array.h b/include/rcutils/types/char_array.h index 2a346426..121924a5 100644 --- a/include/rcutils/types/char_array.h +++ b/include/rcutils/types/char_array.h @@ -20,6 +20,8 @@ extern "C" { #endif +#include + #include "rcutils/allocator.h" #include "rcutils/types/rcutils_ret.h" #include "rcutils/visibility_control.h" @@ -27,6 +29,14 @@ extern "C" typedef struct RCUTILS_PUBLIC_TYPE rcutils_char_array_t { char * buffer; + + /** + * if this is true, we may safely free/realloc the buffer as needed; + * otherwise we will leave the buffer alone and alloc new memory if + * more space is needed + */ + bool owns_buffer; + size_t buffer_length; size_t buffer_capacity; rcutils_allocator_t allocator; @@ -66,9 +76,11 @@ rcutils_char_array_init( /// Finalize a char array struct. /** - * Cleans up and deallocates any resources used in a rcutils_char_array_t. + * Cleans up and deallocates any resources owned by rcutils_char_array_t. * The array passed to this function needs to have been initialized by * rcutils_char_array_init(). + * If .owns_buffer is false, this function has no effect because that + * implies that the char_array does not own the internal buffer. * Passing an uninitialized instance to this function leads to undefined * behavior. * @@ -89,6 +101,11 @@ rcutils_char_array_fini(rcutils_char_array_t * char_array); * truncated. * Be aware, that this will deallocate the memory and therefore invalidates any * pointers to this storage. + * If the new size is larger, new memory is getting allocated and the existing + * content is copied over. + * Note that if the array doesn't own the current buffer the function just + * allocates a new block of memory and copies the contents of the old buffer + * instead of resizing the existing buffer. * * \param char_array pointer to the instance of rcutils_char_array_t which is being resized * \param new_size the new size of the internal buffer @@ -102,6 +119,114 @@ RCUTILS_WARN_UNUSED rcutils_ret_t rcutils_char_array_resize(rcutils_char_array_t * char_array, size_t new_size); +/// Expand the internal buffer of the char array. +/** + * This function is equivalent to `rcutils_char_array_resize` except that it resizes + * the internal buffer only when it is not big enough. + * If the buffer is already big enough for `new_size`, it returns `RCUTILS_RET_OK` without + * doing anything. + * + * \param char_array pointer to the instance of rcutils_char_array_t which is being resized + * \param new_size the new size of the internal buffer + * \return `RCUTILS_RET_OK` if successful, or + * \return `RCUTILS_RET_BAD_ALLOC` if memory allocation failed, or + * \return `RCUTILS_RET_ERROR` if an unexpected error occurs + */ +RCUTILS_PUBLIC +RCUTILS_WARN_UNUSED +rcutils_ret_t +rcutils_char_array_expand_as_needed(rcutils_char_array_t * char_array, size_t new_size); + +/// Produce output according to format and args. +/** + * This function is equivalent to `vsprintf(char_array->buffer, format, args)` + * except that the buffer grows as needed so a user doesn't have to deal with + * memory management. + * The `va_list args` will be cloned before being used, so a user can safely + * use it again after calling this function. + * + * \param char_array pointer to the instance of rcutils_char_array_t which is being written to + * \param format the format string used by the underlying `vsnprintf` + * \param args the `va_list` used by the underlying `vsnprintf` + * \return `RCUTILS_RET_OK` if successful, or + * \return `RCUTILS_RET_BAD_ALLOC` if memory allocation failed, or + * \return `RCUTILS_RET_ERROR` if an unexpected error occurs + */ +RCUTILS_PUBLIC +RCUTILS_WARN_UNUSED +rcutils_ret_t +rcutils_char_array_vsprintf(rcutils_char_array_t * char_array, const char * format, va_list args); + +/// Append a string (or part of it) to the string in buffer. +/** + * This function treats the internal buffer as a string and appends the src string to it. + * If src is longer than n, n bytes will be used and an extra null byte will be appended. + * It is virtually equivalent to `strncat(char_array->buffer, src, n)` except that the buffer + * grows as needed so a user doesn't have to deal with memory management. + * + * \param char_array pointer to the instance of rcutils_char_array_t which is being appended to + * \param src the string to be appended to the end of the string in buffer + * \param n it uses at most n bytes from the src string + * \return `RCUTILS_RET_OK` if successful, or + * \return `RCUTILS_RET_BAD_ALLOC` if memory allocation failed, or + * \return `RCUTILS_RET_ERROR` if an unexpected error occurs + */ +RCUTILS_PUBLIC +RCUTILS_WARN_UNUSED +rcutils_ret_t +rcutils_char_array_strncat(rcutils_char_array_t * char_array, const char * src, size_t n); + +/// Append a string to the string in buffer. +/** + * This function treats the internal buffer as a string and appends the src string to it. + * It is virtually equivalent to `strcat(char_array->buffer, src)` except that the buffer + * grows as needed. That is to say, a user can safely use it without doing calculation or + * checks on the sizes of the src and buffer. + * + * \param char_array pointer to the instance of rcutils_char_array_t which is being appended to + * \param src the string to be appended to the end of the string in buffer + * \return `RCUTILS_RET_OK` if successful, or + * \return `RCUTILS_RET_BAD_ALLOC` if memory allocation failed, or + * \return `RCUTILS_RET_ERROR` if an unexpected error occurs + */ +RCUTILS_PUBLIC +RCUTILS_WARN_UNUSED +rcutils_ret_t +rcutils_char_array_strcat(rcutils_char_array_t * char_array, const char * src); + +/// Copy memory to buffer. +/** + * This function is equivalent to `memcpy(char_array->buffer, src, n)` except that the buffer + * grows as needed so a user doesn't have to worry about overflow. + * + * \param char_array pointer to the instance of rcutils_char_array_t which is being resized + * \param src the memory to be copied from + * \param n a total of n bytes will be copied + * \return `RCUTILS_RET_OK` if successful, or + * \return `RCUTILS_RET_BAD_ALLOC` if memory allocation failed, or + * \return `RCUTILS_RET_ERROR` if an unexpected error occurs + */ +RCUTILS_PUBLIC +RCUTILS_WARN_UNUSED +rcutils_ret_t +rcutils_char_array_memcpy(rcutils_char_array_t * char_array, const char * src, size_t n); + +/// Copy a string to buffer. +/** + * This function is equivalent to `strcpy(char_array->buffer, src)` except that the buffer + * grows as needed so that `src` will fit without overflow. + * + * \param char_array pointer to the instance of rcutils_char_array_t which is being copied to + * \param src the string to be copied from + * \return `RCUTILS_RET_OK` if successful, or + * \return `RCUTILS_RET_BAD_ALLOC` if memory allocation failed, or + * \return `RCUTILS_RET_ERROR` if an unexpected error occurs + */ +RCUTILS_PUBLIC +RCUTILS_WARN_UNUSED +rcutils_ret_t +rcutils_char_array_strcpy(rcutils_char_array_t * char_array, const char * src); + #if __cplusplus } #endif diff --git a/src/allocator.c b/src/allocator.c index 5741289b..92ef82d0 100644 --- a/src/allocator.c +++ b/src/allocator.c @@ -31,28 +31,28 @@ static void * __default_allocate(size_t size, void * state) { - (void)state; // unused + RCUTILS_UNUSED(state); return malloc(size); } static void __default_deallocate(void * pointer, void * state) { - (void)state; // unused + RCUTILS_UNUSED(state); free(pointer); } static void * __default_reallocate(void * pointer, size_t size, void * state) { - (void)state; // unused + RCUTILS_UNUSED(state); return realloc(pointer, size); } static void * __default_zero_allocate(size_t number_of_elements, size_t size_of_element, void * state) { - (void)state; // unused + RCUTILS_UNUSED(state); return calloc(number_of_elements, size_of_element); } diff --git a/src/char_array.c b/src/char_array.c index e87f81c3..54697149 100644 --- a/src/char_array.c +++ b/src/char_array.c @@ -12,14 +12,18 @@ // See the License for the specific language governing permissions and // limitations under the License. +#include #include "rcutils/error_handling.h" #include "rcutils/types/char_array.h" +#define MIN(a, b) ((a) < (b) ? (a) : (b)) + rcutils_char_array_t rcutils_get_zero_initialized_char_array(void) { static rcutils_char_array_t char_array = { .buffer = NULL, + .owns_buffer = true, .buffer_length = 0u, .buffer_capacity = 0u }; @@ -33,9 +37,11 @@ rcutils_char_array_init( size_t buffer_capacity, const rcutils_allocator_t * allocator) { - RCUTILS_CHECK_ARGUMENT_FOR_NULL(char_array, RCUTILS_RET_INVALID_ARGUMENT); - RCUTILS_CHECK_ALLOCATOR(allocator, return RCUTILS_RET_INVALID_ARGUMENT); + RCUTILS_CHECK_ARGUMENT_FOR_NULL(char_array, RCUTILS_RET_ERROR); + RCUTILS_CHECK_ALLOCATOR_WITH_MSG(allocator, "char array has no valid allocator", + return RCUTILS_RET_ERROR); + char_array->owns_buffer = true; char_array->buffer_length = 0lu; char_array->buffer_capacity = buffer_capacity; char_array->allocator = *allocator; @@ -57,12 +63,16 @@ rcutils_char_array_init( rcutils_ret_t rcutils_char_array_fini(rcutils_char_array_t * char_array) { - RCUTILS_CHECK_ARGUMENT_FOR_NULL(char_array, RCUTILS_RET_INVALID_ARGUMENT); + RCUTILS_CHECK_ARGUMENT_FOR_NULL(char_array, RCUTILS_RET_ERROR); - rcutils_allocator_t * allocator = &char_array->allocator; - RCUTILS_CHECK_ALLOCATOR(allocator, return RCUTILS_RET_INVALID_ARGUMENT); + if (char_array->owns_buffer) { + rcutils_allocator_t * allocator = &char_array->allocator; + RCUTILS_CHECK_ALLOCATOR_WITH_MSG(allocator, "char array has no valid allocator", + return RCUTILS_RET_ERROR); + + allocator->deallocate(char_array->buffer, allocator->state); + } - allocator->deallocate(char_array->buffer, allocator->state); char_array->buffer = NULL; char_array->buffer_length = 0lu; char_array->buffer_capacity = 0lu; @@ -73,7 +83,7 @@ rcutils_char_array_fini(rcutils_char_array_t * char_array) rcutils_ret_t rcutils_char_array_resize(rcutils_char_array_t * char_array, size_t new_size) { - RCUTILS_CHECK_ARGUMENT_FOR_NULL(char_array, RCUTILS_RET_INVALID_ARGUMENT); + RCUTILS_CHECK_ARGUMENT_FOR_NULL(char_array, RCUTILS_RET_ERROR); if (0lu == new_size) { RCUTILS_SET_ERROR_MSG("new size of char_array has to be greater than zero"); @@ -81,25 +91,145 @@ rcutils_char_array_resize(rcutils_char_array_t * char_array, size_t new_size) } rcutils_allocator_t * allocator = &char_array->allocator; - RCUTILS_CHECK_ALLOCATOR(allocator, return RCUTILS_RET_INVALID_ARGUMENT); + RCUTILS_CHECK_ALLOCATOR_WITH_MSG(allocator, "char array has no valid allocator", + return RCUTILS_RET_ERROR); if (new_size == char_array->buffer_capacity) { // nothing to do here return RCUTILS_RET_OK; } - char_array->buffer = rcutils_reallocf(char_array->buffer, new_size * sizeof(char), allocator); - RCUTILS_CHECK_FOR_NULL_WITH_MSG( - char_array->buffer, - "failed to reallocate memory for char array", - char_array->buffer_capacity = 0lu; - char_array->buffer_length = 0lu; - return RCUTILS_RET_BAD_ALLOC); + char * old_buf = char_array->buffer; + size_t old_size = char_array->buffer_capacity; + size_t old_length = char_array->buffer_length; + + if (char_array->owns_buffer) { // we own the buffer, we can do whatever we want + char_array->buffer = rcutils_reallocf(char_array->buffer, new_size * sizeof(char), allocator); + RCUTILS_CHECK_FOR_NULL_WITH_MSG( + char_array->buffer, + "failed to reallocate memory for char array", + return RCUTILS_RET_BAD_ALLOC); + } else { // we don't realloc memory we don't own. instead, we alloc some new space + rcutils_ret_t ret = rcutils_char_array_init(char_array, new_size, allocator); + if (ret != RCUTILS_RET_OK) { + return ret; + } + size_t n = MIN(new_size, old_size); + memcpy(char_array->buffer, old_buf, n); + char_array->buffer[n - 1] = '\0'; // always have an ending + } char_array->buffer_capacity = new_size; - if (new_size < char_array->buffer_length) { - char_array->buffer_length = new_size; + char_array->buffer_length = MIN(new_size, old_length); + + return RCUTILS_RET_OK; +} + +rcutils_ret_t +rcutils_char_array_expand_as_needed(rcutils_char_array_t * char_array, size_t new_size) +{ + RCUTILS_CHECK_ARGUMENT_FOR_NULL(char_array, RCUTILS_RET_ERROR); + + if (new_size <= char_array->buffer_capacity) { + return RCUTILS_RET_OK; + } + + return rcutils_char_array_resize(char_array, new_size); +} + +static int +_rcutils_char_array_vsprintf(rcutils_char_array_t * char_array, const char * format, va_list args) +{ + va_list args_clone; + va_copy(args_clone, args); + + // when doing size calculation, remember the return value of vsnprintf excludes terminating null + // byte + int size = vsnprintf(char_array->buffer, char_array->buffer_capacity, format, args_clone); + + va_end(args_clone); + + return size; +} + +rcutils_ret_t +rcutils_char_array_vsprintf(rcutils_char_array_t * char_array, const char * format, va_list args) +{ + int size = _rcutils_char_array_vsprintf(char_array, format, args); + + if (size < 0) { + RCUTILS_SET_ERROR_MSG("vsprintf on char array failed"); + return RCUTILS_RET_ERROR; } + size_t new_size = (size_t) size + 1; // with the terminating null byte + + if (new_size > char_array->buffer_capacity) { + rcutils_ret_t ret = rcutils_char_array_expand_as_needed(char_array, new_size); + if (ret != RCUTILS_RET_OK) { + RCUTILS_SET_ERROR_MSG("char array failed to expand"); + return ret; + } + + if (_rcutils_char_array_vsprintf(char_array, format, args) != size) { + if (rcutils_char_array_fini(char_array) == RCUTILS_RET_OK) { + RCUTILS_SET_ERROR_MSG("vsprintf on resized char array failed"); + } else { + RCUTILS_SET_ERROR_MSG("vsprintf on resized char array failed; clean up failed too"); + } + return RCUTILS_RET_ERROR; + } + } + + char_array->buffer_length = new_size; + + return RCUTILS_RET_OK; +} + +rcutils_ret_t +rcutils_char_array_memcpy(rcutils_char_array_t * char_array, const char * src, size_t n) +{ + rcutils_ret_t ret = rcutils_char_array_expand_as_needed(char_array, n); + if (ret != RCUTILS_RET_OK) { + RCUTILS_SET_ERROR_MSG("char array failed to expand"); + return ret; + } + memcpy(char_array->buffer, src, n); + char_array->buffer_length = n; return RCUTILS_RET_OK; } + +rcutils_ret_t +rcutils_char_array_strcpy(rcutils_char_array_t * char_array, const char * src) +{ + return rcutils_char_array_memcpy(char_array, src, strlen(src) + 1); +} + +rcutils_ret_t +rcutils_char_array_strncat(rcutils_char_array_t * char_array, const char * src, size_t n) +{ + size_t current_strlen = strlen(char_array->buffer); + size_t new_length = current_strlen + n + 1; + rcutils_ret_t ret = rcutils_char_array_expand_as_needed(char_array, new_length); + if (ret != RCUTILS_RET_OK) { + RCUTILS_SET_ERROR_MSG("char array failed to expand"); + return ret; + } +#ifndef _WIN32 + strncat(char_array->buffer, src, n); +#else + errno_t err = strncat_s(char_array->buffer, new_length, src, n); + if (0 != err) { + RCUTILS_SET_ERROR_MSG("strncat_s failed"); + return RCUTILS_RET_ERROR; + } +#endif + char_array->buffer_length = new_length; + return RCUTILS_RET_OK; +} + +rcutils_ret_t +rcutils_char_array_strcat(rcutils_char_array_t * char_array, const char * src) +{ + return rcutils_char_array_strncat(char_array, src, strlen(src)); +} diff --git a/src/logging.c b/src/logging.c index 7a79bb04..c5f9d694 100644 --- a/src/logging.c +++ b/src/logging.c @@ -33,7 +33,7 @@ extern "C" #include "rcutils/time.h" #include "rcutils/types/string_map.h" -#define RCUTILS_LOGGING_MAX_OUTPUT_FORMAT_LEN 2048 +#define RCUTILS_LOGGING_MAX_OUTPUT_FORMAT_LEN (2048) const char * g_rcutils_log_severity_names[] = { [RCUTILS_LOG_SEVERITY_UNSET] = "UNSET", @@ -232,6 +232,9 @@ void rcutils_logging_set_default_logger_level(int level) int rcutils_logging_get_logger_level(const char * name) { RCUTILS_LOGGING_AUTOINIT + if (NULL == name) { + return -1; + } return rcutils_logging_get_logger_leveln(name, strlen(name)); } @@ -363,6 +366,26 @@ bool rcutils_logging_logger_is_enabled_for(const char * name, int severity) } return severity >= logger_level; } +#define SAFE_FWRITE_TO_STDERR_AND(action) \ + RCUTILS_SAFE_FWRITE_TO_STDERR(rcutils_get_error_string().str); \ + rcutils_reset_error(); \ + RCUTILS_SAFE_FWRITE_TO_STDERR("\n"); \ + action; + +#define OK_OR_RETURN_NULL(op) \ + if (op != RCUTILS_RET_OK) { \ + SAFE_FWRITE_TO_STDERR_AND(return NULL); \ + } + +#define OK_OR_RETURN_EARLY(op) \ + if (op != RCUTILS_RET_OK) { \ + return op; \ + } + +#define APPEND_AND_RETURN_LOG_OUTPUT(s) \ + OK_OR_RETURN_NULL(rcutils_char_array_strcat(logging_output, s)); \ + return logging_output->buffer; + void rcutils_log( const rcutils_log_location_t * location, @@ -386,285 +409,312 @@ void rcutils_log( } } -/// Ensure that the logging buffer is large enough. -/** - * Macro for (re)allocating a dynamic buffer if the ouput buffer doesn't have - * enough space for an additional n characters and null terminator. - * Whether to allocate or re-allocate is determined by if the output_buffer - * points to the original static_output_buffer or not. - * If a new buffer is allocated it will be null-terminated. - * - * /param n Number of characters requiring space (not including null terminator) - * /param output_buffer_size Size allocated for the output buffer - * /param output_buffer The output buffer to ensure has enough space - * /param static_output_buffer The static buffer initially used as the output - */ -#define RCUTILS_LOGGING_ENSURE_LARGE_ENOUGH_BUFFER( \ - n, \ - output_buffer_size, \ - output_buffer, \ - static_output_buffer \ -) \ - size_t old_output_buffer_len = strlen(output_buffer); \ - size_t required_output_buffer_size = old_output_buffer_len + n + 1; \ - /* ensure that required size calculation did not overflow */ \ - if (required_output_buffer_size <= old_output_buffer_len) { \ - fprintf(stderr, "required buffer for logging output too large\n"); \ - goto cleanup; \ - } \ - if (required_output_buffer_size > output_buffer_size) { \ - do { \ - if (output_buffer_size <= (SIZE_MAX / 2)) { \ - output_buffer_size *= 2; \ - } else { \ - output_buffer_size = SIZE_MAX; \ - } \ - } while (required_output_buffer_size > output_buffer_size); \ - if (output_buffer == static_output_buffer) { \ - void * dynamic_output_buffer = g_rcutils_logging_allocator.allocate( \ - output_buffer_size, g_rcutils_logging_allocator.state); \ - if (NULL == dynamic_output_buffer) { \ - fprintf(stderr, "failed to allocate buffer for logging output\n"); \ - goto cleanup; \ - } \ - memcpy(dynamic_output_buffer, output_buffer, old_output_buffer_len); \ - output_buffer = (char *)dynamic_output_buffer; \ - } else { \ - void * new_dynamic_output_buffer = g_rcutils_logging_allocator.reallocate( \ - output_buffer, output_buffer_size, g_rcutils_logging_allocator.state); \ - if (NULL == new_dynamic_output_buffer) { \ - fprintf(stderr, "failed to reallocate buffer for logging output\n"); \ - goto cleanup; \ - } \ - output_buffer = (char *)new_dynamic_output_buffer; \ - } \ - output_buffer[old_output_buffer_len] = '\0'; \ - } +typedef struct logging_input +{ + const char * name; + const rcutils_log_location_t * location; + const char * msg; + int severity; + rcutils_time_point_value_t timestamp; +} logging_input; -void rcutils_logging_console_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) +typedef const char * (* token_handler)( + const logging_input * logging_input, + rcutils_char_array_t * logging_output); + +typedef struct token_map_entry { - if (!g_rcutils_logging_initialized) { - fprintf( - stderr, - "logging system isn't initialized: " \ - "call to rcutils_logging_console_output_handler failed.\n"); - return; - } - FILE * stream = NULL; - const char * severity_string = ""; - switch (severity) { - case RCUTILS_LOG_SEVERITY_DEBUG: - stream = stdout; - break; - case RCUTILS_LOG_SEVERITY_INFO: - stream = stdout; - break; - case RCUTILS_LOG_SEVERITY_WARN: - stream = stderr; - break; - case RCUTILS_LOG_SEVERITY_ERROR: - stream = stderr; - break; - case RCUTILS_LOG_SEVERITY_FATAL: - stream = stderr; - break; - default: - fprintf(stderr, "unknown severity level: %d\n", severity); - return; + const char * token; + token_handler handler; +} token_map_entry; + +const char * expand_time( + const logging_input * logging_input, rcutils_char_array_t * logging_output, + rcutils_ret_t (* time_func)(const rcutils_time_point_value_t *, char *, size_t)) +{ + // Temporary, local storage for integer/float conversion to string + // Note: + // 32 characters enough, because the most it can be is 20 characters + // for the 19 possible digits in a signed 64-bit number plus the optional + // decimal point in the floating point seconds version + char numeric_storage[32]; + OK_OR_RETURN_NULL(time_func(&logging_input->timestamp, numeric_storage, sizeof(numeric_storage))); + APPEND_AND_RETURN_LOG_OUTPUT(numeric_storage); +} + +const char * expand_time_as_seconds( + const logging_input * logging_input, + rcutils_char_array_t * logging_output) +{ + return expand_time(logging_input, logging_output, rcutils_time_point_value_as_seconds_string); +} + +const char * expand_time_as_nanoseconds( + const logging_input * logging_input, + rcutils_char_array_t * logging_output) +{ + return expand_time(logging_input, logging_output, rcutils_time_point_value_as_nanoseconds_string); +} + +const char * expand_line_number( + const logging_input * logging_input, + rcutils_char_array_t * logging_output) +{ + // Allow 9 digits for the expansion of the line number (otherwise, truncate). + char line_number_expansion[10]; + + const rcutils_log_location_t * location = logging_input->location; + + if (!location) { + OK_OR_RETURN_NULL(rcutils_char_array_strcpy(logging_output, "0")); + return logging_output->buffer; } - severity_string = g_rcutils_log_severity_names[severity]; - if (NULL == severity_string) { - fprintf(stderr, "couldn't determine name for severity level: %d\n", severity); - return; + + // Even in the case of truncation the result will still be null-terminated. + int written = rcutils_snprintf(line_number_expansion, sizeof(line_number_expansion), "%zu", + location->line_number); + if (written < 0) { + fprintf(stderr, "failed to format line number: '%zu'\n", location->line_number); + return NULL; } - // Declare variables that will be needed for cleanup ahead of time. - char static_output_buffer[1024]; - char * output_buffer = NULL; + APPEND_AND_RETURN_LOG_OUTPUT(line_number_expansion); +} - // Start with a fixed size message buffer and if during message formatting we need longer, we'll - // dynamically allocate space. - char static_message_buffer[1024]; - char * message_buffer = static_message_buffer; +const char * expand_severity( + const logging_input * logging_input, + rcutils_char_array_t * logging_output) +{ + const char * severity_string = g_rcutils_log_severity_names[logging_input->severity]; + APPEND_AND_RETURN_LOG_OUTPUT(severity_string); +} - int written; - { - // use copy of args to keep args for potential later user - va_list args_clone; - va_copy(args_clone, *args); - written = vsnprintf(static_message_buffer, sizeof(static_message_buffer), format, args_clone); - va_end(args_clone); +const char * expand_name(const logging_input * logging_input, rcutils_char_array_t * logging_output) +{ + if (NULL != logging_input->name) { + APPEND_AND_RETURN_LOG_OUTPUT(logging_input->name); } - if (written < 0) { - fprintf(stderr, "failed to format message: '%s'\n", format); - return; + return logging_output->buffer; +} + +const char * expand_message( + const logging_input * logging_input, + rcutils_char_array_t * logging_output) +{ + OK_OR_RETURN_NULL(rcutils_char_array_strcat(logging_output, logging_input->msg)); + return logging_output->buffer; +} + +const char * expand_function_name( + const logging_input * logging_input, + rcutils_char_array_t * logging_output) +{ + if (logging_input->location) { + APPEND_AND_RETURN_LOG_OUTPUT(logging_input->location->function_name); } - if ((size_t)written >= sizeof(static_message_buffer)) { - // write was incomplete, allocate necessary memory dynamically - size_t message_buffer_size = written + 1; - void * dynamic_message_buffer = g_rcutils_logging_allocator.allocate( - message_buffer_size, g_rcutils_logging_allocator.state); - if (NULL == dynamic_message_buffer) { - fprintf(stderr, "failed to allocate buffer for message\n"); - return; - } - written = vsnprintf(dynamic_message_buffer, message_buffer_size, format, *args); - message_buffer = (char *)dynamic_message_buffer; - if (written < 0 || (size_t)written >= message_buffer_size) { - fprintf( - stderr, - "failed to format message (using dynamically allocated memory): '%s'\n", - format); - goto cleanup; + return logging_output->buffer; +} + +const char * expand_file_name( + const logging_input * logging_input, + rcutils_char_array_t * logging_output) +{ + if (logging_input->location) { + APPEND_AND_RETURN_LOG_OUTPUT(logging_input->location->file_name); + } + return logging_output->buffer; +} + +static const token_map_entry tokens[] = { + {.token = "severity", .handler = expand_severity}, + {.token = "name", .handler = expand_name}, + {.token = "message", .handler = expand_message}, + {.token = "function_name", .handler = expand_function_name}, + {.token = "file_name", .handler = expand_file_name}, + {.token = "time", .handler = expand_time_as_seconds}, + {.token = "time_as_nanoseconds", .handler = expand_time_as_nanoseconds}, + {.token = "line_number", .handler = expand_line_number}, +}; + +token_handler find_token_handler(const char * token) +{ + int token_number = sizeof(tokens) / sizeof(tokens[0]); + for (int token_index = 0; token_index < token_number; token_index++) { + if (strcmp(token, tokens[token_index].token) == 0) { + return tokens[token_index].handler; } } + return NULL; +} +rcutils_ret_t rcutils_logging_format_message( + const rcutils_log_location_t * location, + int severity, const char * name, rcutils_time_point_value_t timestamp, + const char * msg, rcutils_char_array_t * logging_output) +{ + rcutils_ret_t status = RCUTILS_RET_OK; // Process the format string looking for known tokens. const char token_start_delimiter = '{'; const char token_end_delimiter = '}'; - // Start with a fixed size output buffer and if during token expansion we need longer, we'll - // dynamically allocate space. - output_buffer = static_output_buffer; - output_buffer[0] = '\0'; - size_t output_buffer_size = sizeof(static_output_buffer); + const char * str = g_rcutils_logging_output_format_string; size_t size = strlen(g_rcutils_logging_output_format_string); + const logging_input logging_input = { + .location = location, + .severity = severity, + .name = name, + .timestamp = timestamp, + .msg = msg + }; + // Walk through the format string and expand tokens when they're encountered. size_t i = 0; while (i < size) { // Print everything up to the next token start delimiter. size_t chars_to_start_delim = rcutils_find(str + i, token_start_delimiter); size_t remaining_chars = size - i; - if (chars_to_start_delim > 0) { - if (chars_to_start_delim > remaining_chars) { - // No start delimiters found; don't allow printing more of than what's left if. - chars_to_start_delim = remaining_chars; - } - RCUTILS_LOGGING_ENSURE_LARGE_ENOUGH_BUFFER( - chars_to_start_delim, output_buffer_size, output_buffer, static_output_buffer) - memcpy(output_buffer + old_output_buffer_len, str + i, chars_to_start_delim); - output_buffer[old_output_buffer_len + chars_to_start_delim] = '\0'; - i += chars_to_start_delim; - if (i >= size) { + + if (chars_to_start_delim > 0) { // there are stuff before a token start delimiter + size_t chars_to_copy = chars_to_start_delim > + remaining_chars ? remaining_chars : chars_to_start_delim; + status = rcutils_char_array_strncat(logging_output, str + i, chars_to_copy); + OK_OR_RETURN_EARLY(status); + i += chars_to_copy; + if (i >= size) { // perhaps no start delimiter was found break; } } + // We are at a token start delimiter: determine if there's a known token or not. // Potential tokens can't possibly be longer than the format string itself. char token[RCUTILS_LOGGING_MAX_OUTPUT_FORMAT_LEN]; + // Look for a token end delimiter. size_t chars_to_end_delim = rcutils_find(str + i, token_end_delimiter); remaining_chars = size - i; + 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. - RCUTILS_LOGGING_ENSURE_LARGE_ENOUGH_BUFFER( - remaining_chars, output_buffer_size, output_buffer, static_output_buffer) - memcpy(output_buffer + old_output_buffer_len, str + i, remaining_chars + 1); + status = rcutils_char_array_strncat(logging_output, str + i, remaining_chars); + OK_OR_RETURN_EARLY(status); break; } + // Found what looks like a token; determine if it's recognized. size_t token_len = chars_to_end_delim - 1; // Not including delimiters. memcpy(token, str + i + 1, token_len); // Skip the start delimiter. token[token_len] = '\0'; - // Expand known tokens into their content strings. - // The resulting token_expansion string must always be null-terminated. - const char * token_expansion = NULL; - // Temporary, local storage for integer/float conversion to string - // Note: - // 32 characters enough, because the most it can be is 20 characters - // for the 19 possible digits in a signed 64-bit number plus the optional - // decimal point in the floating point seconds version - char numeric_storage[32]; - // Allow 9 digits for the expansion of the line number (otherwise, truncate). - char line_number_expansion[10]; - if (strcmp("severity", token) == 0) { - token_expansion = severity_string; - } else if (strcmp("name", token) == 0) { - token_expansion = name; - } else if (strcmp("message", token) == 0) { - token_expansion = message_buffer; - } else if (strcmp("time", token) == 0) { - rcutils_ret_t ret = rcutils_time_point_value_as_seconds_string( - ×tamp, - numeric_storage, sizeof(numeric_storage)); - if (ret != RCUTILS_RET_OK) { - RCUTILS_SAFE_FWRITE_TO_STDERR(rcutils_get_error_string().str); - rcutils_reset_error(); - RCUTILS_SAFE_FWRITE_TO_STDERR("\n"); - goto cleanup; - } - token_expansion = numeric_storage; - } else if (strcmp("time_as_nanoseconds", token) == 0) { - rcutils_ret_t ret = rcutils_time_point_value_as_nanoseconds_string( - ×tamp, - numeric_storage, sizeof(numeric_storage)); - if (ret != RCUTILS_RET_OK) { - RCUTILS_SAFE_FWRITE_TO_STDERR(rcutils_get_error_string().str); - rcutils_reset_error(); - RCUTILS_SAFE_FWRITE_TO_STDERR("\n"); - goto cleanup; - } - token_expansion = numeric_storage; - } else if (strcmp("function_name", token) == 0) { - token_expansion = location ? location->function_name : "\"\""; - } else if (strcmp("file_name", token) == 0) { - token_expansion = location ? location->file_name : "\"\""; - } else if (strcmp("line_number", token) == 0) { - if (location) { - // Even in the case of truncation the result will still be null-terminated. - written = rcutils_snprintf( - line_number_expansion, sizeof(line_number_expansion), "%zu", location->line_number); - if (written < 0) { - fprintf( - stderr, - "failed to format line number: '%zu'\n", - location->line_number); - goto cleanup; - } - token_expansion = line_number_expansion; - } else { - token_expansion = "0"; - } - } else { + + token_handler expand_token = find_token_handler(token); + + 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). - RCUTILS_LOGGING_ENSURE_LARGE_ENOUGH_BUFFER( - 1, output_buffer_size, output_buffer, static_output_buffer) - memcpy(output_buffer + old_output_buffer_len, str + i, 1); - output_buffer[old_output_buffer_len + 1] = '\0'; + status = rcutils_char_array_strncat(logging_output, str + i, 1); + OK_OR_RETURN_EARLY(status); i++; continue; } - size_t n = strlen(token_expansion); - RCUTILS_LOGGING_ENSURE_LARGE_ENOUGH_BUFFER( - n, output_buffer_size, output_buffer, static_output_buffer) - memcpy(output_buffer + old_output_buffer_len, token_expansion, n + 1); + + if (!expand_token(&logging_input, logging_output)) { + return RCUTILS_RET_ERROR; + } // Skip ahead to avoid re-processing the token characters (including the 2 delimiters). i += token_len + 2; } - fprintf(stream, "%s\n", output_buffer); - if (g_force_stdout_line_buffered && stream == stdout) { - int flush_result = fflush(stream); - if (flush_result != 0 && !g_stdout_flush_failure_reported) { - g_stdout_flush_failure_reported = true; - fprintf(stderr, "Error: failed to perform fflush on stdout, fflush return code is: %d\n", - flush_result); + return status; +} + +void rcutils_logging_console_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) +{ + rcutils_ret_t status = RCUTILS_RET_OK; + + if (!g_rcutils_logging_initialized) { + fprintf( + stderr, + "logging system isn't initialized: " \ + "call to rcutils_logging_console_output_handler failed.\n"); + return; + } + FILE * stream = NULL; + switch (severity) { + case RCUTILS_LOG_SEVERITY_DEBUG: + case RCUTILS_LOG_SEVERITY_INFO: + stream = stdout; + break; + case RCUTILS_LOG_SEVERITY_WARN: + case RCUTILS_LOG_SEVERITY_ERROR: + case RCUTILS_LOG_SEVERITY_FATAL: + stream = stderr; + break; + default: + fprintf(stderr, "unknown severity level: %d\n", severity); + return; + } + + char msg_buf[1024] = ""; + rcutils_char_array_t msg_array = { + .buffer = msg_buf, + .owns_buffer = false, + .buffer_length = 0u, + .buffer_capacity = sizeof(msg_buf), + .allocator = g_rcutils_logging_allocator + }; + + char output_buf[1024] = ""; + rcutils_char_array_t output_array = { + .buffer = output_buf, + .owns_buffer = false, + .buffer_length = 0u, + .buffer_capacity = sizeof(output_buf), + .allocator = g_rcutils_logging_allocator + }; + + va_list args_clone; + va_copy(args_clone, *args); + status = rcutils_char_array_vsprintf(&msg_array, format, args_clone); + if (RCUTILS_RET_OK != status) { + fprintf(stderr, "Error: rcutils_char_array_vsprintf failed with: %d\n", + status); + } + va_end(args_clone); + + if (RCUTILS_RET_OK == status) { + status = rcutils_logging_format_message( + location, severity, name, timestamp, msg_array.buffer, &output_array); + if (RCUTILS_RET_OK != status) { + fprintf(stderr, "Error: rcutils_logging_format_message failed with: %d\n", + status); } } -cleanup: - if (message_buffer && message_buffer != static_message_buffer) { - g_rcutils_logging_allocator.deallocate(message_buffer, g_rcutils_logging_allocator.state); + + if (RCUTILS_RET_OK == status) { + fprintf(stream, "%s\n", output_array.buffer); + + if (g_force_stdout_line_buffered && stream == stdout) { + int flush_result = fflush(stream); + if (flush_result != 0 && !g_stdout_flush_failure_reported) { + g_stdout_flush_failure_reported = true; + fprintf(stderr, "Error: failed to perform fflush on stdout, fflush return code is: %d\n", + flush_result); + } + } } - if (output_buffer && output_buffer != static_output_buffer) { - g_rcutils_logging_allocator.deallocate(output_buffer, g_rcutils_logging_allocator.state); + status = rcutils_char_array_fini(&msg_array); + if (RCUTILS_RET_OK != status) { + fprintf(stderr, "Failed to fini array.\n"); + } + status = rcutils_char_array_fini(&output_array); + if (RCUTILS_RET_OK != status) { + fprintf(stderr, "Failed to fini array.\n"); } } diff --git a/test/test_logging_macros.c b/test/test_logging_macros.c index b121801d..7a774160 100644 --- a/test/test_logging_macros.c +++ b/test/test_logging_macros.c @@ -124,7 +124,7 @@ int main(int argc, char ** argv) return 15; } if (strcmp(g_last_log_event.message, "message foo")) { - fprintf(stderr, "message unexpectedly not 'empty message'\n"); + fprintf(stderr, "message unexpectedly not 'message foo'\n"); return 16; }