Merge branch 'bug14950_logs_squashed'

src/common/compat.c

@@ -1793,8 +1793,8 @@ tor_getpwnam(const char *username)
   if ((pw = getpwnam(username))) {
     tor_passwd_free(passwd_cached);
     passwd_cached = tor_passwd_dup(pw);
-    log_notice(LD_GENERAL, "Caching new entry %s for %s",
-               passwd_cached->pw_name, username);
+    log_info(LD_GENERAL, "Caching new entry %s for %s",
+             passwd_cached->pw_name, username);
     return pw;
   }
 

src/or/circuitbuild.c

@@ -960,7 +960,11 @@ circuit_send_next_onion_skin(origin_circuit_t *circ)
         log_notice(LD_GENERAL,
             "Tor has successfully opened a circuit. "
             "Looks like client functionality is working.");
-        control_event_bootstrap(BOOTSTRAP_STATUS_DONE, 0);
+        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.");
+        }
         control_event_client_status(LOG_NOTICE, "CIRCUIT_ESTABLISHED");
         clear_broken_connection_map(1);
         if (server_mode(options) && !check_whether_orport_reachable()) {

src/or/control.c

@@ -4971,15 +4971,18 @@ static int bootstrap_problems = 0;
  *
  * <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. */
-void
+ * represents progress on the task.
+ *
+ * Return true if we logged a message at level NOTICE, and false otherwise.
+ */
+int
 control_event_bootstrap(bootstrap_status_t status, int progress)
 {
   const char *tag, *summary;
   char buf[BOOTSTRAP_MSG_LEN];
 
   if (bootstrap_percent == BOOTSTRAP_STATUS_DONE)
-    return; /* already bootstrapped; nothing to be done here. */
+    return 0; /* 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. */
@@ -5026,7 +5029,10 @@ control_event_bootstrap(bootstrap_status_t status, int progress)
       /* Remember that we gave a notice at this level. */
       notice_bootstrap_percent = bootstrap_percent;
     }
+    return loglevel == LOG_NOTICE;
   }
+
+  return 0;
 }
 
 /** Called when Tor has failed to make bootstrapping progress in a way

src/or/control.h

@@ -92,7 +92,7 @@ void enable_control_logging(void);
 
 void monitor_owning_controller_process(const char *process_spec);
 
-void control_event_bootstrap(bootstrap_status_t status, int progress);
+int control_event_bootstrap(bootstrap_status_t status, int progress);
 MOCK_DECL(void, control_event_bootstrap_problem,(const char *warn,
                                                  int reason,
                                                  or_connection_t *or_conn));

src/or/nodelist.c

@@ -1698,10 +1698,11 @@ update_router_have_minimum_dir_info(void)
 
   /* If paths have just become available in this update. */
   if (res && !have_min_dir_info) {
-    log_notice(LD_DIR,
-        "We now have enough directory information to build circuits.");
     control_event_client_status(LOG_NOTICE, "ENOUGH_DIR_INFO");
-    control_event_bootstrap(BOOTSTRAP_STATUS_CONN_OR, 0);
+    if (control_event_bootstrap(BOOTSTRAP_STATUS_CONN_OR, 0) == 0) {
+      log_notice(LD_DIR,
+              "We now have enough directory information to build circuits.");
+    }
   }
 
   /* If paths have just become unavailable in this update. */

src/or/status.c

@@ -110,22 +110,31 @@ log_heartbeat(time_t now)
 
   log_fn(LOG_NOTICE, LD_HEARTBEAT, "Heartbeat: Tor's uptime is %s, with %d "
          "circuits open. I've sent %s and received %s.%s",
-         uptime, count_circuits(),bw_sent,bw_rcvd,
+         uptime, count_circuits(), bw_sent, bw_rcvd,
          hibernating?" We are currently hibernating.":"");
 
   if (server_mode(options) && accounting_is_enabled(options) && !hibernating) {
     log_accounting(now, options);
   }
 
-  if (stats_n_data_cells_packaged && !hibernating)
-    log_notice(LD_HEARTBEAT, "Average packaged cell fullness: %2.3f%%",
-        100*(U64_TO_DBL(stats_n_data_bytes_packaged) /
-             U64_TO_DBL(stats_n_data_cells_packaged*RELAY_PAYLOAD_SIZE)) );
-
-  if (r > 1.0) {
-    double overhead = ( r - 1.0 ) * 100.0;
-    log_notice(LD_HEARTBEAT, "TLS write overhead: %.f%%", overhead);
+  double fullness_pct = 100;
+  if (stats_n_data_cells_packaged && !hibernating) {
+    fullness_pct =
+      100*(U64_TO_DBL(stats_n_data_bytes_packaged) /
+           U64_TO_DBL(stats_n_data_cells_packaged*RELAY_PAYLOAD_SIZE));
   }
+  const double overhead_pct = ( r - 1.0 ) * 100.0;
+
+#define FULLNESS_PCT_THRESHOLD 80
+#define TLS_OVERHEAD_THRESHOLD 15
+
+  const int severity = (fullness_pct < FULLNESS_PCT_THRESHOLD ||
+                        overhead_pct > TLS_OVERHEAD_THRESHOLD)
+    ? LOG_NOTICE : LOG_INFO;
+
+  log_fn(severity, LD_HEARTBEAT,
+         "Average packaged cell fullness: %2.3f%%"
+         "TLS write overhead: %.f%%", fullness_pct, overhead_pct);
 
   if (public_server_mode(options))
     rep_hist_log_circuit_handshake_stats(now);