1 files changed, 187 insertions, 43 deletions

diff --git a/src/or/circuituse.c b/src/or/circuituse.c
index 827c4bbf2b..3af0fb642d 100644
--- a/src/or/circuituse.c
+++ b/src/or/circuituse.c
@@ -10,6 +10,20 @@
  **/
 
 #include "or.h"
+#include "circuitbuild.h"
+#include "circuitlist.h"
+#include "circuituse.h"
+#include "config.h"
+#include "connection.h"
+#include "connection_edge.h"
+#include "control.h"
+#include "policies.h"
+#include "rendclient.h"
+#include "rendcommon.h"
+#include "rendservice.h"
+#include "rephist.h"
+#include "router.h"
+#include "routerlist.h"
 
 /********* START VARIABLES **********/
 
@@ -113,7 +127,7 @@ circuit_is_acceptable(circuit_t *circ, edge_connection_t *conn,
         return 0;
       }
     }
-    if (exitrouter && !connection_ap_can_use_exit(conn, exitrouter)) {
+    if (exitrouter && !connection_ap_can_use_exit(conn, exitrouter, 0)) {
       /* can't exit from this router */
       return 0;
     }
@@ -263,16 +277,22 @@ circuit_conforms_to_options(const origin_circuit_t *circ,
 void
 circuit_expire_building(time_t now)
 {
-  circuit_t *victim, *circ = global_circuitlist;
-  time_t general_cutoff = now - get_options()->CircuitBuildTimeout;
-  time_t begindir_cutoff = now - get_options()->CircuitBuildTimeout/2;
+  circuit_t *victim, *next_circ = global_circuitlist;
+  /* circ_times.timeout_ms and circ_times.close_ms are from
+   * circuit_build_times_get_initial_timeout() if we haven't computed
+   * custom timeouts yet */
+  time_t general_cutoff = now - tor_lround(circ_times.timeout_ms/1000);
+  time_t begindir_cutoff = now - tor_lround(circ_times.timeout_ms/2000);
+  time_t fourhop_cutoff = now - tor_lround(4*circ_times.timeout_ms/3000);
+  time_t cannibalize_cutoff = now - tor_lround(circ_times.timeout_ms/2000);
+  time_t close_cutoff = now - tor_lround(circ_times.close_ms/1000);
   time_t introcirc_cutoff = begindir_cutoff;
   cpath_build_state_t *build_state;
 
-  while (circ) {
+  while (next_circ) {
     time_t cutoff;
-    victim = circ;
-    circ = circ->next;
+    victim = next_circ;
+    next_circ = next_circ->next;
     if (!CIRCUIT_IS_ORIGIN(victim) || /* didn't originate here */
         victim->marked_for_close) /* don't mess with marked circs */
       continue;
@@ -280,10 +300,18 @@ 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)
+      cutoff = close_cutoff;
     else
       cutoff = general_cutoff;
+
     if (victim->timestamp_created > cutoff)
       continue; /* it's still young, leave it alone */
 
@@ -343,6 +371,54 @@ circuit_expire_building(time_t now)
             continue;
           break;
       }
+    } else { /* circuit not open, consider recording failure as timeout */
+      int first_hop_succeeded = TO_ORIGIN_CIRCUIT(victim)->cpath &&
+            TO_ORIGIN_CIRCUIT(victim)->cpath->state == CPATH_STATE_OPEN;
+
+      if (TO_ORIGIN_CIRCUIT(victim)->p_streams != NULL) {
+        log_warn(LD_BUG, "Circuit %d (purpose %d) has timed out, "
+                 "yet has attached streams!",
+                 TO_ORIGIN_CIRCUIT(victim)->global_identifier,
+                 victim->purpose);
+        tor_fragile_assert();
+        continue;
+      }
+
+      if (circuit_timeout_want_to_count_circ(TO_ORIGIN_CIRCUIT(victim)) &&
+          circuit_build_times_enough_to_compute(&circ_times)) {
+        /* Circuits are allowed to last longer for measurement.
+         * Switch their purpose and wait. */
+        if (victim->purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) {
+          control_event_circuit_status(TO_ORIGIN_CIRCUIT(victim),
+                                       CIRC_EVENT_FAILED,
+                                       END_CIRC_REASON_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. 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);
+        }
+      }
     }
 
     if (victim->n_conn)
@@ -357,7 +433,10 @@ circuit_expire_building(time_t now)
                circuit_state_to_string(victim->state), victim->purpose);
 
     circuit_log_path(LOG_INFO,LD_CIRC,TO_ORIGIN_CIRCUIT(victim));
-    circuit_mark_for_close(victim, END_CIRC_REASON_TIMEOUT);
+    if (victim->purpose == CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT)
+      circuit_mark_for_close(victim, END_CIRC_REASON_MEASUREMENT_EXPIRED);
+    else
+      circuit_mark_for_close(victim, END_CIRC_REASON_TIMEOUT);
   }
 }
 
