From e2eed6a7581193da43210a26ad182fb2a697eaf5 Mon Sep 17 00:00:00 2001 From: Ben Pfaff Date: Mon, 20 Jun 2011 15:06:33 -0700 Subject: [PATCH] vlog: Add a little more detail to ratelimit messages When a message is suppressed by vlog ratelimiting, and then that message occurs again much later, sometimes we get messages like this: Dropped 4 log messages in last 8695 seconds due to excessive rate It seems pretty clear in this case that in fact we just didn't get that kind of message for most of that 8695 seconds. This commit improves the message by adding a little more detail, e.g.: Dropped 4 log messages in last 8695 seconds (most recently, 6697 seconds ago) due to excessive rate. Bug #2144. --- lib/vlog.c | 12 +++++++++--- lib/vlog.h | 2 ++ 2 files changed, 11 insertions(+), 3 deletions(-) diff --git a/lib/vlog.c b/lib/vlog.c index 265e9c6d..279c6e73 100644 --- a/lib/vlog.c +++ b/lib/vlog.c @@ -740,6 +740,7 @@ vlog_should_drop(const struct vlog_module *module, enum vlog_level level, if (!rl->n_dropped) { rl->first_dropped = now; } + rl->last_dropped = now; rl->n_dropped++; return true; } @@ -747,10 +748,15 @@ vlog_should_drop(const struct vlog_module *module, enum vlog_level level, rl->tokens -= VLOG_MSG_TOKENS; if (rl->n_dropped) { + time_t now = time_now(); + unsigned int first_dropped_elapsed = now - rl->first_dropped; + unsigned int last_dropped_elapsed = now - rl->last_dropped; + vlog(module, level, - "Dropped %u log messages in last %u seconds " - "due to excessive rate", - rl->n_dropped, (unsigned int) (time_now() - rl->first_dropped)); + "Dropped %u log messages in last %u seconds (most recently, " + "%u seconds ago) due to excessive rate", + rl->n_dropped, first_dropped_elapsed, last_dropped_elapsed); + rl->n_dropped = 0; } return false; diff --git a/lib/vlog.h b/lib/vlog.h index 3f40c297..1a11f598 100644 --- a/lib/vlog.h +++ b/lib/vlog.h @@ -112,6 +112,7 @@ struct vlog_rate_limit { unsigned int tokens; /* Current number of tokens. */ time_t last_fill; /* Last time tokens added. */ time_t first_dropped; /* Time first message was dropped. */ + time_t last_dropped; /* Time of most recent message drop. */ unsigned int n_dropped; /* Number of messages dropped. */ }; @@ -130,6 +131,7 @@ struct vlog_rate_limit { 0, /* tokens */ \ 0, /* last_fill */ \ 0, /* first_dropped */ \ + 0, /* last_dropped */ \ 0, /* n_dropped */ \ } -- 2.30.2