Merge remote-tracking branch 'tor-gitlab/mr/108'

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.

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

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)
 

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