[tor-commits] [tor/master] Demote a log message due to libevent delays.

[nickm at torproject.org]

commit 0592ee45fcb244f6fedf3d39867c8cb289f518e9
Author: Mike Perry <mikeperry-git at torproject.org>
Date:   Wed Jun 21 16:30:53 2017 -0400

    Demote a log message due to libevent delays.
    
    This is a side-effect of being single-threaded. The worst cases of this are
    actually Bug #16585.
---
 src/or/channelpadding.c        | 16 +++++++++++++---
 src/test/test_channelpadding.c |  2 --
 2 files changed, 13 insertions(+), 5 deletions(-)

diff --git a/src/or/channelpadding.c b/src/or/channelpadding.c
index f5248e8..bed2489 100644
--- a/src/or/channelpadding.c
+++ b/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 */
     }
diff --git a/src/test/test_channelpadding.c b/src/test/test_channelpadding.c
index 0a70184..3b88999 100644
--- a/src/test/test_channelpadding.c
+++ b/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);