commit 285e7c98fdca8eda97683c0b96f86645ee3f0546 Author: Nick Mathewson nickm@torproject.org Date: Thu May 3 11:51:32 2018 -0400
Distinguish true clock jumps from idleness
Since we're going to be disabling the second-elapsed callback, we're going to sometimes have long periods when no events file, and so the current second is not updated. Handle that by having a better means to detect "clock jumps" as opposed to "being idle for a while". Tolerate far more of the latter.
Part of #26009. --- src/or/circuitbuild.c | 28 ++++++++++++++++++---------- src/or/circuitbuild.h | 2 +- src/or/main.c | 43 ++++++++++++++++++++++++++++++++++++++----- src/test/test_mainloop.c | 48 ++++++++++++++++++++++++++++++++++++++++++++---- 4 files changed, 101 insertions(+), 20 deletions(-)
diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c index 24c32b710..0617c2477 100644 --- a/src/or/circuitbuild.c +++ b/src/or/circuitbuild.c @@ -1133,19 +1133,27 @@ circuit_send_intermediate_onion_skin(origin_circuit_t *circ, return 0; }
-/** Our clock just jumped by <b>seconds_elapsed</b>. Assume - * something has also gone wrong with our network: notify the user, - * and abandon all not-yet-used circuits. */ +/** Our clock just jumped by <b>seconds_elapsed</b>. If <b>was_idle</b> is + * true, then the monotonic time matches; otherwise it doesn't. Assume + * something has also gone wrong with our network: notify the user, and + * abandon all not-yet-used circuits. */ void -circuit_note_clock_jumped(int seconds_elapsed) +circuit_note_clock_jumped(int seconds_elapsed, bool was_idle) { int severity = server_mode(get_options()) ? LOG_WARN : LOG_NOTICE; - tor_log(severity, LD_GENERAL, "Your system clock just jumped %d seconds %s; " - "assuming established circuits no longer work.", - seconds_elapsed >=0 ? seconds_elapsed : -seconds_elapsed, - seconds_elapsed >=0 ? "forward" : "backward"); - control_event_general_status(LOG_WARN, "CLOCK_JUMPED TIME=%d", - seconds_elapsed); + if (was_idle) { + tor_log(severity, LD_GENERAL, "Tor has been idle for %d seconds; " + "assuming established circuits no longer work.", + seconds_elapsed); + } else { + tor_log(severity, LD_GENERAL, + "Your system clock just jumped %d seconds %s; " + "assuming established circuits no longer work.", + seconds_elapsed >=0 ? seconds_elapsed : -seconds_elapsed, + seconds_elapsed >=0 ? "forward" : "backward"); + } + control_event_general_status(LOG_WARN, "CLOCK_JUMPED TIME=%d IDLE=%d", + seconds_elapsed, was_idle?1:0); /* so we log when it works again */ note_that_we_maybe_cant_complete_circuits(); control_event_client_status(severity, "CIRCUIT_NOT_ESTABLISHED REASON=%s", diff --git a/src/or/circuitbuild.h b/src/or/circuitbuild.h index bea31ad0d..f3a8bbfc9 100644 --- a/src/or/circuitbuild.h +++ b/src/or/circuitbuild.h @@ -29,7 +29,7 @@ void circuit_n_chan_done(channel_t *chan, int status, int inform_testing_reachability(void); int circuit_timeout_want_to_count_circ(const origin_circuit_t *circ); int circuit_send_next_onion_skin(origin_circuit_t *circ); -void circuit_note_clock_jumped(int seconds_elapsed); +void circuit_note_clock_jumped(int seconds_elapsed, bool was_idle); int circuit_extend(cell_t *cell, circuit_t *circ); int circuit_init_cpath_crypto(crypt_path_t *cpath, const char *key_data, size_t key_data_len, diff --git a/src/or/main.c b/src/or/main.c index d773c8e29..e82162c39 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -2498,6 +2498,8 @@ static int n_libevent_errors = 0;
/** Last time that update_current_time was called. */ static time_t current_second = 0; +/** Last time that update_current_time updated current_second. */ +static monotime_coarse_t current_second_last_changed;
/** * Set the current time to "now", which should be the value returned by @@ -2515,13 +2517,42 @@ update_current_time(time_t now)
const time_t seconds_elapsed = current_second ? (now - current_second) : 0;
-/** If more than this many seconds have elapsed, probably the clock - * jumped: doesn't count. */ + /* Check the wall clock against the monotonic clock, so we can + * better tell idleness from clock jumps and/or other shenanigans. */ + monotime_coarse_t last_updated; + memcpy(&last_updated, ¤t_second_last_changed, sizeof(last_updated)); + monotime_coarse_get(¤t_second_last_changed); + + /** How much clock jumping do we tolerate? */ #define NUM_JUMPED_SECONDS_BEFORE_WARN 100
- if (seconds_elapsed < -NUM_JUMPED_SECONDS_BEFORE_WARN || - seconds_elapsed >= NUM_JUMPED_SECONDS_BEFORE_WARN) { - circuit_note_clock_jumped(seconds_elapsed); + /** How much idleness do we tolerate? */ +#define NUM_IDLE_SECONDS_BEFORE_WARN 3600 + + if (seconds_elapsed < -NUM_JUMPED_SECONDS_BEFORE_WARN) { + // moving back in time is always a bad sign. + circuit_note_clock_jumped(seconds_elapsed, false); + } else if (seconds_elapsed >= NUM_JUMPED_SECONDS_BEFORE_WARN) { + /* Compare the monotonic clock to the result of time(). */ + const int32_t monotime_msec_passed = + monotime_coarse_diff_msec32(&last_updated, + ¤t_second_last_changed); + const int monotime_sec_passed = monotime_msec_passed / 1000; + const int discrepency = monotime_sec_passed - seconds_elapsed; + /* If the monotonic clock deviates from time(NULL), we have a couple of + * possibilities. On some systems, this means we have been suspended or + * sleeping. Everywhere, it can mean that the wall-clock time has + * been changed -- for example, with settimeofday(). + * + * On the other hand, if the monotonic time matches with the wall-clock + * time, we've probably just been idle for a while, with no events firing. + * we tolerate much more of that. + */ + const bool clock_jumped = abs(discrepency) > 2; + + if (clock_jumped || seconds_elapsed >= NUM_IDLE_SECONDS_BEFORE_WARN) { + circuit_note_clock_jumped(seconds_elapsed, ! clock_jumped); + } } else if (seconds_elapsed > 0) { stats_n_seconds_working += seconds_elapsed; } @@ -3686,6 +3717,8 @@ tor_free_all(int postfork) heartbeat_callback_first_time = 1; n_libevent_errors = 0; current_second = 0; + memset(¤t_second_last_changed, 0, + sizeof(current_second_last_changed));
if (!postfork) { release_lockfile(); diff --git a/src/test/test_mainloop.c b/src/test/test_mainloop.c index 2f8a7bca6..9da8a039d 100644 --- a/src/test/test_mainloop.c +++ b/src/test/test_mainloop.c @@ -12,13 +12,19 @@ #include "or.h" #include "main.h"
+static const uint64_t BILLION = 1000000000; + static void test_mainloop_update_time_normal(void *arg) { (void)arg;
+ monotime_enable_test_mocking(); + /* This is arbitrary */ + uint64_t mt_now = U64_LITERAL(7493289274986); /* This time is in the past as of when this test was written. */ time_t now = 1525272090; + monotime_coarse_set_mock_time_nsec(mt_now); reset_uptime(); update_current_time(now); tt_int_op(approx_time(), OP_EQ, now); @@ -28,12 +34,16 @@ test_mainloop_update_time_normal(void *arg) tt_int_op(get_uptime(), OP_EQ, 0);
now += 1; + mt_now += BILLION; + monotime_coarse_set_mock_time_nsec(mt_now); update_current_time(now); tt_int_op(approx_time(), OP_EQ, now); tt_int_op(get_uptime(), OP_EQ, 1);
now += 2; // two-second jump is unremarkable. + mt_now += 2*BILLION; update_current_time(now); + monotime_coarse_set_mock_time_nsec(mt_now); tt_int_op(approx_time(), OP_EQ, now); tt_int_op(get_uptime(), OP_EQ, 3);
@@ -43,7 +53,7 @@ test_mainloop_update_time_normal(void *arg) tt_int_op(get_uptime(), OP_EQ, 3); // but it doesn't roll back our uptime
done: - ; + monotime_disable_test_mocking(); }
static void @@ -51,8 +61,12 @@ test_mainloop_update_time_jumps(void *arg) { (void)arg;
+ monotime_enable_test_mocking(); + /* This is arbitrary */ + uint64_t mt_now = U64_LITERAL(7493289274986); /* This time is in the past as of when this test was written. */ time_t now = 220897152; + monotime_coarse_set_mock_time_nsec(mt_now); reset_uptime(); update_current_time(now); tt_int_op(approx_time(), OP_EQ, now); @@ -60,16 +74,19 @@ test_mainloop_update_time_jumps(void *arg)
/* Put some uptime on the clock.. */ now += 3; + mt_now += 3*BILLION; + monotime_coarse_set_mock_time_nsec(mt_now); update_current_time(now); tt_int_op(approx_time(), OP_EQ, now); tt_int_op(get_uptime(), OP_EQ, 3);
- /* Now try jumping forward. */ + /* Now try jumping forward and backward, without updating the monotonic + * clock. */ setup_capture_of_logs(LOG_NOTICE); - now += 3600; + now += 1800; update_current_time(now); expect_single_log_msg_containing( - "Your system clock just jumped 3600 seconds forward"); + "Your system clock just jumped 1800 seconds forward"); tt_int_op(approx_time(), OP_EQ, now); tt_int_op(get_uptime(), OP_EQ, 3); // no uptime change. mock_clean_saved_logs(); @@ -80,15 +97,38 @@ test_mainloop_update_time_jumps(void *arg) "Your system clock just jumped 600 seconds backward"); tt_int_op(approx_time(), OP_EQ, now); tt_int_op(get_uptime(), OP_EQ, 3); // no uptime change. + mock_clean_saved_logs();
/* uptime tracking should go normally now if the clock moves sensibly. */ now += 2; + mt_now += 2*BILLION; + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 5); + + /* If we skip forward by a few minutes but the monotonic clock agrees, + * we've just been idle: that counts as not worth warning about. */ + now += 1800; + mt_now += 1800*BILLION; + monotime_coarse_set_mock_time_nsec(mt_now); + update_current_time(now); + expect_no_log_entry(); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 5); // this doesn't count to uptime, though. + + /* If we skip forward by a long time, even if the clock agrees, it's + * idnless that counts. */ + now += 4000; + mt_now += 4000*BILLION; + monotime_coarse_set_mock_time_nsec(mt_now); update_current_time(now); + expect_single_log_msg_containing("Tor has been idle for 4000 seconds"); tt_int_op(approx_time(), OP_EQ, now); tt_int_op(get_uptime(), OP_EQ, 5);
done: teardown_capture_of_logs(); + monotime_disable_test_mocking(); }
#define MAINLOOP_TEST(name) \