May 2018 - tor-commits - lists.torproject.org

[webwml/master] fixup! Add new Tor Browser version: 7.5.4
by boklm＠torproject.org 09 May '18

09 May '18

commit 440e0b0441c2d8e23e8f2e9979e1128de9757407 Author: Nicolas Vigier <boklm(a)torproject.org> Date: Wed May 9 20:33:20 2018 +0200 fixup! Add new Tor Browser version: 7.5.4 --- projects/torbrowser/RecommendedTBBVersions | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/projects/torbrowser/RecommendedTBBVersions b/projects/torbrowser/RecommendedTBBVersions index 2fefb90c..3f39fa3e 100644 --- a/projects/torbrowser/RecommendedTBBVersions +++ b/projects/torbrowser/RecommendedTBBVersions @@ -3,6 +3,10 @@ "7.5.3-MacOS", "7.5.3-Linux", "7.5.3-Windows", +"7.5.4", +"7.5.4-MacOS", +"7.5.4-Linux", +"7.5.4-Windows", "8.0a5", "8.0a5-MacOS", "8.0a5-Linux",

1 0

[tor/master] Refactor to remove n_libevent_errors
by nickm＠torproject.org 09 May '18

09 May '18

commit b0e5757710c476a1a79dfc8a706f566ce515c495 Author: Nick Mathewson <nickm(a)torproject.org> Date: Thu May 3 12:44:00 2018 -0400 Refactor to remove n_libevent_errors We cleared this value in second_elapsed_callback. But what were we using it for? For detecting if Libevent returned EINVAL too often! We already have a way to detect too-frequent events, and that's with a ratelim_t. Refactor the code to use that instead. Closes ticket 26016. --- changes/ticket26016 | 4 ++++ src/or/main.c | 32 ++++++++++---------------------- 2 files changed, 14 insertions(+), 22 deletions(-) diff --git a/changes/ticket26016 b/changes/ticket26016 new file mode 100644 index 000000000..f0eb56d32 --- /dev/null +++ b/changes/ticket26016 @@ -0,0 +1,4 @@ + o Code simplification and refactoring: + - Use our standard rate-limiting code to deal with excessive libevent + failures, rather than the hand-rolled logic we had before. + Closes ticket 26016. diff --git a/src/or/main.c b/src/or/main.c index 8cdf27ed4..849101906 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -2493,8 +2493,6 @@ hs_service_callback(time_t now, const or_options_t *options) /** Timer: used to invoke second_elapsed_callback() once per second. */ static periodic_timer_t *second_timer = NULL; -/** Number of libevent errors in the last second: we die if we get too many. */ -static int n_libevent_errors = 0; /** Last time that second_elapsed_callback was called. */ static time_t current_second = 0; @@ -2512,8 +2510,6 @@ second_elapsed_callback(periodic_timer_t *timer, void *arg) (void)timer; (void)arg; - n_libevent_errors = 0; - /* log_notice(LD_GENERAL, "Tick."); */ now = time(NULL); update_approx_time(now); @@ -2558,21 +2554,6 @@ systemd_watchdog_callback(periodic_timer_t *timer, void *arg) } #endif /* defined(HAVE_SYSTEMD_209) */ -#ifndef _WIN32 -/** Called when a possibly ignorable libevent error occurs; ensures that we - * don't get into an infinite loop by ignoring too many errors from - * libevent. */ -static int -got_libevent_error(void) -{ - if (++n_libevent_errors > 8) { - log_err(LD_NET, "Too many libevent errors in one second; dying"); - return -1; - } - return 0; -} -#endif /* !defined(_WIN32) */ - #define UPTIME_CUTOFF_FOR_NEW_BANDWIDTH_TEST (6*60*60) /** Called when our IP address seems to have changed. at_interface @@ -2914,6 +2895,11 @@ do_main_loop(void) return run_main_loop_until_done(); } +#ifndef _WIN32 +/** Rate-limiter for EINVAL-type libevent warnings. */ +static ratelim_t libevent_error_ratelim = RATELIM_INIT(10); +#endif + /** * Run the main loop a single time. Return 0 for "exit"; -1 for "exit with * error", and 1 for "run this again." @@ -2979,9 +2965,12 @@ run_main_loop_once(void) return -1; #ifndef _WIN32 } else if (e == EINVAL) { - log_warn(LD_NET, "EINVAL from libevent: should you upgrade libevent?"); - if (got_libevent_error()) + log_fn_ratelim(&libevent_error_ratelim, LOG_WARN, LD_NET, + "EINVAL from libevent: should you upgrade libevent?"); + if (libevent_error_ratelim.n_calls_since_last_time > 8) { + log_err(LD_NET, "Too many libevent errors, too fast: dying"); return -1; + } #endif /* !defined(_WIN32) */ } else { tor_assert_nonfatal_once(! ERRNO_IS_EINPROGRESS(e)); @@ -3663,7 +3652,6 @@ tor_free_all(int postfork) should_init_bridge_stats = 1; dns_honesty_first_time = 1; heartbeat_callback_first_time = 1; - n_libevent_errors = 0; current_second = 0; if (!postfork) {

