Log descriptor-download bootstrapping messages less verbosely

This is a fix for 9963.  I say this is a feature, but if it's a
bugfix, it's a bugfix on 0.2.4.18-rc.

Old behavior:

    Mar 27 11:02:19.000 [notice] Bootstrapped 50%: Loading relay descriptors.
    Mar 27 11:02:20.000 [notice] Bootstrapped 51%: Loading relay descriptors.
    Mar 27 11:02:20.000 [notice] Bootstrapped 52%: Loading relay descriptors.
    ... [Many lines omitted] ...
    Mar 27 11:02:29.000 [notice] Bootstrapped 78%: Loading relay descriptors.
    Mar 27 11:02:33.000 [notice] We now have enough directory information to build circuits.

New behavior:

    Mar 27 11:16:17.000 [notice] Bootstrapped 50%: Loading relay descriptors
    Mar 27 11:16:19.000 [notice] Bootstrapped 55%: Loading relay descriptors
    Mar 27 11:16:21.000 [notice] Bootstrapped 60%: Loading relay descriptors
    Mar 27 11:16:21.000 [notice] Bootstrapped 65%: Loading relay descriptors
    Mar 27 11:16:21.000 [notice] Bootstrapped 70%: Loading relay descriptors
    Mar 27 11:16:21.000 [notice] Bootstrapped 75%: Loading relay descriptors
    Mar 27 11:16:21.000 [notice] We now have enough directory information to build circuits.

diff --git a/changes/bug9963 b/changes/bug9963
new file mode 100644 (file)
index 0000000..b8b95f2
--- /dev/null
+++ b/changes/bug9963
@@ -0,0 +1,5 @@
+  o Minor features:
+    - Don't log so many notice-level bootstrapping messages at startup about
+      downloading descriptors. Previously, we'd log a notice whenever we
+      learned about more routers. Now, we only log a notice at every 5% of
+      progress. Fixes bug 9963.

diff --git a/src/or/control.c b/src/or/control.c
index a88de12d69ba9f07dda8b467c78518e7c37b7587..27aeab186e8ae4b1d31f0bb3db44c845dcb66209 100644 (file)
--- a/src/or/control.c
+++ b/src/or/control.c
@@ -4636,16 +4636,28 @@ bootstrap_status_to_string(bootstrap_status_t s, const char **tag,
  * Tor initializes. */
 static int bootstrap_percent = 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
+ * microdescriptors */
+static int notice_bootstrap_percent = 0;
+
 /** How many problems have we had getting to the next bootstrapping phase?
  * These include failure to establish a connection to a Tor relay,
  * failures to finish the TLS handshake, failures to validate the
  * consensus document, etc. */
 static int bootstrap_problems = 0;
 
-/* We only tell the controller once we've hit a threshold of problems
+/** We only tell the controller once we've hit a threshold of problems
  * for the current phase. */
 #define BOOTSTRAP_PROBLEM_THRESHOLD 10
 
+/** When our bootstrapping progress level changes, but our bootstrapping
+ * status has not advanced, we only log at NOTICE when we have made at least
+ * this much progress.
+ */
+#define BOOTSTRAP_PCT_INCREMENT 5
+
 /** Called when Tor has made progress at bootstrapping its directory
  * information and initial circuits.
  *
@@ -4665,7 +4677,7 @@ control_event_bootstrap(bootstrap_status_t status, int progress)
    * can't distinguish what the connection is going to be for. */
   if (status == BOOTSTRAP_STATUS_HANDSHAKE) {
     if (bootstrap_percent < BOOTSTRAP_STATUS_CONN_OR) {
-      status =  BOOTSTRAP_STATUS_HANDSHAKE_DIR;
+      status = BOOTSTRAP_STATUS_HANDSHAKE_DIR;
     } else {
       status = BOOTSTRAP_STATUS_HANDSHAKE_OR;
     }
@@ -4673,9 +4685,19 @@ 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);
-    tor_log(status ? LOG_NOTICE : LOG_INFO, LD_CONTROL,
-        "Bootstrapped %d%%: %s.", progress ? progress : status, 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.
+       */
+      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);
@@ -4691,6 +4713,11 @@ control_event_bootstrap(bootstrap_status_t status, int progress)
       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;
+    }
   }
 }