Add BUILDTIMEOUT_SET event for CBT stress testing.

4 files changed, 114 insertions, 4 deletions

diff --git a/doc/spec/control-spec.txt b/doc/spec/control-spec.txt
index 73f0b020a9..4057ffa741 100644
--- a/doc/spec/control-spec.txt
+++ b/doc/spec/control-spec.txt
@@ -219,7 +219,7 @@
          "INFO" / "NOTICE" / "WARN" / "ERR" / "NEWDESC" / "ADDRMAP" /
          "AUTHDIR_NEWDESCS" / "DESCCHANGED" / "STATUS_GENERAL" /
          "STATUS_CLIENT" / "STATUS_SERVER" / "GUARD" / "NS" / "STREAM_BW" /
-         "CLIENTS_SEEN" / "NEWCONSENSUS"
+         "CLIENTS_SEEN" / "NEWCONSENSUS" / "BUILDTIMEOUT_SET"
 
   Any events *not* listed in the SETEVENTS line are turned off; thus, sending
   SETEVENTS with an empty body turns off all event reporting.
@@ -1656,6 +1656,38 @@
 
   [First added in 0.2.1.13-alpha]
 
+4.1.16. New circuit buildtime has been set.
+
+  The syntax is:
+     "650" SP "BUILDTIMEOUT_SET" SP Type SP "TOTAL_TIMES=" Total SP
+        "TIMEOUT_MS=" Timeout SP "XM=" Xm SP "ALPHA=" Alpha SP
+        "CUTOFF_QUANTILE=" Quantile CRLF
+     Type = "COMPUTED" / "RESET" / "SUSPENDED" / "DISCARD" / "RESUME"
+     Total = Integer count of timeouts stored
+     Timeout = Integer timeout in milliseconds
+     Xm = Estimated integer Pareto parameter Xm in milliseconds
+     Alpha = Estimated floating point Paredo paremter alpha
+     Quantile = Floating point CDF quantile cutoff point for this timeout
+
+  A new circuit build timeout time has been set. If Type is "COMPUTED",
+  Tor has computed the value based on historical data. If Type is "RESET",
+  initialization or drastic network changes have caused Tor to reset
+  the timeout back to the default, to relearn again. If Type is
+  "SUSPENDED", Tor has detected a loss of network connectivity and has
+  temporarily changed the timeout value to the default until the network
+  recovers. If type is "DISCARD", Tor has decided to discard timeout
+  values that likely happened while the network was down. If type is
+  "RESUME", Tor has decided to resume timeout calculation.
+
+  The Total value is the count of circuit build times Tor used in
+  computing this value. It is capped internally at the maximum number
+  of build times Tor stores (NCIRCUITS_TO_OBSERVE).
+
+  The Timeout itself is provided in milliseconds. Internally, Tor rounds
+  this value to the nearest second before using it.
+
+  [First added in 0.2.2.7-alpha]
+
 5. Implementation notes
 
 5.1. Authentication
diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c
index 300da7eed0..b16e9a4d80 100644
--- a/src/or/circuitbuild.c
+++ b/src/or/circuitbuild.c
@@ -134,6 +134,7 @@ circuit_build_times_init(circuit_build_times_t *cbt)
 {
   memset(cbt, 0, sizeof(*cbt));
   cbt->timeout_ms = circuit_build_times_get_initial_timeout();
+  control_event_buildtimeout_set(cbt, BUILDTIMEOUT_SET_EVENT_RESET);
 }
 
 /**
@@ -687,6 +688,9 @@ circuit_build_times_needs_circuits_now(circuit_build_times_t *cbt)
 
 /**
  * Called to indicate that the network showed some signs of liveness.
+ *
+ * This function is called every time we receive a cell. Avoid
+ * syscalls, events, and other high-intensity work.
  */
 void
 circuit_build_times_network_is_live(circuit_build_times_t *cbt)
@@ -760,6 +764,7 @@ circuit_build_times_network_check_live(circuit_build_times_t *cbt)
       /* Only discard NETWORK_NONLIVE_TIMEOUT_COUNT-1 because we stopped
        * counting after that */
       circuit_build_times_rewind_history(cbt, NETWORK_NONLIVE_TIMEOUT_COUNT-1);
