diff options
| -rw-r--r-- | docs/ENVIRONMENT.md | 3 | ||||
| -rw-r--r-- | src/basic/list.h | 6 | ||||
| -rw-r--r-- | src/basic/log.c | 164 | ||||
| -rw-r--r-- | src/basic/log.h | 82 | ||||
| -rw-r--r-- | src/test/test-log.c | 71 |
5 files changed, 308 insertions, 18 deletions
diff --git a/docs/ENVIRONMENT.md b/docs/ENVIRONMENT.md index fb35300419..b59b763129 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 4a6e1505a5..ffc8bd8304 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 282130345f..fc5793139e 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 2b1ac5f8c6..fcb8fcfb69 100644 --- a/src/basic/log.h +++ b/src/basic/log.h @@ -7,8 +7,10 @@ #include <string.h> #include <syslog.h> +#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 f21d88f39a..30c536d5c7 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; |