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.

Sign up for GitHub

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

Jump to bottom

Logging #127

Merged
merged 7 commits into from
Dec 7, 2018
Merged

Logging #127

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
c35774e
refactoring so code for console sink can be reused
yyu Nov 2, 2018
454e5a4
Creating a logging configure function that can be used to select whic…
nburek Oct 31, 2018
56f9d74
Moving the external logging library and rosout functions out to rcl. …
nburek Nov 28, 2018
602094e
Switching back to va_list for output handlers.
nburek Dec 6, 2018
744ee84
PR fixup
nburek Dec 6, 2018
8694fd3
use strncat_s on Windows
wjwwood Dec 7, 2018
9a15eaa
derp
wjwwood Dec 7, 2018
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
38 changes: 35 additions & 3 deletions include/rcutils/logging.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -196,14 +196,16 @@ rcutils_logging_severity_level_from_string(
* \param severity The severity level
* \param name The name of the logger
* \param timestamp The timestamp
* \param log_str The string to be logged
* \param format The format string
* \param args The variable argument list
*/
typedef void (* rcutils_logging_output_handler_t)(
const rcutils_log_location_t *, // location
int, // severity
const char *, // name
rcutils_time_point_value_t, // timestamp
const char * // log_str
const char *, // format
va_list * // args
);

/// The function pointer of the current output handler.
Expand Down Expand Up @@ -241,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.
*
* <hr>
* 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
Expand Down Expand Up @@ -463,7 +495,7 @@ RCUTILS_PUBLIC
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 * log_str);
const char * format, va_list * args);

// Provide the compiler with branch prediction information
#ifndef _WIN32
Expand Down
135 changes: 68 additions & 67 deletions src/logging.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -63,13 +63,6 @@ int g_rcutils_logging_default_logger_level = 0;
bool g_force_stdout_line_buffered = false;
bool g_stdout_flush_failure_reported = false;

/**
* Handles formatting the log data into a common string format for every logger
*/
static void format_log(
const rcutils_log_location_t * location,
int severity, const char * name, rcutils_time_point_value_t timestamp,
const char * format, va_list * args, rcutils_char_array_t * logging_output);

rcutils_ret_t rcutils_logging_initialize(void)
{
Expand Down Expand Up @@ -386,7 +379,7 @@ bool rcutils_logging_logger_is_enabled_for(const char * name, int severity)

#define OK_OR_RETURN_EARLY(op) \
if (op != RCUTILS_RET_OK) { \
SAFE_FWRITE_TO_STDERR_AND(return ); \
return op; \
}

#define APPEND_AND_RETURN_LOG_OUTPUT(s) \
Expand All @@ -409,34 +402,18 @@ void rcutils_log(
}
rcutils_logging_output_handler_t output_handler = g_rcutils_logging_output_handler;
if (output_handler != NULL) {
char buf[1024] = "";
rcutils_char_array_t logging_output = {
.buffer = buf,
.owns_buffer = false,
.buffer_length = 0u,
.buffer_capacity = sizeof(buf),
.allocator = g_rcutils_logging_allocator
};

va_list args;
va_start(args, format);
format_log(location, severity, name, now, format, &args, &logging_output);
(*output_handler)(location, severity, name ? name : "", now, format, &args);
va_end(args);

(*output_handler)(location, severity, name ? name : "", now, logging_output.buffer);

if (rcutils_char_array_fini(&logging_output) != RCUTILS_RET_OK) {
SAFE_FWRITE_TO_STDERR_AND(fprintf(stderr, "Error: failed to clean up rcutils char array.\n"));
}
}
}

typedef struct logging_input
{
const char * name;
const rcutils_log_location_t * location;
const char * format;
va_list * args;
const char * msg;
int severity;
rcutils_time_point_value_t timestamp;
} logging_input;
Expand Down Expand Up @@ -524,28 +501,8 @@ const char * expand_message(
const logging_input * logging_input,
rcutils_char_array_t * logging_output)
{
char buf[1024] = "";

rcutils_char_array_t message_buffer = {
.buffer = buf,
.owns_buffer = false,
.buffer_length = 0u,
.buffer_capacity = sizeof(buf),
.allocator = g_rcutils_logging_allocator
};

char * ret = NULL;
if (rcutils_char_array_vsprintf(&message_buffer, logging_input->format,
*(logging_input->args)) == RCUTILS_RET_OK)
{
if (rcutils_char_array_strcat(logging_output, message_buffer.buffer) == RCUTILS_RET_OK) {
ret = logging_output->buffer;
}
}

OK_OR_RETURN_NULL(rcutils_char_array_fini(&message_buffer));

return ret;
OK_OR_RETURN_NULL(rcutils_char_array_strcat(logging_output, logging_input->msg));
return logging_output->buffer;
}

const char * expand_function_name(
Expand Down Expand Up @@ -590,11 +547,12 @@ token_handler find_token_handler(const char * token)
return NULL;
}

static void format_log(
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 * format, va_list * args, rcutils_char_array_t * logging_output)
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 = '}';
Expand All @@ -607,8 +565,7 @@ static void format_log(
.severity = severity,
.name = name,
.timestamp = timestamp,
.format = format,
.args = args
.msg = msg
};