1 0

[tor/master] Merge branch 'ticket26016'
by nickm＠torproject.org 09 May '18

09 May '18

commit d972a8a9440d89143d58b5d0bd57155c38651ee6 Merge: f684b48b5 b0e575771 Author: Nick Mathewson <nickm(a)torproject.org> Date: Wed May 9 14:04:30 2018 -0400 Merge branch 'ticket26016' changes/ticket26016 | 4 ++++ src/or/main.c | 33 ++++++++++----------------------- 2 files changed, 14 insertions(+), 23 deletions(-) diff --cc src/or/main.c index 2497c277a,849101906..c4a42569d --- a/src/or/main.c +++ b/src/or/main.c @@@ -2495,73 -2493,8 +2495,70 @@@ hs_service_callback(time_t now, const o /** Timer: used to invoke second_elapsed_callback() once per second. */ static periodic_timer_t *second_timer = NULL; - /** Number of libevent errors in the last second: we die if we get too many. */ - static int n_libevent_errors = 0; - -/** Last time that second_elapsed_callback was called. */ +/** 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 + * time(). Check for clock jumps and track the total number of seconds we + * have been running. + */ +void +update_current_time(time_t now) +{ + if (PREDICT_LIKELY(now == current_second)) { + /* We call this function a lot. Most frequently, the current second + * will not have changed, so we just return. */ + return; + } + + const time_t seconds_elapsed = current_second ? (now - current_second) : 0; + + /* 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, &current_second_last_changed, sizeof(last_updated)); + monotime_coarse_get(&current_second_last_changed); + + /** How much clock jumping do we tolerate? */ +#define NUM_JUMPED_SECONDS_BEFORE_WARN 100 + + /** 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, + &current_second_last_changed); + const int monotime_sec_passed = monotime_msec_passed / 1000; + const int discrepancy = monotime_sec_passed - (int)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(discrepancy) > 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; + } + + update_approx_time(now); + current_second = now; +} /** Libevent callback: invoked once every second. */ static void @@@ -2576,18 -2509,13 +2573,16 @@@ second_elapsed_callback(periodic_timer_ (void)timer; (void)arg; - n_libevent_errors = 0; - - /* log_notice(LD_GENERAL, "Tick."); */ now = time(NULL); - update_approx_time(now); + + /* We don't need to do this once-per-second any more: time-updating is + * only in this callback _because it is a callback_. It should be fine + * to disable this callback, and the time will still get updated. + */ + update_current_time(now); /* the second has rolled over. check more stuff. */ - seconds_elapsed = current_second ? (int)(now - current_second) : 0; + // remove this once it's unneeded bytes_read = (size_t)(stats_n_bytes_read - stats_prev_n_read); bytes_written = (size_t)(stats_n_bytes_written - stats_prev_n_written); stats_prev_n_read = stats_n_bytes_read; @@@ -3721,10 -3652,7 +3709,9 @@@ tor_free_all(int postfork should_init_bridge_stats = 1; dns_honesty_first_time = 1; heartbeat_callback_first_time = 1; - n_libevent_errors = 0; current_second = 0; + memset(&current_second_last_changed, 0, + sizeof(current_second_last_changed)); if (!postfork) { release_lockfile();

1 0

[tor/master] spelling fix
by nickm＠torproject.org 09 May '18

09 May '18

commit 0abf09b2cea9e2af5a9d743b78447021213d02ab Author: Nick Mathewson <nickm(a)torproject.org> Date: Wed May 9 12:00:39 2018 -0400 spelling fix --- src/or/main.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/or/main.c b/src/or/main.c index b8827b947..ed1bf9aeb 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -2538,7 +2538,7 @@ update_current_time(time_t now) monotime_coarse_diff_msec32(&last_updated, &current_second_last_changed); const int monotime_sec_passed = monotime_msec_passed / 1000; - const int discrepency = monotime_sec_passed - (int)seconds_elapsed; + const int discrepancy = monotime_sec_passed - (int)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 @@ -2548,7 +2548,7 @@ update_current_time(time_t now) * 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; + const bool clock_jumped = abs(discrepancy) > 2; if (clock_jumped || seconds_elapsed >= NUM_IDLE_SECONDS_BEFORE_WARN) { circuit_note_clock_jumped(seconds_elapsed, ! clock_jumped);

1 0

[tor/master] Fix some clang warnings
by nickm＠torproject.org 09 May '18

09 May '18

commit 15ce5a3e5ab18f44172f1ada3fe1735f28a95c09 Author: Nick Mathewson <nickm(a)torproject.org> Date: Thu May 3 12:31:35 2018 -0400 Fix some clang warnings --- src/or/circuitbuild.c | 18 ++++++++++-------- src/or/circuitbuild.h | 2 +- src/or/main.c | 2 +- 3 files changed, 12 insertions(+), 10 deletions(-) diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c index 0617c2477..7f4504f6b 100644 --- a/src/or/circuitbuild.c +++ b/src/or/circuitbuild.c @@ -1138,22 +1138,24 @@ circuit_send_intermediate_onion_skin(origin_circuit_t *circ, * 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, bool was_idle) +circuit_note_clock_jumped(int64_t seconds_elapsed, bool was_idle) { int severity = server_mode(get_options()) ? LOG_WARN : LOG_NOTICE; if (was_idle) { - tor_log(severity, LD_GENERAL, "Tor has been idle for %d seconds; " - "assuming established circuits no longer work.", - seconds_elapsed); + tor_log(severity, LD_GENERAL, "Tor has been idle for "I64_FORMAT + " seconds; assuming established circuits no longer work.", + I64_PRINTF_ARG(seconds_elapsed)); } else { tor_log(severity, LD_GENERAL, - "Your system clock just jumped %d seconds %s; " + "Your system clock just jumped "I64_FORMAT" seconds %s; " "assuming established circuits no longer work.", - seconds_elapsed >=0 ? seconds_elapsed : -seconds_elapsed, + I64_PRINTF_ARG( + 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); + control_event_general_status(LOG_WARN, "CLOCK_JUMPED TIME="I64_FORMAT + " IDLE=%d", + I64_PRINTF_ARG(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 f3a8bbfc9..725d872d0 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, bool was_idle); +void circuit_note_clock_jumped(int64_t 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 b6035fa76..b8827b947 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -2538,7 +2538,7 @@ update_current_time(time_t now) monotime_coarse_diff_msec32(&last_updated, &current_second_last_changed); const int monotime_sec_passed = monotime_msec_passed / 1000; - const int discrepency = monotime_sec_passed - seconds_elapsed; + const int discrepency = monotime_sec_passed - (int)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

1 0

[tor/master] Merge branch 'ticket26009'
by nickm＠torproject.org 09 May '18

09 May '18

commit f684b48b5be5515395846d089a386167e76f895a Merge: 61d5ce83a 0abf09b2c Author: Nick Mathewson <nickm(a)torproject.org> Date: Wed May 9 14:01:08 2018 -0400 Merge branch 'ticket26009' changes/ticket26009 | 9 +++ src/or/circuitbuild.c | 30 ++++++---- src/or/circuitbuild.h | 2 +- src/or/connection.c | 3 +- src/or/main.c | 90 ++++++++++++++++++++++++------ src/or/main.h | 2 + src/or/periodic.c | 2 + src/test/include.am | 1 + src/test/test.c | 1 + src/test/test.h | 1 + src/test/test_mainloop.c | 142 +++++++++++++++++++++++++++++++++++++++++++++++ 11 files changed, 255 insertions(+), 28 deletions(-)

1 0

[tor/master] Add update_current_time() calls to periodic and event-driven callbacks
by nickm＠torproject.org 09 May '18

09 May '18

commit 83137275a77eedbf177fbdb298c89a346abe2243 Author: Nick Mathewson <nickm(a)torproject.org> Date: Thu May 3 10:56:49 2018 -0400 Add update_current_time() calls to periodic and event-driven callbacks This is part of 26009, where we're going to keep track of the current time and its jumps without having to do so in second_elapsed_callback. --- src/or/connection.c | 3 ++- src/or/main.c | 1 + src/or/periodic.c | 2 ++ 3 files changed, 5 insertions(+), 1 deletion(-) diff --git a/src/or/connection.c b/src/or/connection.c index c2673ade1..df36d4211 100644 --- a/src/or/connection.c +++ b/src/or/connection.c @@ -3439,7 +3439,7 @@ int connection_handle_read(connection_t *conn) { int res; - + update_current_time(time(NULL)); res = connection_handle_read_impl(conn); return res; } @@ -3982,6 +3982,7 @@ int connection_handle_write(connection_t *conn, int force) { int res; + update_current_time(time(NULL)); conn->in_connection_handle_write = 1; res = connection_handle_write_impl(conn, force); conn->in_connection_handle_write = 0; diff --git a/src/or/main.c b/src/or/main.c index 6ecc340a9..d773c8e29 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -3047,6 +3047,7 @@ signal_callback(evutil_socket_t fd, short events, void *arg) (void)fd; (void)events; + update_current_time(time(NULL)); process_signal(sig); } diff --git a/src/or/periodic.c b/src/or/periodic.c index 76aa418b3..92fa677f8 100644 --- a/src/or/periodic.c +++ b/src/or/periodic.c @@ -14,6 +14,7 @@ #include "or.h" #include "compat_libevent.h" #include "config.h" +#include "main.h" #include "periodic.h" /** We disable any interval greater than this number of seconds, on the @@ -48,6 +49,7 @@ periodic_event_dispatch(mainloop_event_t *ev, void *data) } time_t now = time(NULL); + update_current_time(now); const or_options_t *options = get_options(); // log_debug(LD_GENERAL, "Dispatching %s", event->name); int r = event->fn(now, options);

1 0

[tor/master] Move the "update the current second" code from second_elapsed_callback
by nickm＠torproject.org 09 May '18

09 May '18

commit b0598f2a124d0b75aa3e1d06c8ed59cc6142a235 Author: Nick Mathewson <nickm(a)torproject.org> Date: Thu May 3 10:35:49 2018 -0400 Move the "update the current second" code from second_elapsed_callback This now happens in a new function, with the intent of having it invoked from our callbacks. This is one step on the way to 26009. --- src/or/main.c | 50 +++++++++++++++++++++++++++++++++++--------------- src/or/main.h | 2 ++ 2 files changed, 37 insertions(+), 15 deletions(-) diff --git a/src/or/main.c b/src/or/main.c index 8cdf27ed4..6ecc340a9 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -2495,9 +2495,41 @@ hs_service_callback(time_t now, const or_options_t *options) static periodic_timer_t *second_timer = NULL; /** Number of libevent errors in the last second: we die if we get too many. */ static int n_libevent_errors = 0; -/** Last time that second_elapsed_callback was called. */ + +/** Last time that update_current_time was called. */ static time_t current_second = 0; +/** + * Set the current time to "now", which should be the value returned by + * time(). Check for clock jumps and track the total number of seconds we + * have been running. + */ +void +update_current_time(time_t now) +{ + if (PREDICT_LIKELY(now == current_second)) { + /* We call this function a lot. Most frequently, the current second + * will not have changed, so we just return. */ + return; + } + + 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. */ +#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); + } else if (seconds_elapsed > 0) { + stats_n_seconds_working += seconds_elapsed; + } + + update_approx_time(now); + current_second = now; +} + /** Libevent callback: invoked once every second. */ static void second_elapsed_callback(periodic_timer_t *timer, void *arg) @@ -2508,7 +2540,6 @@ second_elapsed_callback(periodic_timer_t *timer, void *arg) time_t now; size_t bytes_written; size_t bytes_read; - int seconds_elapsed; (void)timer; (void)arg; @@ -2516,10 +2547,10 @@ second_elapsed_callback(periodic_timer_t *timer, void *arg) /* log_notice(LD_GENERAL, "Tick."); */ now = time(NULL); - update_approx_time(now); + update_current_time(now); /* the second has rolled over. check more stuff. */ - seconds_elapsed = current_second ? (int)(now - current_second) : 0; + // remove this once it's unneeded bytes_read = (size_t)(stats_n_bytes_read - stats_prev_n_read); bytes_written = (size_t)(stats_n_bytes_written - stats_prev_n_written); stats_prev_n_read = stats_n_bytes_read; @@ -2531,18 +2562,7 @@ second_elapsed_callback(periodic_timer_t *timer, void *arg) control_event_circ_bandwidth_used(); control_event_circuit_cell_stats(); -/** If more than this many seconds have elapsed, probably the clock - * jumped: doesn't count. */ -#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); - } else if (seconds_elapsed > 0) - stats_n_seconds_working += seconds_elapsed; - run_scheduled_events(now); - - current_second = now; /* remember which second it is, for next time */ } #ifdef HAVE_SYSTEMD_209 diff --git a/src/or/main.h b/src/or/main.h index a312b51e0..45d6b4478 100644 --- a/src/or/main.h +++ b/src/or/main.h @@ -66,6 +66,8 @@ void reschedule_dirvote(const or_options_t *options); void mainloop_schedule_postloop_cleanup(void); void rescan_periodic_events(const or_options_t *options); +void update_current_time(time_t now); + MOCK_DECL(long,get_uptime,(void)); MOCK_DECL(void,reset_uptime,(void));

1 0

[tor/master] Distinguish true clock jumps from idleness
by nickm＠torproject.org 09 May '18

09 May '18

commit 285e7c98fdca8eda97683c0b96f86645ee3f0546 Author: Nick Mathewson <nickm(a)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 seconds_elapsed. Assume - * something has also gone wrong with our network: notify the user, - * and abandon all not-yet-used circuits. */ +/** Our clock just jumped by seconds_elapsed. If was_idle 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, &current_second_last_changed, sizeof(last_updated)); + monotime_coarse_get(&current_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, + &current_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(&current_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) \

1 0

[tor/master] Basic unit tests for update_current_time().
by nickm＠torproject.org 09 May '18

09 May '18

commit 1d16b7124f8c5cdcd04599aac62fb903862acdee Author: Nick Mathewson <nickm(a)torproject.org> Date: Thu May 3 10:53:19 2018 -0400 Basic unit tests for update_current_time(). This function is about to get more complicated, so we should track how it's working. --- src/test/include.am | 1 + src/test/test.c | 1 + src/test/test.h | 1 + src/test/test_mainloop.c | 102 +++++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 105 insertions(+) diff --git a/src/test/include.am b/src/test/include.am index eb61d7489..aa386b5fa 100644 --- a/src/test/include.am +++ b/src/test/include.am @@ -139,6 +139,7 @@ src_test_test_SOURCES = \ src/test/test_keypin.c \ src/test/test_link_handshake.c \ src/test/test_logging.c \ + src/test/test_mainloop.c \ src/test/test_microdesc.c \ src/test/test_nodelist.c \ src/test/test_oom.c \ diff --git a/src/test/test.c b/src/test/test.c index 2963f169c..8951b0f73 100644 --- a/src/test/test.c +++ b/src/test/test.c @@ -859,6 +859,7 @@ struct testgroup_t testgroups[] = { { "introduce/", introduce_tests }, { "keypin/", keypin_tests }, { "link-handshake/", link_handshake_tests }, + { "mainloop/", mainloop_tests }, { "nodelist/", nodelist_tests }, { "oom/", oom_tests }, { "oos/", oos_tests }, diff --git a/src/test/test.h b/src/test/test.h index 15965ccaf..c9200a937 100644 --- a/src/test/test.h +++ b/src/test/test.h @@ -234,6 +234,7 @@ extern struct testcase_t introduce_tests[]; extern struct testcase_t keypin_tests[]; extern struct testcase_t link_handshake_tests[]; extern struct testcase_t logging_tests[]; +extern struct testcase_t mainloop_tests[]; extern struct testcase_t microdesc_tests[]; extern struct testcase_t nodelist_tests[]; extern struct testcase_t oom_tests[]; diff --git a/src/test/test_mainloop.c b/src/test/test_mainloop.c new file mode 100644 index 000000000..2f8a7bca6 --- /dev/null +++ b/src/test/test_mainloop.c @@ -0,0 +1,102 @@ +/* Copyright (c) 2018, The Tor Project, Inc. */ +/* See LICENSE for licensing information */ + +/** + * \file test_mainloop.c + * \brief Tests for functions closely related to the Tor main loop + */ + +#include "test.h" +#include "log_test_helpers.h" + +#include "or.h" +#include "main.h" + +static void +test_mainloop_update_time_normal(void *arg) +{ + (void)arg; + + /* This time is in the past as of when this test was written. */ + time_t now = 1525272090; + reset_uptime(); + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 0); + + update_current_time(now); // Same time as before is a no-op. + tt_int_op(get_uptime(), OP_EQ, 0); + + now += 1; + 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. + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 3); + + now -= 1; // a one-second hop backwards is also unremarkable. + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); // it changes the approx time... + tt_int_op(get_uptime(), OP_EQ, 3); // but it doesn't roll back our uptime + + done: + ; +} + +static void +test_mainloop_update_time_jumps(void *arg) +{ + (void)arg; + + /* This time is in the past as of when this test was written. */ + time_t now = 220897152; + reset_uptime(); + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 0); + + /* Put some uptime on the clock.. */ + now += 3; + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 3); + + /* Now try jumping forward. */ + setup_capture_of_logs(LOG_NOTICE); + now += 3600; + update_current_time(now); + expect_single_log_msg_containing( + "Your system clock just jumped 3600 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(); + + now -= 600; + update_current_time(now); + expect_single_log_msg_containing( + "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. + + /* uptime tracking should go normally now if the clock moves sensibly. */ + now += 2; + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 5); + + done: + teardown_capture_of_logs(); +} + +#define MAINLOOP_TEST(name) \ + { #name, test_mainloop_## name , TT_FORK, NULL, NULL } + +struct testcase_t mainloop_tests[] = { + MAINLOOP_TEST(update_time_normal), + MAINLOOP_TEST(update_time_jumps), + END_OF_TESTCASES +}; +

1 0