From 0b00f79c82894c0bd0ff2d492420f7d9e6101d9e Mon Sep 17 00:00:00 2001 From: Roger Dingledine Date: Sat, 16 Jan 2021 16:11:33 -0500 Subject: [PATCH 1/3] log more about testing incoming relay descriptors --- src/feature/dirauth/process_descs.c | 8 ++++++-- src/feature/dirauth/reachability.c | 14 +++++++++----- src/feature/dircache/dircache.c | 9 +++++++++ 3 files changed, 24 insertions(+), 7 deletions(-) diff --git a/src/feature/dirauth/process_descs.c b/src/feature/dirauth/process_descs.c index b08ffeba07..a382f237c4 100644 --- a/src/feature/dirauth/process_descs.c +++ b/src/feature/dirauth/process_descs.c @@ -322,8 +322,9 @@ dirserv_router_get_status(const routerinfo_t *router, const char **msg, * and is non-zero (clients check that it's non-zero before using it). */ if (!routerinfo_has_curve25519_onion_key(router)) { log_fn(severity, LD_DIR, - "Descriptor from router %s is missing an ntor curve25519 onion " - "key.", router_describe(router)); + "Descriptor from router %s (platform %s) " + "is missing an ntor curve25519 onion key.", + router_describe(router), router->platform); if (msg) *msg = "Missing ntor curve25519 onion key. Please upgrade!"; return RTR_REJECT; @@ -761,6 +762,9 @@ dirserv_add_descriptor(routerinfo_t *ri, const char **msg, const char *source) goto fail; } + log_info(LD_DIR, "Assessing new descriptor: %s: %s", + ri->nickname, ri->platform); + /* Check whether this descriptor is semantically identical to the last one * from this server. (We do this here and not in router_add_to_routerlist * because we want to be able to accept the newest router descriptor that diff --git a/src/feature/dirauth/reachability.c b/src/feature/dirauth/reachability.c index eb88b4aa07..8717646314 100644 --- a/src/feature/dirauth/reachability.c +++ b/src/feature/dirauth/reachability.c @@ -110,14 +110,18 @@ dirserv_should_launch_reachability_test(const routerinfo_t *ri, if (!ri_old) { /* New router: Launch an immediate reachability test, so we will have an * opinion soon in case we're generating a consensus soon */ + log_info(LD_DIR, "descriptor for new router %s", router_describe(ri)); return 1; } if (ri_old->is_hibernating && !ri->is_hibernating) { /* It just came out of hibernation; launch a reachability test */ + log_info(LD_DIR, "out of hibernation: router %s", router_describe(ri)); return 1; } if (! routers_have_same_or_addrs(ri, ri_old)) { /* Address or port changed; launch a reachability test */ + log_info(LD_DIR, "address or port changed: router %s", + router_describe(ri)); return 1; } return 0; @@ -148,7 +152,7 @@ dirserv_single_reachability_test(time_t now, routerinfo_t *router) } /* IPv4. */ - log_debug(LD_OR,"Testing reachability of %s at %s:%u.", + log_info(LD_OR,"Testing reachability of %s at %s:%u.", router->nickname, fmt_addr(&router->ipv4_addr), router->ipv4_orport); chan = channel_tls_connect(&router->ipv4_addr, router->ipv4_orport, @@ -160,10 +164,10 @@ dirserv_single_reachability_test(time_t now, routerinfo_t *router) if (dirauth_get_options()->AuthDirHasIPv6Connectivity == 1 && !tor_addr_is_null(&router->ipv6_addr)) { char addrstr[TOR_ADDR_BUF_LEN]; - log_debug(LD_OR, "Testing reachability of %s at %s:%u.", - router->nickname, - tor_addr_to_str(addrstr, &router->ipv6_addr, sizeof(addrstr), 1), - router->ipv6_orport); + log_info(LD_OR, "Testing reachability of %s at %s:%u.", + router->nickname, + tor_addr_to_str(addrstr, &router->ipv6_addr, sizeof(addrstr), 1), + router->ipv6_orport); chan = channel_tls_connect(&router->ipv6_addr, router->ipv6_orport, router->cache_info.identity_digest, ed_id_key); diff --git a/src/feature/dircache/dircache.c b/src/feature/dircache/dircache.c index 207ea6698b..7f6452afbb 100644 --- a/src/feature/dircache/dircache.c +++ b/src/feature/dircache/dircache.c @@ -1675,6 +1675,15 @@ directory_handle_command_post,(dir_connection_t *conn, const char *headers, const char *msg = "[None]"; uint8_t purpose = authdir_mode_bridge(options) ? ROUTER_PURPOSE_BRIDGE : ROUTER_PURPOSE_GENERAL; + + { + char *genreason = http_get_header(headers, "X-Desc-Gen-Reason: "); + log_info(LD_DIRSERV, + "New descriptor post, because: %s", + genreason ? genreason : "not specified"); + tor_free(genreason); + } + was_router_added_t r = dirserv_add_multiple_descriptors(body, body_len, purpose, conn->base_.address, &msg); tor_assert(msg); From 9e6064ec359a170ab37fb5d66ef7c46519ac1caa Mon Sep 17 00:00:00 2001 From: Roger Dingledine Date: Sat, 16 Jan 2021 16:23:31 -0500 Subject: [PATCH 2/3] dir auths write consensuses to disk after creation This step happens after we make each consensus flavor, and before we worry about sigs or anything. That way if Tor crashes, or if we fail to get enough sigs, we still have a chance to know what consensus we wanted to make. --- src/feature/dirauth/dirvote.c | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/src/feature/dirauth/dirvote.c b/src/feature/dirauth/dirvote.c index 6824af815f..cf1135ba37 100644 --- a/src/feature/dirauth/dirvote.c +++ b/src/feature/dirauth/dirvote.c @@ -3462,6 +3462,15 @@ dirvote_compute_consensuses(void) pending[flav].body = consensus_body; pending[flav].consensus = consensus; n_generated++; + + /* Write it out to disk too, for dir auth debugging purposes */ + { + char *filename; + tor_asprintf(&filename, "my-consensus-%s", flavor_name); + write_str_to_file(get_datadir_fname(filename), consensus_body, 0); + tor_free(filename); + } + consensus_body = NULL; consensus = NULL; } From 633b68bfe2cfaab41dc473923acc794e789a4c16 Mon Sep 17 00:00:00 2001 From: Roger Dingledine Date: Sat, 16 Jan 2021 23:40:18 -0500 Subject: [PATCH 3/3] log more during consensus voting process Give more visibility to directory authority operators during the consensus voting process. Closes ticket 40245. --- changes/ticket40245 | 4 ++++ src/feature/dirauth/dirvote.c | 21 ++++++++++++++++----- src/feature/dirauth/dirvote.h | 3 +++ src/feature/dircache/dircache.c | 3 ++- src/feature/dirclient/dirclient.c | 8 ++++---- src/test/test_dir_handle_get.c | 18 +++++++++--------- 6 files changed, 38 insertions(+), 19 deletions(-) create mode 100644 changes/ticket40245 diff --git a/changes/ticket40245 b/changes/ticket40245 new file mode 100644 index 0000000000..641372333e --- /dev/null +++ b/changes/ticket40245 @@ -0,0 +1,4 @@ + o Minor features (logging): + - Give more visibility to directory authority operators during the + consensus voting process and while processing relay descriptors. + Closes ticket 40245. diff --git a/src/feature/dirauth/dirvote.c b/src/feature/dirauth/dirvote.c index cf1135ba37..fa4d919aa9 100644 --- a/src/feature/dirauth/dirvote.c +++ b/src/feature/dirauth/dirvote.c @@ -2975,7 +2975,7 @@ dirvote_perform_vote(void) if (!contents) return -1; - pending_vote = dirvote_add_vote(contents, 0, &msg, &status); + pending_vote = dirvote_add_vote(contents, 0, "self", &msg, &status); tor_free(contents); if (!pending_vote) { log_warn(LD_DIR, "Couldn't store my own vote! (I told myself, '%s'.)", @@ -3169,6 +3169,7 @@ add_new_cert_if_needed(const struct authority_cert_t *cert) * only) */ pending_vote_t * dirvote_add_vote(const char *vote_body, time_t time_posted, + const char *where_from, const char **msg_out, int *status_out) { networkstatus_t *vote; @@ -3226,6 +3227,14 @@ dirvote_add_vote(const char *vote_body, time_t time_posted, goto err; } + if (time_posted) { /* they sent it to me via a POST */ + log_notice(LD_DIR, "%s posted a vote to me from %s.", + vi->nickname, where_from); + } else { /* I imported this one myself */ + log_notice(LD_DIR, "Retrieved %s's vote from %s.", + vi->nickname, where_from); + } + /* Check if we received it, as a post, after the cutoff when we * start asking other dir auths for it. If we do, the best plan * is to discard it, because using it greatly increases the chances @@ -3235,10 +3244,10 @@ dirvote_add_vote(const char *vote_body, time_t time_posted, char tbuf1[ISO_TIME_LEN+1], tbuf2[ISO_TIME_LEN+1]; format_iso_time(tbuf1, time_posted); format_iso_time(tbuf2, voting_schedule.fetch_missing_votes); - log_warn(LD_DIR, "Rejecting posted vote from %s received at %s; " + log_warn(LD_DIR, "Rejecting %s's posted vote from %s received at %s; " "our cutoff for received votes is %s. Check your clock, " "CPU load, and network load. Also check the authority that " - "posted the vote.", vi->address, tbuf1, tbuf2); + "posted the vote.", vi->nickname, vi->address, tbuf1, tbuf2); *msg_out = "Posted vote received too late, would be dangerous to count it"; goto err; } @@ -3254,8 +3263,8 @@ dirvote_add_vote(const char *vote_body, time_t time_posted, networkstatus_voter_info_t *vi_old = get_voter(v->vote); if (fast_memeq(vi_old->vote_digest, vi->vote_digest, DIGEST_LEN)) { /* Ah, it's the same vote. Not a problem. */ - log_info(LD_DIR, "Discarding a vote we already have (from %s).", - vi->address); + log_notice(LD_DIR, "Discarding a vote we already have (from %s).", + vi->address); if (*status_out < 200) *status_out = 200; goto discard; @@ -3278,6 +3287,8 @@ dirvote_add_vote(const char *vote_body, time_t time_posted, *msg_out = "OK"; return v; } else { + log_notice(LD_DIR, "Discarding vote from %s because we have " + "a newer one already.", vi->address); *msg_out = "Already have a newer pending vote"; goto err; } diff --git a/src/feature/dirauth/dirvote.h b/src/feature/dirauth/dirvote.h index 4f48e45dc3..f9441773a7 100644 --- a/src/feature/dirauth/dirvote.h +++ b/src/feature/dirauth/dirvote.h @@ -99,6 +99,7 @@ void dirvote_dirreq_get_status_vote(const char *url, smartlist_t *items, /* Storing signatures and votes functions */ struct pending_vote_t * dirvote_add_vote(const char *vote_body, time_t time_posted, + const char *where_from, const char **msg_out, int *status_out); int dirvote_add_signatures(const char *detached_signatures_body, @@ -149,11 +150,13 @@ dirvote_dirreq_get_status_vote(const char *url, smartlist_t *items, static inline struct pending_vote_t * dirvote_add_vote(const char *vote_body, time_t time_posted, + const char *where_from, const char **msg_out, int *status_out) { (void) vote_body; (void) time_posted; + (void) where_from; /* If the dirauth module is disabled, this should NEVER be called else we * failed to safeguard the dirauth module. */ tor_assert_nonfatal_unreached(); diff --git a/src/feature/dircache/dircache.c b/src/feature/dircache/dircache.c index 7f6452afbb..00bb0abf23 100644 --- a/src/feature/dircache/dircache.c +++ b/src/feature/dircache/dircache.c @@ -1708,7 +1708,8 @@ directory_handle_command_post,(dir_connection_t *conn, const char *headers, !strcmp(url,"/tor/post/vote")) { /* v3 networkstatus vote */ const char *msg = "OK"; int status; - if (dirvote_add_vote(body, approx_time(), &msg, &status)) { + if (dirvote_add_vote(body, approx_time(), TO_CONN(conn)->address, + &msg, &status)) { write_short_http_response(conn, status, "Vote stored"); } else { tor_assert(msg); diff --git a/src/feature/dirclient/dirclient.c b/src/feature/dirclient/dirclient.c index 74e68ac6be..a5dd856729 100644 --- a/src/feature/dirclient/dirclient.c +++ b/src/feature/dirclient/dirclient.c @@ -2419,8 +2419,8 @@ handle_response_fetch_status_vote(dir_connection_t *conn, const char *msg; int st; - log_info(LD_DIR,"Got votes (body size %d) from server %s", - (int)body_len, connection_describe_peer(TO_CONN(conn))); + log_notice(LD_DIR,"Got votes (body size %d) from server %s", + (int)body_len, connection_describe_peer(TO_CONN(conn))); if (status_code != 200) { log_warn(LD_DIR, "Received http status code %d (%s) from server " @@ -2430,7 +2430,7 @@ handle_response_fetch_status_vote(dir_connection_t *conn, conn->requested_resource); return -1; } - dirvote_add_vote(body, 0, &msg, &st); + dirvote_add_vote(body, 0, TO_CONN(conn)->address, &msg, &st); if (st > 299) { log_warn(LD_DIR, "Error adding retrieved vote: %s", msg); } else { @@ -2720,7 +2720,7 @@ handle_response_upload_vote(dir_connection_t *conn, switch (status_code) { case 200: { - log_notice(LD_DIR,"Uploaded a vote to dirserver %s", + log_notice(LD_DIR,"Uploaded my vote to dirserver %s", connection_describe_peer(TO_CONN(conn))); } break; diff --git a/src/test/test_dir_handle_get.c b/src/test/test_dir_handle_get.c index f717f83932..28f07efbe8 100644 --- a/src/test/test_dir_handle_get.c +++ b/src/test/test_dir_handle_get.c @@ -2105,7 +2105,7 @@ test_dir_handle_get_status_vote_d(void* data) const char *msg_out = NULL; int status_out = 0; - struct pending_vote_t *pv = dirvote_add_vote(VOTE_BODY_V3, 0, + struct pending_vote_t *pv = dirvote_add_vote(VOTE_BODY_V3, 0, "foo", &msg_out, &status_out); tt_assert(pv); @@ -2487,7 +2487,7 @@ test_dir_handle_get_status_vote_next_authority(void* data) time_t now = 1441223455 -1; dirauth_sched_recalculate_timing(mock_options, now); - struct pending_vote_t *vote = dirvote_add_vote(VOTE_BODY_V3, 0, + struct pending_vote_t *vote = dirvote_add_vote(VOTE_BODY_V3, 0, "foo", &msg_out, &status_out); tt_assert(vote); @@ -2649,7 +2649,7 @@ test_dir_handle_get_status_vote_current_authority(void* data) time_t now = 1441223455; dirauth_sched_recalculate_timing(mock_options, now-1); - struct pending_vote_t *vote = dirvote_add_vote(VOTE_BODY_V3, 0, + struct pending_vote_t *vote = dirvote_add_vote(VOTE_BODY_V3, 0, "foo", &msg_out, &status_out); tt_assert(vote); @@ -2777,7 +2777,7 @@ test_dir_handle_get_status_vote_too_late(void* data) /* Next voting interval */ vote = dirvote_add_vote(VOTE_BODY_V3, - fetch_missing + vote_interval, + fetch_missing + vote_interval, "foo", &msg_out, &status_out); tt_assert(!vote); tt_int_op(status_out, OP_EQ, 400); @@ -2786,7 +2786,7 @@ test_dir_handle_get_status_vote_too_late(void* data) /* Just after fetch missing */ vote = dirvote_add_vote(VOTE_BODY_V3, - fetch_missing + 1, + fetch_missing + 1, "foo", &msg_out, &status_out); tt_assert(!vote); tt_int_op(status_out, OP_EQ, 400); @@ -2795,7 +2795,7 @@ test_dir_handle_get_status_vote_too_late(void* data) /* On fetch missing */ vote = dirvote_add_vote(VOTE_BODY_V3, - fetch_missing, + fetch_missing, "foo", &msg_out, &status_out); tt_assert(vote); @@ -2806,7 +2806,7 @@ test_dir_handle_get_status_vote_too_late(void* data) /* Between voting starts and fetch missing */ vote = dirvote_add_vote(VOTE_BODY_V3, - voting_starts + 1, + voting_starts + 1, "foo", &msg_out, &status_out); tt_assert(vote); @@ -2817,7 +2817,7 @@ test_dir_handle_get_status_vote_too_late(void* data) /* On voting starts */ vote = dirvote_add_vote(VOTE_BODY_V3, - voting_starts, + voting_starts, "foo", &msg_out, &status_out); tt_assert(vote); @@ -2828,7 +2828,7 @@ test_dir_handle_get_status_vote_too_late(void* data) /* Just before voting starts */ vote = dirvote_add_vote(VOTE_BODY_V3, - voting_starts - 1, + voting_starts - 1, "foo", &msg_out, &status_out); tt_assert(vote);