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.
This commit is contained in:
Nick Mathewson 2014-03-27 11:23:53 -04:00
parent a83abcf5ee
commit 5b36f0d7e7
2 changed files with 36 additions and 4 deletions

5
changes/bug9963 Normal file
View File

@ -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.

View File

@ -4636,16 +4636,28 @@ bootstrap_status_to_string(bootstrap_status_t s, const char **tag,
* Tor initializes. */ * Tor initializes. */
static int bootstrap_percent = BOOTSTRAP_STATUS_UNDEF; 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? /** How many problems have we had getting to the next bootstrapping phase?
* These include failure to establish a connection to a Tor relay, * These include failure to establish a connection to a Tor relay,
* failures to finish the TLS handshake, failures to validate the * failures to finish the TLS handshake, failures to validate the
* consensus document, etc. */ * consensus document, etc. */
static int bootstrap_problems = 0; 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. */ * for the current phase. */
#define BOOTSTRAP_PROBLEM_THRESHOLD 10 #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 /** Called when Tor has made progress at bootstrapping its directory
* information and initial circuits. * 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. */ * can't distinguish what the connection is going to be for. */
if (status == BOOTSTRAP_STATUS_HANDSHAKE) { if (status == BOOTSTRAP_STATUS_HANDSHAKE) {
if (bootstrap_percent < BOOTSTRAP_STATUS_CONN_OR) { if (bootstrap_percent < BOOTSTRAP_STATUS_CONN_OR) {
status = BOOTSTRAP_STATUS_HANDSHAKE_DIR; status = BOOTSTRAP_STATUS_HANDSHAKE_DIR;
} else { } else {
status = BOOTSTRAP_STATUS_HANDSHAKE_OR; status = BOOTSTRAP_STATUS_HANDSHAKE_OR;
} }
@ -4673,9 +4685,19 @@ control_event_bootstrap(bootstrap_status_t status, int progress)
if (status > bootstrap_percent || if (status > bootstrap_percent ||
(progress && progress > bootstrap_percent)) { (progress && progress > bootstrap_percent)) {
int loglevel = LOG_NOTICE;
bootstrap_status_to_string(status, &tag, &summary); 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), tor_snprintf(buf, sizeof(buf),
"BOOTSTRAP PROGRESS=%d TAG=%s SUMMARY=\"%s\"", "BOOTSTRAP PROGRESS=%d TAG=%s SUMMARY=\"%s\"",
progress ? progress : status, tag, summary); progress ? progress : status, tag, summary);
@ -4691,6 +4713,11 @@ control_event_bootstrap(bootstrap_status_t status, int progress)
bootstrap_percent = progress; bootstrap_percent = progress;
bootstrap_problems = 0; /* Progress! Reset our problem counter. */ 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;
}
} }
} }