[tor-commits] [tor/master] Improve ratelimit message to list true interval.

[asn at torproject.org]

commit 1d0695fe7eb0b1b8176c71ecc6e5fe74a5b71378
Author: Nick Mathewson <nickm at torproject.org>
Date:   Tue Aug 4 13:51:28 2020 -0400

    Improve ratelimit message to list true interval.
    
    Previous message would say "N messages in the last T seconds", but
    would give an inaccurate number for N.
    
    We now give an accurate number, rounded up to the nearest 60 seconds.
    
    Closes #19431.
---
 changes/bug19431        |  6 ++++++
 src/lib/log/ratelim.c   | 12 +++++++++---
 src/lib/log/ratelim.h   |  8 +++++++-
 src/test/test_logging.c |  6 +++++-
 4 files changed, 27 insertions(+), 5 deletions(-)

diff --git a/changes/bug19431 b/changes/bug19431
new file mode 100644
index 0000000000..09f16b422d
--- /dev/null
+++ b/changes/bug19431
@@ -0,0 +1,6 @@
+  o Minor bugfixes (logging):
+    - When logging a rate-limited message about how many messages have been
+      suppressed in the last N seconds, give an accurate value for N, rounded
+      up to the nearest minute.  Previously we would report the size of the
+      rate-limiting interval, regardless of when the messages started to
+      occur.  Fixes bug 19431; bugfix on 0.2.2.16-alpha.
diff --git a/src/lib/log/ratelim.c b/src/lib/log/ratelim.c
index ac401fb398..8dfaee3384 100644
--- a/src/lib/log/ratelim.c
+++ b/src/lib/log/ratelim.c
@@ -11,6 +11,7 @@
 #include "lib/log/ratelim.h"
 #include "lib/malloc/malloc.h"
 #include "lib/string/printf.h"
+#include "lib/intmath/muldiv.h"
 
 /** If the rate-limiter <b>lim</b> is ready at <b>now</b>, return the number
  * of calls to rate_limit_is_ready (including this one!) since the last time
@@ -42,19 +43,24 @@ rate_limit_log(ratelim_t *lim, time_t now)
 {
   int n;
   if ((n = rate_limit_is_ready(lim, now))) {
+    time_t started_limiting = lim->started_limiting;
+    lim->started_limiting = 0;
     if (n == 1) {
       return tor_strdup("");
     } else {
       char *cp=NULL;
       const char *opt_over = (n >= RATELIM_TOOMANY) ? "over " : "";
-      /* XXXX this is not exactly correct: the messages could have occurred
-       * any time between the old value of lim->allowed and now. */
+      unsigned difference = (unsigned)(now - started_limiting);
+      difference = round_to_next_multiple_of(difference, 60);
       tor_asprintf(&cp,
                    " [%s%d similar message(s) suppressed in last %d seconds]",
-                   opt_over, n-1, lim->rate);
+                   opt_over, n-1, (int)difference);
       return cp;
     }
   } else {
+    if (lim->started_limiting == 0) {
+      lim->started_limiting = now;
+    }
     return NULL;
   }
 }
diff --git a/src/lib/log/ratelim.h b/src/lib/log/ratelim.h
index e9b55d40dc..9e202028cf 100644
--- a/src/lib/log/ratelim.h
+++ b/src/lib/log/ratelim.h
@@ -40,13 +40,19 @@
    </pre>
  */
 typedef struct ratelim_t {
+  /** How many seconds must elapse between log messages? */
   int rate;
+  /** When did this limiter last allow a message to appear? */
   time_t last_allowed;
+  /** When did this limiter start suppressing messages? */
+  time_t started_limiting;
+  /** How many messages has this limiter suppressed since it last allowed
+   * one to appear? */
   int n_calls_since_last_time;
 } ratelim_t;
 
 #ifndef COCCI
-#define RATELIM_INIT(r) { (r), 0, 0 }
+#define RATELIM_INIT(r) { (r), 0, 0, 0 }
 #endif
 #define RATELIM_TOOMANY (16*1000*1000)
 
diff --git a/src/test/test_logging.c b/src/test/test_logging.c
index e09f7a21cd..58d0f24bd3 100644
--- a/src/test/test_logging.c
+++ b/src/test/test_logging.c
@@ -160,6 +160,7 @@ test_ratelim(void *arg)
   tor_free(msg);
 
   int i;
+  time_t first_suppressed_at = now + 60;
   for (i = 0; i < 9; ++i) {
     now += 60; /* one minute has passed. */
     msg = rate_limit_log(&ten_min, now);
@@ -167,12 +168,15 @@ test_ratelim(void *arg)
     tt_int_op(ten_min.last_allowed, OP_EQ, start);
     tt_int_op(ten_min.n_calls_since_last_time, OP_EQ, i + 1);
   }
+  tt_i64_op(ten_min.started_limiting, OP_EQ, first_suppressed_at);
 
   now += 240; /* Okay, we can be done. */
   msg = rate_limit_log(&ten_min, now);
   tt_ptr_op(msg, OP_NE, NULL);
   tt_str_op(msg, OP_EQ,
-            " [9 similar message(s) suppressed in last 600 seconds]");
+            " [9 similar message(s) suppressed in last 720 seconds]");
+  tt_i64_op(now, OP_EQ, first_suppressed_at + 720);
+
  done:
   tor_free(msg);
 }