include tags in the bootstrap status events. also document the

bootstrapping process and how the phases break down.


svn:r15020

3 files changed, 173 insertions, 90 deletions

diff --git a/doc/spec/proposals/ideas/xxx-bootstrap-phases.txt b/doc/spec/proposals/ideas/xxx-bootstrap-phases.txt
index e7d67d8ad0..aba3ffbba5 100644
--- a/doc/spec/proposals/ideas/xxx-bootstrap-phases.txt
+++ b/doc/spec/proposals/ideas/xxx-bootstrap-phases.txt
@@ -17,8 +17,8 @@ Status: Open
   This proposal describes a new client status event so Tor can give
   more details to the controller. Section 2 describes the changes to the
   controller protocol; Section 3 describes Tor's internal bootstrapping
-  phases assuming everything goes correctly; and Section 4 describes
-  how and when Tor chooses to issue bootstrap warnings.
+  phases, both when everything is going correctly and when Tor detects
+  a problem and issues a bootstrap warning.
 
 2. Controller event syntax.
 
@@ -29,7 +29,7 @@ Status: Open
 
   So in this case we send
   650 STATUS_CLIENT NOTICE/WARN BOOTSTRAP \
-  PROGRESS=num TAG=string SUMMARY=string
+  PROGRESS=num TAG=string SUMMARY=string WARNING=string
 
   "Progress" gives a number between 0 and 100 for how far through
   the bootstrapping process we are. "Summary" is a string that can be
@@ -41,66 +41,135 @@ Status: Open
 
   The severity describes whether this is a normal bootstrap phase
   (severity notice) or an indication of a bootstrapping problem
-  (severity warn).
+  (severity warn). If severity warn, it should also include a "warning"
+  argument with any hints Tor has to offer about why it's having troubles
+  bootstrapping.
+
+  It is suggested that controllers start out in phase 0 ("starting"), and
+  then watch for either a bootstrap status event (meaning the Tor they're
+  using is sufficiently new to produce them) or a circuit_established
+  status event (meaning bootstrapping is finished).
 
 3. The bootstrap phases.
 