@@ -414,7 +493,7 @@ circuit_stream_is_being_handled(edge_connection_t *conn,
       if (exitrouter && (!need_uptime || build_state->need_uptime)) {
         int ok;
         if (conn) {
-          ok = connection_ap_can_use_exit(conn, exitrouter);
+          ok = connection_ap_can_use_exit(conn, exitrouter, 0);
         } else {
           addr_policy_result_t r = compare_addr_to_addr_policy(
               0, port, exitrouter->exit_policy);
@@ -431,11 +510,11 @@ circuit_stream_is_being_handled(edge_connection_t *conn,
 }
 
 /** Don't keep more than this many unused open circuits around. */
-#define MAX_UNUSED_OPEN_CIRCUITS 12
+#define MAX_UNUSED_OPEN_CIRCUITS 14
 
 /** Figure out how many circuits we have open that are clean. Make
  * sure it's enough for all the upcoming behaviors we predict we'll have.
- * But if we have too many, close the not-so-useful ones.
+ * But put an upper bound on the total number of circuits.
  */
 static void
 circuit_predict_and_launch_new(void)
@@ -517,6 +596,19 @@ circuit_predict_and_launch_new(void)
     circuit_launch_by_router(CIRCUIT_PURPOSE_C_GENERAL, NULL, flags);
     return;
   }
+
+  /* Finally, check to see if we still need more circuits to learn
+   * a good build timeout. But if we're close to our max number we
+   * want, don't do another -- we want to leave a few slots open so
+   * we can still build circuits preemptively as needed. */
+  if (num < MAX_UNUSED_OPEN_CIRCUITS-2 &&
+      circuit_build_times_needs_circuits_now(&circ_times)) {
+    flags = CIRCLAUNCH_NEED_CAPACITY;
+    log_info(LD_CIRC,
+             "Have %d clean circs need another buildtime test circ.", num);
+    circuit_launch_by_router(CIRCUIT_PURPOSE_C_GENERAL, NULL, flags);
+    return;
+  }
 }
 
 /** Build a new test circuit every 5 minutes */
@@ -624,6 +716,11 @@ circuit_detach_stream(circuit_t *circ, edge_connection_t *conn)
   tor_fragile_assert();
 }
 
+/** If we haven't yet decided on a good timeout value for circuit
+ * building, we close idles circuits aggressively so we can get more
+ * data points. */
+#define IDLE_TIMEOUT_WHILE_LEARNING (10*60)
+
 /** Find each circuit that has been unused for too long, or dirty
  * for too long and has no streams on it: mark it for close.
  */
