From d6df3bfbb82330fc0e2f90c5455bfe2a89d67477 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Mon, 27 Feb 2023 15:35:01 +0100 Subject: [PATCH 1/6] journald: make sure shall_try_append_again() logs about all return codes passed in, not just some --- src/journal/journald-server.c | 1 + 1 file changed, 1 insertion(+) diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index de08c4e965..ec784c957f 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -894,6 +894,7 @@ static bool shall_try_append_again(JournalFile *f, int r) { return false; default: + log_ratelimit_error_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Unexpected error while writing to journal file: %m", f->path); return false; } } From 07a06f5d0c6c118b3efcc4999aec110e0141ed89 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Mon, 27 Feb 2023 15:39:24 +0100 Subject: [PATCH 2/6] journald: start log message uppercase, like every other one around --- src/journal/journald-server.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index ec784c957f..1fe587f324 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -890,7 +890,7 @@ static bool shall_try_append_again(JournalFile *f, int r) { return true; case -EAFNOSUPPORT: - log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: underlying file system does not support memory mapping or another required file system feature.", f->path); + log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: Underlying file system does not support memory mapping or another required file system feature.", f->path); return false; default: From ab84a03fdaf3954918d66da5c5294f9fe9a59074 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Mon, 27 Feb 2023 15:40:48 +0100 Subject: [PATCH 3/6] journald: downgrade various log messages from LOG_WARNING to LOG_INFO None of these conditions are real issues, but they can simply happen because we just swtched from /run to /var as backend for logging and there are old files from different boots with different systemd versions and so on. Let's not make more noise than necessary: still log, but not consider it a warning, but just some normal thing. We are handling these issues safely after all: by rotating and starting anew, i.e. there's no reason to be concerned. --- src/journal/journald-server.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index 1fe587f324..87dfd55f00 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -866,27 +866,27 @@ static bool shall_try_append_again(JournalFile *f, int r) { case -EBADMSG: /* Corrupted */ case -ENODATA: /* Truncated */ case -ESHUTDOWN: /* Already archived */ - log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: Journal file corrupted, rotating.", f->path); + log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Journal file corrupted, rotating.", f->path); return true; case -EIDRM: /* Journal file has been deleted */ - log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: Journal file has been deleted, rotating.", f->path); + log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Journal file has been deleted, rotating.", f->path); return true; case -EREMCHG: /* Wallclock time (CLOCK_REALTIME) jumped backwards relative to last journal entry */ - log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: Realtime clock jumped backwards relative to last journal entry, rotating.", f->path); + log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Realtime clock jumped backwards relative to last journal entry, rotating.", f->path); return true; case -EREMOTE: /* Boot ID different from the one of the last entry */ - log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: Boot ID changed since last record, rotating.", f->path); + log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Boot ID changed since last record, rotating.", f->path); return true; case -ENOTNAM: /* Monotonic time (CLOCK_MONOTONIC) jumped backwards relative to last journal entry */ - log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: Monotonic clock jumped backwards relative to last journal entry, rotating.", f->path); + log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Monotonic clock jumped backwards relative to last journal entry, rotating.", f->path); return true; case -EILSEQ: /* seqnum ID last used in the file doesn't match the one we'd passed when writing an entry to it */ - log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: Journal file uses a different sequence number ID, rotating.", f->path); + log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Journal file uses a different sequence number ID, rotating.", f->path); return true; case -EAFNOSUPPORT: From 8253cb35fa8343c1e2eee4f71256384b3cd9b270 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Mon, 27 Feb 2023 15:42:59 +0100 Subject: [PATCH 4/6] journald: upgrade log message about missing mmap() support to LOG_ERR in this case we really cannot proceed and fail. Let's log about this loudly, since we simply fail the operation to write anything. --- src/journal/journald-server.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index 87dfd55f00..1c7372e628 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -890,7 +890,7 @@ static bool shall_try_append_again(JournalFile *f, int r) { return true; case -EAFNOSUPPORT: - log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: Underlying file system does not support memory mapping or another required file system feature.", f->path); + log_ratelimit_error(JOURNAL_LOG_RATELIMIT, "%s: Underlying file system does not support memory mapping or another required file system feature.", f->path); return false; default: From 32b0678c868b42ad68d383c8bf18fc2cdb1fbe95 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Mon, 27 Feb 2023 15:47:11 +0100 Subject: [PATCH 5/6] journald: always pass error code to logging function, even if we don't use it with %m We always want to pass the error code along with the log call, so that it can add it to structured logging, even if the format string does not contain %m. --- src/journal/journald-server.c | 26 +++++++++++++------------- 1 file changed, 13 insertions(+), 13 deletions(-) diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index 1c7372e628..a6741ff8cc 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -836,7 +836,7 @@ static bool shall_try_append_again(JournalFile *f, int r) { case -EFBIG: /* Hit fs limit */ case -EDQUOT: /* Quota limit hit */ case -ENOSPC: /* Disk full */ - log_debug("%s: Allocation limit reached, rotating.", f->path); + log_debug_errno(r, "%s: Allocation limit reached, rotating.", f->path); return true; case -EROFS: /* Read-only file system */ @@ -844,53 +844,53 @@ static bool shall_try_append_again(JournalFile *f, int r) { * rotated. If the FS is read-only, rotation will fail and s->system_journal will be set to * NULL. After that, when find_journal will try to open the journal since s->system_journal * will be NULL, it will open the runtime journal. */ - log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: Read-only file system, rotating.", f->path); + log_ratelimit_warning_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Read-only file system, rotating.", f->path); return true; case -EIO: /* I/O error of some kind (mmap) */ - log_ratelimit_warning(JOURNAL_LOG_RATELIMIT, "%s: IO error, rotating.", f->path); + log_ratelimit_warning_errno(r, JOURNAL_LOG_RATELIMIT, "%s: IO error, rotating.", f->path); return true; case -EHOSTDOWN: /* Other machine */ - log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Journal file from other machine, rotating.", f->path); + log_ratelimit_info_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Journal file from other machine, rotating.", f->path); return true; case -EBUSY: /* Unclean shutdown */ - log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Unclean shutdown, rotating.", f->path); + log_ratelimit_info_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Unclean shutdown, rotating.", f->path); return true; case -EPROTONOSUPPORT: /* Unsupported feature */ - log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Unsupported feature, rotating.", f->path); + log_ratelimit_info_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Unsupported feature, rotating.", f->path); return true; case -EBADMSG: /* Corrupted */ case -ENODATA: /* Truncated */ case -ESHUTDOWN: /* Already archived */ - log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Journal file corrupted, rotating.", f->path); + log_ratelimit_info_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Journal file corrupted, rotating.", f->path); return true; case -EIDRM: /* Journal file has been deleted */ - log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Journal file has been deleted, rotating.", f->path); + log_ratelimit_info_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Journal file has been deleted, rotating.", f->path); return true; case -EREMCHG: /* Wallclock time (CLOCK_REALTIME) jumped backwards relative to last journal entry */ - log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Realtime clock jumped backwards relative to last journal entry, rotating.", f->path); + log_ratelimit_info_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Realtime clock jumped backwards relative to last journal entry, rotating.", f->path); return true; case -EREMOTE: /* Boot ID different from the one of the last entry */ - log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Boot ID changed since last record, rotating.", f->path); + log_ratelimit_info_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Boot ID changed since last record, rotating.", f->path); return true; case -ENOTNAM: /* Monotonic time (CLOCK_MONOTONIC) jumped backwards relative to last journal entry */ - log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Monotonic clock jumped backwards relative to last journal entry, rotating.", f->path); + log_ratelimit_info_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Monotonic clock jumped backwards relative to last journal entry, rotating.", f->path); return true; case -EILSEQ: /* seqnum ID last used in the file doesn't match the one we'd passed when writing an entry to it */ - log_ratelimit_info(JOURNAL_LOG_RATELIMIT, "%s: Journal file uses a different sequence number ID, rotating.", f->path); + log_ratelimit_info_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Journal file uses a different sequence number ID, rotating.", f->path); return true; case -EAFNOSUPPORT: - log_ratelimit_error(JOURNAL_LOG_RATELIMIT, "%s: Underlying file system does not support memory mapping or another required file system feature.", f->path); + log_ratelimit_error_errno(r, JOURNAL_LOG_RATELIMIT, "%s: Underlying file system does not support memory mapping or another required file system feature.", f->path); return false; default: From 0631aabdf567e5ce87166827e9645bc18083a7c9 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Mon, 27 Feb 2023 15:48:45 +0100 Subject: [PATCH 6/6] journald: remove triplicate logging about failure to write log lines Let's log exactly at one place about failed writing of log lines to journal file: in shall_try_append_again(). Then, if we decide to suppress a retry-after-vacuum because we already vacuumed anyway then say this explicitly as "supressed rotation", because that's what we do here. This removes triplicate logging about the same error, and logs exactly once, plus optional one "suppressed rotation" message. (plus more debug output). The triplicate logging was bad in particular because it had no understanding of the actual error codes and just showed generic UNIX error strings ("Not a XENIX named type file"). By relying on shall_try_append_again() to do all logging we now get very clean error strings for all conditions. Fixes: #26496 --- src/journal/journald-server.c | 18 +++++++----------- 1 file changed, 7 insertions(+), 11 deletions(-) diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index a6741ff8cc..23942f9575 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -969,20 +969,16 @@ static void server_write_to_journal( return; } - if (vacuumed || !shall_try_append_again(f->file, r)) { - log_ratelimit_error_errno(r, FAILED_TO_WRITE_ENTRY_RATELIMIT, - "Failed to write entry (%zu items, %zu bytes), ignoring: %m", - n, IOVEC_TOTAL_SIZE(iovec, n)); + log_debug_errno(r, "Failed to write entry to %s (%zu items, %zu bytes): %m", f->file->path, n, IOVEC_TOTAL_SIZE(iovec, n)); + + if (!shall_try_append_again(f->file, r)) + return; + if (vacuumed) { + log_ratelimit_warning_errno(r, JOURNAL_LOG_RATELIMIT, + "Suppressing rotation, as we already rotated immediately before write attempt. Giving up."); return; } - if (r == -E2BIG) - log_debug("Journal file %s is full, rotating to a new file", f->file->path); - else - log_ratelimit_info_errno(r, FAILED_TO_WRITE_ENTRY_RATELIMIT, - "Failed to write entry to %s (%zu items, %zu bytes), rotating before retrying: %m", - f->file->path, n, IOVEC_TOTAL_SIZE(iovec, n)); - server_rotate(s); server_vacuum(s, false);