Merge commit 'mikeperry/bug1740' into maint-0.2.2

changes/bug1740

@@ -0,0 +1,5 @@
+ o Minor bugfixes:
+   - Fix to ignore cannibalized circuits when recording circuit build times.
+     This should provide for a minor performance improvement for hidden
+     service users using 0.2.2.14-alpha, and should remove two spurious
+     notice log messages. Bugfix on 0.2.2.14-alpha; fixes bug #1740.

src/or/circuitbuild.c

@@ -1197,6 +1197,11 @@ circuit_build_times_count_close(circuit_build_times_t *cbt,
 /**
  * Update timeout counts to determine if we need to expire
  * our build time history due to excessive timeouts.
+ *
+ * We do not record any actual time values at this stage;
+ * we are only interested in recording the fact that a timeout
+ * happened. We record the time values via
+ * circuit_build_times_count_close() and circuit_build_times_add_time().
  */
 void
 circuit_build_times_count_timeout(circuit_build_times_t *cbt,
@@ -1208,11 +1213,11 @@ circuit_build_times_count_timeout(circuit_build_times_t *cbt,
     return;
   }
 
+  /* Register the fact that a timeout just occurred. */
   circuit_build_times_network_timeout(cbt, did_onehop);
 
   /* If there are a ton of timeouts, we should reset
-   * the circuit build timeout.
-   */
+   * the circuit build timeout. */
   circuit_build_times_network_check_changed(cbt);
 }
 
@@ -1816,6 +1821,18 @@ should_use_create_fast_for_circuit(origin_circuit_t *circ)
   return 1;
 }
 
+/** Return true if <b>circ</b> is the type of circuit we want to count
+ * timeouts from. In particular, we want it to have not completed yet
+ * (already completing indicates we cannibalized it), and we want it to
+ * have exactly three hops.
+ */
+int
+circuit_timeout_want_to_count_circ(origin_circuit_t *circ)
+{
+  return !circ->has_opened
+          && circ->build_state->desired_path_len == DEFAULT_ROUTE_LEN;
+}
+
 /** This is the backbone function for building circuits.
  *
  * If circ's first hop is closed, then we need to build a create
@@ -1889,11 +1906,12 @@ circuit_send_next_onion_skin(origin_circuit_t *circ)
     if (!hop) {
       /* done building the circuit. whew. */
       circuit_set_state(TO_CIRCUIT(circ), CIRCUIT_STATE_OPEN);
