journald: use rate-limited logging to log 'Failed to write entry' message

This commit is contained in:
Richard Phibel 2022-08-17 22:24:52 +02:00 committed by Luca Boccassi
parent 298b3de6d4
commit 34683dbdd0
5 changed files with 68 additions and 4 deletions

View file

@ -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; \
})

View file

@ -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;
}

View file

@ -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);

View file

@ -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);
}

View file

@ -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);