From 5b36f0d7e78db369da0552ca8fad53b7f202aece Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Thu, 27 Mar 2014 11:23:53 -0400 Subject: [PATCH] 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. --- changes/bug9963 | 5 +++++ src/or/control.c | 35 +++++++++++++++++++++++++++++++---- 2 files changed, 36 insertions(+), 4 deletions(-) create mode 100644 changes/bug9963 diff --git a/changes/bug9963 b/changes/bug9963 new file mode 100644 index 0000000000..b8b95f2a7d --- /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 a88de12d69..27aeab186e 100644 --- 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; + } } }