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

@@ -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

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"

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;
+}

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))

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;