@@ -631,10 +728,18 @@ static void
 circuit_expire_old_circuits_clientside(time_t now)
 {
   circuit_t *circ;
-  time_t cutoff = now - get_options()->CircuitIdleTimeout;
+  time_t cutoff;
+
+  if (circuit_build_times_needs_circuits(&circ_times)) {
+    /* Circuits should be shorter lived if we need more of them
+     * for learning a good build timeout */
+    cutoff = now - IDLE_TIMEOUT_WHILE_LEARNING;
+  } else {
+    cutoff = now - get_options()->CircuitIdleTimeout;
+  }
 
   for (circ = global_circuitlist; circ; circ = circ->next) {
-    if (circ->marked_for_close || ! CIRCUIT_IS_ORIGIN(circ))
+    if (circ->marked_for_close || !CIRCUIT_IS_ORIGIN(circ))
       continue;
     /* If the circuit has been dirty for too long, and there are no streams
      * on it, mark it for close.
@@ -647,14 +752,38 @@ circuit_expire_old_circuits_clientside(time_t now)
                 circ->n_circ_id, (int)(now - circ->timestamp_dirty),
                 circ->purpose);
       circuit_mark_for_close(circ, END_CIRC_REASON_FINISHED);
-    } else if (!circ->timestamp_dirty &&
-               circ->state == CIRCUIT_STATE_OPEN &&
-               circ->purpose == CIRCUIT_PURPOSE_C_GENERAL) {
+    } else if (!circ->timestamp_dirty && circ->state == CIRCUIT_STATE_OPEN) {
       if (circ->timestamp_created < cutoff) {
-        log_debug(LD_CIRC,
-                  "Closing circuit that has been unused for %d seconds.",
-                  (int)(now - circ->timestamp_created));
-        circuit_mark_for_close(circ, END_CIRC_REASON_FINISHED);
+        if (circ->purpose == CIRCUIT_PURPOSE_C_GENERAL ||
+                circ->purpose == CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT ||
+                circ->purpose == CIRCUIT_PURPOSE_S_ESTABLISH_INTRO ||
+                circ->purpose == CIRCUIT_PURPOSE_TESTING ||
+                (circ->purpose >= CIRCUIT_PURPOSE_C_INTRODUCING &&
+                circ->purpose <= CIRCUIT_PURPOSE_C_REND_READY_INTRO_ACKED) ||
+                circ->purpose == CIRCUIT_PURPOSE_S_CONNECT_REND) {
+          log_debug(LD_CIRC,
+                    "Closing circuit that has been unused for %ld seconds.",
+                    (long)(now - circ->timestamp_created));
+          circuit_mark_for_close(circ, END_CIRC_REASON_FINISHED);
+        } else if (!TO_ORIGIN_CIRCUIT(circ)->is_ancient) {
+          /* Server-side rend joined circuits can end up really old, because
+           * they are reused by clients for longer than normal. The client
+           * controls their lifespan. (They never become dirty, because
+           * connection_exit_begin_conn() never marks anything as dirty.)
+           * Similarly, server-side intro circuits last a long time. */
+          if (circ->purpose != CIRCUIT_PURPOSE_S_REND_JOINED &&
+              circ->purpose != CIRCUIT_PURPOSE_S_INTRO) {
+            log_notice(LD_CIRC,
+                       "Ancient non-dirty circuit %d is still around after "
+                       "%ld seconds. Purpose: %d",
+                       TO_ORIGIN_CIRCUIT(circ)->global_identifier,
+                       (long)(now - circ->timestamp_created),
+                       circ->purpose);
+            /* FFFF implement a new circuit_purpose_to_string() so we don't
+             * just print out a number for circ->purpose */
+            TO_ORIGIN_CIRCUIT(circ)->is_ancient = 1;
+          }
+        }
       }
     }
   }
@@ -794,6 +923,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);
@@ -846,15 +980,29 @@ circuit_build_failed(origin_circuit_t *circ)
      * to blame, blame it. Also, avoid this relay for a while, and
      * fail any one-hop directory fetches destined for it. */
     const char *n_conn_id = circ->cpath->extend_info->identity_digest;
+    int already_marked = 0;
     if (circ->_base.n_conn) {
       or_connection_t *n_conn = circ->_base.n_conn;
+      if (n_conn->is_bad_for_new_circs) {
+        /* We only want to blame this router when a fresh healthy
+         * connection fails. So don't mark this router as newly failed,
+         * since maybe this was just an old circuit attempt that's
+         * finally timing out now. Also, there's no need to blow away
+         * circuits/streams/etc, since the failure of an unhealthy conn
+         * doesn't tell us much about whether a healthy conn would
+         * succeed. */
+        already_marked = 1;
+      }
       log_info(LD_OR,
                "Our circuit failed to get a response from the first hop "
                "(%s:%d). I'm going to try to rotate to a better connection.",
                n_conn->_base.address, n_conn->_base.port);
       n_conn->is_bad_for_new_circs = 1;
+    } else {
+      log_info(LD_OR,
+               "Our circuit died before the first hop with no connection");
     }
-    if (n_conn_id) {
+    if (n_conn_id && !already_marked) {
       entry_guard_register_connect_status(n_conn_id, 0, 1, time(NULL));
       /* if there are any one-hop streams waiting on this circuit, fail
        * them now so they can retry elsewhere. */
@@ -936,8 +1084,8 @@ circuit_launch_by_router(uint8_t purpose,
   if (exit)
     info = extend_info_from_router(exit);
   circ = circuit_launch_by_extend_info(purpose, info, flags);
-  if (info)
-    extend_info_free(info);
+
+  extend_info_free(info);
   return circ;
 }
 
@@ -1080,15 +1228,17 @@ circuit_get_open_circ_or_launch(edge_connection_t *conn,
       int severity = LOG_NOTICE;
       /* FFFF if this is a tunneled directory fetch, don't yell
        * as loudly. the user doesn't even know it's happening. */
-      if (options->UseBridges && bridges_known_but_down()) {
+      if (entry_list_is_constrained(options) &&
+          entries_known_but_down(options)) {
         log_fn(severity, LD_APP|LD_DIR,
-               "Application request when we're believed to be "
-               "offline. Optimistically trying known bridges again.");
-        bridges_retry_all();
+               "Application request when we haven't used client functionality "
+               "lately. Optimistically trying known %s again.",
+               options->UseBridges ? "bridges" : "entrynodes");
+        entries_retry_all(options);
       } else if (!options->UseBridges || any_bridge_descriptors_known()) {
         log_fn(severity, LD_APP|LD_DIR,
-               "Application request when we're believed to be "
-               "offline. Optimistically trying directory fetches again.");
+               "Application request when we haven't used client functionality "
+               "lately. Optimistically trying directory fetches again.");
         routerlist_retry_directory_downloads(time(NULL));
       }
     }
@@ -1111,7 +1261,7 @@ circuit_get_open_circ_or_launch(edge_connection_t *conn,
                                                 need_uptime)) {
         log_notice(LD_APP,
                    "No Tor server allows exit to %s:%d. Rejecting.",
-                   safe_str(conn->socks_request->address),
+                   safe_str_client(conn->socks_request->address),
                    conn->socks_request->port);
         return -1;
       }
