Bug 6475: Explicitly track our path bias state.

This is done to avoid spurious warns. Additional log lines are also
added to try to track down the codepaths where we are somehow overcounting
success counts.

2 files changed, 75 insertions, 11 deletions

diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c
index b82cce9881..7ac2b97824 100644
--- a/src/or/circuitbuild.c
+++ b/src/or/circuitbuild.c
@@ -2293,18 +2293,34 @@ circuit_send_next_onion_skin(origin_circuit_t *circ)
           entry_guard_get_by_id_digest(circ->_base.n_conn->identity_digest);
 
         if (guard) {
-          guard->circuit_successes++;
+          if (circ->path_state == PATH_STATE_DID_FIRST_HOP) {
+            circ->path_state = PATH_STATE_SUCCEEDED;
+            guard->circuit_successes++;
 
-          log_info(LD_PROTOCOL, "Got success count %u/%u for guard %s=%s",
-                   guard->circuit_successes, guard->first_hops,
-                   guard->nickname, hex_str(guard->identity, DIGEST_LEN));
+            log_info(LD_PROTOCOL, "Got success count %u/%u for guard %s=%s",
+                     guard->circuit_successes, guard->first_hops,
+                     guard->nickname, hex_str(guard->identity, DIGEST_LEN));
+          } else {
+            log_info(LD_BUG,
+                     "Succeeded circuit has strange path state %d. "
+                     "Circuit is a %s currently %s.",
+                     circ->path_state,
+                     circuit_purpose_to_string(circ->_base.purpose),
+                     circuit_state_to_string(circ->_base.state));
+          }
 
           if (guard->first_hops < guard->circuit_successes) {
             log_warn(LD_BUG, "Unexpectedly high circuit_successes (%u/%u) "
-                     "for guard %s",
+                     "for guard %s=%s",
                      guard->circuit_successes, guard->first_hops,
-                     guard->nickname);
+                     guard->nickname, hex_str(guard->identity, DIGEST_LEN));
           }
+        } else {
+          log_info(LD_BUG,
+                  "Completed circuit has no known guard. "
+                  "Circuit is a %s currently %s.",
+                  circuit_purpose_to_string(circ->_base.purpose),
+                  circuit_state_to_string(circ->_base.state));
         }
       }
       if (!can_complete_circuit && !circ->build_state->onehop_tunnel) {
@@ -2666,8 +2682,9 @@ entry_guard_inc_first_hop_count(entry_guard_t *guard)
     guard->circuit_successes /= scale_factor;
   }
   guard->first_hops++;
-  log_info(LD_PROTOCOL, "Got success count %u/%u for guard %s",
-           guard->circuit_successes, guard->first_hops, guard->nickname);
+  log_info(LD_PROTOCOL, "Got success count %u/%u for guard %s=%s",
+           guard->circuit_successes, guard->first_hops, guard->nickname,
+           hex_str(guard->identity, DIGEST_LEN));
   return 0;
 }
 
@@ -2690,6 +2707,16 @@ circuit_finish_handshake(origin_circuit_t *circ, uint8_t reply_type,
 
   if (circ->cpath->state == CPATH_STATE_AWAITING_KEYS) {
     hop = circ->cpath;
+
+    /* Help track down the real cause of bug #6475: */
+    if (circ->has_opened && circ->path_state == PATH_STATE_NEW_CIRC) {
+      log_info(LD_BUG,
+              "Opened circuit seems new. "
+              "Circuit is a %s currently %s.",
+              circuit_purpose_to_string(circ->_base.purpose),
+              circuit_state_to_string(circ->_base.state));
+    }
+
     /* Don't count cannibalized or onehop circs for path bias */
     if (!circ->has_opened && !circ->build_state->onehop_tunnel) {
       entry_guard_t *guard;
@@ -2697,13 +2724,40 @@ circuit_finish_handshake(origin_circuit_t *circ, uint8_t reply_type,
       guard = entry_guard_get_by_id_digest(
               circ->_base.n_conn->identity_digest);
       if (guard) {
-        if (entry_guard_inc_first_hop_count(guard) < 0) {
-          /* Bogus guard; we already warned. */
-          return -END_CIRC_REASON_TORPROTOCOL;
+        if (circ->path_state == PATH_STATE_NEW_CIRC) {
+          circ->path_state = PATH_STATE_DID_FIRST_HOP;
+
+          if (entry_guard_inc_first_hop_count(guard) < 0) {
+            /* Bogus guard; we already warned. */
+            return -END_CIRC_REASON_TORPROTOCOL;
+          }
+        } else {
+          log_info(LD_BUG,
+                   "Unopened circuit has strange path state %d. "
+                   "Circuit is a %s currently %s.",
+                   circ->path_state,
+                   circuit_purpose_to_string(circ->_base.purpose),
+                   circuit_state_to_string(circ->_base.state));
         }
+      } else {
+        log_info(LD_BUG,
+                "Opened circuit has no known guard. "
+                "Circuit is a %s currently %s.",
+                circuit_purpose_to_string(circ->_base.purpose),
+                circuit_state_to_string(circ->_base.state));
       }
     }
   } else {
+    /* Help track down the real cause of bug #6475: */
+    if (circ->path_state == PATH_STATE_NEW_CIRC) {
+      log_info(LD_BUG,
+              "New circuit is in cpath state %d (opened: %d). "
+              "Circuit is a %s currently %s.",
+              circ->cpath->state, circ->has_opened, 
+              circuit_purpose_to_string(circ->_base.purpose),
+              circuit_state_to_string(circ->_base.state));
+    }
+
     hop = onion_next_hop_in_cpath(circ->cpath);
     if (!hop) { /* got an extended when we're all done? */
       log_warn(LD_PROTOCOL,"got extended when circ already built? Closing.");
diff --git a/src/or/or.h b/src/or/or.h
index 3a53e5ed86..0db6137e97 100644
--- a/src/or/or.h
+++ b/src/or/or.h
@@ -2596,6 +2596,12 @@ typedef struct circuit_t {
  * circuit. */
 #define MAX_RELAY_EARLY_CELLS_PER_CIRCUIT 8
 
+typedef enum {
+    PATH_STATE_NEW_CIRC = 0,
+    PATH_STATE_DID_FIRST_HOP = 1,
+    PATH_STATE_SUCCEEDED = 2,
+} path_state_t;
+
 /** An origin_circuit_t holds data necessary to build and use a circuit.
  */
 typedef struct origin_circuit_t {
@@ -2629,6 +2635,10 @@ typedef struct origin_circuit_t {
    * cannibalized circuits. */
   unsigned int has_opened : 1;
 
+  /** Kludge to help us prevent the warn in bug #6475 and eventually
+   * debug why we are not seeing first hops in some cases. */
+  path_state_t path_state;
+
   /** Set iff this is a hidden-service circuit which has timed out
    * according to our current circuit-build timeout, but which has
    * been kept around because it might still succeed in connecting to