From: Nick Mathewson Date: Wed, 18 Aug 2010 19:55:49 +0000 (-0400) Subject: Add a generic rate-limited log mechanism, and use it in a few places X-Git-Tag: tor-0.2.2.16-alpha~29^2~1 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=ba9c1275c4b2325aed6a2fe2cc236794dab11052;p=thirdparty%2Ftor.git Add a generic rate-limited log mechanism, and use it in a few places Incidentally fixes bug 1042. --- diff --git a/changes/log-ratelim b/changes/log-ratelim new file mode 100644 index 0000000000..612a510fdf --- /dev/null +++ b/changes/log-ratelim @@ -0,0 +1,7 @@ + o Minor bugfixes + - Rate-limit "Failed to hand off onionskin" warnings. + + o Minor features + - When logging a rate-limited warning, we now mention how many messages + got suppressed since the last warning. + diff --git a/src/common/util.c b/src/common/util.c index 6830ef3aa4..3c735e9c7c 100644 --- a/src/common/util.c +++ b/src/common/util.c @@ -1577,6 +1577,49 @@ ftime_definitely_before(time_t now, time_t when) return (now + ftime_skew + ftime_slop) < when; } +/* ===== + * Rate limiting + * ===== */ + +/** 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 + * rate_limit_is_ready returned nonzero. Otherwise return 0. */ +int +rate_limit_is_ready(ratelim_t *lim, time_t now) +{ + if (lim->rate + lim->last_allowed >= now) { + int res = lim->n_calls_since_last_time + 1; + lim->last_allowed = now; + lim->n_calls_since_last_time = 0; + return res; + } else { + ++lim->n_calls_since_last_time; + return 0; + } +} + +/** If the rate-limiter lim is ready at now, return a newly + * allocated string indicating how many messages were suppressed, suitable to + * append to a log message. Otherwise return NULL. */ +char * +rate_limit_log(ratelim_t *lim, time_t now) +{ + int n; + if ((n = rate_limit_is_ready(lim, now))) { + if (n == 1) { + return tor_strdup(""); + } else { + char *cp=NULL; + tor_asprintf(&cp, + " [%d similar message(s) suppressed in last %d seconds]", + n-1, lim->rate); + return cp; + } + } else { + return NULL; + } +} + /* ===== * File helpers * ===== */ diff --git a/src/common/util.h b/src/common/util.h index ba38f4c7ed..1e22bd5b1b 100644 --- a/src/common/util.h +++ b/src/common/util.h @@ -252,6 +252,34 @@ int ftime_maybe_before(time_t now, time_t when); int ftime_definitely_after(time_t now, time_t when); int ftime_definitely_before(time_t now, time_t when); +/* Rate-limiter */ + +/** A ratelim_t remembers how often an event is occurring, and how often + * it's allowed to occur. Typical usage is something like: + * + 
+    if (possibly_very_frequent_event()) {
+      const int INTERVAL = 300;
+      static ratelim_t warning_limit = RATELIM_INIT(INTERVAL);
+      char *m;
+      if ((m = rate_limit_log(&warning_limit, approx_time()))) {
+        log_warn(LD_GENERAL, "The event occurred!%s", m);
+        tor_free(m);
+      }
+    }
+
+ */ +typedef struct ratelim_t { + int rate; + time_t last_allowed; + int n_calls_since_last_time; +} ratelim_t; + +#define RATELIM_INIT(r) { (r), 0, 0 } + +int rate_limit_is_ready(ratelim_t *lim, time_t now); +char *rate_limit_log(ratelim_t *lim, time_t now); + /* File helpers */ ssize_t write_all(int fd, const char *buf, size_t count, int isSocket); ssize_t read_all(int fd, char *buf, size_t count, int isSocket); diff --git a/src/or/command.c b/src/or/command.c index 0460e25c25..ad8abfe5c9 100644 --- a/src/or/command.c +++ b/src/or/command.c @@ -288,7 +288,12 @@ command_process_create_cell(cell_t *cell, or_connection_t *conn) /* hand it off to the cpuworkers, and then return. */ if (assign_onionskin_to_cpuworker(NULL, circ, onionskin) < 0) { - log_warn(LD_GENERAL,"Failed to hand off onionskin. Closing."); + static ratelim_t handoff_warning = RATELIM_INIT(3600); + char *m; + if ((m = rate_limit_log(&handoff_warning, approx_time()))) { + log_warn(LD_GENERAL,"Failed to hand off onionskin. Closing.%s",m); + tor_free(m); + } circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_INTERNAL); return; } diff --git a/src/or/connection.c b/src/or/connection.c index c040be041e..91ce74b5b0 100644 --- a/src/or/connection.c +++ b/src/or/connection.c @@ -839,13 +839,13 @@ static void warn_too_many_conns(void) { #define WARN_TOO_MANY_CONNS_INTERVAL (6*60*60) - static time_t last_warned = 0; - time_t now = time(NULL); - int n_conns = get_n_open_sockets(); - if (last_warned + WARN_TOO_MANY_CONNS_INTERVAL < now) { + static ratelim_t last_warned = RATELIM_INIT(WARN_TOO_MANY_CONNS_INTERVAL); + char *m; + if ((m = rate_limit_log(&last_warned, approx_time()))) { + int n_conns = get_n_open_sockets(); log_warn(LD_NET,"Failing because we have %d connections already. Please " - "raise your ulimit -n.", n_conns); - last_warned = now; + "raise your ulimit -n.%s", n_conns, m); + tor_free(m); control_event_general_status(LOG_WARN, "TOO_MANY_CONNECTIONS CURRENT=%d", n_conns); } diff --git a/src/or/onion.c b/src/or/onion.c index ebc3583648..fa001656e6 100644 --- a/src/or/onion.c +++ b/src/or/onion.c @@ -63,15 +63,16 @@ onion_pending_add(or_circuit_t *circ, char *onionskin) if (ol_length >= get_options()->MaxOnionsPending) { #define WARN_TOO_MANY_CIRC_CREATIONS_INTERVAL (60) - static time_t last_warned = 0; - time_t now = time(NULL); - if (last_warned + WARN_TOO_MANY_CIRC_CREATIONS_INTERVAL < now) { + static ratelim_t last_warned = + RATELIM_INIT(WARN_TOO_MANY_CIRC_CREATIONS_INTERVAL); + char *m; + if ((m = rate_limit_log(&last_warned, approx_time()))) { log_warn(LD_GENERAL, "Your computer is too slow to handle this many circuit " "creation requests! Please consider using the " "MaxAdvertisedBandwidth config option or choosing a more " - "restricted exit policy."); - last_warned = now; + "restricted exit policy.%s",m); + tor_free(m); } tor_free(tmp); return -1;