From 7c7a9138a20a6657071b3dd112fda9747ba1d6c1 Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Thu, 12 May 2022 13:50:51 +0200 Subject: [PATCH] basic: Add log context This commit adds support for attaching extra metadata to log messages written to the journal via log.h. We keep track of a thread local log context in log.c onto which we can push extra metadata fields that should be logged. Once a field is no longer relevant, it can be popped again from the log context. On top of this, we then add macros to allow pushing extra fields onto the log context. LOG_CONTEXT_PUSH() will push the provided field onto the log context and pop the last field from the log context when the current block ends. LOG_CONTEXT_PUSH_STRV() will do the same but for all fields in the given strv. Using the macros is as simple as putting them anywhere inside a block to add a field to all following log messages logged from inside that block. void myfunction(...) { ... LOG_CONTEXT_PUSH("MYMETADATA=abc"); // Every journal message logged will now have the MYMETADATA=abc // field included. } For convenience, there's also LOG_CONTEXT_PUSHF() to allow constructing the field to be logged using printf() syntax. log_context_new()/log_context_free() can be used to attach a log context to an async operation by storing it in the associated userdata struct. --- docs/ENVIRONMENT.md | 3 + src/basic/list.h | 6 +- src/basic/log.c | 164 +++++++++++++++++++++++++++++++++++++++----- src/basic/log.h | 82 ++++++++++++++++++++++ src/test/test-log.c | 71 +++++++++++++++++++ 5 files changed, 308 insertions(+), 18 deletions(-) diff --git a/docs/ENVIRONMENT.md b/docs/ENVIRONMENT.md index fb353004190..b59b7631294 100644 --- a/docs/ENVIRONMENT.md +++ b/docs/ENVIRONMENT.md @@ -114,6 +114,9 @@ All tools: for example in `systemd-nspawn`, will be logged to the audit log, if the kernel supports this. +* `$SYSTEMD_ENABLE_LOG_CONTEXT` — if set, extra fields will always be logged to +the journal instead of only when logging in debug mode. + `systemctl`: * `$SYSTEMCTL_FORCE_BUS=1` — if set, do not connect to PID 1's private D-Bus diff --git a/src/basic/list.h b/src/basic/list.h index 4a6e1505a51..ffc8bd83045 100644 --- a/src/basic/list.h +++ b/src/basic/list.h @@ -1,8 +1,6 @@ /* SPDX-License-Identifier: LGPL-2.1-or-later */ #pragma once -#include "macro.h" - /* The head of the linked list. Use this in the structure that shall * contain the head of the linked list */ #define LIST_HEAD(t,name) \ @@ -190,3 +188,7 @@ LIST_REMOVE(name, *_a, _p); \ _p; \ }) + +/* Now include "macro.h", because we want our definition of assert() which the macros above use. We include + * it down here instead of up top, since macro.h pulls in log.h which in turn needs our own definitions. */ +#include "macro.h" diff --git a/src/basic/log.c b/src/basic/log.c index 282130345f3..fc5793139ed 100644 --- a/src/basic/log.c +++ b/src/basic/log.c @@ -17,6 +17,7 @@ #include "alloc-util.h" #include "argv-util.h" +#include "env-util.h" #include "errno-util.h" #include "fd-util.h" #include "format-util.h" @@ -33,12 +34,14 @@ #include "stdio-util.h" #include "string-table.h" #include "string-util.h" +#include "strv.h" #include "syslog-util.h" #include "terminal-util.h" #include "time-util.h" #include "utf8.h" #define SNDBUF_SIZE (8*1024*1024) +#define IOVEC_MAX 128U static log_syntax_callback_t log_syntax_callback = NULL; static void *log_syntax_callback_userdata = NULL; @@ -68,6 +71,17 @@ static bool prohibit_ipc = false; * use here. */ static char *log_abort_msg = NULL; +typedef struct LogContext { + /* Depending on which destructor is used (log_context_free() or log_context_detach()) the memory + * referenced by this is freed or not */ + char **fields; + bool owned; + LIST_FIELDS(struct LogContext, ll); +} LogContext; + +static thread_local LIST_HEAD(LogContext, _log_context) = NULL; +static thread_local size_t _log_context_num_fields = 0; + #if LOG_MESSAGE_VERIFICATION || defined(__COVERITY__) bool _log_message_dummy = false; /* Always false */ #endif @@ -589,6 +603,20 @@ static int log_do_header( return 0; } +static void log_do_context(struct iovec *iovec, size_t iovec_len, size_t *n) { + assert(iovec); + assert(n); + + LIST_FOREACH(ll, c, _log_context) + STRV_FOREACH(s, c->fields) { + if (*n + 2 >= iovec_len) + return; + + iovec[(*n)++] = IOVEC_MAKE_STRING(*s); + iovec[(*n)++] = IOVEC_MAKE_STRING("\n"); + } +} + static int write_to_journal( int level, int error, @@ -602,21 +630,27 @@ static int write_to_journal( const char *buffer) { char header[LINE_MAX]; + size_t n = 0, iovec_len; + struct iovec *iovec; if (journal_fd < 0) return 0; + iovec_len = MIN(4 + _log_context_num_fields * 2, IOVEC_MAX); + iovec = newa(struct iovec, iovec_len); + log_do_header(header, sizeof(header), level, error, file, line, func, object_field, object, extra_field, extra); - struct iovec iovec[4] = { - IOVEC_MAKE_STRING(header), - IOVEC_MAKE_STRING("MESSAGE="), - IOVEC_MAKE_STRING(buffer), - IOVEC_MAKE_STRING("\n"), - }; + iovec[n++] = IOVEC_MAKE_STRING(header); + iovec[n++] = IOVEC_MAKE_STRING("MESSAGE="); + iovec[n++] = IOVEC_MAKE_STRING(buffer); + iovec[n++] = IOVEC_MAKE_STRING("\n"); + + log_do_context(iovec, iovec_len, &n); + const struct msghdr msghdr = { .msg_iov = iovec, - .msg_iovlen = ELEMENTSOF(iovec), + .msg_iovlen = n, }; if (sendmsg(journal_fd, &msghdr, MSG_NOSIGNAL) < 0) @@ -948,21 +982,27 @@ int log_struct_internal( if (journal_fd >= 0) { char header[LINE_MAX]; - struct iovec iovec[17]; - size_t n = 0; + struct iovec *iovec; + size_t n = 0, m, iovec_len; int r; bool fallback = false; + iovec_len = MIN(17 + _log_context_num_fields * 2, IOVEC_MAX); + iovec = newa(struct iovec, iovec_len); + /* If the journal is available do structured logging. * Do not report the errno if it is synthetic. */ log_do_header(header, sizeof(header), level, error, file, line, func, NULL, NULL, NULL, NULL); iovec[n++] = IOVEC_MAKE_STRING(header); va_start(ap, format); - r = log_format_iovec(iovec, ELEMENTSOF(iovec), &n, true, error, format, ap); + r = log_format_iovec(iovec, iovec_len, &n, true, error, format, ap); + m = n; if (r < 0) fallback = true; else { + log_do_context(iovec, iovec_len, &n); + const struct msghdr msghdr = { .msg_iov = iovec, .msg_iovlen = n, @@ -972,7 +1012,7 @@ int log_struct_internal( } va_end(ap); - for (size_t i = 1; i < n; i += 2) + for (size_t i = 1; i < m; i += 2) free(iovec[i].iov_base); if (!fallback) { @@ -1041,18 +1081,25 @@ int log_struct_iovec_internal( journal_fd >= 0) { char header[LINE_MAX]; + struct iovec *iovec; + size_t n = 0, iovec_len; + + iovec_len = MIN(1 + n_input_iovec * 2 + _log_context_num_fields * 2, IOVEC_MAX); + iovec = newa(struct iovec, iovec_len); + log_do_header(header, sizeof(header), level, error, file, line, func, NULL, NULL, NULL, NULL); - struct iovec iovec[1 + n_input_iovec*2]; - iovec[0] = IOVEC_MAKE_STRING(header); + iovec[n++] = IOVEC_MAKE_STRING(header); for (size_t i = 0; i < n_input_iovec; i++) { - iovec[1+i*2] = input_iovec[i]; - iovec[1+i*2+1] = IOVEC_MAKE_STRING("\n"); + iovec[n++] = input_iovec[i]; + iovec[n++] = IOVEC_MAKE_STRING("\n"); } + log_do_context(iovec, iovec_len, &n); + const struct msghdr msghdr = { .msg_iov = iovec, - .msg_iovlen = 1 + n_input_iovec*2, + .msg_iovlen = n, }; if (sendmsg(journal_fd, &msghdr, MSG_NOSIGNAL) >= 0) @@ -1477,3 +1524,88 @@ void log_setup(void) { if (log_on_console() && show_color < 0) log_show_color(true); } + +static int saved_log_context_enabled = -1; + +bool log_context_enabled(void) { + int r; + + if (log_get_max_level() == LOG_DEBUG) + return true; + + if (saved_log_context_enabled >= 0) + return saved_log_context_enabled; + + r = getenv_bool_secure("SYSTEMD_ENABLE_LOG_CONTEXT"); + if (r < 0 && r != -ENXIO) + log_debug_errno(r, "Failed to parse $SYSTEMD_ENABLE_LOG_CONTEXT, ignoring: %m"); + + saved_log_context_enabled = r > 0; + + return saved_log_context_enabled; +} + +LogContext* log_context_attach(LogContext *c) { + assert(c); + + _log_context_num_fields += strv_length(c->fields); + + return LIST_PREPEND(ll, _log_context, c); +} + +LogContext* log_context_detach(LogContext *c) { + if (!c) + return NULL; + + assert(_log_context_num_fields >= strv_length(c->fields)); + _log_context_num_fields -= strv_length(c->fields); + + LIST_REMOVE(ll, _log_context, c); + return NULL; +} + +LogContext* log_context_new(char **fields, bool owned) { + LogContext *c = new(LogContext, 1); + if (!c) + return NULL; + + *c = (LogContext) { + .fields = fields, + .owned = owned, + }; + + return log_context_attach(c); +} + +LogContext* log_context_free(LogContext *c) { + if (!c) + return NULL; + + log_context_detach(c); + + if (c->owned) + strv_free(c->fields); + + return mfree(c); +} + +LogContext* log_context_new_consume(char **fields) { + LogContext *c = log_context_new(fields, /*owned=*/ true); + if (!c) + strv_free(fields); + + return c; +} + +size_t log_context_num_contexts(void) { + size_t n = 0; + + LIST_FOREACH(ll, c, _log_context) + n++; + + return n; +} + +size_t log_context_num_fields(void) { + return _log_context_num_fields; +} diff --git a/src/basic/log.h b/src/basic/log.h index 2b1ac5f8c64..fcb8fcfb69a 100644 --- a/src/basic/log.h +++ b/src/basic/log.h @@ -7,8 +7,10 @@ #include #include +#include "list.h" #include "macro.h" #include "ratelimit.h" +#include "stdio-util.h" /* Some structures we reference but don't want to pull in headers for */ struct iovec; @@ -420,3 +422,83 @@ typedef struct LogRateLimit { #define log_ratelimit_warning_errno(error, ...) log_ratelimit_full_errno(LOG_WARNING, error, __VA_ARGS__) #define log_ratelimit_error_errno(error, ...) log_ratelimit_full_errno(LOG_ERR, error, __VA_ARGS__) #define log_ratelimit_emergency_errno(error, ...) log_ratelimit_full_errno(log_emergency_level(), error, __VA_ARGS__) + +/* + * The log context allows attaching extra metadata to log messages written to the journal via log.h. We keep + * track of a thread local log context onto which we can push extra metadata fields that should be logged. + * + * LOG_CONTEXT_PUSH() will add the provided field to the log context and will remove it again when the + * current block ends. LOG_CONTEXT_PUSH_STRV() will do the same but for all fields in the given strv. + * LOG_CONTEXT_PUSHF() is like LOG_CONTEXT_PUSH() but takes a format string and arguments. + * + * Using the macros is as simple as putting them anywhere inside a block to add a field to all following log + * messages logged from inside that block. + * + * void myfunction(...) { + * ... + * + * LOG_CONTEXT_PUSHF("MYMETADATA=%s", "abc"); + * + * // Every journal message logged will now have the MYMETADATA=abc + * // field included. + * } + * + * One special case to note is async code, where we use callbacks that are invoked to continue processing + * when some event occurs. For async code, there's usually an associated "userdata" struct containing all the + * information associated with the async operation. In this "userdata" struct, we can store a log context + * allocated with log_context_new() and freed with log_context_free(). We can then add and remove fields to + * the `fields` member of the log context object and all those fields will be logged along with each log + * message. + */ + +typedef struct LogContext LogContext; + +bool log_context_enabled(void); + +LogContext* log_context_attach(LogContext *c); +LogContext* log_context_detach(LogContext *c); + +LogContext* log_context_new(char **fields, bool owned); +LogContext* log_context_free(LogContext *c); + +/* Same as log_context_new(), but frees the given fields strv on failure. */ +LogContext* log_context_new_consume(char **fields); + +/* Returns the number of attached log context objects. */ +size_t log_context_num_contexts(void); +/* Returns the number of fields in all attached log contexts. */ +size_t log_context_num_fields(void); + +DEFINE_TRIVIAL_CLEANUP_FUNC(LogContext*, log_context_detach); +DEFINE_TRIVIAL_CLEANUP_FUNC(LogContext*, log_context_free); + +#define LOG_CONTEXT_PUSH(...) \ + LOG_CONTEXT_PUSH_STRV(STRV_MAKE(__VA_ARGS__)) + +#define LOG_CONTEXT_PUSHF(...) \ + LOG_CONTEXT_PUSH(snprintf_ok((char[LINE_MAX]) {}, LINE_MAX, __VA_ARGS__)) + +#define _LOG_CONTEXT_PUSH_STRV(strv, c) \ + _unused_ _cleanup_(log_context_freep) LogContext *c = log_context_new(strv, /*owned=*/ false); + +#define LOG_CONTEXT_PUSH_STRV(strv) \ + _LOG_CONTEXT_PUSH_STRV(strv, UNIQ_T(c, UNIQ)) + +/* LOG_CONTEXT_CONSUME_STR()/LOG_CONTEXT_CONSUME_STRV() are identical to + * LOG_CONTEXT_PUSH_STR()/LOG_CONTEXT_PUSH_STRV() except they take ownership of the given str/strv argument. + */ + +#define _LOG_CONTEXT_CONSUME_STR(s, c, strv) \ + _unused_ _cleanup_strv_free_ strv = strv_new(s); \ + if (!strv) \ + free(s); \ + _unused_ _cleanup_(log_context_freep) LogContext *c = log_context_new_consume(TAKE_PTR(strv)) + +#define LOG_CONTEXT_CONSUME_STR(s) \ + _LOG_CONTEXT_CONSUME_STR(s, UNIQ_T(c, UNIQ), UNIQ_T(sv, UNIQ)) + +#define _LOG_CONTEXT_CONSUME_STRV(strv, c) \ + _unused_ _cleanup_(log_context_freep) LogContext *c = log_context_new_consume(strv); + +#define LOG_CONTEXT_CONSUME_STRV(strv) \ + _LOG_CONTEXT_CONSUME_STRV(strv, UNIQ_T(c, UNIQ)) diff --git a/src/test/test-log.c b/src/test/test-log.c index f21d88f39ab..30c536d5c7c 100644 --- a/src/test/test-log.c +++ b/src/test/test-log.c @@ -7,6 +7,7 @@ #include "log.h" #include "process-util.h" #include "string-util.h" +#include "strv.h" assert_cc(IS_SYNTHETIC_ERRNO(SYNTHETIC_ERRNO(EINVAL))); assert_cc(!IS_SYNTHETIC_ERRNO(EINVAL)); @@ -69,6 +70,75 @@ static void test_log_syntax(void) { assert_se(log_syntax("unit", LOG_ERR, "filename", 10, SYNTHETIC_ERRNO(ENOTTY), "ENOTTY: %s: %m", "hogehoge") == -ENOTTY); } +static void test_log_context(void) { + { + char **strv = STRV_MAKE("FIRST=abc", "SECOND=qrs"); + + LOG_CONTEXT_PUSH("THIRD=pfs"); + LOG_CONTEXT_PUSH("FOURTH=def"); + LOG_CONTEXT_PUSH_STRV(strv); + LOG_CONTEXT_PUSH_STRV(strv); + + /* Test that the log context was set up correctly. */ + assert_se(log_context_num_contexts() == 4); + assert_se(log_context_num_fields() == 6); + + /* Test that everything still works with modifications to the log context. */ + test_log_struct(); + test_long_lines(); + test_log_syntax(); + + { + LOG_CONTEXT_PUSH("FIFTH=123"); + LOG_CONTEXT_PUSH_STRV(strv); + + /* Check that our nested fields got added correctly. */ + assert_se(log_context_num_contexts() == 6); + assert_se(log_context_num_fields() == 9); + + /* Test that everything still works in a nested block. */ + test_log_struct(); + test_long_lines(); + test_log_syntax(); + } + + /* Check that only the fields from the nested block got removed. */ + assert_se(log_context_num_contexts() == 4); + assert_se(log_context_num_fields() == 6); + } + + assert_se(log_context_num_contexts() == 0); + assert_se(log_context_num_fields() == 0); + + { + _cleanup_(log_context_freep) LogContext *ctx = NULL; + + char **strv = STRV_MAKE("SIXTH=ijn", "SEVENTH=PRP"); + assert_se(ctx = log_context_new(strv, /*owned=*/ false)); + + assert_se(log_context_num_contexts() == 1); + assert_se(log_context_num_fields() == 2); + + /* Test that everything still works with a manually configured log context. */ + test_log_struct(); + test_long_lines(); + test_log_syntax(); + } + + { + char **strv = NULL; + + assert_se(strv = strv_new("ABC", "DEF")); + LOG_CONTEXT_CONSUME_STRV(strv); + + assert_se(log_context_num_contexts() == 1); + assert_se(log_context_num_fields() == 2); + } + + assert_se(log_context_num_contexts() == 0); + assert_se(log_context_num_fields() == 0); +} + int main(int argc, char* argv[]) { test_file(); @@ -81,6 +151,7 @@ int main(int argc, char* argv[]) { test_log_struct(); test_long_lines(); test_log_syntax(); + test_log_context(); } return 0;