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 6824af815f..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; } @@ -3462,6 +3473,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; } 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/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..00bb0abf23 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); @@ -1699,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);