Merge branch 'tor-gitlab/mr/270' into maint-0.4.5

8 files changed, 71 insertions, 26 deletions

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