]> git.ipfire.org Git - thirdparty/systemd.git/blobdiff - src/basic/log.c
Merge pull request #31524 from poettering/secure-getenv-naming-fix
[thirdparty/systemd.git] / src / basic / log.c
index 8b973f9e0a905502529aa63c01c7f249f1f89196..172a2c8ada086cbf4d3ea98c671c5b92ee4e5556 100644 (file)
@@ -21,7 +21,7 @@
 #include "errno-util.h"
 #include "fd-util.h"
 #include "format-util.h"
-#include "io-util.h"
+#include "iovec-util.h"
 #include "log.h"
 #include "macro.h"
 #include "missing_syscall.h"
@@ -42,7 +42,7 @@
 #include "utf8.h"
 
 #define SNDBUF_SIZE (8*1024*1024)
-#define IOVEC_MAX 128U
+#define IOVEC_MAX 256U
 
 static log_syntax_callback_t log_syntax_callback = NULL;
 static void *log_syntax_callback_userdata = NULL;
@@ -50,8 +50,10 @@ static void *log_syntax_callback_userdata = NULL;
 static LogTarget log_target = LOG_TARGET_CONSOLE;
 static int log_max_level = LOG_INFO;
 static int log_facility = LOG_DAEMON;
+static bool ratelimit_kmsg = true;
 
 static int console_fd = STDERR_FILENO;
+static int console_fd_is_tty = -1; /* tri-state: -1 means don't know */
 static int syslog_fd = -EBADF;
 static int kmsg_fd = -EBADF;
 static int journal_fd = -EBADF;
@@ -67,17 +69,21 @@ static bool upgrade_syslog_to_journal = false;
 static bool always_reopen_console = false;
 static bool open_when_needed = false;
 static bool prohibit_ipc = false;
+static bool assert_return_is_critical = BUILD_MODE_DEVELOPER;
 
 /* Akin to glibc's __abort_msg; which is private and we hence cannot
  * use here. */
 static char *log_abort_msg = NULL;
 
 typedef struct LogContext {
+        unsigned n_ref;
         /* Depending on which destructor is used (log_context_free() or log_context_detach()) the memory
          * referenced by this is freed or not */
         char **fields;
         struct iovec *input_iovec;
         size_t n_input_iovec;
+        char *key;
+        char *value;
         bool owned;
         LIST_FIELDS(struct LogContext, ll);
 } LogContext;
