Merge remote-tracking branch 'tor-github/pr/315'

changes/ticket27169

@@ -0,0 +1,6 @@
+  o Minor features (bootstrap):
+    - Improve user experience by deferring directory progress
+      reporting until after a connection to a relay or bridge has
+      succeeded.  This avoids reporting 80% progress based on cached
+      directory information when we can't even connect to a bridge or
+      relay.  Closes ticket 27169.

src/core/or/circuitbuild.c

@@ -1051,14 +1051,10 @@ circuit_build_no_more_hops(origin_circuit_t *circ)
     const or_options_t *options = get_options();
     note_that_we_completed_a_circuit();
     /* FFFF Log a count of known routers here */
-    log_notice(LD_GENERAL,
-               "Tor has successfully opened a circuit. "
-               "Looks like client functionality is working.");
-    if (control_event_bootstrap(BOOTSTRAP_STATUS_DONE, 0) == 0) {
-      log_notice(LD_GENERAL,
-                 "Tor has successfully opened a circuit. "
-                 "Looks like client functionality is working.");
-    }
+    log_info(LD_GENERAL,
+             "Tor has successfully opened a circuit. "
+             "Looks like client functionality is working.");
+    control_event_bootstrap(BOOTSTRAP_STATUS_DONE, 0);
     control_event_client_status(LOG_NOTICE, "CIRCUIT_ESTABLISHED");
     clear_broken_connection_map(1);
     if (server_mode(options) && !check_whether_orport_reachable(options)) {

src/core/or/connection_or.c

@@ -705,6 +705,7 @@ connection_or_finished_connecting(or_connection_t *or_conn)
   log_debug(LD_HANDSHAKE,"OR connect() to router at %s:%u finished.",
             conn->address,conn->port);
   control_event_bootstrap(BOOTSTRAP_STATUS_HANDSHAKE, 0);
+  control_event_boot_first_orconn();
 
   if (proxy_type != PROXY_NONE) {
     /* start proxy handshake */

src/core/or/relay.c

@@ -1389,8 +1389,8 @@ connection_edge_process_relay_cell_not_open(
         case DIR_PURPOSE_FETCH_SERVERDESC:
         case DIR_PURPOSE_FETCH_MICRODESC:
           if (TO_DIR_CONN(dirconn)->router_purpose == ROUTER_PURPOSE_GENERAL)
-            control_event_bootstrap(BOOTSTRAP_STATUS_LOADING_DESCRIPTORS,
-                                    count_loading_descriptors_progress());
+            control_event_boot_dir(BOOTSTRAP_STATUS_LOADING_DESCRIPTORS,
+                                   count_loading_descriptors_progress());
           break;
       }
     }

src/feature/control/control.c

@@ -7073,6 +7073,11 @@ bootstrap_status_to_string(bootstrap_status_t s, const char **tag,
  * Tor initializes. */
 static int bootstrap_percent = BOOTSTRAP_STATUS_UNDEF;
 
+/** Like bootstrap_percent, but only takes on the enumerated values in
+ * bootstrap_status_t.
+ */
+static int bootstrap_phase = BOOTSTRAP_STATUS_UNDEF;
+
 /** As bootstrap_percent, but holds the bootstrapping level at which we last
  * logged a NOTICE-level message. We use this, plus BOOTSTRAP_PCT_INCREMENT,
  * to avoid flooding the log with a new message every time we get a few more
@@ -7095,23 +7100,46 @@ static int bootstrap_problems = 0;
  */
 #define BOOTSTRAP_PCT_INCREMENT 5
 
+/** Do the actual logging and notifications for
+ * control_event_bootstrap().  Doesn't change any state beyond that.
+ */
+static void
+control_event_bootstrap_core(int loglevel, bootstrap_status_t status,
+                             int progress)
+{
+  char buf[BOOTSTRAP_MSG_LEN];
+  const char *tag, *summary;
+
+  bootstrap_status_to_string(status, &tag, &summary);
+  /* Locally reset status if there's incremental progress */
+  if (progress)
+    status = progress;
+
+  tor_log(loglevel, LD_CONTROL,
+          "Bootstrapped %d%%: %s", status, summary);
+  tor_snprintf(buf, sizeof(buf),
+               "BOOTSTRAP PROGRESS=%d TAG=%s SUMMARY=\"%s\"",
+               status, tag, summary);
+  tor_snprintf(last_sent_bootstrap_message,
+               sizeof(last_sent_bootstrap_message),
+               "NOTICE %s", buf);
+  control_event_client_status(LOG_NOTICE, "%s", buf);
+}
+
 /** Called when Tor has made progress at bootstrapping its directory
  * information and initial circuits.
  *
  * <b>status</b> is the new status, that is, what task we will be doing
  * next. <b>progress</b> is zero if we just started this task, else it
  * represents progress on the task.
- *
- * Return true if we logged a message at level NOTICE, and false otherwise.
  */
-int
+void
 control_event_bootstrap(bootstrap_status_t status, int progress)
 {
-  const char *tag, *summary;
-  char buf[BOOTSTRAP_MSG_LEN];
+  int loglevel = LOG_NOTICE;
 
   if (bootstrap_percent == BOOTSTRAP_STATUS_DONE)
-    return 0; /* already bootstrapped; nothing to be done here. */
+    return; /* already bootstrapped; nothing to be done here. */
 
   /* special case for handshaking status, since our TLS handshaking code
    * can't distinguish what the connection is going to be for. */
@@ -7123,45 +7151,70 @@ control_event_bootstrap(bootstrap_status_t status, int progress)
     }
   }
 
-  if (status > bootstrap_percent ||
-      (progress && progress > bootstrap_percent)) {
-    int loglevel = LOG_NOTICE;
-    bootstrap_status_to_string(status, &tag, &summary);
-
-    if (status <= bootstrap_percent &&
-        (progress < notice_bootstrap_percent + BOOTSTRAP_PCT_INCREMENT)) {
-      /* We log the message at info if the status hasn't advanced, and if less
-       * than BOOTSTRAP_PCT_INCREMENT progress has been made.
-       */
+  if (status <= bootstrap_percent) {
+    /* If there's no new progress, return early. */
+    if (!progress || progress <= bootstrap_percent)
+      return;
+    /* Log at INFO if not enough progress happened. */
+    if (progress < notice_bootstrap_percent + BOOTSTRAP_PCT_INCREMENT)
       loglevel = LOG_INFO;
-    }
+  }
 
-    tor_log(loglevel, LD_CONTROL,
-            "Bootstrapped %d%%: %s", progress ? progress : status, summary);
-    tor_snprintf(buf, sizeof(buf),
-        "BOOTSTRAP PROGRESS=%d TAG=%s SUMMARY=\"%s\"",
-        progress ? progress : status, tag, summary);
-    tor_snprintf(last_sent_bootstrap_message,
-                 sizeof(last_sent_bootstrap_message),
-                 "NOTICE %s", buf);
-    control_event_client_status(LOG_NOTICE, "%s", buf);
-    if (status > bootstrap_percent) {
-      bootstrap_percent = status; /* new milestone reached */
-    }
-    if (progress > bootstrap_percent) {
-      /* incremental progress within a milestone */
-      bootstrap_percent = progress;
-      bootstrap_problems = 0; /* Progress! Reset our problem counter. */
-    }
-    if (loglevel == LOG_NOTICE &&
-        bootstrap_percent > notice_bootstrap_percent) {
-      /* Remember that we gave a notice at this level. */
-      notice_bootstrap_percent = bootstrap_percent;
-    }
-    return loglevel == LOG_NOTICE;
+  control_event_bootstrap_core(loglevel, status, progress);
+
+  if (status > bootstrap_percent) {
+    bootstrap_phase = status; /* new milestone reached */
+    bootstrap_percent = status;
+  }
+  if (progress > bootstrap_percent) {
+    /* incremental progress within a milestone */
+    bootstrap_percent = progress;
+    bootstrap_problems = 0; /* Progress! Reset our problem counter. */
   }
+  if (loglevel == LOG_NOTICE &&
+      bootstrap_percent > notice_bootstrap_percent) {
+    /* Remember that we gave a notice at this level. */
+    notice_bootstrap_percent = bootstrap_percent;
+  }
+}
 
-  return 0;
+/** Flag whether we've opened an OR_CONN yet  */
+static int bootstrap_first_orconn = 0;
+
+/** Like bootstrap_phase, but for (possibly deferred) directory progress */
+static int bootstrap_dir_phase = BOOTSTRAP_STATUS_UNDEF;
+
+/** Like bootstrap_problems, but for (possibly deferred) directory progress  */
+static int bootstrap_dir_progress = BOOTSTRAP_STATUS_UNDEF;
+
+/** Defer directory info bootstrap events until we have successfully
+ * completed our first connection to a router.  */
+void
+control_event_boot_dir(bootstrap_status_t status, int progress)
+{
+  if (status > bootstrap_dir_progress) {
+    bootstrap_dir_progress = status;
+    bootstrap_dir_phase = status;
+  }
+  if (progress && progress >= bootstrap_dir_progress) {
+    bootstrap_dir_progress = progress;
+  }
+
+  /* Don't report unless we have successfully opened at least one OR_CONN */
+  if (!bootstrap_first_orconn)
+    return;
+
+  control_event_bootstrap(status, progress);
+}
+
+/** Set a flag to allow reporting of directory bootstrap progress.
+ * (Code that reports completion of an OR_CONN calls this.)  Also,
+ * report directory progress so far. */
+void
+control_event_boot_first_orconn(void)
+{
+  bootstrap_first_orconn = 1;
+  control_event_bootstrap(bootstrap_dir_phase, bootstrap_dir_progress);
 }
 
 /** Called when Tor has failed to make bootstrapping progress in a way
@@ -7198,9 +7251,7 @@ control_event_bootstrap_problem(const char *warn, const char *reason,
   if (we_are_hibernating())
     dowarn = 0;
 
-  while (status>=0 && bootstrap_status_to_string(status, &tag, &summary) < 0)
-    status--; /* find a recognized status string based on current progress */
-  status = bootstrap_percent; /* set status back to the actual number */
+  tor_assert(bootstrap_status_to_string(bootstrap_phase, &tag, &summary) == 0);
 
   severity = dowarn ? LOG_WARN : LOG_INFO;
 

src/feature/control/control.h

@@ -191,10 +191,12 @@ void enable_control_logging(void);
 
 void monitor_owning_controller_process(const char *process_spec);
 
-int control_event_bootstrap(bootstrap_status_t status, int progress);
+void control_event_bootstrap(bootstrap_status_t status, int progress);
 MOCK_DECL(void, control_event_bootstrap_prob_or,(const char *warn,
                                                  int reason,
                                                  or_connection_t *or_conn));
+void control_event_boot_dir(bootstrap_status_t status, int progress);
+void control_event_boot_first_orconn(void);
 void control_event_bootstrap_problem(const char *warn, const char *reason,
                                      const connection_t *conn, int dowarn);
 

src/feature/dircache/directory.c

@@ -2226,8 +2226,8 @@ load_downloaded_routers(const char *body, smartlist_t *which,
   added = router_load_routers_from_string(body, NULL, SAVED_NOWHERE, which,
                                   descriptor_digests, buf);
   if (added && general)
-    control_event_bootstrap(BOOTSTRAP_STATUS_LOADING_DESCRIPTORS,
-                            count_loading_descriptors_progress());
+    control_event_boot_dir(BOOTSTRAP_STATUS_LOADING_DESCRIPTORS,
+                           count_loading_descriptors_progress());
   return added;
 }
 
@@ -2949,8 +2949,8 @@ handle_response_fetch_microdesc(dir_connection_t *conn,
       dir_microdesc_download_failed(which, status_code, conn->identity_digest);
     }
     if (mds && smartlist_len(mds)) {
-      control_event_bootstrap(BOOTSTRAP_STATUS_LOADING_DESCRIPTORS,
-                              count_loading_descriptors_progress());
+      control_event_boot_dir(BOOTSTRAP_STATUS_LOADING_DESCRIPTORS,
+                             count_loading_descriptors_progress());
       directory_info_has_arrived(now, 0, 1);
     }
     SMARTLIST_FOREACH(which, char *, cp, tor_free(cp));

src/feature/nodelist/nodelist.c

@@ -2528,7 +2528,7 @@ update_router_have_minimum_dir_info(void)
                    (int)(paths*100), status);
       tor_free(status);
       res = 0;
