]> git.ipfire.org Git - thirdparty/systemd.git/blobdiff - src/basic/log.c
Merge pull request #31899 from yuwata/sd-journal-add-match
[thirdparty/systemd.git] / src / basic / log.c
index 7caa587ebf075331e0c2afe772d41835c2732d3b..6faa6ad4fcef8de0e3f28211a388ded74f594d46 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"
@@ -49,9 +49,17 @@ static void *log_syntax_callback_userdata = NULL;
 
 static LogTarget log_target = LOG_TARGET_CONSOLE;
 static int log_max_level = LOG_INFO;
+static int log_target_max_level[] = {
+        [LOG_TARGET_CONSOLE] = INT_MAX,
+        [LOG_TARGET_KMSG]    = INT_MAX,
+        [LOG_TARGET_SYSLOG]  = INT_MAX,
+        [LOG_TARGET_JOURNAL] = INT_MAX,
+};
 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,6 +75,7 @@ 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. */
@@ -88,6 +97,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
@@ -103,13 +114,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;
         }
 
@@ -121,13 +135,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) {
@@ -144,7 +160,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) {
@@ -209,7 +226,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) {
@@ -371,18 +392,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,
@@ -395,13 +438,16 @@ 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;
 
         if (console_fd < 0)
                 return 0;
 
+        if (LOG_PRI(level) > log_target_max_level[LOG_TARGET_CONSOLE])
+                return 0;
+
         if (log_target == LOG_TARGET_CONSOLE_PREFIXED) {
                 xsprintf(prefix, "<%i>", level);
                 iovec[n++] = IOVEC_MAKE_STRING(prefix);
@@ -434,10 +480,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) {
 
@@ -477,6 +532,9 @@ static int write_to_syslog(
         if (syslog_fd < 0)
                 return 0;
 
+        if (LOG_PRI(level) > log_target_max_level[LOG_TARGET_SYSLOG])
+                return 0;
+
         xsprintf(header_priority, "<%i>", level);
 
         t = (time_t) (now(CLOCK_REALTIME) / USEC_PER_SEC);
@@ -493,6 +551,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 = {
@@ -514,7 +574,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;
         }
 
@@ -544,9 +604,16 @@ static int write_to_kmsg(
         if (kmsg_fd < 0)
                 return 0;
 
-        if (!ratelimit_below(&ratelimit))
+        if (LOG_PRI(level) > log_target_max_level[LOG_TARGET_KMSG])
                 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());
 
@@ -554,6 +621,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"),
         };
@@ -665,13 +734,20 @@ static int write_to_journal(
         if (journal_fd < 0)
                 return 0;
 
-        iovec_len = MIN(4 + _log_context_num_fields * 2, IOVEC_MAX);
+        if (LOG_PRI(level) > log_target_max_level[LOG_TARGET_JOURNAL])
+                return 0;
+
+        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");
 
@@ -847,16 +923,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,
@@ -931,9 +1000,13 @@ 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.");
+                   "Assertion '%s' failed at %s:%u, function %s(), ignoring.");
 }
 
 int log_oom_internal(int level, const char *file, int line, const char *func) {
@@ -1161,16 +1234,98 @@ 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;
+        for (;;) {
+                _cleanup_free_ char *word = NULL, *prefix = NULL;
+                LogTarget target;
+                const char *colon;
+
+                r = extract_first_word(&e, &word, ",", 0);
+                if (r < 0)
+                        return r;
+                if (r == 0)
+                        break;
+
+                colon = strchr(word, ':');
+                if (!colon) {
+                        r = log_level_from_string(word);
+                        if (r < 0)
+                                return r;
+
+                        log_set_max_level(r);
+                        continue;
+                }
+
+                prefix = strndup(word, colon - word);
+                if (!prefix)
+                        return -ENOMEM;
+
+                target = log_target_from_string(prefix);
+                if (target < 0)
+                        return target;
+
+                if (target >= _LOG_TARGET_SINGLE_MAX)
+                        return -EINVAL;
+
+                r = log_level_from_string(colon + 1);
+                if (r < 0)
+                        return r;
+
+                log_target_max_level[target] = r;
+        }
 
-        log_set_max_level(t);
         return 0;
 }
 
+int log_max_levels_to_string(int level, char **ret) {
+        _cleanup_free_ char *s = NULL;
+        int r;
+
+        assert(ret);
+
+        r = log_level_to_string_alloc(level, &s);
+        if (r < 0)
+                return r;
+
+        for (LogTarget target = 0; target < _LOG_TARGET_SINGLE_MAX; target++) {
+                _cleanup_free_ char *l = NULL;
+
+                if (log_target_max_level[target] == INT_MAX)
+                        continue;
+
+                r = log_level_to_string_alloc(log_target_max_level[target], &l);
+                if (r < 0)
+                        return r;
+
+                r = strextendf_with_separator(&s, ",", "%s:%s", log_target_to_string(target), l);
+                if (r < 0)
+                        return r;
+        }
+
+        *ret = TAKE_PTR(s);
+        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) {
 
         /*
@@ -1191,7 +1346,7 @@ static int parse_proc_cmdline_item(const char *key, const char *value, void *dat
                         return 0;
 
                 if (log_set_target_from_string(value) < 0)
-                        log_warning("Failed to parse log target '%s'. Ignoring.", value);
+                        log_warning("Failed to parse log target '%s', ignoring.", value);
 
         } else if (proc_cmdline_key_streq(key, "systemd.log_level")) {
 
@@ -1199,28 +1354,32 @@ static int parse_proc_cmdline_item(const char *key, const char *value, void *dat
                         return 0;
 
                 if (log_set_max_level_from_string(value) < 0)
-                        log_warning("Failed to parse log level '%s'. Ignoring.", value);
+                        log_warning("Failed to parse log level setting '%s', ignoring.", value);
 
         } else if (proc_cmdline_key_streq(key, "systemd.log_color")) {
 
                 if (log_show_color_from_string(value ?: "1") < 0)
-                        log_warning("Failed to parse log color setting '%s'. Ignoring.", value);
+                        log_warning("Failed to parse log color setting '%s', ignoring.", value);
 
         } else if (proc_cmdline_key_streq(key, "systemd.log_location")) {
 
                 if (log_show_location_from_string(value ?: "1") < 0)
-                        log_warning("Failed to parse log location setting '%s'. Ignoring.", value);
+                        log_warning("Failed to parse log location setting '%s', ignoring.", value);
 
         } else if (proc_cmdline_key_streq(key, "systemd.log_tid")) {
 
                 if (log_show_tid_from_string(value ?: "1") < 0)
-                        log_warning("Failed to parse log tid setting '%s'. Ignoring.", value);
+                        log_warning("Failed to parse log tid setting '%s', ignoring.", value);
 
         } else if (proc_cmdline_key_streq(key, "systemd.log_time")) {
 
                 if (log_show_time_from_string(value ?: "1") < 0)
-                        log_warning("Failed to parse log time setting '%s'. Ignoring.", value);
+                        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;
@@ -1231,7 +1390,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();
 }
 
@@ -1240,27 +1399,31 @@ void log_parse_environment_variables(void) {
 
         e = getenv("SYSTEMD_LOG_TARGET");
         if (e && log_set_target_from_string(e) < 0)
-                log_warning("Failed to parse log target '%s'. Ignoring.", e);
+                log_warning("Failed to parse log target '%s', ignoring.", e);
 
         e = getenv("SYSTEMD_LOG_LEVEL");
         if (e && log_set_max_level_from_string(e) < 0)
-                log_warning("Failed to parse log level '%s'. Ignoring.", e);
+                log_warning("Failed to parse log level '%s', ignoring.", e);
 
         e = getenv("SYSTEMD_LOG_COLOR");
         if (e && log_show_color_from_string(e) < 0)
-                log_warning("Failed to parse log color '%s'. Ignoring.", e);
+                log_warning("Failed to parse log color '%s', ignoring.", e);
 
         e = getenv("SYSTEMD_LOG_LOCATION");
         if (e && log_show_location_from_string(e) < 0)
-                log_warning("Failed to parse log location '%s'. Ignoring.", e);
+                log_warning("Failed to parse log location '%s', ignoring.", e);
 
         e = getenv("SYSTEMD_LOG_TIME");
         if (e && log_show_time_from_string(e) < 0)
-                log_warning("Failed to parse log time '%s'. Ignoring.", e);
+                log_warning("Failed to parse log time '%s', ignoring.", e);
 
         e = getenv("SYSTEMD_LOG_TID");
         if (e && log_show_tid_from_string(e) < 0)
-                log_warning("Failed to parse log tid '%s'. Ignoring.", e);
+                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) {
@@ -1331,46 +1494,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;
 }
 
@@ -1402,7 +1565,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).",
@@ -1572,6 +1735,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) {
@@ -1583,7 +1755,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");