From c8e6e1f10d8a3f3a0bd7f484c73aadc87602de4d Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Tue, 12 Oct 2021 11:00:00 +0100 Subject: [PATCH 1/3] journal: Add log level argument to journal_file_rotate_suggested() When journald is rotating a file, we'd like to log the reason at LOG_INFO or higher instead of LOG_DEBUG. For journalctl --header, logging the reason at a level higher than LOG_DEBUG doesn't really make sense. To accomodate both use cases, make the log level used by journal_file_rotate_suggested() configurable. --- src/journal-remote/journal-remote-write.c | 2 +- src/journal/journald-server.c | 2 +- src/libsystemd/sd-journal/journal-file.c | 42 +++++++++++++---------- src/libsystemd/sd-journal/journal-file.h | 2 +- 4 files changed, 26 insertions(+), 22 deletions(-) diff --git a/src/journal-remote/journal-remote-write.c b/src/journal-remote/journal-remote-write.c index ea7162318e..c953a5e93e 100644 --- a/src/journal-remote/journal-remote-write.c +++ b/src/journal-remote/journal-remote-write.c @@ -68,7 +68,7 @@ int writer_write(Writer *w, assert(iovw); assert(iovw->count > 0); - if (journal_file_rotate_suggested(w->journal, 0)) { + if (journal_file_rotate_suggested(w->journal, 0, LOG_DEBUG)) { log_info("%s: Journal header limits reached or header out-of-date, rotating", w->journal->path); r = do_rotate(&w->journal, compress, seal); diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index c93499bbc6..b8ec409cf1 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -819,7 +819,7 @@ static void write_to_journal(Server *s, uid_t uid, struct iovec *iovec, size_t n if (!f) return; - if (journal_file_rotate_suggested(f, s->max_file_usec)) { + if (journal_file_rotate_suggested(f, s->max_file_usec, LOG_DEBUG)) { log_debug("%s: Journal header limits reached or header out-of-date, rotating.", f->path); rotate = true; } diff --git a/src/libsystemd/sd-journal/journal-file.c b/src/libsystemd/sd-journal/journal-file.c index d5ceba2f8f..c7186fdb37 100644 --- a/src/libsystemd/sd-journal/journal-file.c +++ b/src/libsystemd/sd-journal/journal-file.c @@ -3316,7 +3316,7 @@ void journal_file_print_header(JournalFile *f) { le64toh(f->header->arena_size), le64toh(f->header->data_hash_table_size) / sizeof(HashItem), le64toh(f->header->field_hash_table_size) / sizeof(HashItem), - yes_no(journal_file_rotate_suggested(f, 0)), + yes_no(journal_file_rotate_suggested(f, 0, LOG_DEBUG)), le64toh(f->header->head_entry_seqnum), le64toh(f->header->head_entry_seqnum), le64toh(f->header->tail_entry_seqnum), le64toh(f->header->tail_entry_seqnum), FORMAT_TIMESTAMP_SAFE(le64toh(f->header->head_entry_realtime)), le64toh(f->header->head_entry_realtime), @@ -4107,14 +4107,14 @@ int journal_file_get_cutoff_monotonic_usec(JournalFile *f, sd_id128_t boot_id, u return 1; } -bool journal_file_rotate_suggested(JournalFile *f, usec_t max_file_usec) { +bool journal_file_rotate_suggested(JournalFile *f, usec_t max_file_usec, int log_level) { assert(f); assert(f->header); /* If we gained new header fields we gained new features, * hence suggest a rotation */ if (le64toh(f->header->header_size) < sizeof(Header)) { - log_debug("%s uses an outdated header, suggesting rotation.", f->path); + log_full(log_level, "%s uses an outdated header, suggesting rotation.", f->path); return true; } @@ -4124,23 +4124,25 @@ bool journal_file_rotate_suggested(JournalFile *f, usec_t max_file_usec) { if (JOURNAL_HEADER_CONTAINS(f->header, n_data)) if (le64toh(f->header->n_data) * 4ULL > (le64toh(f->header->data_hash_table_size) / sizeof(HashItem)) * 3ULL) { - log_debug("Data hash table of %s has a fill level at %.1f (%"PRIu64" of %"PRIu64" items, %llu file size, %"PRIu64" bytes per hash table item), suggesting rotation.", - f->path, - 100.0 * (double) le64toh(f->header->n_data) / ((double) (le64toh(f->header->data_hash_table_size) / sizeof(HashItem))), - le64toh(f->header->n_data), - le64toh(f->header->data_hash_table_size) / sizeof(HashItem), - (unsigned long long) f->last_stat.st_size, - f->last_stat.st_size / le64toh(f->header->n_data)); + log_full(log_level, + "Data hash table of %s has a fill level at %.1f (%"PRIu64" of %"PRIu64" items, %llu file size, %"PRIu64" bytes per hash table item), suggesting rotation.", + f->path, + 100.0 * (double) le64toh(f->header->n_data) / ((double) (le64toh(f->header->data_hash_table_size) / sizeof(HashItem))), + le64toh(f->header->n_data), + le64toh(f->header->data_hash_table_size) / sizeof(HashItem), + (unsigned long long) f->last_stat.st_size, + f->last_stat.st_size / le64toh(f->header->n_data)); return true; } if (JOURNAL_HEADER_CONTAINS(f->header, n_fields)) if (le64toh(f->header->n_fields) * 4ULL > (le64toh(f->header->field_hash_table_size) / sizeof(HashItem)) * 3ULL) { - log_debug("Field hash table of %s has a fill level at %.1f (%"PRIu64" of %"PRIu64" items), suggesting rotation.", - f->path, - 100.0 * (double) le64toh(f->header->n_fields) / ((double) (le64toh(f->header->field_hash_table_size) / sizeof(HashItem))), - le64toh(f->header->n_fields), - le64toh(f->header->field_hash_table_size) / sizeof(HashItem)); + log_full(log_level, + "Field hash table of %s has a fill level at %.1f (%"PRIu64" of %"PRIu64" items), suggesting rotation.", + f->path, + 100.0 * (double) le64toh(f->header->n_fields) / ((double) (le64toh(f->header->field_hash_table_size) / sizeof(HashItem))), + le64toh(f->header->n_fields), + le64toh(f->header->field_hash_table_size) / sizeof(HashItem)); return true; } @@ -4148,15 +4150,17 @@ bool journal_file_rotate_suggested(JournalFile *f, usec_t max_file_usec) { * longest chain is longer than some threshold, let's suggest rotation. */ if (JOURNAL_HEADER_CONTAINS(f->header, data_hash_chain_depth) && le64toh(f->header->data_hash_chain_depth) > HASH_CHAIN_DEPTH_MAX) { - log_debug("Data hash table of %s has deepest hash chain of length %" PRIu64 ", suggesting rotation.", - f->path, le64toh(f->header->data_hash_chain_depth)); + log_full(log_level, + "Data hash table of %s has deepest hash chain of length %" PRIu64 ", suggesting rotation.", + f->path, le64toh(f->header->data_hash_chain_depth)); return true; } if (JOURNAL_HEADER_CONTAINS(f->header, field_hash_chain_depth) && le64toh(f->header->field_hash_chain_depth) > HASH_CHAIN_DEPTH_MAX) { - log_debug("Field hash table of %s has deepest hash chain of length at %" PRIu64 ", suggesting rotation.", - f->path, le64toh(f->header->field_hash_chain_depth)); + log_full(log_level, + "Field hash table of %s has deepest hash chain of length at %" PRIu64 ", suggesting rotation.", + f->path, le64toh(f->header->field_hash_chain_depth)); return true; } diff --git a/src/libsystemd/sd-journal/journal-file.h b/src/libsystemd/sd-journal/journal-file.h index de3df7692d..b4488259ad 100644 --- a/src/libsystemd/sd-journal/journal-file.h +++ b/src/libsystemd/sd-journal/journal-file.h @@ -259,7 +259,7 @@ void journal_default_metrics(JournalMetrics *m, int fd); int journal_file_get_cutoff_realtime_usec(JournalFile *f, usec_t *from, usec_t *to); int journal_file_get_cutoff_monotonic_usec(JournalFile *f, sd_id128_t boot, usec_t *from, usec_t *to); -bool journal_file_rotate_suggested(JournalFile *f, usec_t max_file_usec); +bool journal_file_rotate_suggested(JournalFile *f, usec_t max_file_usec, int log_level); int journal_file_map_data_hash_table(JournalFile *f); int journal_file_map_field_hash_table(JournalFile *f); From 012181eaef0792f4feff9cc2dbaab629291d1b5d Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Tue, 12 Oct 2021 11:03:44 +0100 Subject: [PATCH 2/3] journal: Add two more log messages to journal_file_rotate_suggested() This ensures every reason for rotation has an associated log message. --- src/libsystemd/sd-journal/journal-file.c | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/src/libsystemd/sd-journal/journal-file.c b/src/libsystemd/sd-journal/journal-file.c index c7186fdb37..9f8b02d89b 100644 --- a/src/libsystemd/sd-journal/journal-file.c +++ b/src/libsystemd/sd-journal/journal-file.c @@ -4168,8 +4168,12 @@ bool journal_file_rotate_suggested(JournalFile *f, usec_t max_file_usec, int log if (JOURNAL_HEADER_CONTAINS(f->header, n_data) && JOURNAL_HEADER_CONTAINS(f->header, n_fields) && le64toh(f->header->n_data) > 0 && - le64toh(f->header->n_fields) == 0) + le64toh(f->header->n_fields) == 0) { + log_full(log_level, + "Data objects of %s are not indexed by field objects, suggesting rotation.", + f->path); return true; + } if (max_file_usec > 0) { usec_t t, h; @@ -4177,8 +4181,12 @@ bool journal_file_rotate_suggested(JournalFile *f, usec_t max_file_usec, int log h = le64toh(f->header->head_entry_realtime); t = now(CLOCK_REALTIME); - if (h > 0 && t > h + max_file_usec) + if (h > 0 && t > h + max_file_usec) { + log_full(log_level, + "Oldest entry in %s is older than the configured file retention duration (%s), suggesting rotation.", + f->path, FORMAT_TIMESPAN(max_file_usec, USEC_PER_SEC)); return true; + } } return false; From b2b7cf1df57cc475ee685f174654a34d4f122cd9 Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Tue, 12 Oct 2021 11:20:59 +0100 Subject: [PATCH 3/3] journal: Expand rotate log messages in journald Make sure we always log when we rotate journals and always do so at least at INFO log level. Doing so we make sure there's always a clear reason available explaining why we rotated a journal. --- src/journal/journald-server.c | 14 +++++++++----- src/journal/journald.c | 2 +- 2 files changed, 10 insertions(+), 6 deletions(-) diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index b8ec409cf1..7aa734d2d3 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -811,7 +811,7 @@ static void write_to_journal(Server *s, uid_t uid, struct iovec *iovec, size_t n * to ensure that the entries in the journal files are strictly ordered by time, in order to ensure * bisection works correctly. */ - log_debug("Time jumped backwards, rotating."); + log_info("Time jumped backwards, rotating."); rotate = true; } else { @@ -819,8 +819,8 @@ static void write_to_journal(Server *s, uid_t uid, struct iovec *iovec, size_t n if (!f) return; - if (journal_file_rotate_suggested(f, s->max_file_usec, LOG_DEBUG)) { - log_debug("%s: Journal header limits reached or header out-of-date, rotating.", f->path); + if (journal_file_rotate_suggested(f, s->max_file_usec, LOG_INFO)) { + log_info("%s: Journal header limits reached or header out-of-date, rotating.", f->path); rotate = true; } } @@ -848,6 +848,8 @@ static void write_to_journal(Server *s, uid_t uid, struct iovec *iovec, size_t n return; } + log_info_errno(r, "Failed to write entry (%zu items, %zu bytes), rotating before retrying: %m", n, IOVEC_TOTAL_SIZE(iovec, n)); + server_rotate(s); server_vacuum(s, false); @@ -1172,6 +1174,8 @@ int server_flush_to_var(Server *s, bool require_flag_file) { goto finish; } + log_info("Rotating system journal."); + server_rotate(s); server_vacuum(s, false); @@ -1428,7 +1432,7 @@ static int dispatch_sigusr2(sd_event_source *es, const struct signalfd_siginfo * assert(s); - log_info("Received SIGUSR2 signal from PID " PID_FMT ", as request to rotate journal.", si->ssi_pid); + log_info("Received SIGUSR2 signal from PID " PID_FMT ", as request to rotate journal, rotating.", si->ssi_pid); server_full_rotate(s); return 0; @@ -1970,7 +1974,7 @@ static int vl_method_rotate(Varlink *link, JsonVariant *parameters, VarlinkMetho if (json_variant_elements(parameters) > 0) return varlink_error_invalid_parameter(link, parameters); - log_info("Received client request to rotate journal."); + log_info("Received client request to rotate journal, rotating."); server_full_rotate(s); return varlink_reply(link, NULL); diff --git a/src/journal/journald.c b/src/journal/journald.c index 536717ce0a..94aad05de9 100644 --- a/src/journal/journald.c +++ b/src/journal/journald.c @@ -88,7 +88,7 @@ int main(int argc, char *argv[]) { /* The retention time is reached, so let's vacuum! */ if (server.oldest_file_usec + server.max_retention_usec < n) { - log_info("Retention time reached."); + log_info("Retention time reached, rotating."); server_rotate(&server); server_vacuum(&server, false); continue;