diff options
author | Luca Boccassi <bluca@debian.org> | 2023-01-20 15:01:03 +0000 |
---|---|---|
committer | GitHub <noreply@github.com> | 2023-01-20 15:01:03 +0000 |
commit | 71c6f0ac524e174800a23410b121bee45f9e3f67 (patch) | |
tree | 28d862288c21287a000a0e6fa6eeee7e54d11418 | |
parent | 24a3b37f12a1a752e5a1379cadc15031b04c3fba (diff) | |
parent | e808a1d12eaa3c0e9eff600d1d8d84fff19de990 (diff) | |
download | systemd-71c6f0ac524e174800a23410b121bee45f9e3f67.tar.gz |
Merge pull request #23309 from DaanDeMeyer/log-context
basic: Add log context
-rw-r--r-- | docs/ENVIRONMENT.md | 3 | ||||
-rw-r--r-- | src/basic/list.h | 71 | ||||
-rw-r--r-- | src/basic/log.c | 164 | ||||
-rw-r--r-- | src/basic/log.h | 82 | ||||
-rw-r--r-- | src/basic/stdio-util.h | 23 | ||||
-rw-r--r-- | src/basic/strv.c | 16 | ||||
-rw-r--r-- | src/basic/strv.h | 2 | ||||
-rw-r--r-- | src/core/execute.c | 2 | ||||
-rw-r--r-- | src/core/load-fragment.c | 2 | ||||
-rw-r--r-- | src/libsystemd/sd-bus/bus-message.c | 23 | ||||
-rw-r--r-- | src/libsystemd/sd-bus/bus-message.h | 2 | ||||
-rw-r--r-- | src/libsystemd/sd-bus/sd-bus.c | 4 | ||||
-rw-r--r-- | src/libsystemd/sd-device/device-monitor.c | 4 | ||||
-rw-r--r-- | src/libsystemd/sd-device/device-util.c | 76 | ||||
-rw-r--r-- | src/libsystemd/sd-device/device-util.h | 2 | ||||
-rw-r--r-- | src/resolve/resolved-dns-search-domain.c | 4 | ||||
-rw-r--r-- | src/resolve/resolved-dns-server.c | 6 | ||||
-rw-r--r-- | src/systemctl/systemctl-show.c | 2 | ||||
-rw-r--r-- | src/test/test-list.c | 51 | ||||
-rw-r--r-- | src/test/test-log.c | 71 | ||||
-rw-r--r-- | src/test/test-strv.c | 12 | ||||
-rw-r--r-- | src/timesync/timesyncd-server.c | 2 |
22 files changed, 528 insertions, 96 deletions
diff --git a/docs/ENVIRONMENT.md b/docs/ENVIRONMENT.md index ef0141e1a6..30ef1e7e42 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 ca30039690..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) \ @@ -28,26 +26,27 @@ /* Prepend an item to the list */ #define LIST_PREPEND(name,head,item) \ - do { \ + ({ \ typeof(*(head)) **_head = &(head), *_item = (item); \ assert(_item); \ if ((_item->name##_next = *_head)) \ _item->name##_next->name##_prev = _item; \ _item->name##_prev = NULL; \ *_head = _item; \ - } while (false) + _item; \ + }) /* Append an item to the list */ #define LIST_APPEND(name,head,item) \ - do { \ + ({ \ typeof(*(head)) **_hhead = &(head), *_tail; \ - LIST_FIND_TAIL(name, *_hhead, _tail); \ + _tail = LIST_FIND_TAIL(name, *_hhead); \ LIST_INSERT_AFTER(name, *_hhead, _tail, item); \ - } while (false) + }) /* Remove an item from the list */ #define LIST_REMOVE(name,head,item) \ - do { \ + ({ \ typeof(*(head)) **_head = &(head), *_item = (item); \ assert(_item); \ if (_item->name##_next) \ @@ -59,37 +58,30 @@ *_head = _item->name##_next; \ } \ _item->name##_next = _item->name##_prev = NULL; \ - } while (false) + _item; \ + }) /* Find the head of the list */ -#define LIST_FIND_HEAD(name,item,head) \ - do { \ +#define LIST_FIND_HEAD(name,item) \ + ({ \ typeof(*(item)) *_item = (item); \ - if (!_item) \ - (head) = NULL; \ - else { \ - while (_item->name##_prev) \ - _item = _item->name##_prev; \ - (head) = _item; \ - } \ - } while (false) + while (_item && _item->name##_prev) \ + _item = _item->name##_prev; \ + _item; \ + }) /* Find the tail of the list */ -#define LIST_FIND_TAIL(name,item,tail) \ - do { \ +#define LIST_FIND_TAIL(name,item) \ + ({ \ typeof(*(item)) *_item = (item); \ - if (!_item) \ - (tail) = NULL; \ - else { \ - while (_item->name##_next) \ - _item = _item->name##_next; \ - (tail) = _item; \ - } \ - } while (false) + while (_item && _item->name##_next) \ + _item = _item->name##_next; \ + _item; \ + }) /* Insert an item after another one (a = where, b = what) */ #define LIST_INSERT_AFTER(name,head,a,b) \ - do { \ + ({ \ typeof(*(head)) **_head = &(head), *_a = (a), *_b = (b); \ assert(_b); \ if (!_a) { \ @@ -103,11 +95,12 @@ _b->name##_prev = _a; \ _a->name##_next = _b; \ } \ - } while (false) + _b; \ + }) /* Insert an item before another one (a = where, b = what) */ #define LIST_INSERT_BEFORE(name,head,a,b) \ - do { \ + ({ \ typeof(*(head)) **_head = &(head), *_a = (a), *_b = (b); \ assert(_b); \ if (!_a) { \ @@ -131,7 +124,8 @@ _b->name##_next = _a; \ _a->name##_prev = _b; \ } \ - } while (false) + _b; \ + }) #define LIST_JUST_US(name,item) \ (!(item)->name##_prev && !(item)->name##_next) @@ -172,18 +166,19 @@ /* Join two lists tail to head: a->b, c->d to a->b->c->d and de-initialise second list */ #define LIST_JOIN(name,a,b) \ - do { \ + ({ \ assert(b); \ if (!(a)) \ (a) = (b); \ else { \ typeof(*(a)) *_head = (b), *_tail; \ - LIST_FIND_TAIL(name, (a), _tail); \ + _tail = LIST_FIND_TAIL(name, (a)); \ _tail->name##_next = _head; \ _head->name##_prev = _tail; \ } \ (b) = NULL; \ - } while (false) + a; \ + }) #define LIST_POP(name, a) \ ({ \ @@ -193,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/basic/stdio-util.h b/src/basic/stdio-util.h index f647f125ac..4e93ac90c9 100644 --- a/src/basic/stdio-util.h +++ b/src/basic/stdio-util.h @@ -7,15 +7,20 @@ #include <sys/types.h> #include "macro.h" -#include "memory-util.h" -#define snprintf_ok(buf, len, fmt, ...) \ - ({ \ - char *_buf = (buf); \ - size_t _len = (len); \ - int _snpf = snprintf(_buf, _len, (fmt), ##__VA_ARGS__); \ - _snpf >= 0 && (size_t) _snpf < _len ? _buf : NULL; \ - }) +_printf_(3, 4) +static inline char *snprintf_ok(char *buf, size_t len, const char *format, ...) { + va_list ap; + int r; + + va_start(ap, format); + DISABLE_WARNING_FORMAT_NONLITERAL; + r = vsnprintf(buf, len, format, ap); + REENABLE_WARNING; + va_end(ap); + + return r >= 0 && (size_t) r < len ? buf : NULL; +} #define xsprintf(buf, fmt, ...) \ assert_message_se(snprintf_ok(buf, ELEMENTSOF(buf), fmt, ##__VA_ARGS__), "xsprintf: " #buf "[] must be big enough") @@ -26,7 +31,7 @@ do { \ size_t _i, _k; \ /* See https://github.com/google/sanitizers/issues/992 */ \ if (HAS_FEATURE_MEMORY_SANITIZER) \ - zero(_argtypes); \ + memset(_argtypes, 0, sizeof(_argtypes)); \ _k = parse_printf_format((format), ELEMENTSOF(_argtypes), _argtypes); \ assert(_k < ELEMENTSOF(_argtypes)); \ for (_i = 0; _i < _k; _i++) { \ diff --git a/src/basic/strv.c b/src/basic/strv.c index 74e87046cc..2b7a61d442 100644 --- a/src/basic/strv.c +++ b/src/basic/strv.c @@ -789,6 +789,22 @@ rollback: return -ENOMEM; } +int strv_extend_assignment(char ***l, const char *lhs, const char *rhs) { + char *j; + + assert(l); + assert(lhs); + + if (!rhs) /* value is optional, in which case we suppress the field */ + return 0; + + j = strjoin(lhs, "=", rhs); + if (!j) + return -ENOMEM; + + return strv_consume(l, j); +} + int fputstrv(FILE *f, char * const *l, const char *separator, bool *space) { bool b = false; int r; diff --git a/src/basic/strv.h b/src/basic/strv.h index f82c76589d..1f8da85fcc 100644 --- a/src/basic/strv.h +++ b/src/basic/strv.h @@ -241,6 +241,8 @@ char** strv_skip(char **l, size_t n); int strv_extend_n(char ***l, const char *value, size_t n); +int strv_extend_assignment(char ***l, const char *lhs, const char *rhs); + int fputstrv(FILE *f, char * const *l, const char *separator, bool *space); #define strv_free_and_replace(a, b) \ diff --git a/src/core/execute.c b/src/core/execute.c index f5d57a63b5..ac3f096b0d 100644 --- a/src/core/execute.c +++ b/src/core/execute.c @@ -6650,7 +6650,7 @@ void exec_command_append_list(ExecCommand **l, ExecCommand *e) { if (*l) { /* It's kind of important, that we keep the order here */ - LIST_FIND_TAIL(command, *l, end); + end = LIST_FIND_TAIL(command, *l); LIST_INSERT_AFTER(command, *l, end, e); } else *l = e; diff --git a/src/core/load-fragment.c b/src/core/load-fragment.c index 6c55bc5187..0ed2d1b31d 100644 --- a/src/core/load-fragment.c +++ b/src/core/load-fragment.c @@ -680,7 +680,7 @@ int config_parse_socket_listen( p->n_auxiliary_fds = 0; p->socket = s; - LIST_FIND_TAIL(port, s->ports, tail); + tail = LIST_FIND_TAIL(port, s->ports); LIST_INSERT_AFTER(port, s->ports, tail, p); p = NULL; diff --git a/src/libsystemd/sd-bus/bus-message.c b/src/libsystemd/sd-bus/bus-message.c index 07168f660b..9719f97c02 100644 --- a/src/libsystemd/sd-bus/bus-message.c +++ b/src/libsystemd/sd-bus/bus-message.c @@ -4667,3 +4667,26 @@ _public_ int sd_bus_message_sensitive(sd_bus_message *m) { m->sensitive = true; return 0; } + +char** bus_message_make_log_fields(sd_bus_message *m) { + _cleanup_strv_free_ char **strv = NULL; + + assert(m); + + (void) strv_extend_assignment(&strv, "DBUS_MESSAGE_TYPE", bus_message_type_to_string(m->header->type)); + (void) strv_extend_assignment(&strv, "DBUS_SENDER", sd_bus_message_get_sender(m)); + (void) strv_extend_assignment(&strv, "DBUS_DESTINATION", sd_bus_message_get_destination(m)); + (void) strv_extend_assignment(&strv, "DBUS_PATH", sd_bus_message_get_path(m)); + (void) strv_extend_assignment(&strv, "DBUS_INTERFACE", sd_bus_message_get_interface(m)); + (void) strv_extend_assignment(&strv, "DBUS_MEMBER", sd_bus_message_get_member(m)); + + (void) strv_extendf(&strv, "DBUS_MESSAGE_COOKIE=%" PRIu64, BUS_MESSAGE_COOKIE(m)); + if (m->reply_cookie != 0) + (void) strv_extendf(&strv, "DBUS_MESSAGE_REPLY_COOKIE=%" PRIu64, m->reply_cookie); + + (void) strv_extend_assignment(&strv, "DBUS_SIGNATURE", m->root_container.signature); + (void) strv_extend_assignment(&strv, "DBUS_ERROR_NAME", m->error.name); + (void) strv_extend_assignment(&strv, "DBUS_ERROR_MESSAGE", m->error.message); + + return TAKE_PTR(strv); +} diff --git a/src/libsystemd/sd-bus/bus-message.h b/src/libsystemd/sd-bus/bus-message.h index 0439fbd45a..76f0d853d3 100644 --- a/src/libsystemd/sd-bus/bus-message.h +++ b/src/libsystemd/sd-bus/bus-message.h @@ -187,3 +187,5 @@ void bus_message_set_sender_local(sd_bus *bus, sd_bus_message *m); sd_bus_message* bus_message_ref_queued(sd_bus_message *m, sd_bus *bus); sd_bus_message* bus_message_unref_queued(sd_bus_message *m, sd_bus *bus); + +char** bus_message_make_log_fields(sd_bus_message *m); diff --git a/src/libsystemd/sd-bus/sd-bus.c b/src/libsystemd/sd-bus/sd-bus.c index d85dcc52c1..10796e25c7 100644 --- a/src/libsystemd/sd-bus/sd-bus.c +++ b/src/libsystemd/sd-bus/sd-bus.c @@ -2928,6 +2928,7 @@ static int process_fd_check(sd_bus *bus, sd_bus_message *m) { } static int process_message(sd_bus *bus, sd_bus_message *m) { + _unused_ _cleanup_(log_context_freep) LogContext *c = NULL; int r; assert(bus); @@ -2936,6 +2937,9 @@ static int process_message(sd_bus *bus, sd_bus_message *m) { bus->current_message = m; bus->iteration_counter++; + if (log_context_enabled()) + c = log_context_new_consume(bus_message_make_log_fields(m)); + log_debug_bus_message(m); r = process_hello(bus, m); diff --git a/src/libsystemd/sd-device/device-monitor.c b/src/libsystemd/sd-device/device-monitor.c index 049b3aa97f..0d2eea5f59 100644 --- a/src/libsystemd/sd-device/device-monitor.c +++ b/src/libsystemd/sd-device/device-monitor.c @@ -242,11 +242,15 @@ _public_ int sd_device_monitor_stop(sd_device_monitor *m) { static int device_monitor_event_handler(sd_event_source *s, int fd, uint32_t revents, void *userdata) { _cleanup_(sd_device_unrefp) sd_device *device = NULL; + _unused_ _cleanup_(log_context_freep) LogContext *c = NULL; sd_device_monitor *m = ASSERT_PTR(userdata); if (device_monitor_receive_device(m, &device) <= 0) return 0; + if (log_context_enabled()) + c = log_context_new_consume(device_make_log_fields(device)); + if (m->callback) return m->callback(m, device, m->userdata); diff --git a/src/libsystemd/sd-device/device-util.c b/src/libsystemd/sd-device/device-util.c index 56acec67f6..47c5d98896 100644 --- a/src/libsystemd/sd-device/device-util.c +++ b/src/libsystemd/sd-device/device-util.c @@ -5,6 +5,7 @@ #include "devnum-util.h" #include "fd-util.h" #include "string-util.h" +#include "strv.h" int devname_from_devnum(mode_t mode, dev_t devnum, char **ret) { _cleanup_(sd_device_unrefp) sd_device *dev = NULL; @@ -63,3 +64,78 @@ int device_open_from_devnum(mode_t mode, dev_t devnum, int flags, char **ret) { return TAKE_FD(fd); } + +static int add_string_field( + sd_device *device, + const char *field, + int (*func)(sd_device *dev, const char **s), + char ***strv) { + + const char *s; + int r; + + assert(device); + assert(field); + assert(func); + assert(strv); + + r = func(device, &s); + if (r < 0 && r != -ENOENT) + log_device_debug_errno(device, r, "Failed to get device \"%s\" property, ignoring: %m", field); + if (r >= 0) + (void) strv_extend_assignment(strv, field, s); + + return 0; +} + +char** device_make_log_fields(sd_device *device) { + _cleanup_strv_free_ char **strv = NULL; + dev_t devnum; + int ifindex; + sd_device_action_t action; + uint64_t seqnum, diskseq; + int r; + + assert(device); + + (void) add_string_field(device, "SYSPATH", sd_device_get_syspath, &strv); + (void) add_string_field(device, "SUBSYSTEM", sd_device_get_subsystem, &strv); + (void) add_string_field(device, "DEVTYPE", sd_device_get_devtype, &strv); + (void) add_string_field(device, "DRIVER", sd_device_get_driver, &strv); + (void) add_string_field(device, "DEVPATH", sd_device_get_devpath, &strv); + (void) add_string_field(device, "DEVNAME", sd_device_get_devname, &strv); + (void) add_string_field(device, "SYSNAME", sd_device_get_sysname, &strv); + (void) add_string_field(device, "SYSNUM", sd_device_get_sysnum, &strv); + + r = sd_device_get_devnum(device, &devnum); + if (r < 0 && r != -ENOENT) + log_device_debug_errno(device, r, "Failed to get device \"DEVNUM\" property, ignoring: %m"); + if (r >= 0) + (void) strv_extendf(&strv, "DEVNUM="DEVNUM_FORMAT_STR, DEVNUM_FORMAT_VAL(devnum)); + + r = sd_device_get_ifindex(device, &ifindex); + if (r < 0 && r != -ENOENT) + log_device_debug_errno(device, r, "Failed to get device \"IFINDEX\" property, ignoring: %m"); + if (r >= 0) + (void) strv_extendf(&strv, "IFINDEX=%i", ifindex); + + r = sd_device_get_action(device, &action); + if (r < 0 && r != -ENOENT) + log_device_debug_errno(device, r, "Failed to get device \"ACTION\" property, ignoring: %m"); + if (r >= 0) + (void) strv_extendf(&strv, "ACTION=%s", device_action_to_string(action)); + + r = sd_device_get_seqnum(device, &seqnum); + if (r < 0 && r != -ENOENT) + log_device_debug_errno(device, r, "Failed to get device \"SEQNUM\" property, ignoring: %m"); + if (r >= 0) + (void) strv_extendf(&strv, "SEQNUM=%"PRIu64, seqnum); + + r = sd_device_get_diskseq(device, &diskseq); + if (r < 0 && r != -ENOENT) + log_device_debug_errno(device, r, "Failed to get device \"DISKSEQ\" property, ignoring: %m"); + if (r >= 0) + (void) strv_extendf(&strv, "DISKSEQ=%"PRIu64, diskseq); + + return TAKE_PTR(strv); +} diff --git a/src/libsystemd/sd-device/device-util.h b/src/libsystemd/sd-device/device-util.h index f139e114a8..a1b5e91edf 100644 --- a/src/libsystemd/sd-device/device-util.h +++ b/src/libsystemd/sd-device/device-util.h @@ -99,3 +99,5 @@ static inline int devname_from_stat_rdev(const struct stat *st, char **ret) { return devname_from_devnum(st->st_mode, st->st_rdev, ret); } int device_open_from_devnum(mode_t mode, dev_t devnum, int flags, char **ret); + +char** device_make_log_fields(sd_device *device); diff --git a/src/resolve/resolved-dns-search-domain.c b/src/resolve/resolved-dns-search-domain.c index 647c0bd1f9..a11b21350a 100644 --- a/src/resolve/resolved-dns-search-domain.c +++ b/src/resolve/resolved-dns-search-domain.c @@ -123,13 +123,13 @@ void dns_search_domain_move_back_and_unmark(DnsSearchDomain *d) { case DNS_SEARCH_DOMAIN_LINK: assert(d->link); - LIST_FIND_TAIL(domains, d, tail); + tail = LIST_FIND_TAIL(domains, d); LIST_REMOVE(domains, d->link->search_domains, d); LIST_INSERT_AFTER(domains, d->link->search_domains, tail, d); break; case DNS_SEARCH_DOMAIN_SYSTEM: - LIST_FIND_TAIL(domains, d, tail); + tail = LIST_FIND_TAIL(domains, d); LIST_REMOVE(domains, d->manager->search_domains, d); LIST_INSERT_AFTER(domains, d->manager->search_domains, tail, d); break; diff --git a/src/resolve/resolved-dns-server.c b/src/resolve/resolved-dns-server.c index 8ff513fa33..342a90abcb 100644 --- a/src/resolve/resolved-dns-server.c +++ b/src/resolve/resolved-dns-server.c @@ -195,19 +195,19 @@ void dns_server_move_back_and_unmark(DnsServer *s) { case DNS_SERVER_LINK: assert(s->link); - LIST_FIND_TAIL(servers, s, tail); + tail = LIST_FIND_TAIL(servers, s); LIST_REMOVE(servers, s->link->dns_servers, s); LIST_INSERT_AFTER(servers, s->link->dns_servers, tail, s); break; case DNS_SERVER_SYSTEM: - LIST_FIND_TAIL(servers, s, tail); + tail = LIST_FIND_TAIL(servers, s); LIST_REMOVE(servers, s->manager->dns_servers, s); LIST_INSERT_AFTER(servers, s->manager->dns_servers, tail, s); break; case DNS_SERVER_FALLBACK: - LIST_FIND_TAIL(servers, s, tail); + tail = LIST_FIND_TAIL(servers, s); LIST_REMOVE(servers, s->manager->fallback_dns_servers, s); LIST_INSERT_AFTER(servers, s->manager->fallback_dns_servers, tail, s); break; diff --git a/src/systemctl/systemctl-show.c b/src/systemctl/systemctl-show.c index db489a671e..3f88d1a2cc 100644 --- a/src/systemctl/systemctl-show.c +++ b/src/systemctl/systemctl-show.c @@ -954,7 +954,7 @@ static int map_exec(sd_bus *bus, const char *member, sd_bus_message *m, sd_bus_e if (!info) return -ENOMEM; - LIST_FIND_TAIL(exec_status_info_list, i->exec_status_info_list, last); + last = LIST_FIND_TAIL(exec_status_info_list, i->exec_status_info_list); while ((r = exec_status_info_deserialize(m, info, is_ex_prop)) > 0) { diff --git a/src/test/test-list.c b/src/test/test-list.c index ea45f5b95c..307c1bf936 100644 --- a/src/test/test-list.c +++ b/src/test/test-list.c @@ -19,7 +19,7 @@ int main(int argc, const char *argv[]) { for (i = 0; i < ELEMENTSOF(items); i++) { LIST_INIT(item_list, &items[i]); assert_se(LIST_JUST_US(item_list, &items[i])); - LIST_PREPEND(item_list, head, &items[i]); + assert_se(LIST_PREPEND(item_list, head, &items[i]) == &items[i]); } i = 0; @@ -55,14 +55,13 @@ int main(int argc, const char *argv[]) { assert_se(items[2].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - list_item *cursor; - LIST_FIND_HEAD(item_list, &items[0], cursor); + list_item *cursor = LIST_FIND_HEAD(item_list, &items[0]); assert_se(cursor == &items[3]); - LIST_FIND_TAIL(item_list, &items[3], cursor); + cursor = LIST_FIND_TAIL(item_list, &items[3]); assert_se(cursor == &items[0]); - LIST_REMOVE(item_list, head, &items[1]); + assert_se(LIST_REMOVE(item_list, head, &items[1]) == &items[1]); assert_se(LIST_JUST_US(item_list, &items[1])); assert_se(items[0].item_list_next == NULL); @@ -73,7 +72,7 @@ int main(int argc, const char *argv[]) { assert_se(items[2].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_INSERT_AFTER(item_list, head, &items[3], &items[1]); + assert_se(LIST_INSERT_AFTER(item_list, head, &items[3], &items[1]) == &items[1]); assert_se(items[0].item_list_next == NULL); assert_se(items[2].item_list_next == &items[0]); assert_se(items[1].item_list_next == &items[2]); @@ -84,7 +83,7 @@ int main(int argc, const char *argv[]) { assert_se(items[1].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_REMOVE(item_list, head, &items[1]); + assert_se(LIST_REMOVE(item_list, head, &items[1]) == &items[1]); assert_se(LIST_JUST_US(item_list, &items[1])); assert_se(items[0].item_list_next == NULL); @@ -95,7 +94,7 @@ int main(int argc, const char *argv[]) { assert_se(items[2].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_INSERT_BEFORE(item_list, head, &items[2], &items[1]); + assert_se(LIST_INSERT_BEFORE(item_list, head, &items[2], &items[1]) == &items[1]); assert_se(items[0].item_list_next == NULL); assert_se(items[2].item_list_next == &items[0]); assert_se(items[1].item_list_next == &items[2]); @@ -106,7 +105,7 @@ int main(int argc, const char *argv[]) { assert_se(items[1].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_REMOVE(item_list, head, &items[0]); + assert_se(LIST_REMOVE(item_list, head, &items[0]) == &items[0]); assert_se(LIST_JUST_US(item_list, &items[0])); assert_se(items[2].item_list_next == NULL); @@ -117,7 +116,7 @@ int main(int argc, const char *argv[]) { assert_se(items[1].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_INSERT_BEFORE(item_list, head, &items[3], &items[0]); + assert_se(LIST_INSERT_BEFORE(item_list, head, &items[3], &items[0]) == &items[0]); assert_se(items[2].item_list_next == NULL); assert_se(items[1].item_list_next == &items[2]); assert_se(items[3].item_list_next == &items[1]); @@ -129,7 +128,7 @@ int main(int argc, const char *argv[]) { assert_se(items[0].item_list_prev == NULL); assert_se(head == &items[0]); - LIST_REMOVE(item_list, head, &items[0]); + assert_se(LIST_REMOVE(item_list, head, &items[0]) == &items[0]); assert_se(LIST_JUST_US(item_list, &items[0])); assert_se(items[2].item_list_next == NULL); @@ -140,7 +139,7 @@ int main(int argc, const char *argv[]) { assert_se(items[1].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_INSERT_BEFORE(item_list, head, NULL, &items[0]); + assert_se(LIST_INSERT_BEFORE(item_list, head, NULL, &items[0]) == &items[0]); assert_se(items[0].item_list_next == NULL); assert_se(items[2].item_list_next == &items[0]); assert_se(items[1].item_list_next == &items[2]); @@ -151,7 +150,7 @@ int main(int argc, const char *argv[]) { assert_se(items[1].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_REMOVE(item_list, head, &items[0]); + assert_se(LIST_REMOVE(item_list, head, &items[0]) == &items[0]); assert_se(LIST_JUST_US(item_list, &items[0])); assert_se(items[2].item_list_next == NULL); @@ -162,7 +161,7 @@ int main(int argc, const char *argv[]) { assert_se(items[1].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_REMOVE(item_list, head, &items[1]); + assert_se(LIST_REMOVE(item_list, head, &items[1]) == &items[1]); assert_se(LIST_JUST_US(item_list, &items[1])); assert_se(items[2].item_list_next == NULL); @@ -171,18 +170,18 @@ int main(int argc, const char *argv[]) { assert_se(items[2].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_REMOVE(item_list, head, &items[2]); + assert_se(LIST_REMOVE(item_list, head, &items[2]) == &items[2]); assert_se(LIST_JUST_US(item_list, &items[2])); assert_se(LIST_JUST_US(item_list, head)); - LIST_REMOVE(item_list, head, &items[3]); + assert_se(LIST_REMOVE(item_list, head, &items[3]) == &items[3]); assert_se(LIST_JUST_US(item_list, &items[3])); assert_se(head == NULL); for (i = 0; i < ELEMENTSOF(items); i++) { assert_se(LIST_JUST_US(item_list, &items[i])); - LIST_APPEND(item_list, head, &items[i]); + assert_se(LIST_APPEND(item_list, head, &items[i]) == &items[i]); } assert_se(!LIST_JUST_US(item_list, head)); @@ -198,20 +197,20 @@ int main(int argc, const char *argv[]) { assert_se(items[3].item_list_prev == &items[2]); for (i = 0; i < ELEMENTSOF(items); i++) - LIST_REMOVE(item_list, head, &items[i]); + assert_se(LIST_REMOVE(item_list, head, &items[i]) == &items[i]); assert_se(head == NULL); for (i = 0; i < ELEMENTSOF(items) / 2; i++) { LIST_INIT(item_list, &items[i]); assert_se(LIST_JUST_US(item_list, &items[i])); - LIST_PREPEND(item_list, head, &items[i]); + assert_se(LIST_PREPEND(item_list, head, &items[i]) == &items[i]); } for (i = ELEMENTSOF(items) / 2; i < ELEMENTSOF(items); i++) { LIST_INIT(item_list, &items[i]); assert_se(LIST_JUST_US(item_list, &items[i])); - LIST_PREPEND(item_list, head2, &items[i]); + assert_se(LIST_PREPEND(item_list, head2, &items[i]) == &items[i]); } assert_se(items[0].item_list_next == NULL); @@ -224,7 +223,7 @@ int main(int argc, const char *argv[]) { assert_se(items[2].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_JOIN(item_list, head2, head); + assert_se(LIST_JOIN(item_list, head2, head) == head2); assert_se(head == NULL); assert_se(items[0].item_list_next == NULL); @@ -237,18 +236,18 @@ int main(int argc, const char *argv[]) { assert_se(items[2].item_list_prev == &items[3]); assert_se(items[3].item_list_prev == NULL); - LIST_JOIN(item_list, head, head2); + assert_se(LIST_JOIN(item_list, head, head2) == head); assert_se(head2 == NULL); assert_se(head); for (i = 0; i < ELEMENTSOF(items); i++) - LIST_REMOVE(item_list, head, &items[i]); + assert_se(LIST_REMOVE(item_list, head, &items[i]) == &items[i]); assert_se(head == NULL); - LIST_PREPEND(item_list, head, items + 0); - LIST_PREPEND(item_list, head, items + 1); - LIST_PREPEND(item_list, head, items + 2); + assert_se(LIST_PREPEND(item_list, head, items + 0) == items + 0); + assert_se(LIST_PREPEND(item_list, head, items + 1) == items + 1); + assert_se(LIST_PREPEND(item_list, head, items + 2) == items + 2); assert_se(LIST_POP(item_list, head) == items + 2); assert_se(LIST_POP(item_list, head) == items + 1); 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; diff --git a/src/test/test-strv.c b/src/test/test-strv.c index 9208faafa4..5c03eaa960 100644 --- a/src/test/test-strv.c +++ b/src/test/test-strv.c @@ -942,4 +942,16 @@ TEST(strv_fnmatch) { assert_se(pos == 1); } +TEST(strv_extend_join) { + _cleanup_strv_free_ char **v = NULL; + + assert_se(strv_extend_assignment(&v, "MESSAGE", "ABC") >= 0); + assert_se(strv_extend_assignment(&v, "ABC", "QER") >= 0); + assert_se(strv_extend_assignment(&v, "MISSING", NULL) >= 0); + + assert_se(strv_length(v) == 2); + assert_se(streq(v[0], "MESSAGE=ABC")); + assert_se(streq(v[1], "ABC=QER")); +} + DEFINE_TEST_MAIN(LOG_INFO); diff --git a/src/timesync/timesyncd-server.c b/src/timesync/timesyncd-server.c index 3b7d79323f..7aa1551baf 100644 --- a/src/timesync/timesyncd-server.c +++ b/src/timesync/timesyncd-server.c @@ -37,7 +37,7 @@ int server_address_new( memcpy(&a->sockaddr, sockaddr, socklen); - LIST_FIND_TAIL(addresses, n->addresses, tail); + tail = LIST_FIND_TAIL(addresses, n->addresses); LIST_INSERT_AFTER(addresses, n->addresses, tail, a); if (ret) |