Merge branch 'ticket26009'

This commit is contained in:
Nick Mathewson 2018-05-09 14:01:08 -04:00
commit f684b48b5b
11 changed files with 255 additions and 28 deletions

9
changes/ticket26009 Normal file
View File

@ -0,0 +1,9 @@
o Minor features (mainloop):
- Move responsibility for
keeping track of Tor's uptime
from a nce-per-second callback to a callback that is only scheduled as
needed. Once enough items are removed from our once-per-second
callback, we can eliminate it entirely to conserve CPU when idle.
Closes ticket
26009.

View File

@ -1130,19 +1130,29 @@ 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(int64_t 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 "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 "I64_FORMAT" seconds %s; "
"assuming established circuits no longer work.",
I64_PRINTF_ARG(
seconds_elapsed >=0 ? seconds_elapsed : -seconds_elapsed),
seconds_elapsed >=0 ? "forward" : "backward");
}
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",

View File

@ -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(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,

View File

@ -3440,7 +3440,7 @@ int
connection_handle_read(connection_t *conn)
{
int res;
update_current_time(time(NULL));
res = connection_handle_read_impl(conn);
return res;
}
@ -3983,6 +3983,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;

View File

@ -2497,8 +2497,71 @@ 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;
/** 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
@ -2510,18 +2573,21 @@ 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;
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;
@ -2533,18 +2599,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
@ -3029,6 +3084,7 @@ signal_callback(evutil_socket_t fd, short events, void *arg)
(void)fd;
(void)events;
update_current_time(time(NULL));
process_signal(sig);
}
@ -3667,6 +3723,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();

View File

@ -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));

View File

@ -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);

View File

@ -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 \

View File

@ -880,6 +880,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 },

View File

@ -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[];

142
src/test/test_mainloop.c Normal file
View File

@ -0,0 +1,142 @@
/* 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 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);
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;
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);
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:
monotime_disable_test_mocking();
}
static void
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);
tt_int_op(get_uptime(), OP_EQ, 0);
/* 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 and backward, without updating the monotonic
* clock. */
setup_capture_of_logs(LOG_NOTICE);
now += 1800;
update_current_time(now);
expect_single_log_msg_containing(
"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();
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.
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) \
{ #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
};