@@ -1119,7 +1269,7 @@ circuit_get_open_circ_or_launch(edge_connection_t *conn,
       /* XXXX022 Duplicates checks in connection_ap_handshake_attach_circuit */
       routerinfo_t *router = router_get_by_nickname(conn->chosen_exit_name, 1);
       int opt = conn->chosen_exit_optional;
-      if (router && !connection_ap_can_use_exit(conn, router)) {
+      if (router && !connection_ap_can_use_exit(conn, router, 0)) {
         log_fn(opt ? LOG_INFO : LOG_WARN, LD_APP,
                "Requested exit point '%s' would refuse request. %s.",
                conn->chosen_exit_name, opt ? "Trying others" : "Closing");
@@ -1152,19 +1302,14 @@ circuit_get_open_circ_or_launch(edge_connection_t *conn,
       if (!extend_info) {
         log_info(LD_REND,
                  "No intro points for '%s': re-fetching service descriptor.",
-                 safe_str(conn->rend_data->onion_address));
-        /* Fetch both, v0 and v2 rend descriptors in parallel. Use whichever
-         * arrives first. Exception: When using client authorization, only
-         * fetch v2 descriptors.*/
+                 safe_str_client(conn->rend_data->onion_address));
         rend_client_refetch_v2_renddesc(conn->rend_data);
-        if (conn->rend_data->auth_type == REND_NO_AUTH)
-          rend_client_refetch_renddesc(conn->rend_data->onion_address);
         conn->_base.state = AP_CONN_STATE_RENDDESC_WAIT;
         return 0;
       }
       log_info(LD_REND,"Chose '%s' as intro point for '%s'.",
                extend_info->nickname,
-               safe_str(conn->rend_data->onion_address));
+               safe_str_client(conn->rend_data->onion_address));
     }
 
     /* If we have specified a particular exit node for our
@@ -1193,7 +1338,7 @@ circuit_get_open_circ_or_launch(edge_connection_t *conn,
             }
             if (tor_addr_from_str(&addr, conn->socks_request->address) < 0) {
               log_info(LD_DIR, "Broken address %s on tunnel conn. Closing.",
-                       escaped_safe_str(conn->socks_request->address));
+                       escaped_safe_str_client(conn->socks_request->address));
               return -1;
             }
             extend_info = extend_info_alloc(conn->chosen_exit_name+1,
@@ -1235,8 +1380,7 @@ circuit_get_open_circ_or_launch(edge_connection_t *conn,
                                            flags);
     }
 
-    if (extend_info)
-      extend_info_free(extend_info);
+    extend_info_free(extend_info);
 
     if (desired_circuit_purpose != CIRCUIT_PURPOSE_C_GENERAL) {
       /* help predict this next time */
@@ -1418,7 +1562,7 @@ connection_ap_handshake_attach_circuit(edge_connection_t *conn)
       LOG_INFO : LOG_NOTICE;
     log_fn(severity, LD_APP,
            "Tried for %d seconds to get a connection to %s:%d. Giving up.",
-           conn_age, safe_str(conn->socks_request->address),
+           conn_age, safe_str_client(conn->socks_request->address),
            conn->socks_request->port);
     return -1;
   }
@@ -1445,7 +1589,7 @@ connection_ap_handshake_attach_circuit(edge_connection_t *conn)
         }
         return -1;
       }
-      if (router && !connection_ap_can_use_exit(conn, router)) {
+      if (router && !connection_ap_can_use_exit(conn, router, 0)) {
         log_fn(opt ? LOG_INFO : LOG_WARN, LD_APP,
                "Requested exit point '%s' would refuse request. %s.",
                conn->chosen_exit_name, opt ? "Trying others" : "Closing");