-      control_event_bootstrap(BOOTSTRAP_STATUS_REQUESTING_DESCRIPTORS, 0);
+      control_event_boot_dir(BOOTSTRAP_STATUS_REQUESTING_DESCRIPTORS, 0);
       goto done;
     }
 
@@ -2553,10 +2553,9 @@ update_router_have_minimum_dir_info(void)
   /* If paths have just become available in this update. */
   if (res && !have_min_dir_info) {
     control_event_client_status(LOG_NOTICE, "ENOUGH_DIR_INFO");
-    if (control_event_bootstrap(BOOTSTRAP_STATUS_CONN_OR, 0) == 0) {
-      log_notice(LD_DIR,
-              "We now have enough directory information to build circuits.");
-    }
+    control_event_boot_dir(BOOTSTRAP_STATUS_CONN_OR, 0);
+    log_info(LD_DIR,
+             "We now have enough directory information to build circuits.");
   }
 
   /* If paths have just become unavailable in this update. */

src/test/test_controller_events.c

@@ -322,6 +322,72 @@ test_cntev_event_mask(void *arg)
   ;
 }
 
+static char *saved_event_str = NULL;
+
+static void
+mock_queue_control_event_string(uint16_t event, char *msg)
+{
+  (void)event;
+
+  tor_free(saved_event_str);
+  saved_event_str = msg;
+}
+
+/* Helper macro for checking bootstrap control event strings */
+#define assert_bootmsg(s)                                               \
+  tt_ptr_op(strstr(saved_event_str, "650 STATUS_CLIENT NOTICE "         \
+                   "BOOTSTRAP PROGRESS=" s), OP_EQ, saved_event_str)
+
+/* Test deferral of directory bootstrap messages (requesting_descriptors) */
+static void
+test_cntev_dirboot_defer_desc(void *arg)
+{
+  (void)arg;
+
+  MOCK(queue_control_event_string, mock_queue_control_event_string);
+  control_testing_set_global_event_mask(EVENT_MASK_(EVENT_STATUS_CLIENT));
+  control_event_bootstrap(BOOTSTRAP_STATUS_STARTING, 0);
+  assert_bootmsg("0 TAG=starting");
+  /* This event should get deferred */
+  control_event_boot_dir(BOOTSTRAP_STATUS_REQUESTING_DESCRIPTORS, 0);
+  assert_bootmsg("0 TAG=starting");
+  control_event_bootstrap(BOOTSTRAP_STATUS_CONN_DIR, 0);
+  assert_bootmsg("5 TAG=conn_dir");
+  control_event_bootstrap(BOOTSTRAP_STATUS_HANDSHAKE, 0);
+  assert_bootmsg("10 TAG=handshake_dir");
+  /* The deferred event should appear */
+  control_event_boot_first_orconn();
+  assert_bootmsg("45 TAG=requesting_descriptors");
+ done:
+  tor_free(saved_event_str);
+  UNMOCK(queue_control_event_string);
+}
+
+/* Test deferral of directory bootstrap messages (conn_or) */
+static void
+test_cntev_dirboot_defer_orconn(void *arg)
+{
+  (void)arg;
+
+  MOCK(queue_control_event_string, mock_queue_control_event_string);
+  control_testing_set_global_event_mask(EVENT_MASK_(EVENT_STATUS_CLIENT));
+  control_event_bootstrap(BOOTSTRAP_STATUS_STARTING, 0);
+  assert_bootmsg("0 TAG=starting");
+  /* This event should get deferred */
+  control_event_boot_dir(BOOTSTRAP_STATUS_CONN_OR, 0);
+  assert_bootmsg("0 TAG=starting");
+  control_event_bootstrap(BOOTSTRAP_STATUS_CONN_DIR, 0);
+  assert_bootmsg("5 TAG=conn_dir");
+  control_event_bootstrap(BOOTSTRAP_STATUS_HANDSHAKE, 0);
+  assert_bootmsg("10 TAG=handshake_dir");
+  /* The deferred event should appear */
+  control_event_boot_first_orconn();
+  assert_bootmsg("80 TAG=conn_or");
+ done:
+  tor_free(saved_event_str);
+  UNMOCK(queue_control_event_string);
+}
+
 #define TEST(name, flags)                                               \
   { #name, test_cntev_ ## name, flags, 0, NULL }
 
@@ -330,5 +396,7 @@ struct testcase_t controller_event_tests[] = {
   TEST(append_cell_stats, TT_FORK),
   TEST(format_cell_stats, TT_FORK),
   TEST(event_mask, TT_FORK),
+  TEST(dirboot_defer_desc, TT_FORK),
+  TEST(dirboot_defer_orconn, TT_FORK),
   END_OF_TESTCASES
 };