Merge branch 'bug22212_squashed' into maint-0.3.1

changes/bug22212

@@ -0,0 +1,5 @@
+  o Minor bugfixes (netflow padding logging):
+    - Demote a warn that was caused by libevent delays to info if
+      the padding is less than 4.5 seconds late, or notice if it is more
+      (4.5 seconds is the amount of time that a netflow record might
+       be emitted after, if we chose the maximum timeout). Fixes bug #22212.

src/or/channelpadding.c

@@ -530,10 +530,20 @@ channelpadding_compute_time_until_pad_for_netflow(channel_t *chan)
       >= chan->next_padding_time_ms) {
     int64_t ms_until_pad_for_netflow = chan->next_padding_time_ms -
                                        long_now;
+    /* If the padding time is in the past, that means that libevent delayed
+     * calling the once-per-second callback due to other work taking too long.
+     * See https://bugs.torproject.org/22212 and
+     * https://bugs.torproject.org/16585. This is a systemic problem
+     * with being single-threaded, but let's emit a notice if this
+     * is long enough in the past that we might have missed a netflow window,
+     * and allowed a router to emit a netflow frame, just so we don't forget
+     * about it entirely.. */
+#define NETFLOW_MISSED_WINDOW (150000 - DFLT_NETFLOW_INACTIVE_KEEPALIVE_HIGH)
     if (ms_until_pad_for_netflow < 0) {
-      log_warn(LD_BUG,
-              "Channel padding timeout scheduled "I64_FORMAT"ms in the past. "
-              "Did the monotonic clock just jump?",
+      int severity = (ms_until_pad_for_netflow < -NETFLOW_MISSED_WINDOW)
+                      ? LOG_NOTICE : LOG_INFO;
+      log_fn(severity, LD_OR,
+              "Channel padding timeout scheduled "I64_FORMAT"ms in the past. ",
               I64_PRINTF_ARG(-ms_until_pad_for_netflow));
       return 0; /* Clock jumped: Send padding now */
     }

src/test/test_channelpadding.c

@@ -795,8 +795,6 @@ test_channelpadding_decide_to_pad_channel(void *arg)
   tried_to_write_cell = 0;
   chan->next_padding_time_ms = monotime_coarse_absolute_msec() - 100;
   decision = channelpadding_decide_to_pad_channel(chan);
-  expect_log_msg("Channel padding timeout scheduled 100ms in the past. "
-                 "Did the monotonic clock just jump?\n");
   tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SENT);
   tt_int_op(tried_to_write_cell, OP_EQ, 1);
   tt_assert(!chan->pending_padding_callback);