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.

diff --git a/lib/vlog.c b/lib/vlog.c
index 265e9c6dd0bc914b53d27bb2f5b4db7a3538b45f..279c6e739c73a742ef3caf1cadd914f83ed821c8 100644 (file)
--- 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 3f40c297dbbe736197a9841e1316777d9a7ff841..1a11f598e00935772b2e1960ca422420b7d94151 100644 (file)
--- 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 */ \
         }