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 lim is ready at now, 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 @@
*/
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);
}