-  Phase 0: tag=STARTING
+  This section describes the various phases currently reported by
+  Tor. Controllers should not assume that the percentages and tags listed
+  here will continue to match up, or even that the tags will stay in
+  the same order. Some phases might also be skipped (not reported) if the
+  associated bootstrap step is already complete.
+
+  Phase 0:
+  tag=starting summary="starting"
+
+  Tor starts out in this phase. It doesn't actually send a status event
+  to say so.
+
+  Phase 5:
+  tag=conn_dir summary="Connecting to directory mirror"
+
+  Tor sends this event as soon as Tor has chosen a directory mirror ---
+  one of the authorities if bootstrapping for the first time or after
+  a long downtime, or one of the relays listed in its cached directory
+  information otherwise.
+
+  Tor will stay at this phase until it has successfully established
+  a TCP connection with some directory mirror. Problems in this phase
+  generally happen because Tor doesn't have a network connection, or
+  because the local firewall is dropping SYN packets.
+
+  Phase 10
+  tag=handshake_dir summary="Finishing handshake with directory mirror"
+
+  This event occurs when Tor establishes a TCP connection with a relay
+  (or its https proxy if it's using one). Tor remains in this phase until
+  the TLS handshake with the relay is finished.
+
+  Problems in this phase generally happen because Tor's firewall is
+  doing more sophisticated MITM attacks on it, or doing packet-level
+  keyword recognition of Tor's handshake.
+
+  Phase 15:
+  tag=onehop_create summary="Establishing one-hop circuit for dir info"
+
+  Once TLS is finished with a relay, Tor will send a CREATE_FAST cell
+  to establish a one-hop circuit for retrieving directory information.
+  It will remain in this phase until it receives the CREATED_FAST cell
+  back, indicating that the circuit is ready.
+
+  Phase 20:
+  tag=requesting_status summary="Asking for networkstatus consensus"
+
+  Once we've finished our one-hop circuit, we will start a new stream
+  for fetching the networkstatus consensus. We'll stay in this phase
+  until we get the 'connected' relay cell back, indicating that we've
+  established a directory connection.
+
+  Phase 25:
+  tag=loading_status summary="Loading networkstatus consensus"
+
+  Once we've established a directory connection, we will start fetching
+  the networkstatus consensus document. This could take a while; this
+  phase is a good opportunity for using the "progress" keyword to indicate
+  partial progress.
+
+  This phase could stall if the directory mirror we picked doesn't
+  have a copy of the networkstatus consensus so we have to ask another,
+  or it does give us a copy but we don't find it valid.
+
+  Phase 40:
+  tag=loading_keys summary="Loading authority key certs"
 
-  Phase 5: tag=CONN_DIR
+  Sometimes when we've finished loading the networkstatus consensus,
+  we find that we don't have all the authority key certificates for the
+  keys that signed the consensus. At that point we put the consensus we
+  fetched on hold and fetch the keys so we can verify the signatures.
 
-  Phase 10: tag=HANDSHAKE_DIR
+  Phase 45
+  tag=requesting_descriptors summary="Asking for relay descriptors"
 
-  Phase 15: tag=ONEHOP_CREATE
+  Once we have a valid networkstatus consensus and we've checked all
+  its signatures, we start asking for relay descriptors. We stay in this
+  phase until we have received a 'connected' relay cell in response to
+  a request for descriptors.
 
-  Phase 20: tag=REQUESTING_STATUS
+  Phase 50:
+  tag=loading_descriptors summary="Loading relay descriptors"
 
-  Phase 25: tag=LOADING_STATUS
+  We will ask for relay descriptors from several different locations,
+  so this step will probably make up the bulk of the bootstrapping,
+  especially for users with slow connections. We stay in this phase until
+  we have descriptors for at least 1/4 of the usable relays listed in
+  the networkstatus consensus. This phase is also a good opportunity to
+  use the "progress" keyword to indicate partial steps.
 
-  Phase 40: tag=LOADING_KEYS
+  Phase 80:
+  tag=conn_or summary="Connecting to entry guard"
 
-  Phase 45: tag=REQUESTING_DESCRIPTORS
+  Once we have a valid consensus and enough relay descriptors, we choose
+  some entry guards and start trying to build some circuits. This step
+  is similar to the "conn_dir" phase above; the only difference is
+  the context.
 
-  Phase 50: tag=LOADING_DESCRIPTORS
+  If a Tor starts with enough recent cached directory information,
+  its first bootstrap status event will be for the conn_or phase.
 
-  Phase 80: tag=CONN_OR
+  Phase 85:
+  tag=handshake_or summary="Finishing handshake with entry guard"
 
-  Phase 85: tag=HANDSHAKE_OR
+  This phase is similar to the "handshake_dir" phase, but it gets reached
+  if we finish a TCP connection to a Tor relay and we have already reached
+  the "conn_or" phase. We'll stay in this phase until we complete a TLS
+  handshake with a Tor relay.
 
-  Phase 90: tag=CIRCUIT_CREATE
+  Phase 90:
+  tag=circuit_create "Establishing circuits"
 
-  Phase 100: tag=DONE
+  Once we've finished our TLS handshake with an entry guard, we will
+  set about rying to make some 3-hop circuits in case we need them soon.
 
+  Phase 100:
+  tag=done summary="Done"
 
- 5: fetching authority key certs
-    LOADING_KEYS
-    (authority_certs_fetch_missing)
-10: Connecting to directory mirror
-    CONN_DIR
-    (circuit_handle_first_hop)
-15: Finishing handshake with directory mirror
-    HANDSHAKE_DIR
-    (connection_or_finished_connecting)
-20: Establishing one-hop circuit for dir info
-    ONEHOP_CREATE
-    (circuit_send_next_onion_skin)
-25: Asking for networkstatus consensus
-    REQUESTING_STATUS
-    (circuit_send_next_onion_skin)
-30: Fetching networkstatus consensus
-    LOADING_STATUS
-    (update_consensus_networkstatus_downloads)
-50: Fetching relay descriptors
-    LOADING_DESCRIPTORS
-    (update_router_have_minimum_dir_info)
-80: Connecting to entry guard
-    CONN_OR
-    (update_router_have_minimum_dir_info)
-85: Finishing handshake with entry guard
-    HANDSHAKE_OR
-    (connection_or_finished_connecting)
-90: Establishing circuit
-    CIRCUIT_CREATE
-    (circuit_send_next_onion_skin)
-100: Done
+  A full 3-hop circuit has been established. Tor is ready to handle
+  application connections now.
 
diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c
index ef251da233..2875222c76 100644
--- a/src/or/circuitbuild.c
+++ b/src/or/circuitbuild.c
@@ -1059,7 +1059,7 @@ new_route_len(uint8_t purpose, extend_info_t *exit,
 
   num_acceptable_routers = count_acceptable_routers(routers);
 
-  log_debug(LD_CIRC,"Chosen route length %d (%d/%d routers available).",
+  log_debug(LD_CIRC,"Chosen route length %d (%d/%d routers suitable).",
             routelen, num_acceptable_routers, smartlist_len(routers));
 
   if (num_acceptable_routers < 2) {
diff --git a/src/or/control.c b/src/or/control.c
index c4a4e4932c..97ca13225a 100644
--- a/src/or/control.c
+++ b/src/or/control.c
@@ -3823,43 +3823,72 @@ init_cookie_authentication(int enabled)
   return 0;
 }
 
-/** Convert the name of a bootstrapping phase <b>s</b> into a string
- * suitable for display by the controller. */
-static const char *
-bootstrap_status_to_string(bootstrap_status_t s)
+/** Convert the name of a bootstrapping phase <b>s</b> into strings
+ * <b>tag</b> and <b>summary</b> suitable for display by the controller. */
+static void
+bootstrap_status_to_string(bootstrap_status_t s, const char **tag,
+                           const char **summary)
 {
   switch (s) {
     case BOOTSTRAP_STATUS_STARTING:
-      return "Starting";
+      *tag = "starting";
+      *summary = "Starting";
+      break;
     case BOOTSTRAP_STATUS_CONN_DIR:
-      return "Connecting to directory mirror";
+      *tag = "conn_dir";
+      *summary = "Connecting to directory mirror";
+      break;
     case BOOTSTRAP_STATUS_HANDSHAKE:
-      return "Finishing handshake";
+      *tag = "status_handshake";
+      *summary = "Finishing handshake";
+      break;
     case BOOTSTRAP_STATUS_HANDSHAKE_DIR:
-      return "Finishing handshake with directory mirror";
+      *tag = "handshake_dir";
+      *summary = "Finishing handshake with directory mirror";
+      break;
     case BOOTSTRAP_STATUS_ONEHOP_CREATE:
-      return "Establishing one-hop circuit for dir info";
+      *tag = "onehop_create";
+      *summary = "Establishing one-hop circuit for dir info";
+      break;
     case BOOTSTRAP_STATUS_REQUESTING_STATUS:
-      return "Asking for networkstatus consensus";
+      *tag = "requesting_status";
+      *summary = "Asking for networkstatus consensus";
+      break;
     case BOOTSTRAP_STATUS_LOADING_STATUS:
-      return "Loading networkstatus consensus";
+      *tag = "loading_status";
+      *summary = "Loading networkstatus consensus";
+      break;
     case BOOTSTRAP_STATUS_LOADING_KEYS:
-      return "Loading authority key certs";
+      *tag = "loading_keys";
+      *summary = "Loading authority key certs";
+      break;
     case BOOTSTRAP_STATUS_REQUESTING_DESCRIPTORS:
-      return "Asking for relay descriptors";
+      *tag = "requesting_descriptors";
+      *summary = "Asking for relay descriptors";
+      break;
     case BOOTSTRAP_STATUS_LOADING_DESCRIPTORS:
-      return "Loading relay descriptors";
+      *tag = "loading_descriptors";
+      *summary = "Loading relay descriptors";
+      break;
     case BOOTSTRAP_STATUS_CONN_OR:
-      return "Connecting to entry guard";
+      *tag = "conn_or";
+      *summary = "Connecting to entry guard";
+      break;
     case BOOTSTRAP_STATUS_HANDSHAKE_OR:
-      return "Finishing handshake with entry guard";
+      *tag = "handshake_or";
+      *summary = "Finishing handshake with entry guard";
+      break;
     case BOOTSTRAP_STATUS_CIRCUIT_CREATE:
-      return "Establishing circuits";
+      *tag = "circuit_create";
+      *summary = "Establishing circuits";
+      break;
     case BOOTSTRAP_STATUS_DONE:
-      return "Done!";
+      *tag = "done";
+      *summary = "Done";
+      break;
     default:
       log_warn(LD_BUG, "Unrecognized bootstrap status code %d", s);
-      return "unknown";
+      *tag = *summary = "unknown";
   }
 }
 
@@ -3872,6 +3901,7 @@ int
 control_event_bootstrap(bootstrap_status_t status, int percent)
 {
   static int last_percent = 0;
+  const char *tag, *summary;
 
   if (last_percent == 100)
     return 0; /* already bootstrapped; nothing to be done here. */
@@ -3886,35 +3916,19 @@ control_event_bootstrap(bootstrap_status_t status, int percent)
     }
   }
 
-#if 0
-  if (status <= last_percent)
-    switch (status) {
-      case BOOTSTRAP_STATUS_CONN_DIR:
-      case BOOTSTRAP_STATUS_ONEHOP_CREATE:
-      case BOOTSTRAP_STATUS_HANDSHAKE_DIR:
-      case BOOTSTRAP_STATUS_REQUESTING_STATUS:
-      case BOOTSTRAP_STATUS_REQUESTING_DESCRIPTORS:
-        boring = 1;
-        break;
-      default: ;
-    }
-
-  if (!boring)
-#endif
   if (status > last_percent || (percent && percent > last_percent)) {
+    bootstrap_status_to_string(status, &tag, &summary);
     log_notice(LD_CONTROL, "Bootstrapped %d%%: %s.",
-               percent ? percent : status,
-               bootstrap_status_to_string(status));
+               percent ? percent : status, summary);
     control_event_client_status(LOG_NOTICE,
-        "BOOTSTRAP PROGRESS=%d SUMMARY=\"%s\"",
-        percent ? percent : status,
-        bootstrap_status_to_string(status));
+        "BOOTSTRAP PROGRESS=%d TAG=%s SUMMARY=\"%s\"",
+        percent ? percent : status, tag, summary);
   }
 
-  if (percent > last_percent) /* incremental progress within a milestone */
-    last_percent = percent;
   if (status > last_percent) /* new milestone reached */
     last_percent = status ;
+  if (percent > last_percent) /* incremental progress within a milestone */
+    last_percent = percent;
   return 0;
 }