// Walk through the format string and expand tokens when they're encountered.
Expand All @@ -621,7 +578,8 @@ static void format_log(
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;
OK_OR_RETURN_EARLY(rcutils_char_array_strncat(logging_output, str + i, chars_to_copy));
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;
Expand All @@ -639,7 +597,8 @@ static void format_log(
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.
OK_OR_RETURN_EARLY(rcutils_char_array_strncat(logging_output, str + i, remaining_chars));
status = rcutils_char_array_strncat(logging_output, str + i, remaining_chars);
OK_OR_RETURN_EARLY(status);
break;
}

Expand All @@ -653,27 +612,29 @@ static void format_log(
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).
OK_OR_RETURN_EARLY(rcutils_char_array_strncat(logging_output, str + i, 1));
status = rcutils_char_array_strncat(logging_output, str + i, 1);
OK_OR_RETURN_EARLY(status);
i++;
continue;
}

if (!expand_token(&logging_input, logging_output)) {
return;
return RCUTILS_RET_ERROR;
}
// Skip ahead to avoid re-processing the token characters (including the 2 delimiters).
i += token_len + 2;
}

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 * log_str)
const char * format, va_list * args)
{
RCUTILS_UNUSED(location);
RCUTILS_UNUSED(name);
RCUTILS_UNUSED(timestamp);
rcutils_ret_t status = RCUTILS_RET_OK;

if (!g_rcutils_logging_initialized) {
fprintf(
stderr,
Expand All @@ -697,16 +658,56 @@ void rcutils_logging_console_output_handler(
return;
}

fprintf(stream, "%s\n", log_str);
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);
va_end(args_clone);

if (RCUTILS_RET_OK == status) {
status = rcutils_logging_format_message(
location, severity, name, timestamp, msg_array.buffer, &output_array);
Copy link
Member

Choose a reason for hiding this comment

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

Similarly, we should check status and notify someone somehow if status is no OK.

}
Copy link
Member

Choose a reason for hiding this comment

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

I think we need an else case here where we at least either set the error state or use the SAFE_FWRITE macro or fprintf(stderr, ...) (as appears to be the style in this file) to let someone know that vsprintf failed.



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 (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);
}
}
}

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

#ifdef __cplusplus
Expand Down
8 changes: 4 additions & 4 deletions test/test_logging.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,15 +58,15 @@ TEST(CLASSNAME(TestLogging, RMW_IMPLEMENTATION), test_logging) {
auto rcutils_logging_console_output_handler = [](
const rcutils_log_location_t * location,
int level, const char * name, rcutils_time_point_value_t timestamp,
const char * log_str) -> void
const char * format, va_list * args) -> void
{
g_log_calls += 1;
g_last_log_event.location = location;
g_last_log_event.level = level;
g_last_log_event.name = name ? name : "";
g_last_log_event.timestamp = timestamp;
char buffer[1024];
strncpy(buffer, log_str, sizeof(buffer));
vsnprintf(buffer, sizeof(buffer), format, *args);
g_last_log_event.message = buffer;
};

Expand All @@ -88,7 +88,7 @@ TEST(CLASSNAME(TestLogging, RMW_IMPLEMENTATION), test_logging) {
}
EXPECT_EQ(RCUTILS_LOG_SEVERITY_DEBUG, g_last_log_event.level);
EXPECT_EQ("name1", g_last_log_event.name);
EXPECT_EQ("[DEBUG] [name1]: message 11", g_last_log_event.message);
EXPECT_EQ("message 11", g_last_log_event.message);

// check default level
int original_level = rcutils_logging_get_default_logger_level();
Expand All @@ -106,7 +106,7 @@ TEST(CLASSNAME(TestLogging, RMW_IMPLEMENTATION), test_logging) {
EXPECT_EQ(2u, g_log_calls);
EXPECT_EQ(RCUTILS_LOG_SEVERITY_INFO, g_last_log_event.level);
EXPECT_EQ("name3", g_last_log_event.name);
EXPECT_EQ("[INFO] [name3]: message 33", g_last_log_event.message);
EXPECT_EQ("message 33", g_last_log_event.message);

rcutils_log(NULL, RCUTILS_LOG_SEVERITY_WARN, "", "");
EXPECT_EQ(3u, g_log_calls);
Expand Down
12 changes: 6 additions & 6 deletions test/test_logging_macros.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,7 +34,7 @@ struct LogEvent g_last_log_event;
void custom_handler(
const rcutils_log_location_t * location,
int severity, const char * name, rcutils_time_point_value_t timestamp,
const char * log_str)
const char * format, va_list * args)
{
rcutils_allocator_t allocator = rcutils_get_default_allocator();
g_log_calls += 1;
Expand All @@ -47,7 +47,7 @@ void custom_handler(
}
const size_t size = 1024;
g_last_log_event.message = allocator.allocate(size, allocator.state);
strncpy(g_last_log_event.message, log_str, size);
vsnprintf(g_last_log_event.message, size, format, *args);
}

int main(int argc, char ** argv)
Expand Down Expand Up @@ -93,8 +93,8 @@ int main(int argc, char ** argv)
fprintf(stderr, "name unexpectedly not empty string\n");
return 8;
}
if (strcmp(g_last_log_event.message, "[INFO] []: empty message")) {
fprintf(stderr, "message unexpectedly not '[INFO] []: empty message'\n");
if (strcmp(g_last_log_event.message, "empty message")) {
fprintf(stderr, "message unexpectedly not 'empty message'\n");
return 9;
}

Expand Down Expand Up @@ -123,8 +123,8 @@ int main(int argc, char ** argv)
fprintf(stderr, "name unexpectedly not empty string\n");
return 15;
}
if (strcmp(g_last_log_event.message, "[INFO] []: message foo")) {
fprintf(stderr, "message unexpectedly not '[INFO] []: message foo'\n");
if (strcmp(g_last_log_event.message, "message foo")) {
fprintf(stderr, "message unexpectedly not 'message foo'\n");
return 16;
}

Expand Down
Loading