+      control_event_buildtimeout_set(cbt, BUILDTIMEOUT_SET_EVENT_DISCARD);
     }
     return 0;
   } else if (cbt->liveness.nonlive_timeouts >= NETWORK_NONLIVE_TIMEOUT_COUNT) {
@@ -770,9 +775,17 @@ circuit_build_times_network_check_live(circuit_build_times_t *cbt)
                 (long int)(now - cbt->liveness.network_last_live),
                 tor_lround(circuit_build_times_get_initial_timeout()/1000));
       cbt->timeout_ms = circuit_build_times_get_initial_timeout();
+      cbt->liveness.net_suspended = 1;
+      control_event_buildtimeout_set(cbt, BUILDTIMEOUT_SET_EVENT_SUSPENDED);
     }
 
     return 0;
+  } else if (cbt->liveness.net_suspended) {
+    log_notice(LD_CIRC,
+              "Network activity has resumed. "
+              "Resuming circuit timeout calculations.");
+    cbt->liveness.net_suspended = 0;
+    control_event_buildtimeout_set(cbt, BUILDTIMEOUT_SET_EVENT_RESUME);
   }
 
   return 1;
@@ -819,6 +832,8 @@ circuit_build_times_network_check_changed(circuit_build_times_t *cbt)
     cbt->timeout_ms = circuit_build_times_get_initial_timeout();
   }
 
+  control_event_buildtimeout_set(cbt, BUILDTIMEOUT_SET_EVENT_RESET);
+
   log_notice(LD_CIRC,
             "Network connection speed appears to have changed. Resetting "
             "timeout to %lds after %d timeouts and %d buildtimes.",
@@ -893,6 +908,8 @@ circuit_build_times_set_timeout(circuit_build_times_t *cbt)
     cbt->timeout_ms = BUILD_TIMEOUT_MIN_VALUE;
   }
 
