From: Richard Phibel Date: Wed, 17 Aug 2022 20:24:52 +0000 (+0200) Subject: journald: use rate-limited logging to log 'Failed to write entry' message X-Git-Tag: v252-rc1~353 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=34683dbdd019f7e1cf6598d94efce3c0dfe42afe;p=thirdparty%2Fsystemd.git journald: use rate-limited logging to log 'Failed to write entry' message --- diff --git a/src/basic/log.h b/src/basic/log.h index b7b0a42e494..c51941c1416 100644 --- a/src/basic/log.h +++ b/src/basic/log.h @@ -8,6 +8,7 @@ #include #include "macro.h" +#include "ratelimit.h" /* Some structures we reference but don't want to pull in headers for */ struct iovec; @@ -367,3 +368,41 @@ int log_syntax_invalid_utf8_internal( #define DEBUG_LOGGING _unlikely_(log_get_max_level() >= LOG_DEBUG) void log_setup(void); + +typedef struct LogRateLimit { + int error; + int level; + RateLimit ratelimit; +} LogRateLimit; + +#define log_ratelimit_internal(_level, _error, _format, _file, _line, _func, ...) \ +({ \ + int _log_ratelimit_error = (_error); \ + int _log_ratelimit_level = (_level); \ + static LogRateLimit _log_ratelimit = { \ + .ratelimit = { \ + .interval = 1 * USEC_PER_SEC, \ + .burst = 1, \ + }, \ + }; \ + unsigned _num_dropped_errors = ratelimit_num_dropped(&_log_ratelimit.ratelimit); \ + if (_log_ratelimit_error != _log_ratelimit.error || _log_ratelimit_level != _log_ratelimit.level) { \ + ratelimit_reset(&_log_ratelimit.ratelimit); \ + _log_ratelimit.error = _log_ratelimit_error; \ + _log_ratelimit.level = _log_ratelimit_level; \ + } \ + if (ratelimit_below(&_log_ratelimit.ratelimit)) \ + _log_ratelimit_error = _num_dropped_errors > 0 \ + ? log_internal(_log_ratelimit_level, _log_ratelimit_error, _file, _line, _func, _format " (Dropped %u similar message(s))", __VA_ARGS__, _num_dropped_errors) \ + : log_internal(_log_ratelimit_level, _log_ratelimit_error, _file, _line, _func, _format, __VA_ARGS__); \ + _log_ratelimit_error; \ +}) + +#define log_ratelimit_full_errno(level, error, format, ...) \ + ({ \ + int _level = (level), _e = (error); \ + _e = (log_get_max_level() >= LOG_PRI(_level)) \ + ? log_ratelimit_internal(_level, _e, format, PROJECT_FILE, __LINE__, __func__, __VA_ARGS__) \ + : -ERRNO_VALUE(_e); \ + _e < 0 ? _e : -ESTRPIPE; \ + }) diff --git a/src/basic/ratelimit.c b/src/basic/ratelimit.c index 005bf31dc7c..c16c8f7103a 100644 --- a/src/basic/ratelimit.c +++ b/src/basic/ratelimit.c @@ -30,9 +30,16 @@ bool ratelimit_below(RateLimit *r) { if (r->num < r->burst) goto good; + r->num++; return false; good: r->num++; return true; } + +unsigned ratelimit_num_dropped(RateLimit *r) { + assert(r); + + return r->num > r->burst ? r->num - r->burst : 0; +} diff --git a/src/basic/ratelimit.h b/src/basic/ratelimit.h index ee1d17c0e74..2236189851e 100644 --- a/src/basic/ratelimit.h +++ b/src/basic/ratelimit.h @@ -4,7 +4,6 @@ #include #include "time-util.h" -#include "util.h" typedef struct RateLimit { usec_t interval; /* Keep those two fields first so they can be initialized easily: */ @@ -22,3 +21,5 @@ static inline bool ratelimit_configured(RateLimit *rl) { } bool ratelimit_below(RateLimit *r); + +unsigned ratelimit_num_dropped(RateLimit *r); diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index 0061abadff5..49cede6892f 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -873,14 +873,14 @@ static void write_to_journal(Server *s, uid_t uid, struct iovec *iovec, size_t n } if (vacuumed || !shall_try_append_again(f->file, r)) { - log_error_errno(r, "Failed to write entry (%zu items, %zu bytes), ignoring: %m", n, IOVEC_TOTAL_SIZE(iovec, n)); + log_ratelimit_full_errno(LOG_ERR, r, "Failed to write entry (%zu items, %zu bytes), ignoring: %m", n, IOVEC_TOTAL_SIZE(iovec, n)); return; } if (r == -E2BIG) log_debug("Journal file %s is full, rotating to a new file", f->file->path); else - log_info_errno(r, "Failed to write entry to %s (%zu items, %zu bytes), rotating before retrying: %m", f->file->path, n, IOVEC_TOTAL_SIZE(iovec, n)); + log_ratelimit_full_errno(LOG_INFO, r, "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); @@ -892,7 +892,7 @@ static void write_to_journal(Server *s, uid_t uid, struct iovec *iovec, size_t n log_debug("Retrying write."); r = journal_file_append_entry(f->file, &ts, NULL, iovec, n, &s->seqnum, NULL, NULL); if (r < 0) - log_error_errno(r, "Failed to write entry to %s (%zu items, %zu bytes) despite vacuuming, ignoring: %m", f->file->path, n, IOVEC_TOTAL_SIZE(iovec, n)); + log_ratelimit_full_errno(LOG_ERR, r, "Failed to write entry to %s (%zu items, %zu bytes) despite vacuuming, ignoring: %m", f->file->path, n, IOVEC_TOTAL_SIZE(iovec, n)); else server_schedule_sync(s, priority); } diff --git a/src/test/test-ratelimit.c b/src/test/test-ratelimit.c index 47978121079..d82bda53472 100644 --- a/src/test/test-ratelimit.c +++ b/src/test/test-ratelimit.c @@ -23,4 +23,21 @@ TEST(ratelimit_below) { assert_se(ratelimit_below(&ratelimit)); } +TEST(ratelimit_num_dropped) { + int i; + RateLimit ratelimit = { 1 * USEC_PER_SEC, 10 }; + + for (i = 0; i < 10; i++) { + assert_se(ratelimit_below(&ratelimit)); + assert_se(ratelimit_num_dropped(&ratelimit) == 0); + } + assert_se(!ratelimit_below(&ratelimit)); + assert_se(ratelimit_num_dropped(&ratelimit) == 1); + assert_se(!ratelimit_below(&ratelimit)); + assert_se(ratelimit_num_dropped(&ratelimit) == 2); + sleep(1); + assert_se(ratelimit_below(&ratelimit)); + assert_se(ratelimit_num_dropped(&ratelimit) == 0); +} + DEFINE_TEST_MAIN(LOG_INFO);