From 5bd2060054095f590559beb57b46c353476084f0 Mon Sep 17 00:00:00 2001 From: Taylor Yu Date: Thu, 3 May 2018 15:24:31 -0500 Subject: [PATCH 1/7] tests: Add "now" param to construct_consensus() construct_consensus() in test_routerlist.c created votes using a timestamp from time(). Tests that called construct_consensus() might have nondeterministic results if they rely on time() not changing too much on two successive calls. Neither existing of the two existing tests that calls construct_consensus is likely to have a failure due to this problem. --- src/test/test_routerlist.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/test/test_routerlist.c b/src/test/test_routerlist.c index 7fed65628..88894391b 100644 --- a/src/test/test_routerlist.c +++ b/src/test/test_routerlist.c @@ -37,7 +37,7 @@ #include "test_dir_common.h" #include "log_test_helpers.h" -void construct_consensus(char **consensus_text_md); +void construct_consensus(char **consensus_text_md, time_t now); static authority_cert_t *mock_cert; @@ -136,7 +136,7 @@ test_routerlist_launch_descriptor_downloads(void *arg) } void -construct_consensus(char **consensus_text_md) +construct_consensus(char **consensus_text_md, time_t now) { networkstatus_t *vote = NULL; networkstatus_t *v1 = NULL, *v2 = NULL, *v3 = NULL; @@ -144,7 +144,6 @@ construct_consensus(char **consensus_text_md) authority_cert_t *cert1=NULL, *cert2=NULL, *cert3=NULL; crypto_pk_t *sign_skey_1=NULL, *sign_skey_2=NULL, *sign_skey_3=NULL; crypto_pk_t *sign_skey_leg=NULL; - time_t now = time(NULL); smartlist_t *votes = NULL; int n_vrs; @@ -259,7 +258,7 @@ test_router_pick_directory_server_impl(void *arg) rs = router_pick_directory_server_impl(V3_DIRINFO, (const int) 0, NULL); tt_ptr_op(rs, OP_EQ, NULL); - construct_consensus(&consensus_text_md); + construct_consensus(&consensus_text_md, now); tt_assert(consensus_text_md); con_md = networkstatus_parse_vote_from_string(consensus_text_md, NULL, NS_TYPE_CONSENSUS); @@ -453,6 +452,7 @@ test_directory_guard_fetch_with_no_dirinfo(void *arg) int retval; char *consensus_text_md = NULL; or_options_t *options = get_options_mutable(); + time_t now = time(NULL); (void) arg; @@ -496,7 +496,7 @@ test_directory_guard_fetch_with_no_dirinfo(void *arg) conn->requested_resource = tor_strdup("ns"); /* Construct a consensus */ - construct_consensus(&consensus_text_md); + construct_consensus(&consensus_text_md, now); tt_assert(consensus_text_md); /* Place the consensus in the dirconn */ @@ -507,7 +507,7 @@ test_directory_guard_fetch_with_no_dirinfo(void *arg) args.body_len = strlen(consensus_text_md); /* Update approx time so that the consensus is considered live */ - update_approx_time(time(NULL)+1010); + update_approx_time(now+1010); setup_capture_of_logs(LOG_DEBUG); From c223377ce60ed07a11e0c3b5af29601722b07bac Mon Sep 17 00:00:00 2001 From: Taylor Yu Date: Thu, 3 May 2018 20:57:07 -0500 Subject: [PATCH 2/7] Make clock_skew_warning() mockable --- src/or/connection.c | 8 ++++---- src/or/connection.h | 7 ++++--- 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/src/or/connection.c b/src/or/connection.c index 4361e1ca0..fa9881cb8 100644 --- a/src/or/connection.c +++ b/src/or/connection.c @@ -5233,10 +5233,10 @@ connection_free_all(void) * that we had more faith in and therefore the warning level should have higher * severity. */ -void -clock_skew_warning(const connection_t *conn, long apparent_skew, int trusted, - log_domain_mask_t domain, const char *received, - const char *source) +MOCK_IMPL(void, +clock_skew_warning, (const connection_t *conn, long apparent_skew, int trusted, + log_domain_mask_t domain, const char *received, + const char *source)) { char dbuf[64]; char *ext_source = NULL, *warn = NULL; diff --git a/src/or/connection.h b/src/or/connection.h index a2dce2435..ad3129c9d 100644 --- a/src/or/connection.h +++ b/src/or/connection.h @@ -254,9 +254,10 @@ void assert_connection_ok(connection_t *conn, time_t now); int connection_or_nonopen_was_started_here(or_connection_t *conn); void connection_dump_buffer_mem_stats(int severity); -void clock_skew_warning(const connection_t *conn, long apparent_skew, - int trusted, log_domain_mask_t domain, - const char *received, const char *source); +MOCK_DECL(void, clock_skew_warning, + (const connection_t *conn, long apparent_skew, int trusted, + log_domain_mask_t domain, const char *received, + const char *source)); /** Check if a connection is on the way out so the OOS handler doesn't try * to kill more than it needs. */ From be8306c1fb344d9ff3c03b5dc1bb8815706d4ae7 Mon Sep 17 00:00:00 2001 From: Taylor Yu Date: Thu, 3 May 2018 21:49:19 -0500 Subject: [PATCH 3/7] Add expect_no_log_msg_containing() --- src/test/log_test_helpers.h | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/test/log_test_helpers.h b/src/test/log_test_helpers.h index 70c584eb3..f5bbfcf3f 100644 --- a/src/test/log_test_helpers.h +++ b/src/test/log_test_helpers.h @@ -85,6 +85,10 @@ void mock_dump_saved_logs(void); assert_log_predicate(!mock_saved_log_has_message(str), \ "expected log to not contain " # str); +#define expect_no_log_msg_containing(str) \ + assert_log_predicate(!mock_saved_log_has_message_containing(str), \ + "expected log to not contain " # str); + #define expect_log_severity(severity) \ assert_log_predicate(mock_saved_log_has_severity(severity), \ "expected log to contain severity " # severity); From 4921670a8c155965e919debc3048a76b3e868802 Mon Sep 17 00:00:00 2001 From: Taylor Yu Date: Thu, 3 May 2018 21:53:24 -0500 Subject: [PATCH 4/7] Test early-consensus clock skew warnings --- src/test/test_routerlist.c | 105 +++++++++++++++++++++++++++++++++++++ 1 file changed, 105 insertions(+) diff --git a/src/test/test_routerlist.c b/src/test/test_routerlist.c index 88894391b..6dd58d313 100644 --- a/src/test/test_routerlist.c +++ b/src/test/test_routerlist.c @@ -599,11 +599,111 @@ test_routerlist_router_is_already_dir_fetching(void *arg) #undef TEST_ADDR_STR #undef TEST_DIR_PORT +static long mock_apparent_skew = 0; + +/** Store apparent_skew and assert that the other arguments are as + * expected. */ +static void +mock_clock_skew_warning(const connection_t *conn, long apparent_skew, + int trusted, log_domain_mask_t domain, + const char *received, const char *source) +{ + (void)conn; + mock_apparent_skew = apparent_skew; + tt_int_op(trusted, OP_EQ, 1); + tt_int_op(domain, OP_EQ, LD_GENERAL); + tt_str_op(received, OP_EQ, "microdesc flavor consensus"); + tt_str_op(source, OP_EQ, "CONSENSUS"); + done: + ; +} + +/** Do common setup for test_timely_consensus() and + * test_early_consensus(). Call networkstatus_set_current_consensus() + * on a constructed consensus and with an appropriately-modified + * approx_time. Callers expect presence or absence of appropriate log + * messages and control events. */ +static int +test_skew_common(void *arg, time_t now, unsigned long *offset) +{ + char *consensus = NULL; + int retval = 0; + + *offset = strtoul(arg, NULL, 10); + + /* Initialize the SRV subsystem */ + MOCK(get_my_v3_authority_cert, get_my_v3_authority_cert_m); + mock_cert = authority_cert_parse_from_string(AUTHORITY_CERT_1, NULL); + sr_init(0); + UNMOCK(get_my_v3_authority_cert); + + construct_consensus(&consensus, now); + tt_assert(consensus); + + update_approx_time(now + *offset); + + mock_apparent_skew = 0; + /* Caller will call UNMOCK() */ + MOCK(clock_skew_warning, mock_clock_skew_warning); + /* Caller will call teardown_capture_of_logs() */ + setup_capture_of_logs(LOG_WARN); + retval = networkstatus_set_current_consensus(consensus, "microdesc", 0, + NULL); + + done: + tor_free(consensus); + return retval; +} + +/** Test non-early consensus */ +static void +test_timely_consensus(void *arg) +{ + time_t now = time(NULL); + unsigned long offset = 0; + int retval = 0; + + retval = test_skew_common(arg, now, &offset); + (void)offset; + expect_no_log_msg_containing("behind the time published in the consensus"); + tt_int_op(retval, OP_EQ, 0); + tt_int_op(mock_apparent_skew, OP_EQ, 0); + done: + teardown_capture_of_logs(); + UNMOCK(clock_skew_warning); +} + +/** Test early consensus */ +static void +test_early_consensus(void *arg) +{ + time_t now = time(NULL); + unsigned long offset = 0; + int retval = 0; + + retval = test_skew_common(arg, now, &offset); + /* Can't use expect_single_log_msg() because of unrecognized authorities */ + expect_log_msg_containing("behind the time published in the consensus"); + tt_int_op(retval, OP_EQ, 0); + /* This depends on construct_consensus() setting valid_after=now+1000 */ + tt_int_op(mock_apparent_skew, OP_EQ, offset - 1000); + done: + teardown_capture_of_logs(); + UNMOCK(clock_skew_warning); +} + #define NODE(name, flags) \ { #name, test_routerlist_##name, (flags), NULL, NULL } #define ROUTER(name,flags) \ { #name, test_router_##name, (flags), NULL, NULL } +#define TIMELY(name, arg) \ + { name, test_timely_consensus, TT_FORK, &passthrough_setup, \ + (char *)(arg) } +#define EARLY(name, arg) \ + { name, test_early_consensus, TT_FORK, &passthrough_setup, \ + (char *)(arg) } + struct testcase_t routerlist_tests[] = { NODE(initiate_descriptor_downloads, 0), NODE(launch_descriptor_downloads, 0), @@ -611,6 +711,11 @@ struct testcase_t routerlist_tests[] = { ROUTER(pick_directory_server_impl, TT_FORK), { "directory_guard_fetch_with_no_dirinfo", test_directory_guard_fetch_with_no_dirinfo, TT_FORK, NULL, NULL }, + /* These depend on construct_consensus() setting valid_after=now+1000 */ + TIMELY("timely_consensus1", "1010"), + TIMELY("timely_consensus2", "1000"), + TIMELY("timely_consensus3", "940"), + EARLY("early_consensus1", "939"), END_OF_TESTCASES }; From 0b80a0e500d5132ca4dd77403b5a4c7f23f26a80 Mon Sep 17 00:00:00 2001 From: Taylor Yu Date: Tue, 1 May 2018 18:13:37 -0500 Subject: [PATCH 5/7] Factor out warn_early_consensus() Factor out the early consensus warning code from networkstatus_set_current_consensus() into a new function warn_early_consensus(). --- src/or/networkstatus.c | 62 +++++++++++++++++++++++++++++------------- src/or/networkstatus.h | 2 ++ 2 files changed, 45 insertions(+), 19 deletions(-) diff --git a/src/or/networkstatus.c b/src/or/networkstatus.c index 44c0638c2..ace9fc94a 100644 --- a/src/or/networkstatus.c +++ b/src/or/networkstatus.c @@ -1751,6 +1751,48 @@ handle_missing_protocol_warning(const networkstatus_t *c, handle_missing_protocol_warning_impl(c, 1); } +/** + * Check whether we received a consensus that appears to be coming + * from the future. Because we implicitly trust the directory + * authorities' idea of the current time, we produce a warning if we + * get an early consensus. + * + * If we got a consensus that is time stamped far in the past, that + * could simply have come from a stale cache. Possible ways to get a + * consensus from the future can include: + * + * - enough directory authorities have wrong clocks + * - directory authorities collude to produce misleading time stamps + * - our own clock is wrong (this is by far the most likely) + * + * We neglect highly improbable scenarios that involve actual time + * travel. + */ +STATIC void +warn_early_consensus(const networkstatus_t *c, const char *flavor, + time_t now) +{ +/** If a consensus appears more than this many seconds before its declared + * valid-after time, declare that our clock is skewed. */ +#define EARLY_CONSENSUS_NOTICE_SKEW 60 + + if (now < c->valid_after - EARLY_CONSENSUS_NOTICE_SKEW) { + char tbuf[ISO_TIME_LEN+1]; + char dbuf[64]; + long delta = now - c->valid_after; + char *flavormsg = NULL; + format_iso_time(tbuf, c->valid_after); + format_time_interval(dbuf, sizeof(dbuf), delta); + log_warn(LD_GENERAL, "Our clock is %s behind the time published in the " + "consensus network status document (%s UTC). Tor needs an " + "accurate clock to work correctly. Please check your time and " + "date settings!", dbuf, tbuf); + tor_asprintf(&flavormsg, "%s flavor consensus", flavor); + clock_skew_warning(NULL, delta, 1, LD_GENERAL, flavormsg, "CONSENSUS"); + tor_free(flavormsg); + } +} + /** Try to replace the current cached v3 networkstatus with the one in * consensus. If we don't have enough certificates to validate it, * store it in consensus_waiting_for_certs and launch a certificate fetch. @@ -2053,25 +2095,7 @@ networkstatus_set_current_consensus(const char *consensus, write_str_to_file(consensus_fname, consensus, 0); } -/** If a consensus appears more than this many seconds before its declared - * valid-after time, declare that our clock is skewed. */ -#define EARLY_CONSENSUS_NOTICE_SKEW 60 - - if (now < c->valid_after - EARLY_CONSENSUS_NOTICE_SKEW) { - char tbuf[ISO_TIME_LEN+1]; - char dbuf[64]; - long delta = now - c->valid_after; - char *flavormsg = NULL; - format_iso_time(tbuf, c->valid_after); - format_time_interval(dbuf, sizeof(dbuf), delta); - log_warn(LD_GENERAL, "Our clock is %s behind the time published in the " - "consensus network status document (%s UTC). Tor needs an " - "accurate clock to work correctly. Please check your time and " - "date settings!", dbuf, tbuf); - tor_asprintf(&flavormsg, "%s flavor consensus", flavor); - clock_skew_warning(NULL, delta, 1, LD_GENERAL, flavormsg, "CONSENSUS"); - tor_free(flavormsg); - } + warn_early_consensus(c, flavor, now); /* We got a new consesus. Reset our md fetch fail cache */ microdesc_reset_outdated_dirservers_list(); diff --git a/src/or/networkstatus.h b/src/or/networkstatus.h index 0c325959d..b133f43dc 100644 --- a/src/or/networkstatus.h +++ b/src/or/networkstatus.h @@ -153,6 +153,8 @@ int any_client_port_set(const or_options_t *options); #ifdef TOR_UNIT_TESTS STATIC int networkstatus_set_current_consensus_from_ns(networkstatus_t *c, const char *flavor); +STATIC void warn_early_consensus(const networkstatus_t *c, const char *flavor, + time_t now); extern networkstatus_t *current_ns_consensus; extern networkstatus_t *current_md_consensus; #endif /* defined(TOR_UNIT_TESTS) */ From d6948bc7764dca7644b331aaf37453b328239e6d Mon Sep 17 00:00:00 2001 From: Taylor Yu Date: Thu, 3 May 2018 22:11:44 -0500 Subject: [PATCH 6/7] Deindent warn_early_consensus() Remove one level of indentation by returning early from the function. --- src/or/networkstatus.c | 31 ++++++++++++++++--------------- 1 file changed, 16 insertions(+), 15 deletions(-) diff --git a/src/or/networkstatus.c b/src/or/networkstatus.c index ace9fc94a..d1c217119 100644 --- a/src/or/networkstatus.c +++ b/src/or/networkstatus.c @@ -1772,25 +1772,26 @@ STATIC void warn_early_consensus(const networkstatus_t *c, const char *flavor, time_t now) { + char tbuf[ISO_TIME_LEN+1]; + char dbuf[64]; + long delta = now - c->valid_after; + char *flavormsg = NULL; + /** If a consensus appears more than this many seconds before its declared * valid-after time, declare that our clock is skewed. */ #define EARLY_CONSENSUS_NOTICE_SKEW 60 + if (now >= c->valid_after - EARLY_CONSENSUS_NOTICE_SKEW) + return; - if (now < c->valid_after - EARLY_CONSENSUS_NOTICE_SKEW) { - char tbuf[ISO_TIME_LEN+1]; - char dbuf[64]; - long delta = now - c->valid_after; - char *flavormsg = NULL; - format_iso_time(tbuf, c->valid_after); - format_time_interval(dbuf, sizeof(dbuf), delta); - log_warn(LD_GENERAL, "Our clock is %s behind the time published in the " - "consensus network status document (%s UTC). Tor needs an " - "accurate clock to work correctly. Please check your time and " - "date settings!", dbuf, tbuf); - tor_asprintf(&flavormsg, "%s flavor consensus", flavor); - clock_skew_warning(NULL, delta, 1, LD_GENERAL, flavormsg, "CONSENSUS"); - tor_free(flavormsg); - } + format_iso_time(tbuf, c->valid_after); + format_time_interval(dbuf, sizeof(dbuf), delta); + log_warn(LD_GENERAL, "Our clock is %s behind the time published in the " + "consensus network status document (%s UTC). Tor needs an " + "accurate clock to work correctly. Please check your time and " + "date settings!", dbuf, tbuf); + tor_asprintf(&flavormsg, "%s flavor consensus", flavor); + clock_skew_warning(NULL, delta, 1, LD_GENERAL, flavormsg, "CONSENSUS"); + tor_free(flavormsg); } /** Try to replace the current cached v3 networkstatus with the one in From de343b4e421c0c651eaac1d52d23c3c792bee73a Mon Sep 17 00:00:00 2001 From: Taylor Yu Date: Fri, 4 May 2018 17:16:06 -0500 Subject: [PATCH 7/7] Improve tolerance for dirauths with skewed clocks Previously, an authority with a clock more than 60 seconds ahead could cause a client with a correct clock to warn that the client's clock was behind. Now the clocks of a majority of directory authorities have to be ahead of the client before this warning will occur. Relax the early-consensus check so that a client's clock must be 60 seconds behind the earliest time that a given sufficiently-signed consensus could possibly be available. Add a new unit test that calls warn_early_consensus() directly. Fixes bug 25756; bugfix on 0.2.2.25-alpha. --- changes/bug25756 | 7 +++++ src/or/networkstatus.c | 14 +++++++-- src/test/test_routerlist.c | 64 ++++++++++++++++++++++++++++++++++++-- 3 files changed, 79 insertions(+), 6 deletions(-) create mode 100644 changes/bug25756 diff --git a/changes/bug25756 b/changes/bug25756 new file mode 100644 index 000000000..ff5ac0391 --- /dev/null +++ b/changes/bug25756 @@ -0,0 +1,7 @@ + o Minor bugfixes (error reporting): + - Improve tolerance for directory authorities with skewed clocks. + Previously, an authority with a clock more than 60 seconds ahead + could cause a client with a correct clock to warn that the + client's clock was behind. Now the clocks of a majority of + directory authorities have to be ahead of the client before this + warning will occur. Fixes bug 25756; bugfix on 0.2.2.25-alpha. diff --git a/src/or/networkstatus.c b/src/or/networkstatus.c index d1c217119..51b2f4af1 100644 --- a/src/or/networkstatus.c +++ b/src/or/networkstatus.c @@ -1777,10 +1777,18 @@ warn_early_consensus(const networkstatus_t *c, const char *flavor, long delta = now - c->valid_after; char *flavormsg = NULL; -/** If a consensus appears more than this many seconds before its declared - * valid-after time, declare that our clock is skewed. */ +/** If a consensus appears more than this many seconds before it could + * possibly be a sufficiently-signed consensus, declare that our clock + * is skewed. */ #define EARLY_CONSENSUS_NOTICE_SKEW 60 - if (now >= c->valid_after - EARLY_CONSENSUS_NOTICE_SKEW) + + /* We assume that if a majority of dirauths have accurate clocks, + * the earliest that a dirauth with a skewed clock could possibly + * publish a sufficiently-signed consensus is (valid_after - + * dist_seconds). Before that time, the skewed dirauth would be + * unable to obtain enough authority signatures for the consensus to + * be valid. */ + if (now >= c->valid_after - c->dist_seconds - EARLY_CONSENSUS_NOTICE_SKEW) return; format_iso_time(tbuf, c->valid_after); diff --git a/src/test/test_routerlist.c b/src/test/test_routerlist.c index 6dd58d313..701227c1c 100644 --- a/src/test/test_routerlist.c +++ b/src/test/test_routerlist.c @@ -692,6 +692,62 @@ test_early_consensus(void *arg) UNMOCK(clock_skew_warning); } +/** Test warn_early_consensus(), expecting no warning */ +static void +test_warn_early_consensus_no(const networkstatus_t *c, time_t now, + long offset) +{ + mock_apparent_skew = 0; + setup_capture_of_logs(LOG_WARN); + warn_early_consensus(c, "microdesc", now + offset); + expect_no_log_msg_containing("behind the time published in the consensus"); + tt_int_op(mock_apparent_skew, OP_EQ, 0); + done: + teardown_capture_of_logs(); +} + +/** Test warn_early_consensus(), expecting a warning */ +static void +test_warn_early_consensus_yes(const networkstatus_t *c, time_t now, + long offset) +{ + mock_apparent_skew = 0; + setup_capture_of_logs(LOG_WARN); + warn_early_consensus(c, "microdesc", now + offset); + /* Can't use expect_single_log_msg() because of unrecognized authorities */ + expect_log_msg_containing("behind the time published in the consensus"); + tt_int_op(mock_apparent_skew, OP_EQ, offset); + done: + teardown_capture_of_logs(); +} + +/** + * Test warn_early_consensus() directly, checking both the non-warning + * case (consensus is not early) and the warning case (consensus is + * early). Depends on EARLY_CONSENSUS_NOTICE_SKEW=60. + */ +static void +test_warn_early_consensus(void *arg) +{ + networkstatus_t *c = NULL; + time_t now = time(NULL); + + (void)arg; + c = tor_malloc_zero(sizeof *c); + c->valid_after = now; + c->dist_seconds = 300; + mock_apparent_skew = 0; + MOCK(clock_skew_warning, mock_clock_skew_warning); + test_warn_early_consensus_no(c, now, 60); + test_warn_early_consensus_no(c, now, 0); + test_warn_early_consensus_no(c, now, -60); + test_warn_early_consensus_no(c, now, -360); + test_warn_early_consensus_yes(c, now, -361); + test_warn_early_consensus_yes(c, now, -600); + UNMOCK(clock_skew_warning); + tor_free(c); +} + #define NODE(name, flags) \ { #name, test_routerlist_##name, (flags), NULL, NULL } #define ROUTER(name,flags) \ @@ -711,11 +767,13 @@ struct testcase_t routerlist_tests[] = { ROUTER(pick_directory_server_impl, TT_FORK), { "directory_guard_fetch_with_no_dirinfo", test_directory_guard_fetch_with_no_dirinfo, TT_FORK, NULL, NULL }, - /* These depend on construct_consensus() setting valid_after=now+1000 */ + /* These depend on construct_consensus() setting + * valid_after=now+1000 and dist_seconds=250 */ TIMELY("timely_consensus1", "1010"), TIMELY("timely_consensus2", "1000"), - TIMELY("timely_consensus3", "940"), - EARLY("early_consensus1", "939"), + TIMELY("timely_consensus3", "690"), + EARLY("early_consensus1", "689"), + { "warn_early_consensus", test_warn_early_consensus, 0, NULL, NULL }, END_OF_TESTCASES };