-      if (!circ->build_state->onehop_tunnel) {
+      if (circuit_timeout_want_to_count_circ(circ)) {
         struct timeval end;
         long timediff;
         tor_gettimeofday(&end);
         timediff = tv_mdiff(&circ->_base.highres_created, &end);
+
         /*
          * If the circuit build time is much greater than we would have cut
          * it off at, we probably had a suspend event along this codepath,
@@ -1901,9 +1919,10 @@ circuit_send_next_onion_skin(origin_circuit_t *circ)
          */
         if (timediff < 0 || timediff > 2*circ_times.close_ms+1000) {
           log_notice(LD_CIRC, "Strange value for circuit build time: %ldmsec. "
-                              "Assuming clock jump.", timediff);
+                              "Assuming clock jump. Purpose %d", timediff,
+                              circ->_base.purpose);
         } else if (!circuit_build_times_disabled()) {
-          /* Don't count circuit times if the network was not live */
+          /* Only count circuit times if the network is live */
           if (circuit_build_times_network_check_live(&circ_times)) {
             circuit_build_times_add_time(&circ_times, (build_time_t)timediff);
             circuit_build_times_set_timeout(&circ_times);

src/or/circuitbuild.h

@@ -24,6 +24,7 @@ origin_circuit_t *circuit_establish_circuit(uint8_t purpose,
 int circuit_handle_first_hop(origin_circuit_t *circ);
 void circuit_n_conn_done(or_connection_t *or_conn, int status);
 int inform_testing_reachability(void);
+int circuit_timeout_want_to_count_circ(origin_circuit_t *circ);
 int circuit_send_next_onion_skin(origin_circuit_t *circ);
 void circuit_note_clock_jumped(int seconds_elapsed);
 int circuit_extend(cell_t *cell, circuit_t *circ);

src/or/circuituse.c

@@ -284,6 +284,8 @@ circuit_expire_building(time_t now)
    * decided on a customized one yet */
   time_t general_cutoff = now - lround(circ_times.timeout_ms/1000);
   time_t begindir_cutoff = now - lround(circ_times.timeout_ms/2000);
+  time_t fourhop_cutoff = now - lround(4*circ_times.timeout_ms/3000);
+  time_t cannibalize_cutoff = now - lround(circ_times.timeout_ms/2000);
   time_t close_cutoff = now - lround(circ_times.close_ms/1000);
   time_t introcirc_cutoff = begindir_cutoff;
   cpath_build_state_t *build_state;
@@ -299,6 +301,11 @@ circuit_expire_building(time_t now)
     build_state = TO_ORIGIN_CIRCUIT(victim)->build_state;
     if (build_state && build_state->onehop_tunnel)
       cutoff = begindir_cutoff;
+    else if (build_state && build_state->desired_path_len == 4
+             && !TO_ORIGIN_CIRCUIT(victim)->has_opened)
+      cutoff = fourhop_cutoff;
+    else if (TO_ORIGIN_CIRCUIT(victim)->has_opened)
+      cutoff = cannibalize_cutoff;
     else if (victim->purpose == CIRCUIT_PURPOSE_C_INTRODUCING)
       cutoff = introcirc_cutoff;
     else if (victim->purpose == CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT)
@@ -378,29 +385,36 @@ circuit_expire_building(time_t now)
         continue;
       }
 
-      /* circuits are allowed to last longer for measurement.
-       * Switch their purpose and wait. */
-      if (victim->purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) {
-        victim->purpose = CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT;
-        circuit_build_times_count_timeout(&circ_times,
-                                          first_hop_succeeded);
-        continue;
-      }
+      if (circuit_timeout_want_to_count_circ(TO_ORIGIN_CIRCUIT(victim))) {
+        /* Circuits are allowed to last longer for measurement.
+         * Switch their purpose and wait. */
+        if (victim->purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) {
+          victim->purpose = CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT;
+          /* Record this failure to check for too many timeouts
+           * in a row. This function does not record a time value yet
+           * (we do that later); it only counts the fact that we did
+           * have a timeout. */
+          circuit_build_times_count_timeout(&circ_times,
+                                            first_hop_succeeded);
+          continue;
+        }
 
-      /*
-       * If the circuit build time is much greater than we would have cut
-       * it off at, we probably had a suspend event along this codepath,
-       * and we should discard the value.
-       */
-      if (now - victim->timestamp_created > 2*circ_times.close_ms/1000+1) {
-        log_notice(LD_CIRC,
-                   "Extremely large value for circuit build timeout: %lds. "
-                   "Assuming clock jump.",
-                   (long)(now - victim->timestamp_created));
-      } else if (circuit_build_times_count_close(&circ_times,
-                                          first_hop_succeeded,
-                                          victim->timestamp_created)) {
-        circuit_build_times_set_timeout(&circ_times);
+        /*
+         * If the circuit build time is much greater than we would have cut
+         * it off at, we probably had a suspend event along this codepath,
+         * and we should discard the value.
+         */
+        if (now - victim->timestamp_created > 2*circ_times.close_ms/1000+1) {
+          log_notice(LD_CIRC,
+                     "Extremely large value for circuit build timeout: %lds. "
+                     "Assuming clock jump. Purpose %d",
+                     (long)(now - victim->timestamp_created),
+                      victim->purpose);
+        } else if (circuit_build_times_count_close(&circ_times,
+                                            first_hop_succeeded,
+                                            victim->timestamp_created)) {
+          circuit_build_times_set_timeout(&circ_times);
+        }
       }
     }
 
@@ -903,6 +917,11 @@ circuit_has_opened(origin_circuit_t *circ)
 {
   control_event_circuit_status(circ, CIRC_EVENT_BUILT, 0);
 
+  /* Remember that this circuit has finished building. Now if we start
+   * it building again later (e.g. by extending it), we will know not
+   * to consider its build time. */
+  circ->has_opened = 1;
+
   switch (TO_CIRCUIT(circ)->purpose) {
     case CIRCUIT_PURPOSE_C_ESTABLISH_REND:
       rend_client_rendcirc_has_opened(circ);

src/or/or.h

@@ -2163,9 +2163,13 @@ typedef struct origin_circuit_t {
    * to the specification? */
   unsigned int remaining_relay_early_cells : 4;
 
-  /** Set if this circuit insanely old and if we already informed the user */
+  /** Set if this circuit is insanely old and we already informed the user */
   unsigned int is_ancient : 1;
 
+  /** Set if this circuit has already been opened. Used to detect
+   * cannibalized circuits. */
+  unsigned int has_opened : 1;
+
   /** What commands were sent over this circuit that decremented the
    * RELAY_EARLY counter? This is for debugging task 878. */
   uint8_t relay_early_commands[MAX_RELAY_EARLY_CELLS_PER_CIRCUIT];