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 b7b0a42e49454dc9aa89b007ba094870c94f23b9..c51941c14167a0165ad56e8bbe3a8fb5ebe762d0 100644 (file)
--- a/src/basic/log.h
+++ b/src/basic/log.h
@@ -8,6 +8,7 @@
 #include <syslog.h>
 
 #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 005bf31dc7ceeb14821e3ec8d5c67df69486c406..c16c8f7103ae0bb76eea1f56fe4ba7636303aaf3 100644 (file)
--- 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 ee1d17c0e74e5afcc7b240cd5f6936bfdb2e6ac4..2236189851e6fcbf2167826daa9a41e8a9f525c4 100644 (file)
--- a/src/basic/ratelimit.h
+++ b/src/basic/ratelimit.h
@@ -4,7 +4,6 @@
 #include <stdbool.h>
 
 #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 0061abadff5ef0b2498b6f72cf19081157e0cc77..49cede6892fed9bc11a11f76bb3b1c4591e0be67 100644 (file)
--- 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 479781210797d2c8faee8d8e7e48cf6c648b70dc..d82bda53472f059a59c03dbd39ce81413db30055 100644 (file)
--- 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);