+  control_event_buildtimeout_set(cbt, BUILDTIMEOUT_SET_EVENT_COMPUTED);
+
   log_info(LD_CIRC,
            "Set circuit build timeout to %lds (%lfms, Xm: %d, a: %lf) "
            "based on %d circuit times", tor_lround(cbt->timeout_ms/1000),
diff --git a/src/or/control.c b/src/or/control.c
index c08d6a2440..c34848d454 100644
--- a/src/or/control.c
+++ b/src/or/control.c
@@ -43,7 +43,8 @@
 #define EVENT_STREAM_BANDWIDTH_USED   0x0014
 #define EVENT_CLIENTS_SEEN     0x0015
 #define EVENT_NEWCONSENSUS     0x0016
-#define _EVENT_MAX             0x0016
+#define EVENT_BUILDTIMEOUT_SET     0x0017
+#define _EVENT_MAX             0x0017
 /* If _EVENT_MAX ever hits 0x0020, we need to make the mask wider. */
 
 /** Bitfield: The bit 1&lt;&lt;e is set if <b>any</b> open control
@@ -922,6 +923,8 @@ handle_control_setevents(control_connection_t *conn, uint32_t len,
         event_code = EVENT_CLIENTS_SEEN;
       else if (!strcasecmp(ev, "NEWCONSENSUS"))
         event_code = EVENT_NEWCONSENSUS;
+      else if (!strcasecmp(ev, "BUILDTIMEOUT_SET"))
+        event_code = EVENT_BUILDTIMEOUT_SET;
       else {
         connection_printf_to_buf(conn, "552 Unrecognized event \"%s\"\r\n",
                                  ev);
@@ -3440,6 +3443,51 @@ control_event_newconsensus(const networkstatus_t *consensus)
            consensus->routerstatus_list, EVENT_NEWCONSENSUS, "NEWCONSENSUS");
 }
 
+/** Called when we compute a new circuitbuildtimeout */
+int
+control_event_buildtimeout_set(const circuit_build_times_t *cbt,
+                        buildtimeout_set_event_t type)
+{
+  const char *type_string = NULL;
+  double qnt = BUILDTIMEOUT_QUANTILE_CUTOFF;
+
+  if (!control_event_is_interesting(EVENT_BUILDTIMEOUT_SET))
+    return 0;
+
+  switch (type) {
+    case BUILDTIMEOUT_SET_EVENT_COMPUTED: 
+      type_string = "COMPUTED";
+      break;
+    case BUILDTIMEOUT_SET_EVENT_RESET:
+      type_string = "RESET";
+      qnt = 1.0;
+      break;
+    case BUILDTIMEOUT_SET_EVENT_SUSPENDED:
+      type_string = "SUSPENDED";
+      qnt = 1.0;
+      break;
+    case BUILDTIMEOUT_SET_EVENT_DISCARD:
+      type_string = "DISCARD";
+      qnt = 1.0;
+      break;
+    case BUILDTIMEOUT_SET_EVENT_RESUME:
+      type_string = "RESUME";
+      break;
+    default:
+      type_string = "UNKNOWN";
+      break;
+  }
+
+  send_control_event(EVENT_BUILDTIMEOUT_SET, ALL_FORMATS,
+                     "650 BUILDTIMEOUT_SET %s TOTAL_TIMES=%lu "
+                     "TIMEOUT_MS=%lu XM=%lu ALPHA=%lf CUTOFF_QUANTILE=%lf\r\n",
+                     type_string, (unsigned long)cbt->total_build_times,
+                     (unsigned long)cbt->timeout_ms, 
+                     (unsigned long)cbt->Xm, cbt->alpha, qnt);
+
+  return 0;
+}
+
 /** Called when a single local_routerstatus_t has changed: Sends an NS event
  * to any controller that cares. */
 int
diff --git a/src/or/or.h b/src/or/or.h
index e0b86387fa..24cabb4300 100644
--- a/src/or/or.h
+++ b/src/or/or.h
@@ -3008,7 +3008,7 @@ void entry_guards_free_all(void);
 #define MAX_SYNTHETIC_QUANTILE 0.985
 
 /** Minimum circuits before estimating a timeout */
-#define MIN_CIRCUITS_TO_OBSERVE 500
+#define MIN_CIRCUITS_TO_OBSERVE 20
 
 /** Total size of the circuit timeout history to accumulate.
  * 5000 is approx 1.5 weeks worth of continual-use circuits. */
@@ -3035,7 +3035,7 @@ typedef uint32_t build_time_t;
 #define BUILD_TIMES_TEST_FREQUENCY 60
 
 /** Save state every 10 circuits */
-#define BUILD_TIMES_SAVE_STATE_EVERY 10
+#define BUILD_TIMES_SAVE_STATE_EVERY 1
 
 /* Circuit Build Timeout network liveness constants */
 
@@ -3090,6 +3090,8 @@ typedef struct {
   int8_t timeouts_after_firsthop[RECENT_CIRCUITS];
   /** Index into circular array. */
   int after_firsthop_idx;
+  /** The network is not live. Timeout gathering is suspended */
+  int net_suspended;
 } network_liveness_t;
 
 /** Structure for circuit build times history */
@@ -3583,6 +3585,15 @@ typedef enum or_conn_status_event_t {
   OR_CONN_EVENT_NEW          = 4,
 } or_conn_status_event_t;
 
+/** Used to indicate the type of a buildtime event */
+typedef enum buildtimeout_set_event_t {
+  BUILDTIMEOUT_SET_EVENT_COMPUTED  = 0,
+  BUILDTIMEOUT_SET_EVENT_RESET     = 1,
+  BUILDTIMEOUT_SET_EVENT_SUSPENDED = 2,
+  BUILDTIMEOUT_SET_EVENT_DISCARD = 3,
+  BUILDTIMEOUT_SET_EVENT_RESUME = 4
+} buildtimeout_set_event_t;
+
 void control_update_global_event_mask(void);
 void control_adjust_event_log_severity(void);
 
@@ -3648,6 +3659,8 @@ int control_event_server_status(int severity, const char *format, ...)
   CHECK_PRINTF(2,3);
 int control_event_guard(const char *nickname, const char *digest,
                         const char *status);
+int control_event_buildtimeout_set(const circuit_build_times_t *cbt,
+                                   buildtimeout_set_event_t type);
 
 int init_cookie_authentication(int enabled);
 smartlist_t *decode_hashed_passwords(config_line_t *passwords);