commit 0592ee45fcb244f6fedf3d39867c8cb289f518e9 Author: Mike Perry <mikeperry-git@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);