/* SPDX-License-Identifier: LGPL-2.1-or-later */ #include #include #include #include #include #include #include #include #include #include #include #include #include "sd-messages.h" #include "alloc-util.h" #include "ansi-color.h" #include "argv-util.h" #include "env-util.h" #include "errno-util.h" #include "fd-util.h" #include "format-util.h" #include "iovec-util.h" #include "log.h" #include "macro.h" #include "missing_syscall.h" #include "missing_threads.h" #include "parse-util.h" #include "proc-cmdline.h" #include "process-util.h" #include "ratelimit.h" #include "signal-util.h" #include "socket-util.h" #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 256U static log_syntax_callback_t log_syntax_callback = NULL; 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; static bool syslog_is_stream = false; static int show_color = -1; /* tristate */ static bool show_location = false; static bool show_time = false; static bool show_tid = false; 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; 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 /* An assert to use in logging functions that does not call recursively * into our logging functions (since that might lead to a loop). */ #define assert_raw(expr) \ do { \ if (_unlikely_(!(expr))) { \ fputs(#expr "\n", stderr); \ abort(); \ } \ } while (false) static void log_close_console(void) { /* 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; } if (console_fd < 3) { int fd; fd = open_terminal("/dev/console", O_WRONLY|O_NOCTTY|O_CLOEXEC); if (fd < 0) return fd; console_fd = fd_move_above_stdio(fd); console_fd_is_tty = true; } return 0; } static void log_close_kmsg(void) { /* See comment in log_close_journal() */ (void) safe_close(TAKE_FD(kmsg_fd)); } static int log_open_kmsg(void) { if (kmsg_fd >= 0) return 0; kmsg_fd = open("/dev/kmsg", O_WRONLY|O_NOCTTY|O_CLOEXEC); if (kmsg_fd < 0) return -errno; kmsg_fd = fd_move_above_stdio(kmsg_fd); return 0; } static void log_close_syslog(void) { /* See comment in log_close_journal() */ (void) safe_close(TAKE_FD(syslog_fd)); } static int create_log_socket(int type) { struct timeval tv; int fd; fd = socket(AF_UNIX, type|SOCK_CLOEXEC, 0); if (fd < 0) return -errno; fd = fd_move_above_stdio(fd); (void) fd_inc_sndbuf(fd, SNDBUF_SIZE); /* We need a blocking fd here since we'd otherwise lose messages way too early. However, let's not hang forever * in the unlikely case of a deadlock. */ if (getpid_cached() == 1) timeval_store(&tv, 10 * USEC_PER_MSEC); else timeval_store(&tv, 10 * USEC_PER_SEC); (void) setsockopt(fd, SOL_SOCKET, SO_SNDTIMEO, &tv, sizeof(tv)); return fd; } static int log_open_syslog(void) { int r; if (syslog_fd >= 0) return 0; syslog_fd = create_log_socket(SOCK_DGRAM); if (syslog_fd < 0) { r = syslog_fd; goto fail; } r = connect_unix_path(syslog_fd, AT_FDCWD, "/dev/log"); if (r < 0) { safe_close(syslog_fd); /* Some legacy syslog systems still use stream sockets. They really shouldn't. But what can * we do... */ syslog_fd = create_log_socket(SOCK_STREAM); if (syslog_fd < 0) { r = syslog_fd; goto fail; } r = connect_unix_path(syslog_fd, AT_FDCWD, "/dev/log"); if (r < 0) goto fail; syslog_is_stream = true; } else syslog_is_stream = false; return 0; fail: log_close_syslog(); return r; } static void log_close_journal(void) { /* 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) { int r; if (journal_fd >= 0) return 0; journal_fd = create_log_socket(SOCK_DGRAM); if (journal_fd < 0) { r = journal_fd; goto fail; } r = connect_unix_path(journal_fd, AT_FDCWD, "/run/systemd/journal/socket"); if (r < 0) goto fail; return 0; fail: log_close_journal(); return r; } bool stderr_is_journal(void) { _cleanup_free_ char *w = NULL; const char *e; uint64_t dev, ino; struct stat st; e = getenv("JOURNAL_STREAM"); if (!e) return false; if (extract_first_word(&e, &w, ":", EXTRACT_DONT_COALESCE_SEPARATORS) <= 0) return false; if (!e) return false; if (safe_atou64(w, &dev) < 0) return false; if (safe_atou64(e, &ino) < 0) return false; if (fstat(STDERR_FILENO, &st) < 0) return false; return st.st_dev == dev && st.st_ino == ino; } int log_open(void) { int r; /* Do not call from library code. */ /* This function is often called in preparation for logging. Let's make sure we don't clobber errno, * so that a call to a logging function immediately following a log_open() call can still easily * reference an error that happened immediately before the log_open() call. */ PROTECT_ERRNO; /* If we don't use the console, we close it here to not get killed by SAK. If we don't use syslog, we * close it here too, so that we are not confused by somebody deleting the socket in the fs, and to * make sure we don't use it if prohibit_ipc is set. If we don't use /dev/kmsg we still keep it open, * because there is no reason to close it. */ if (log_target == LOG_TARGET_NULL) { log_close_journal(); log_close_syslog(); log_close_console(); return 0; } if (getpid_cached() == 1 || stderr_is_journal() || IN_SET(log_target, LOG_TARGET_KMSG, LOG_TARGET_JOURNAL, LOG_TARGET_JOURNAL_OR_KMSG, LOG_TARGET_SYSLOG, LOG_TARGET_SYSLOG_OR_KMSG)) { if (!prohibit_ipc) { if (IN_SET(log_target, LOG_TARGET_AUTO, LOG_TARGET_JOURNAL_OR_KMSG, LOG_TARGET_JOURNAL)) { r = log_open_journal(); if (r >= 0) { log_close_syslog(); log_close_console(); return r; } } if (IN_SET(log_target, LOG_TARGET_SYSLOG_OR_KMSG, LOG_TARGET_SYSLOG)) { r = log_open_syslog(); if (r >= 0) { log_close_journal(); log_close_console(); return r; } } } if (IN_SET(log_target, LOG_TARGET_AUTO, LOG_TARGET_JOURNAL_OR_KMSG, LOG_TARGET_SYSLOG_OR_KMSG, LOG_TARGET_KMSG)) { r = log_open_kmsg(); if (r >= 0) { log_close_journal(); log_close_syslog(); log_close_console(); return r; } } } log_close_journal(); log_close_syslog(); return log_open_console(); } void log_set_target(LogTarget target) { assert(target >= 0); assert(target < _LOG_TARGET_MAX); if (upgrade_syslog_to_journal) { if (target == LOG_TARGET_SYSLOG) target = LOG_TARGET_JOURNAL; else if (target == LOG_TARGET_SYSLOG_OR_KMSG) target = LOG_TARGET_JOURNAL_OR_KMSG; } log_target = target; } void log_set_target_and_open(LogTarget target) { log_set_target(target); log_open(); } void log_close(void) { /* Do not call from library code. */ log_close_journal(); log_close_syslog(); log_close_kmsg(); log_close_console(); } 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; } int log_set_max_level(int level) { assert(level == LOG_NULL || LOG_PRI(level) == level); int old = log_max_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); return old; } 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, const char *file, int line, const char *func, const char *buffer) { static int dumb = -1; char location[256], header_time[FORMAT_TIMESTAMP_MAX], prefix[1 + DECIMAL_STR_MAX(int) + 2], tid_string[3 + DECIMAL_STR_MAX(pid_t) + 1]; struct iovec iovec[11]; const char *on = NULL, *off = NULL; size_t n = 0; if (console_fd < 0) return 0; if (dumb < 0) dumb = getenv_terminal_is_dumb(); 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); } if (show_time && format_timestamp(header_time, sizeof(header_time), now(CLOCK_REALTIME))) { iovec[n++] = IOVEC_MAKE_STRING(header_time); iovec[n++] = IOVEC_MAKE_STRING(" "); } if (show_tid) { xsprintf(tid_string, "(" PID_FMT ") ", gettid()); iovec[n++] = IOVEC_MAKE_STRING(tid_string); } if (log_get_show_color()) get_log_colors(LOG_PRI(level), &on, &off, NULL); if (show_location) { const char *lon = "", *loff = ""; if (log_get_show_color()) { lon = ansi_highlight_yellow4(); loff = ansi_normal(); } (void) snprintf(location, sizeof location, "%s%s:%i%s: ", lon, file, line, loff); iovec[n++] = IOVEC_MAKE_STRING(location); } 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); /* 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. If we're writing to * a dumb terminal, only write NL as CRNL might be interpreted as a double newline. */ iovec[n++] = IOVEC_MAKE_STRING(check_console_fd_is_tty() && !dumb ? "\r\n" : "\n"); if (writev(console_fd, iovec, n) < 0) { if (errno == EIO && getpid_cached() == 1) { /* If somebody tried to kick us from our console tty (via vhangup() or suchlike), try * to reconnect. */ log_close_console(); (void) log_open_console(); if (console_fd < 0) return 0; if (writev(console_fd, iovec, n) < 0) return -errno; } else return -errno; } return 1; } static int write_to_syslog( int level, int error, const char *file, int line, const char *func, const char *buffer) { char header_priority[2 + DECIMAL_STR_MAX(int) + 1], header_time[64], header_pid[4 + DECIMAL_STR_MAX(pid_t) + 1]; struct tm tm; int r; if (syslog_fd < 0) return 0; if (LOG_PRI(level) > log_target_max_level[LOG_TARGET_SYSLOG]) return 0; xsprintf(header_priority, "<%i>", level); r = localtime_or_gmtime_usec(now(CLOCK_REALTIME), /* utc= */ false, &tm); if (r < 0) return r; if (strftime(header_time, sizeof(header_time), "%h %e %T ", &tm) <= 0) return -EINVAL; xsprintf(header_pid, "["PID_FMT"]: ", getpid_cached()); struct iovec iovec[] = { IOVEC_MAKE_STRING(header_priority), 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 = { .msg_iov = iovec, .msg_iovlen = ELEMENTSOF(iovec), }; /* When using syslog via SOCK_STREAM separate the messages by NUL chars */ if (syslog_is_stream) iovec[ELEMENTSOF(iovec) - 1].iov_len++; for (;;) { ssize_t n; n = sendmsg(syslog_fd, &msghdr, MSG_NOSIGNAL); if (n < 0) return -errno; if (!syslog_is_stream) break; if (iovec_increment(iovec, ELEMENTSOF(iovec), n)) break; } return 1; } static int write_to_kmsg( int level, int error, const char *file, int line, const char *func, const char *buffer) { /* Set a ratelimit on the amount of messages logged to /dev/kmsg. This is mostly supposed to be a * safety catch for the case where start indiscriminately logging in a loop. It will not catch cases * where we log excessively, but not in a tight loop. * * Note that this ratelimit is per-emitter, so we might still overwhelm /dev/kmsg with multiple * loggers. */ static thread_local RateLimit ratelimit = { 5 * USEC_PER_SEC, 200 }; char header_priority[2 + DECIMAL_STR_MAX(int) + 1], header_pid[4 + DECIMAL_STR_MAX(pid_t) + 1]; if (kmsg_fd < 0) return 0; 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()); const struct iovec iovec[] = { 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"), }; if (writev(kmsg_fd, iovec, ELEMENTSOF(iovec)) < 0) return -errno; return 1; } static int log_do_header( char *header, size_t size, int level, int error, const char *file, int line, const char *func, const char *object_field, const char *object, const char *extra_field, const char *extra) { int r; error = IS_SYNTHETIC_ERRNO(error) ? 0 : ERRNO_VALUE(error); r = snprintf(header, size, "PRIORITY=%i\n" "SYSLOG_FACILITY=%i\n" "TID=" PID_FMT "\n" "%s%.256s%s" /* CODE_FILE */ "%s%.*i%s" /* CODE_LINE */ "%s%.256s%s" /* CODE_FUNC */ "%s%.*i%s" /* ERRNO */ "%s%.256s%s" /* object */ "%s%.256s%s" /* extra */ "SYSLOG_IDENTIFIER=%.256s\n", LOG_PRI(level), LOG_FAC(level), gettid(), isempty(file) ? "" : "CODE_FILE=", isempty(file) ? "" : file, isempty(file) ? "" : "\n", line ? "CODE_LINE=" : "", line ? 1 : 0, line, /* %.0d means no output too, special case for 0 */ line ? "\n" : "", isempty(func) ? "" : "CODE_FUNC=", isempty(func) ? "" : func, isempty(func) ? "" : "\n", error ? "ERRNO=" : "", error ? 1 : 0, error, error ? "\n" : "", isempty(object) ? "" : object_field, isempty(object) ? "" : object, isempty(object) ? "" : "\n", isempty(extra) ? "" : extra_field, isempty(extra) ? "" : extra, isempty(extra) ? "" : "\n", program_invocation_short_name); assert_raw((size_t) r < size); 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"); } for (size_t i = 0; i < c->n_input_iovec; i++) { if (*n + 2 >= iovec_len) return; 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"); } } } static int write_to_journal( int level, int error, const char *file, int line, const char *func, const char *object_field, const char *object, const char *extra_field, const char *extra, const char *buffer) { char header[LINE_MAX]; size_t n = 0, iovec_len; struct iovec *iovec; if (journal_fd < 0) return 0; if (LOG_PRI(level) > log_target_max_level[LOG_TARGET_JOURNAL]) return 0; iovec_len = MIN(6 + _log_context_num_fields * 3, 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"); log_do_context(iovec, iovec_len, &n); const struct msghdr msghdr = { .msg_iov = iovec, .msg_iovlen = n, }; if (sendmsg(journal_fd, &msghdr, MSG_NOSIGNAL) < 0) return -errno; return 1; } int log_dispatch_internal( int level, int error, const char *file, int line, const char *func, const char *object_field, const char *object, const char *extra_field, const char *extra, char *buffer) { assert_raw(buffer); if (log_target == LOG_TARGET_NULL) return -ERRNO_VALUE(error); /* Patch in LOG_DAEMON facility if necessary */ if (LOG_FAC(level) == 0) level |= log_facility; if (open_when_needed) (void) log_open(); do { char *e; int k = 0; buffer += strspn(buffer, NEWLINE); if (buffer[0] == 0) break; if ((e = strpbrk(buffer, NEWLINE))) *(e++) = 0; if (IN_SET(log_target, LOG_TARGET_AUTO, LOG_TARGET_JOURNAL_OR_KMSG, LOG_TARGET_JOURNAL)) { k = write_to_journal(level, error, file, line, func, object_field, object, extra_field, extra, buffer); if (k < 0 && k != -EAGAIN) log_close_journal(); } if (IN_SET(log_target, LOG_TARGET_SYSLOG_OR_KMSG, LOG_TARGET_SYSLOG)) { k = write_to_syslog(level, error, file, line, func, buffer); if (k < 0 && k != -EAGAIN) log_close_syslog(); } if (k <= 0 && IN_SET(log_target, LOG_TARGET_AUTO, LOG_TARGET_SYSLOG_OR_KMSG, LOG_TARGET_JOURNAL_OR_KMSG, LOG_TARGET_KMSG)) { if (k < 0) log_open_kmsg(); k = write_to_kmsg(level, error, file, line, func, buffer); if (k < 0) { log_close_kmsg(); (void) log_open_console(); } } if (k <= 0) (void) write_to_console(level, error, file, line, func, buffer); buffer = e; } while (buffer); if (open_when_needed) log_close(); return -ERRNO_VALUE(error); } int log_dump_internal( int level, int error, const char *file, int line, const char *func, char *buffer) { PROTECT_ERRNO; /* This modifies the buffer... */ if (_likely_(LOG_PRI(level) > log_max_level)) return -ERRNO_VALUE(error); return log_dispatch_internal(level, error, file, line, func, NULL, NULL, NULL, NULL, buffer); } int log_internalv( int level, int error, const char *file, int line, const char *func, const char *format, va_list ap) { if (_likely_(LOG_PRI(level) > log_max_level)) return -ERRNO_VALUE(error); /* Make sure that %m maps to the specified error (or "Success"). */ char buffer[LINE_MAX]; LOCAL_ERRNO(ERRNO_VALUE(error)); (void) vsnprintf(buffer, sizeof buffer, format, ap); return log_dispatch_internal(level, error, file, line, func, NULL, NULL, NULL, NULL, buffer); } int log_internal( int level, int error, const char *file, int line, const char *func, const char *format, ...) { va_list ap; int r; va_start(ap, format); r = log_internalv(level, error, file, line, func, format, ap); va_end(ap); return r; } int log_object_internalv( int level, int error, const char *file, int line, const char *func, const char *object_field, const char *object, const char *extra_field, const char *extra, const char *format, va_list ap) { char *buffer, *b; if (_likely_(LOG_PRI(level) > log_max_level)) return -ERRNO_VALUE(error); /* Make sure that %m maps to the specified error (or "Success"). */ LOCAL_ERRNO(ERRNO_VALUE(error)); 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, object_field, object, extra_field, extra, buffer); } int log_object_internal( int level, int error, const char *file, int line, const char *func, const char *object_field, const char *object, const char *extra_field, const char *extra, const char *format, ...) { va_list ap; int r; va_start(ap, format); r = log_object_internalv(level, error, file, line, func, object_field, object, extra_field, extra, format, ap); va_end(ap); return r; } static void log_assert( int level, const char *text, const char *file, int line, const char *func, const char *format) { static char buffer[LINE_MAX]; if (_likely_(LOG_PRI(level) > log_max_level)) return; DISABLE_WARNING_FORMAT_NONLITERAL; (void) snprintf(buffer, sizeof buffer, format, text, file, line, func); REENABLE_WARNING; log_abort_msg = buffer; log_dispatch_internal(level, 0, file, line, func, NULL, NULL, NULL, NULL, buffer); } _noreturn_ void log_assert_failed( const char *text, const char *file, int line, const char *func) { log_assert(LOG_CRIT, text, file, line, func, "Assertion '%s' failed at %s:%u, function %s(). Aborting."); abort(); } _noreturn_ void log_assert_failed_unreachable( const char *file, int line, const char *func) { log_assert(LOG_CRIT, "Code should not be reached", file, line, func, "%s at %s:%u, function %s(). Aborting. 💥"); abort(); } void log_assert_failed_return( const char *text, 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."); } int log_oom_internal(int level, const char *file, int line, const char *func) { return log_internal(level, ENOMEM, file, line, func, "Out of memory."); } int log_format_iovec( struct iovec *iovec, size_t iovec_len, size_t *n, bool newline_separator, int error, const char *format, va_list ap) { static const char nl = '\n'; while (format && *n + 1 < iovec_len) { va_list aq; char *m; int r; /* We need to copy the va_list structure, * since vasprintf() leaves it afterwards at * an undefined location */ errno = ERRNO_VALUE(error); va_copy(aq, ap); r = vasprintf(&m, format, aq); va_end(aq); if (r < 0) return -EINVAL; /* Now, jump enough ahead, so that we point to * the next format string */ VA_FORMAT_ADVANCE(format, ap); iovec[(*n)++] = IOVEC_MAKE_STRING(m); if (newline_separator) iovec[(*n)++] = IOVEC_MAKE((char *)&nl, 1); format = va_arg(ap, char *); } return 0; } int log_struct_internal( int level, int error, const char *file, int line, const char *func, const char *format, ...) { char buf[LINE_MAX]; bool found = false; PROTECT_ERRNO; va_list ap; if (_likely_(LOG_PRI(level) > log_max_level) || log_target == LOG_TARGET_NULL) return -ERRNO_VALUE(error); if (LOG_FAC(level) == 0) level |= log_facility; if (IN_SET(log_target, LOG_TARGET_AUTO, LOG_TARGET_JOURNAL_OR_KMSG, LOG_TARGET_JOURNAL)) { if (open_when_needed) log_open_journal(); if (journal_fd >= 0) { char header[LINE_MAX]; struct iovec *iovec; size_t n = 0, m, iovec_len; int r; bool fallback = false; iovec_len = MIN(17 + _log_context_num_fields * 3, 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, 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, }; (void) sendmsg(journal_fd, &msghdr, MSG_NOSIGNAL); } va_end(ap); for (size_t i = 1; i < m; i += 2) free(iovec[i].iov_base); if (!fallback) { if (open_when_needed) log_close(); return -ERRNO_VALUE(error); } } } /* Fallback if journal logging is not available or didn't work. */ va_start(ap, format); while (format) { va_list aq; errno = ERRNO_VALUE(error); va_copy(aq, ap); (void) vsnprintf(buf, sizeof buf, format, aq); va_end(aq); if (startswith(buf, "MESSAGE=")) { found = true; break; } VA_FORMAT_ADVANCE(format, ap); format = va_arg(ap, char *); } va_end(ap); if (!found) { if (open_when_needed) log_close(); return -ERRNO_VALUE(error); } return log_dispatch_internal(level, error, file, line, func, NULL, NULL, NULL, NULL, buf + 8); } int log_struct_iovec_internal( int level, int error, const char *file, int line, const char *func, const struct iovec input_iovec[], size_t n_input_iovec) { PROTECT_ERRNO; if (_likely_(LOG_PRI(level) > log_max_level) || log_target == LOG_TARGET_NULL) return -ERRNO_VALUE(error); if (LOG_FAC(level) == 0) level |= log_facility; if (IN_SET(log_target, LOG_TARGET_AUTO, LOG_TARGET_JOURNAL_OR_KMSG, LOG_TARGET_JOURNAL) && 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 * 3, IOVEC_MAX); iovec = newa(struct iovec, iovec_len); log_do_header(header, sizeof(header), level, error, file, line, func, NULL, NULL, NULL, NULL); iovec[n++] = IOVEC_MAKE_STRING(header); for (size_t i = 0; i < n_input_iovec; i++) { 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 = n, }; if (sendmsg(journal_fd, &msghdr, MSG_NOSIGNAL) >= 0) return -ERRNO_VALUE(error); } for (size_t i = 0; i < n_input_iovec; i++) if (memory_startswith(input_iovec[i].iov_base, input_iovec[i].iov_len, "MESSAGE=")) { char *m; m = strndupa_safe((char*) input_iovec[i].iov_base + STRLEN("MESSAGE="), input_iovec[i].iov_len - STRLEN("MESSAGE=")); return log_dispatch_internal(level, error, file, line, func, NULL, NULL, NULL, NULL, m); } /* Couldn't find MESSAGE=. */ return -ERRNO_VALUE(error); } int log_set_target_from_string(const char *e) { LogTarget t; t = log_target_from_string(e); if (t < 0) return t; log_set_target(t); return 0; } int log_set_max_level_from_string(const char *e) { int r; 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; } 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) { /* * The systemd.log_xyz= settings are parsed by all tools, and * so is "debug". * * However, "quiet" is only parsed by PID 1, and only turns of * status output to /dev/console, but does not alter the log * level. */ if (streq(key, "debug") && !value) log_set_max_level(LOG_DEBUG); else if (proc_cmdline_key_streq(key, "systemd.log_target")) { if (proc_cmdline_value_missing(key, value)) return 0; if (log_set_target_from_string(value) < 0) log_warning("Failed to parse log target '%s', ignoring.", value); } else if (proc_cmdline_key_streq(key, "systemd.log_level")) { if (proc_cmdline_value_missing(key, value)) return 0; if (log_set_max_level_from_string(value) < 0) 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); } 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); } 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); } 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); } 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; } static bool should_parse_proc_cmdline(void) { /* PID1 always reads the kernel command line. */ if (getpid_cached() == 1) return true; /* Otherwise, parse the command line if invoked directly by systemd. */ return invoked_by_systemd(); } void log_parse_environment_variables(void) { const char *e; e = getenv("SYSTEMD_LOG_TARGET"); if (e && log_set_target_from_string(e) < 0) 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); e = getenv("SYSTEMD_LOG_COLOR"); if (e && log_show_color_from_string(e) < 0) 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); e = getenv("SYSTEMD_LOG_TIME"); if (e && log_show_time_from_string(e) < 0) 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); 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) { /* Do not call from library code. */ if (should_parse_proc_cmdline()) (void) proc_cmdline_parse(parse_proc_cmdline_item, NULL, PROC_CMDLINE_STRIP_RD_PREFIX); log_parse_environment_variables(); } 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; } void log_show_color(bool b) { show_color = b; } bool log_get_show_color(void) { return show_color > 0; /* Defaults to false. */ } void log_show_location(bool b) { show_location = b; } bool log_get_show_location(void) { return show_location; } void log_show_time(bool b) { show_time = b; } bool log_get_show_time(void) { return show_time; } void log_show_tid(bool b) { show_tid = b; } bool log_get_show_tid(void) { return show_tid; } int log_show_color_from_string(const char *e) { int r; r = parse_boolean(e); if (r < 0) return r; log_show_color(r); return 0; } int log_show_location_from_string(const char *e) { int r; r = parse_boolean(e); if (r < 0) return r; log_show_location(r); return 0; } int log_show_time_from_string(const char *e) { int r; r = parse_boolean(e); if (r < 0) return r; log_show_time(r); return 0; } int log_show_tid_from_string(const char *e) { int r; r = parse_boolean(e); if (r < 0) return r; log_show_tid(r); return 0; } bool log_on_console(void) { if (IN_SET(log_target, LOG_TARGET_CONSOLE, LOG_TARGET_CONSOLE_PREFIXED)) return true; return syslog_fd < 0 && kmsg_fd < 0 && journal_fd < 0; } static const char *const log_target_table[_LOG_TARGET_MAX] = { [LOG_TARGET_CONSOLE] = "console", [LOG_TARGET_CONSOLE_PREFIXED] = "console-prefixed", [LOG_TARGET_KMSG] = "kmsg", [LOG_TARGET_JOURNAL] = "journal", [LOG_TARGET_JOURNAL_OR_KMSG] = "journal-or-kmsg", [LOG_TARGET_SYSLOG] = "syslog", [LOG_TARGET_SYSLOG_OR_KMSG] = "syslog-or-kmsg", [LOG_TARGET_AUTO] = "auto", [LOG_TARGET_NULL] = "null", }; DEFINE_STRING_TABLE_LOOKUP(log_target, LogTarget); void log_received_signal(int level, const struct signalfd_siginfo *si) { assert(si); if (pid_is_valid(si->ssi_pid)) { _cleanup_free_ char *p = NULL; (void) pid_get_comm(si->ssi_pid, &p); log_full(level, "Received SIG%s from PID %"PRIu32" (%s).", signal_to_string(si->ssi_signo), si->ssi_pid, strna(p)); } else log_full(level, "Received SIG%s.", signal_to_string(si->ssi_signo)); } void set_log_syntax_callback(log_syntax_callback_t cb, void *userdata) { assert(!log_syntax_callback || !cb); assert(!log_syntax_callback_userdata || !userdata); log_syntax_callback = cb; log_syntax_callback_userdata = userdata; } int log_syntax_internal( const char *unit, int level, const char *config_file, unsigned config_line, int error, const char *file, int line, const char *func, const char *format, ...) { PROTECT_ERRNO; if (log_syntax_callback) log_syntax_callback(unit, level, log_syntax_callback_userdata); if (_likely_(LOG_PRI(level) > log_max_level) || log_target == LOG_TARGET_NULL) return -ERRNO_VALUE(error); char buffer[LINE_MAX]; va_list ap; const char *unit_fmt = NULL; errno = ERRNO_VALUE(error); va_start(ap, format); (void) vsnprintf(buffer, sizeof buffer, format, ap); va_end(ap); if (unit) unit_fmt = getpid_cached() == 1 ? "UNIT=%s" : "USER_UNIT=%s"; if (config_file) { if (config_line > 0) return log_struct_internal( level, error, file, line, func, "MESSAGE_ID=" SD_MESSAGE_INVALID_CONFIGURATION_STR, "CONFIG_FILE=%s", config_file, "CONFIG_LINE=%u", config_line, LOG_MESSAGE("%s:%u: %s", config_file, config_line, buffer), unit_fmt, unit, NULL); else return log_struct_internal( level, error, file, line, func, "MESSAGE_ID=" SD_MESSAGE_INVALID_CONFIGURATION_STR, "CONFIG_FILE=%s", config_file, LOG_MESSAGE("%s: %s", config_file, buffer), unit_fmt, unit, NULL); } else if (unit) return log_struct_internal( level, error, file, line, func, "MESSAGE_ID=" SD_MESSAGE_INVALID_CONFIGURATION_STR, LOG_MESSAGE("%s: %s", unit, buffer), unit_fmt, unit, NULL); else return log_struct_internal( level, error, file, line, func, "MESSAGE_ID=" SD_MESSAGE_INVALID_CONFIGURATION_STR, LOG_MESSAGE("%s", buffer), NULL); } int log_syntax_invalid_utf8_internal( const char *unit, int level, const char *config_file, unsigned config_line, const char *file, int line, const char *func, const char *rvalue) { PROTECT_ERRNO; _cleanup_free_ char *p = NULL; if (rvalue) p = utf8_escape_invalid(rvalue); return log_syntax_internal(unit, level, config_file, config_line, SYNTHETIC_ERRNO(EINVAL), file, line, func, "String is not UTF-8 clean, ignoring assignment: %s", strna(p)); } int log_syntax_parse_error_internal( const char *unit, const char *config_file, unsigned config_line, int error, bool critical, const char *file, int line, const char *func, const char *lvalue, const char *rvalue) { PROTECT_ERRNO; _cleanup_free_ char *escaped = NULL; /* OOM is always handled as critical. */ if (ERRNO_VALUE(error) == ENOMEM) return log_oom_internal(LOG_ERR, file, line, func); if (rvalue && !utf8_is_valid(rvalue)) { escaped = utf8_escape_invalid(rvalue); if (!escaped) rvalue = "(oom)"; else rvalue = " (escaped)"; } log_syntax_internal(unit, critical ? LOG_ERR : LOG_WARNING, config_file, config_line, error, file, line, func, "Failed to parse %s=%s%s%s%s%s", strna(lvalue), strempty(escaped), strempty(rvalue), critical ? "" : ", ignoring", error == 0 ? "." : ": ", error == 0 ? "" : STRERROR(error)); return critical ? -ERRNO_VALUE(error) : 0; } void log_set_upgrade_syslog_to_journal(bool b) { upgrade_syslog_to_journal = b; /* Make the change effective immediately */ if (b) { if (log_target == LOG_TARGET_SYSLOG) log_target = LOG_TARGET_JOURNAL; else if (log_target == LOG_TARGET_SYSLOG_OR_KMSG) log_target = LOG_TARGET_JOURNAL_OR_KMSG; } } void log_set_always_reopen_console(bool b) { always_reopen_console = b; } void log_set_open_when_needed(bool b) { open_when_needed = b; } void log_set_prohibit_ipc(bool b) { prohibit_ipc = b; } int log_emergency_level(void) { /* Returns the log level to use for log_emergency() logging. We use LOG_EMERG only when we are PID 1, as only * then the system of the whole system is obviously affected. */ return getpid_cached() == 1 ? LOG_EMERG : LOG_ERR; } int log_dup_console(void) { int copy; /* Duplicate the fd we use for fd logging if it's < 3 and use the copy from now on. This call is useful * whenever we want to continue logging through the original fd, but want to rearrange stderr. */ if (console_fd < 0 || console_fd >= 3) return 0; copy = fcntl(console_fd, F_DUPFD_CLOEXEC, 3); if (copy < 0) return -errno; console_fd = copy; return 0; } void log_setup(void) { log_set_target(LOG_TARGET_AUTO); log_parse_environment(); (void) log_open(); if (log_on_console() && show_color < 0) 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) { int r; if (log_get_max_level() == LOG_DEBUG) return true; if (saved_log_context_enabled >= 0) return saved_log_context_enabled; 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"); saved_log_context_enabled = r > 0; return saved_log_context_enabled; } 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); } static LogContext* log_context_detach(LogContext *c) { if (!c) return NULL; 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(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, }; return log_context_attach(c); } 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; 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, }; return log_context_attach(c); } static LogContext* log_context_free(LogContext *c) { if (!c) return NULL; log_context_detach(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); } 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_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); 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; }