@@ -85,6 +91,8 @@ typedef struct LogContext {
 static thread_local LIST_HEAD(LogContext, _log_context) = NULL;
 static thread_local size_t _log_context_num_fields = 0;
 
+static thread_local const char *log_prefix = NULL;
+
 #if LOG_MESSAGE_VERIFICATION || defined(__COVERITY__)
 bool _log_message_dummy = false; /* Always false */
 #endif
@@ -100,13 +108,16 @@ bool _log_message_dummy = false; /* Always false */
         } while (false)
 
 static void log_close_console(void) {
-        console_fd = safe_close_above_stdio(console_fd);
+        /* See comment in log_close_journal() */
+        (void) safe_close_above_stdio(TAKE_FD(console_fd));
+        console_fd_is_tty = -1;
 }
 
 static int log_open_console(void) {
 
         if (!always_reopen_console) {
                 console_fd = STDERR_FILENO;
+                console_fd_is_tty = -1;
                 return 0;
         }
 
@@ -118,13 +129,15 @@ static int log_open_console(void) {
                         return fd;
 
                 console_fd = fd_move_above_stdio(fd);
+                console_fd_is_tty = true;
         }
 
         return 0;
 }
 
 static void log_close_kmsg(void) {
-        kmsg_fd = safe_close(kmsg_fd);
+        /* See comment in log_close_journal() */
+        (void) safe_close(TAKE_FD(kmsg_fd));
 }
 
 static int log_open_kmsg(void) {
@@ -141,7 +154,8 @@ static int log_open_kmsg(void) {
 }
 
 static void log_close_syslog(void) {
-        syslog_fd = safe_close(syslog_fd);
+        /* See comment in log_close_journal() */
+        (void) safe_close(TAKE_FD(syslog_fd));
 }
 
 static int create_log_socket(int type) {
@@ -206,7 +220,11 @@ fail:
 }
 
 static void log_close_journal(void) {
-        journal_fd = safe_close(journal_fd);
+        /* If the journal FD is bad, safe_close will fail, and will try to log, which will fail, so we'll
+         * try to close the journal FD, which is bad, so safe_close will fail... Whether we can close it
+         * or not, invalidate it immediately so that we don't get in a recursive loop until we run out of
+         * stack. */
+        (void) safe_close(TAKE_FD(journal_fd));
 }
 
 static int log_open_journal(void) {
@@ -368,18 +386,40 @@ void log_forget_fds(void) {
         /* Do not call from library code. */
 
         console_fd = kmsg_fd = syslog_fd = journal_fd = -EBADF;
+        console_fd_is_tty = -1;
 }
 
 void log_set_max_level(int level) {
         assert(level == LOG_NULL || (level & LOG_PRIMASK) == level);
 
         log_max_level = level;
+
+        /* Also propagate max log level to libc's syslog(), just in case some other component loaded into our
+         * process logs directly via syslog(). You might wonder why we maintain our own log level variable if
+         * libc has the same functionality. This has multiple reasons, first and foremost that we want to
+         * apply this to all our log targets, not just syslog and console. Moreover, we cannot query the
+         * current log mask from glibc without changing it, but that's useful for testing the current log
+         * level before even entering the log functions like we do in our macros. */
+        setlogmask(LOG_UPTO(level));
+
+        /* Ensure that our own LOG_NULL define maps sanely to the log mask */
+        assert_cc(LOG_UPTO(LOG_NULL) == 0);
 }
 
 void log_set_facility(int facility) {
         log_facility = facility;
 }
 
+static bool check_console_fd_is_tty(void) {
+        if (console_fd < 0)
+                return false;
+
+        if (console_fd_is_tty < 0)
+                console_fd_is_tty = isatty_safe(console_fd);
+
+        return console_fd_is_tty;
+}
+
 static int write_to_console(
                 int level,
                 int error,
@@ -392,7 +432,7 @@ static int write_to_console(
              header_time[FORMAT_TIMESTAMP_MAX],
              prefix[1 + DECIMAL_STR_MAX(int) + 2],
              tid_string[3 + DECIMAL_STR_MAX(pid_t) + 1];
-        struct iovec iovec[9];
+        struct iovec iovec[11];
         const char *on = NULL, *off = NULL;
         size_t n = 0;
 
@@ -431,10 +471,19 @@ static int write_to_console(
 
         if (on)
                 iovec[n++] = IOVEC_MAKE_STRING(on);
+        if (log_prefix) {
+                iovec[n++] = IOVEC_MAKE_STRING(log_prefix);
+                iovec[n++] = IOVEC_MAKE_STRING(": ");
+        }
         iovec[n++] = IOVEC_MAKE_STRING(buffer);
         if (off)
                 iovec[n++] = IOVEC_MAKE_STRING(off);
-        iovec[n++] = IOVEC_MAKE_STRING("\n");
+
+        /* When writing to a TTY we output an extra '\r' (i.e. CR) first, to generate CRNL rather than just
+         * NL. This is a robustness thing in case the TTY is currently in raw mode (specifically: has the
+         * ONLCR flag off). We want that subsequent output definitely starts at the beginning of the line
+         * again, after all. If the TTY is not in raw mode the extra CR should not hurt. */
+        iovec[n++] = IOVEC_MAKE_STRING(check_console_fd_is_tty() ? "\r\n" : "\n");
 
         if (writev(console_fd, iovec, n) < 0) {
 
@@ -490,6 +539,8 @@ static int write_to_syslog(
                 IOVEC_MAKE_STRING(header_time),
                 IOVEC_MAKE_STRING(program_invocation_short_name),
                 IOVEC_MAKE_STRING(header_pid),
+                IOVEC_MAKE_STRING(strempty(log_prefix)),
+                IOVEC_MAKE_STRING(log_prefix ? ": " : ""),
                 IOVEC_MAKE_STRING(buffer),
         };
         const struct msghdr msghdr = {
@@ -511,7 +562,7 @@ static int write_to_syslog(
                 if (!syslog_is_stream)
                         break;
 
-                if (IOVEC_INCREMENT(iovec, ELEMENTSOF(iovec), n))
+                if (iovec_increment(iovec, ELEMENTSOF(iovec), n))
                         break;
         }
 
@@ -541,8 +592,12 @@ static int write_to_kmsg(
         if (kmsg_fd < 0)
                 return 0;
 
-        if (!ratelimit_below(&ratelimit))
-                return 0;
+        if (ratelimit_kmsg && !ratelimit_below(&ratelimit)) {
+                if (ratelimit_num_dropped(&ratelimit) > 1)
+                        return 0;
+
+                buffer = "Too many messages being logged to kmsg, ignoring";
+        }
 
         xsprintf(header_priority, "<%i>", level);
         xsprintf(header_pid, "["PID_FMT"]: ", getpid_cached());
@@ -551,6 +606,8 @@ static int write_to_kmsg(
                 IOVEC_MAKE_STRING(header_priority),
                 IOVEC_MAKE_STRING(program_invocation_short_name),
                 IOVEC_MAKE_STRING(header_pid),
+                IOVEC_MAKE_STRING(strempty(log_prefix)),
+                IOVEC_MAKE_STRING(log_prefix ? ": " : ""),
                 IOVEC_MAKE_STRING(buffer),
                 IOVEC_MAKE_STRING("\n"),
         };
@@ -631,6 +688,15 @@ static void log_do_context(struct iovec *iovec, size_t iovec_len, size_t *n) {
                         iovec[(*n)++] = c->input_iovec[i];
                         iovec[(*n)++] = IOVEC_MAKE_STRING("\n");
                 }
+
+                if (c->key && c->value) {
+                        if (*n + 3 >= iovec_len)
+                                return;
+
+                        iovec[(*n)++] = IOVEC_MAKE_STRING(c->key);
+                        iovec[(*n)++] = IOVEC_MAKE_STRING(c->value);
+                        iovec[(*n)++] = IOVEC_MAKE_STRING("\n");
+                }
         }
 }
 
@@ -653,13 +719,17 @@ static int write_to_journal(
         if (journal_fd < 0)
                 return 0;
 
-        iovec_len = MIN(4 + _log_context_num_fields * 2, IOVEC_MAX);
+        iovec_len = MIN(6 + _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);
 
         iovec[n++] = IOVEC_MAKE_STRING(header);
         iovec[n++] = IOVEC_MAKE_STRING("MESSAGE=");
+        if (log_prefix) {
+                iovec[n++] = IOVEC_MAKE_STRING(log_prefix);
+                iovec[n++] = IOVEC_MAKE_STRING(": ");
+        }
         iovec[n++] = IOVEC_MAKE_STRING(buffer);
         iovec[n++] = IOVEC_MAKE_STRING("\n");
 
@@ -835,16 +905,9 @@ int log_object_internalv(
         /* Make sure that %m maps to the specified error (or "Success"). */
         LOCAL_ERRNO(ERRNO_VALUE(error));
 
-        /* Prepend the object name before the message */
-        if (object) {
-                size_t n;
-
-                n = strlen(object);
-                buffer = newa(char, n + 2 + LINE_MAX);
-                b = stpcpy(stpcpy(buffer, object), ": ");
-        } else
-                b = buffer = newa(char, LINE_MAX);
+        LOG_SET_PREFIX(object);
 
+        b = buffer = newa(char, LINE_MAX);
         (void) vsnprintf(b, LINE_MAX, format, ap);
 
         return log_dispatch_internal(level, error, file, line, func,
@@ -919,6 +982,10 @@ void log_assert_failed_return(
                 const char *file,
                 int line,
                 const char *func) {
+
+        if (assert_return_is_critical)
+                log_assert_failed(text, file, line, func);
+
         PROTECT_ERRNO;
         log_assert(LOG_DEBUG, text, file, line, func,
                    "Assertion '%s' failed at %s:%u, function %s(). Ignoring.");
@@ -1149,16 +1216,35 @@ int log_set_target_from_string(const char *e) {
 }
 
 int log_set_max_level_from_string(const char *e) {
-        int t;
+        int r;
 
-        t = log_level_from_string(e);
-        if (t < 0)
-                return t;
+        r = log_level_from_string(e);
+        if (r < 0)
+                return r;
 
-        log_set_max_level(t);
+        log_set_max_level(r);
         return 0;
 }
 
+static int log_set_ratelimit_kmsg_from_string(const char *e) {
+        int r;
+
+        r = parse_boolean(e);
+        if (r < 0)
+                return r;
+
+        ratelimit_kmsg = r;
+        return 0;
+}
+
+void log_set_assert_return_is_critical(bool b) {
+        assert_return_is_critical = b;
+}
+
+bool log_get_assert_return_is_critical(void) {
+        return assert_return_is_critical;
+}
+
 static int parse_proc_cmdline_item(const char *key, const char *value, void *data) {
 
         /*
@@ -1209,6 +1295,10 @@ static int parse_proc_cmdline_item(const char *key, const char *value, void *dat
                 if (log_show_time_from_string(value ?: "1") < 0)
                         log_warning("Failed to parse log time setting '%s'. Ignoring.", value);
 
+        } else if (proc_cmdline_key_streq(key, "systemd.log_ratelimit_kmsg")) {
+
+                if (log_set_ratelimit_kmsg_from_string(value ?: "1") < 0)
+                        log_warning("Failed to parse log ratelimit kmsg boolean '%s'. Ignoring.", value);
         }
 
         return 0;
@@ -1219,7 +1309,7 @@ static bool should_parse_proc_cmdline(void) {
         if (getpid_cached() == 1)
                 return true;
 
-        /* Otherwise, parse the commandline if invoked directly by systemd. */
+        /* Otherwise, parse the command line if invoked directly by systemd. */
         return invoked_by_systemd();
 }
 
@@ -1249,6 +1339,10 @@ void log_parse_environment_variables(void) {
         e = getenv("SYSTEMD_LOG_TID");
         if (e && log_show_tid_from_string(e) < 0)
                 log_warning("Failed to parse log tid '%s'. Ignoring.", e);
+
+        e = getenv("SYSTEMD_LOG_RATELIMIT_KMSG");
+        if (e && log_set_ratelimit_kmsg_from_string(e) < 0)
+                log_warning("Failed to parse log ratelimit kmsg boolean '%s'. Ignoring.", e);
 }
 
 void log_parse_environment(void) {
@@ -1264,6 +1358,24 @@ LogTarget log_get_target(void) {
         return log_target;
 }
 
+void log_settle_target(void) {
+
+        /* If we're using LOG_TARGET_AUTO and opening the log again on every single log call, we'll check if
+         * stderr is attached to the journal every single log call. However, if we then close all file
+         * descriptors later, that will stop working because stderr will be closed as well. To avoid that
+         * problem, this function is used to permanently change the log target depending on whether stderr is
+         * connected to the journal or not. */
+
+        LogTarget t = log_get_target();
+
+        if (t != LOG_TARGET_AUTO)
+                return;
+
+        t = getpid_cached() == 1 || stderr_is_journal() ? (prohibit_ipc ? LOG_TARGET_KMSG : LOG_TARGET_JOURNAL_OR_KMSG)
+                                                        : LOG_TARGET_CONSOLE;
+        log_set_target(t);
+}
+
 int log_get_max_level(void) {
         return log_max_level;
 }
@@ -1301,46 +1413,46 @@ bool log_get_show_tid(void) {
 }
 
 int log_show_color_from_string(const char *e) {
-        int t;
+        int r;
 
-        t = parse_boolean(e);
-        if (t < 0)
-                return t;
+        r = parse_boolean(e);
+        if (r < 0)
+                return r;
 
-        log_show_color(t);
+        log_show_color(r);
         return 0;
 }
 
 int log_show_location_from_string(const char *e) {
-        int t;
+        int r;
 
-        t = parse_boolean(e);
-        if (t < 0)
-                return t;
+        r = parse_boolean(e);
+        if (r < 0)
+                return r;
 
-        log_show_location(t);
+        log_show_location(r);
         return 0;
 }
 
 int log_show_time_from_string(const char *e) {
-        int t;
+        int r;
 
-        t = parse_boolean(e);
-        if (t < 0)
-                return t;
+        r = parse_boolean(e);
+        if (r < 0)
+                return r;
 
-        log_show_time(t);
+        log_show_time(r);
         return 0;
 }
 
 int log_show_tid_from_string(const char *e) {
-        int t;
+        int r;
 
-        t = parse_boolean(e);
-        if (t < 0)
-                return t;
+        r = parse_boolean(e);
+        if (r < 0)
+                return r;
 
-        log_show_tid(t);
+        log_show_tid(r);
         return 0;
 }
 
@@ -1372,7 +1484,7 @@ void log_received_signal(int level, const struct signalfd_siginfo *si) {
         if (pid_is_valid(si->ssi_pid)) {
                 _cleanup_free_ char *p = NULL;
 
-                (void) get_process_comm(si->ssi_pid, &p);
+                (void) pid_get_comm(si->ssi_pid, &p);
 
                 log_full(level,
                          "Received SIG%s from PID %"PRIu32" (%s).",
@@ -1542,6 +1654,15 @@ void log_setup(void) {
                 log_show_color(true);
 }
 
+const char *_log_set_prefix(const char *prefix, bool force) {
+        const char *old = log_prefix;
+
+        if (prefix || force)
+                log_prefix = prefix;
+
+        return old;
+}
+
 static int saved_log_context_enabled = -1;
 
 bool log_context_enabled(void) {
@@ -1553,7 +1674,7 @@ bool log_context_enabled(void) {
         if (saved_log_context_enabled >= 0)
                 return saved_log_context_enabled;
 
-        r = getenv_bool_secure("SYSTEMD_ENABLE_LOG_CONTEXT");
+        r = secure_getenv_bool("SYSTEMD_ENABLE_LOG_CONTEXT");
         if (r < 0 && r != -ENXIO)
                 log_debug_errno(r, "Failed to parse $SYSTEMD_ENABLE_LOG_CONTEXT, ignoring: %m");
 
@@ -1562,33 +1683,67 @@ bool log_context_enabled(void) {
         return saved_log_context_enabled;
 }
 
-LogContext* log_context_attach(LogContext *c) {
+static LogContext* log_context_attach(LogContext *c) {
         assert(c);
 
         _log_context_num_fields += strv_length(c->fields);
         _log_context_num_fields += c->n_input_iovec;
+        _log_context_num_fields += !!c->key;
 
         return LIST_PREPEND(ll, _log_context, c);
 }
 
-LogContext* log_context_detach(LogContext *c) {
+static LogContext* log_context_detach(LogContext *c) {
         if (!c)
                 return NULL;
 
-        assert(_log_context_num_fields >= strv_length(c->fields) + c->n_input_iovec);
+        assert(_log_context_num_fields >= strv_length(c->fields) + c->n_input_iovec +!!c->key);
         _log_context_num_fields -= strv_length(c->fields);
         _log_context_num_fields -= c->n_input_iovec;
+        _log_context_num_fields -= !!c->key;
 
         LIST_REMOVE(ll, _log_context, c);
         return NULL;
 }
 
-LogContext* log_context_new(char **fields, bool owned) {
+LogContext* log_context_new(const char *key, const char *value) {
+        assert(key);
+        assert(endswith(key, "="));
+        assert(value);
+
+        LIST_FOREACH(ll, i, _log_context)
+                if (i->key == key && i->value == value)
+                        return log_context_ref(i);
+
+        LogContext *c = new(LogContext, 1);
+        if (!c)
+                return NULL;
+
+        *c = (LogContext) {
+                .n_ref = 1,
+                .key = (char *) key,
+                .value = (char *) value,
+        };
+
+        return log_context_attach(c);
+}
+
+LogContext* log_context_new_strv(char **fields, bool owned) {
+        if (!fields)
+                return NULL;
+
+        LIST_FOREACH(ll, i, _log_context)
+                if (i->fields == fields) {
+                        assert(!owned);
+                        return log_context_ref(i);
+                }
+
         LogContext *c = new(LogContext, 1);
         if (!c)
                 return NULL;
 
         *c = (LogContext) {
+                .n_ref = 1,
                 .fields = fields,
                 .owned = owned,
         };
@@ -1596,15 +1751,22 @@ LogContext* log_context_new(char **fields, bool owned) {
         return log_context_attach(c);
 }
 
-LogContext* log_context_newv(struct iovec *input_iovec, size_t n_input_iovec, bool owned) {
+LogContext* log_context_new_iov(struct iovec *input_iovec, size_t n_input_iovec, bool owned) {
         if (!input_iovec || n_input_iovec == 0)
-                return NULL; /* Nothing to do */
+                return NULL;
+
+        LIST_FOREACH(ll, i, _log_context)
+                if (i->input_iovec == input_iovec && i->n_input_iovec == n_input_iovec) {
+                        assert(!owned);
+                        return log_context_ref(i);
+                }
 
         LogContext *c = new(LogContext, 1);
         if (!c)
                 return NULL;
 
         *c = (LogContext) {
+                .n_ref = 1,
                 .input_iovec = input_iovec,
                 .n_input_iovec = n_input_iovec,
                 .owned = owned,
@@ -1613,7 +1775,7 @@ LogContext* log_context_newv(struct iovec *input_iovec, size_t n_input_iovec, bo
         return log_context_attach(c);
 }
 
-LogContext* log_context_free(LogContext *c) {
+static LogContext* log_context_free(LogContext *c) {
         if (!c)
                 return NULL;
 
@@ -1622,21 +1784,25 @@ LogContext* log_context_free(LogContext *c) {
         if (c->owned) {
                 strv_free(c->fields);
                 iovec_array_free(c->input_iovec, c->n_input_iovec);
+                free(c->key);
+                free(c->value);
         }
 
         return mfree(c);
 }
 
-LogContext* log_context_new_consume(char **fields) {
-        LogContext *c = log_context_new(fields, /*owned=*/ true);
+DEFINE_TRIVIAL_REF_UNREF_FUNC(LogContext, log_context, log_context_free);
+
+LogContext* log_context_new_strv_consume(char **fields) {
+        LogContext *c = log_context_new_strv(fields, /*owned=*/ true);
         if (!c)
                 strv_free(fields);
 
         return c;
 }
 
-LogContext* log_context_new_consumev(struct iovec *input_iovec, size_t n_input_iovec) {
-        LogContext *c = log_context_newv(input_iovec, n_input_iovec, /*owned=*/ true);
+LogContext* log_context_new_iov_consume(struct iovec *input_iovec, size_t n_input_iovec) {
+        LogContext *c = log_context_new_iov(input_iovec, n_input_iovec, /*owned=*/ true);
         if (!c)
                 iovec_array_free(input_iovec, n_input_iovec);