From 131819424db7cae7a4f0251cc675dabd2c9e0d49 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Mon, 30 Oct 2017 20:01:50 +0100 Subject: [PATCH] journald: when logging about dropped messages, include more meta data When we drop messages of a unit, we log about. Let's add some structured data to that. Let's include how many messages we dropped, but more importantly, let's link up the message we generate to the unit we dropped the messages from by using the "OBJECT" logic, i.e. by generating OBJECT_SYSTEMD_UNIT= fields and suchlike, that "journalctl -u" and friends already look for. Fixes: #6494 --- src/journal/journald-kmsg.c | 2 +- src/journal/journald-server.c | 17 ++++++++++------- src/journal/journald-server.h | 2 +- src/journal/journald-syslog.c | 2 +- src/journal/journald.c | 4 ++-- 5 files changed, 15 insertions(+), 12 deletions(-) diff --git a/src/journal/journald-kmsg.c b/src/journal/journald-kmsg.c index 36f16a1ec8..a53075ac00 100644 --- a/src/journal/journald-kmsg.c +++ b/src/journal/journald-kmsg.c @@ -155,7 +155,7 @@ static void dev_kmsg_record(Server *s, const char *p, size_t l) { /* Did we lose any? */ if (serial > *s->kernel_seqnum) - server_driver_message(s, + server_driver_message(s, 0, "MESSAGE_ID=" SD_MESSAGE_JOURNAL_MISSED_STR, LOG_MESSAGE("Missed %"PRIu64" kernel messages", serial - *s->kernel_seqnum), diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index e719fae007..e85e4e0f10 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -219,7 +219,8 @@ void server_space_usage_message(Server *s, JournalStorage *storage) { format_bytes(fb5, sizeof(fb5), storage->space.limit); format_bytes(fb6, sizeof(fb6), storage->space.available); - server_driver_message(s, "MESSAGE_ID=" SD_MESSAGE_JOURNAL_USAGE_STR, + server_driver_message(s, 0, + "MESSAGE_ID=" SD_MESSAGE_JOURNAL_USAGE_STR, LOG_MESSAGE("%s (%s) is %s, max %s, %s free.", storage->name, storage->path, fb1, fb5, fb6), "JOURNAL_NAME=%s", storage->name, @@ -859,7 +860,7 @@ static void dispatch_message_real( write_to_journal(s, journal_uid, iovec, n, priority); } -void server_driver_message(Server *s, const char *message_id, const char *format, ...) { +void server_driver_message(Server *s, pid_t object_pid, const char *message_id, const char *format, ...) { struct iovec iovec[N_IOVEC_META_FIELDS + 5 + N_IOVEC_PAYLOAD_FIELDS]; unsigned n = 0, m; @@ -887,7 +888,7 @@ void server_driver_message(Server *s, const char *message_id, const char *format va_end(ap); if (r >= 0) - dispatch_message_real(s, iovec, n, ELEMENTSOF(iovec), s->my_context, NULL, LOG_INFO, 0); + dispatch_message_real(s, iovec, n, ELEMENTSOF(iovec), s->my_context, NULL, LOG_INFO, object_pid); while (m < n) free(iovec[m++].iov_base); @@ -901,7 +902,7 @@ void server_driver_message(Server *s, const char *message_id, const char *format n = 3; iovec[n++] = IOVEC_MAKE_STRING("PRIORITY=4"); iovec[n++] = IOVEC_MAKE_STRING(buf); - dispatch_message_real(s, iovec, n, ELEMENTSOF(iovec), s->my_context, NULL, LOG_INFO, 0); + dispatch_message_real(s, iovec, n, ELEMENTSOF(iovec), s->my_context, NULL, LOG_INFO, object_pid); } } @@ -939,8 +940,10 @@ void server_dispatch_message( /* Write a suppression message if we suppressed something */ if (rl > 1) - server_driver_message(s, "MESSAGE_ID=" SD_MESSAGE_JOURNAL_DROPPED_STR, - LOG_MESSAGE("Suppressed %u messages from %s", rl - 1, c->unit), + server_driver_message(s, c->pid, + "MESSAGE_ID=" SD_MESSAGE_JOURNAL_DROPPED_STR, + LOG_MESSAGE("Suppressed %i messages from %s", rl - 1, c->unit), + LOG_MESSAGE("N_DROPPED=%i", rl - 1), NULL); } @@ -1038,7 +1041,7 @@ finish: sd_journal_close(j); - server_driver_message(s, NULL, + server_driver_message(s, 0, NULL, LOG_MESSAGE("Time spent on flushing to /var is %s for %u entries.", format_timespan(ts, sizeof(ts), now(CLOCK_MONOTONIC) - start, 0), n), diff --git a/src/journal/journald-server.h b/src/journal/journald-server.h index f4bdd588cb..5efc5fe119 100644 --- a/src/journal/journald-server.h +++ b/src/journal/journald-server.h @@ -188,7 +188,7 @@ struct Server { #define N_IOVEC_PAYLOAD_FIELDS 15 void server_dispatch_message(Server *s, struct iovec *iovec, unsigned n, unsigned m, ClientContext *c, const struct timeval *tv, int priority, pid_t object_pid); -void server_driver_message(Server *s, const char *message_id, const char *format, ...) _printf_(3,0) _sentinel_; +void server_driver_message(Server *s, pid_t object_pid, const char *message_id, const char *format, ...) _sentinel_; /* gperf lookup function */ const struct ConfigPerfItem* journald_gperf_lookup(const char *key, GPERF_LEN_TYPE length); diff --git a/src/journal/journald-syslog.c b/src/journal/journald-syslog.c index 1fde0271a6..b3db310fbf 100644 --- a/src/journal/journald-syslog.c +++ b/src/journal/journald-syslog.c @@ -449,7 +449,7 @@ void server_maybe_warn_forward_syslog_missed(Server *s) { if (s->last_warn_forward_syslog_missed + WARN_FORWARD_SYSLOG_MISSED_USEC > n) return; - server_driver_message(s, + server_driver_message(s, 0, "MESSAGE_ID=" SD_MESSAGE_FORWARD_SYSLOG_MISSED_STR, LOG_MESSAGE("Forwarding to syslog missed %u messages.", s->n_forward_syslog_missed), diff --git a/src/journal/journald.c b/src/journal/journald.c index 318e067563..1ee477cf1c 100644 --- a/src/journal/journald.c +++ b/src/journal/journald.c @@ -56,7 +56,7 @@ int main(int argc, char *argv[]) { server_flush_dev_kmsg(&server); log_debug("systemd-journald running as pid "PID_FMT, getpid_cached()); - server_driver_message(&server, + server_driver_message(&server, 0, "MESSAGE_ID=" SD_MESSAGE_JOURNAL_START_STR, LOG_MESSAGE("Journal started"), NULL); @@ -115,7 +115,7 @@ int main(int argc, char *argv[]) { } log_debug("systemd-journald stopped as pid "PID_FMT, getpid_cached()); - server_driver_message(&server, + server_driver_message(&server, 0, "MESSAGE_ID=" SD_MESSAGE_JOURNAL_STOP_STR, LOG_MESSAGE("Journal stopped"), NULL);