commit 1d0695fe7eb0b1b8176c71ecc6e5fe74a5b71378 Author: Nick Mathewson <nickm@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); }