Merge branch 'ratelim'

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.
+

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 <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
+ * rate_limit_is_ready returned nonzero.  Otherwise return 0. */
+static 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 <b>lim</b> is ready at <b>now</b>, 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
  * ===== */

src/common/util.h

@@ -252,6 +252,33 @@ 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:
+ *
+   <pre>
+    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);
+      }
+    }
+   </pre>
+ */
+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 }
+
+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);

src/or/command.c

@@ -288,7 +288,14 @@ 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.");
+#define WARN_HANDOFF_FAILURE_INTERVAL (6*60*60)
+      static ratelim_t handoff_warning =
+        RATELIM_INIT(WARN_HANDOFF_FAILURE_INTERVAL);
+      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;
     }

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;
+  static ratelim_t last_warned = RATELIM_INIT(WARN_TOO_MANY_CONNS_INTERVAL);
-  time_t now = time(NULL);
+  char *m;
+  if ((m = rate_limit_log(&last_warned, approx_time()))) {
     int n_conns = get_n_open_sockets();
-  if (last_warned + WARN_TOO_MANY_CONNS_INTERVAL < now) {
     log_warn(LD_NET,"Failing because we have %d connections already. Please "
-             "raise your ulimit -n.", n_conns);
+             "raise your ulimit -n.%s", n_conns, m);
-    last_warned = now;
+    tor_free(m);
     control_event_general_status(LOG_WARN, "TOO_MANY_CONNECTIONS CURRENT=%d",
                                  n_conns);
   }

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;
+    static ratelim_t last_warned =
-    time_t now = time(NULL);
+      RATELIM_INIT(WARN_TOO_MANY_CIRC_CREATIONS_INTERVAL);
-    if (last_warned + WARN_TOO_MANY_CIRC_CREATIONS_INTERVAL < now) {
+    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.");
+               "restricted exit policy.%s",m);
-      last_warned = now;
+      tor_free(m);
     }
     tor_free(tmp);
     return -1;