From 5aa4564ab940250fd9a8776d7cbfde8ab4f3cd31 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Wed, 29 Sep 2010 11:41:27 -0700 Subject: [PATCH 1/4] Only count timeout data for 3 hop circuits. Use 4/3 of this timeout value for 4 hop circuits, and use half of it for canabalized circuits. --- src/or/circuitbuild.c | 29 ++++++++++++++++---- src/or/circuitbuild.h | 1 + src/or/circuituse.c | 63 ++++++++++++++++++++++++++++--------------- src/or/or.h | 6 ++++- 4 files changed, 71 insertions(+), 28 deletions(-) diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c index 35d8087b6f..be435b950a 100644 --- a/src/or/circuitbuild.c +++ b/src/or/circuitbuild.c @@ -1197,6 +1197,11 @@ circuit_build_times_count_close(circuit_build_times_t *cbt, /** * Update timeout counts to determine if we need to expire * our build time history due to excessive timeouts. + * + * We do not record any actual time values at this stage; + * we are only interested in recording the fact that a timeout + * happened. We record the time values via + * circuit_build_times_count_close() and circuit_build_times_add_time(). */ void circuit_build_times_count_timeout(circuit_build_times_t *cbt, @@ -1208,11 +1213,11 @@ circuit_build_times_count_timeout(circuit_build_times_t *cbt, return; } + /* Register the fact that a timeout just occurred. */ circuit_build_times_network_timeout(cbt, did_onehop); /* If there are a ton of timeouts, we should reset - * the circuit build timeout. - */ + * the circuit build timeout. */ circuit_build_times_network_check_changed(cbt); } @@ -1816,6 +1821,18 @@ should_use_create_fast_for_circuit(origin_circuit_t *circ) return 1; } +/** Return true if circ is the type of circuit we want to count + * timeouts from. In particular, we want it to have not completed yet + * (already completing indicates we cannibalized it), and we want it to + * have exactly three hops. + */ +int +circuit_timeout_want_to_count_circ(origin_circuit_t *circ) +{ + return !circ->has_opened + && circ->build_state->desired_path_len == DEFAULT_ROUTE_LEN; +} + /** This is the backbone function for building circuits. * * If circ's first hop is closed, then we need to build a create @@ -1889,11 +1906,12 @@ circuit_send_next_onion_skin(origin_circuit_t *circ) if (!hop) { /* done building the circuit. whew. */ circuit_set_state(TO_CIRCUIT(circ), CIRCUIT_STATE_OPEN); - if (!circ->build_state->onehop_tunnel) { + if (circuit_timeout_want_to_count_circ(circ)) { struct timeval end; long timediff; tor_gettimeofday(&end); timediff = tv_mdiff(&circ->_base.highres_created, &end); + /* * If the circuit build time is much greater than we would have cut * it off at, we probably had a suspend event along this codepath, @@ -1901,9 +1919,10 @@ circuit_send_next_onion_skin(origin_circuit_t *circ) */ if (timediff < 0 || timediff > 2*circ_times.close_ms+1000) { log_notice(LD_CIRC, "Strange value for circuit build time: %ldmsec. " - "Assuming clock jump.", timediff); + "Assuming clock jump. Purpose %d", timediff, + circ->_base.purpose); } else if (!circuit_build_times_disabled()) { - /* Don't count circuit times if the network was not live */ + /* Only count circuit times if the network is live */ if (circuit_build_times_network_check_live(&circ_times)) { circuit_build_times_add_time(&circ_times, (build_time_t)timediff); circuit_build_times_set_timeout(&circ_times); diff --git a/src/or/circuitbuild.h b/src/or/circuitbuild.h index f4cc2a904d..7cc5c2877a 100644 --- a/src/or/circuitbuild.h +++ b/src/or/circuitbuild.h @@ -24,6 +24,7 @@ origin_circuit_t *circuit_establish_circuit(uint8_t purpose, int circuit_handle_first_hop(origin_circuit_t *circ); void circuit_n_conn_done(or_connection_t *or_conn, int status); int inform_testing_reachability(void); +int circuit_timeout_want_to_count_circ(origin_circuit_t *circ); int circuit_send_next_onion_skin(origin_circuit_t *circ); void circuit_note_clock_jumped(int seconds_elapsed); int circuit_extend(cell_t *cell, circuit_t *circ); diff --git a/src/or/circuituse.c b/src/or/circuituse.c index e9335b18d6..d9c16c139e 100644 --- a/src/or/circuituse.c +++ b/src/or/circuituse.c @@ -284,6 +284,8 @@ circuit_expire_building(time_t now) * decided on a customized one yet */ time_t general_cutoff = now - lround(circ_times.timeout_ms/1000); time_t begindir_cutoff = now - lround(circ_times.timeout_ms/2000); + time_t fourhop_cutoff = now - lround(4*circ_times.timeout_ms/3000); + time_t cannibalize_cutoff = now - lround(circ_times.timeout_ms/2000); time_t close_cutoff = now - lround(circ_times.close_ms/1000); time_t introcirc_cutoff = begindir_cutoff; cpath_build_state_t *build_state; @@ -299,6 +301,11 @@ circuit_expire_building(time_t now) build_state = TO_ORIGIN_CIRCUIT(victim)->build_state; if (build_state && build_state->onehop_tunnel) cutoff = begindir_cutoff; + else if (build_state && build_state->desired_path_len == 4 + && !TO_ORIGIN_CIRCUIT(victim)->has_opened) + cutoff = fourhop_cutoff; + else if (TO_ORIGIN_CIRCUIT(victim)->has_opened) + cutoff = cannibalize_cutoff; else if (victim->purpose == CIRCUIT_PURPOSE_C_INTRODUCING) cutoff = introcirc_cutoff; else if (victim->purpose == CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) @@ -378,29 +385,36 @@ circuit_expire_building(time_t now) continue; } - /* circuits are allowed to last longer for measurement. - * Switch their purpose and wait. */ - if (victim->purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) { - victim->purpose = CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT; - circuit_build_times_count_timeout(&circ_times, - first_hop_succeeded); - continue; - } + if (circuit_timeout_want_to_count_circ(TO_ORIGIN_CIRCUIT(victim))) { + /* Circuits are allowed to last longer for measurement. + * Switch their purpose and wait. */ + if (victim->purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) { + victim->purpose = CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT; + /* Record this failure to check for too many timeouts + * in a row. This function does not record a time value yet + * (we do that later); it only counts the fact that we did + * have a timeout. */ + circuit_build_times_count_timeout(&circ_times, + first_hop_succeeded); + continue; + } - /* - * If the circuit build time is much greater than we would have cut - * it off at, we probably had a suspend event along this codepath, - * and we should discard the value. - */ - if (now - victim->timestamp_created > 2*circ_times.close_ms/1000+1) { - log_notice(LD_CIRC, - "Extremely large value for circuit build timeout: %lds. " - "Assuming clock jump.", - (long)(now - victim->timestamp_created)); - } else if (circuit_build_times_count_close(&circ_times, - first_hop_succeeded, - victim->timestamp_created)) { - circuit_build_times_set_timeout(&circ_times); + /* + * If the circuit build time is much greater than we would have cut + * it off at, we probably had a suspend event along this codepath, + * and we should discard the value. + */ + if (now - victim->timestamp_created > 2*circ_times.close_ms/1000+1) { + log_notice(LD_CIRC, + "Extremely large value for circuit build timeout: %lds. " + "Assuming clock jump. Purpose %d", + (long)(now - victim->timestamp_created), + victim->purpose); + } else if (circuit_build_times_count_close(&circ_times, + first_hop_succeeded, + victim->timestamp_created)) { + circuit_build_times_set_timeout(&circ_times); + } } } @@ -903,6 +917,11 @@ circuit_has_opened(origin_circuit_t *circ) { control_event_circuit_status(circ, CIRC_EVENT_BUILT, 0); + /* Remember that this circuit has finished building. Now if we start + * it building again later (e.g. by extending it), we will know not + * to consider its build time. */ + circ->has_opened = 1; + switch (TO_CIRCUIT(circ)->purpose) { case CIRCUIT_PURPOSE_C_ESTABLISH_REND: rend_client_rendcirc_has_opened(circ); diff --git a/src/or/or.h b/src/or/or.h index 6332de83a1..2399ecff39 100644 --- a/src/or/or.h +++ b/src/or/or.h @@ -2160,9 +2160,13 @@ typedef struct origin_circuit_t { * to the specification? */ unsigned int remaining_relay_early_cells : 4; - /** Set if this circuit insanely old and if we already informed the user */ + /** Set if this circuit is insanely old and we already informed the user */ unsigned int is_ancient : 1; + /** Set if this circuit has already been opened. Used to detect + * cannibalized circuits. */ + unsigned int has_opened : 1; + /** What commands were sent over this circuit that decremented the * RELAY_EARLY counter? This is for debugging task 878. */ uint8_t relay_early_commands[MAX_RELAY_EARLY_CELLS_PER_CIRCUIT]; From caba3bc57e2895a7c51a87e23fa783b9c48892a5 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Tue, 27 Jul 2010 09:30:52 -0700 Subject: [PATCH 2/4] Add changes file. --- changes/bug1740 | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 changes/bug1740 diff --git a/changes/bug1740 b/changes/bug1740 new file mode 100644 index 0000000000..2e7769b0d6 --- /dev/null +++ b/changes/bug1740 @@ -0,0 +1,5 @@ + o Minor bugfixes: + - Fix to ignore cannibalized circuits when recording circuit build times. + This should provide for a minor performance improvement for hidden + service users using 0.2.2.14-alpha, and should remove two spurious + notice log messages. Bugfix on 0.2.2.14-alpha; fixes bug #1740. From c5b5643965f57520842756e16d7ca7e8ea1cb2f8 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Sat, 24 Jul 2010 18:19:20 +0200 Subject: [PATCH 3/4] Send control port events for timeouts. We now differentiate between timeouts and cutoffs by the REASON string and the PURPOSE string. --- doc/spec/control-spec.txt | 3 ++- src/or/circuitlist.c | 2 +- src/or/circuituse.c | 8 +++++++- src/or/or.h | 4 ++++ src/or/reasons.c | 2 ++ 5 files changed, 16 insertions(+), 3 deletions(-) diff --git a/doc/spec/control-spec.txt b/doc/spec/control-spec.txt index 31ce35074b..1864666047 100644 --- a/doc/spec/control-spec.txt +++ b/doc/spec/control-spec.txt @@ -1005,7 +1005,8 @@ Reason = "NONE" / "TORPROTOCOL" / "INTERNAL" / "REQUESTED" / "HIBERNATING" / "RESOURCELIMIT" / "CONNECTFAILED" / "OR_IDENTITY" / "OR_CONN_CLOSED" / "TIMEOUT" / - "FINISHED" / "DESTROYED" / "NOPATH" / "NOSUCHSERVICE" + "FINISHED" / "DESTROYED" / "NOPATH" / "NOSUCHSERVICE" / + "MEASUREMENT_EXPIRED" The path is provided only when the circuit has been extended at least one hop. diff --git a/src/or/circuitlist.c b/src/or/circuitlist.c index fa800db1a4..fb4b69be0d 100644 --- a/src/or/circuitlist.c +++ b/src/or/circuitlist.c @@ -368,7 +368,7 @@ circuit_purpose_to_controller_string(uint8_t purpose) case CIRCUIT_PURPOSE_TESTING: return "TESTING"; case CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT: - return "EXPIRED"; + return "MEASURE_TIMEOUT"; case CIRCUIT_PURPOSE_CONTROLLER: return "CONTROLLER"; diff --git a/src/or/circuituse.c b/src/or/circuituse.c index d9c16c139e..ce03500f34 100644 --- a/src/or/circuituse.c +++ b/src/or/circuituse.c @@ -389,6 +389,9 @@ circuit_expire_building(time_t now) /* Circuits are allowed to last longer for measurement. * Switch their purpose and wait. */ if (victim->purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) { + control_event_circuit_status(TO_ORIGIN_CIRCUIT(victim), + CIRC_EVENT_FAILED, + END_CIRC_REASON_TIMEOUT); victim->purpose = CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT; /* Record this failure to check for too many timeouts * in a row. This function does not record a time value yet @@ -430,7 +433,10 @@ circuit_expire_building(time_t now) circuit_state_to_string(victim->state), victim->purpose); circuit_log_path(LOG_INFO,LD_CIRC,TO_ORIGIN_CIRCUIT(victim)); - circuit_mark_for_close(victim, END_CIRC_REASON_TIMEOUT); + if (victim->purpose == CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) + circuit_mark_for_close(victim, END_CIRC_REASON_MEASUREMENT_EXPIRED); + else + circuit_mark_for_close(victim, END_CIRC_REASON_TIMEOUT); } } diff --git a/src/or/or.h b/src/or/or.h index 2399ecff39..6c398b7dcb 100644 --- a/src/or/or.h +++ b/src/or/or.h @@ -614,6 +614,10 @@ typedef enum { /* Negative reasons are internal: we never send them in a DESTROY or TRUNCATE * call; they only go to the controller for tracking */ +/** Our post-timeout circuit time measurement period expired. + * We must give up now */ +#define END_CIRC_REASON_MEASUREMENT_EXPIRED -3 + /** We couldn't build a path for this circuit. */ #define END_CIRC_REASON_NOPATH -2 /** Catch-all "other" reason for closing origin circuits. */ diff --git a/src/or/reasons.c b/src/or/reasons.c index ade9a3abfc..aa7972be5b 100644 --- a/src/or/reasons.c +++ b/src/or/reasons.c @@ -334,6 +334,8 @@ circuit_end_reason_to_control_string(int reason) return "NOPATH"; case END_CIRC_REASON_NOSUCHSERVICE: return "NOSUCHSERVICE"; + case END_CIRC_REASON_MEASUREMENT_EXPIRED: + return "MEASUREMENT_EXPIRED"; default: log_warn(LD_BUG, "Unrecognized reason code %d", (int)reason); return NULL; From 4caf39f1c8db6acc25f84df024073d43c04c8645 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Wed, 29 Sep 2010 02:37:53 -0700 Subject: [PATCH 4/4] Add changes file. --- changes/bug1739 | 4 ++++ 1 file changed, 4 insertions(+) create mode 100644 changes/bug1739 diff --git a/changes/bug1739 b/changes/bug1739 new file mode 100644 index 0000000000..ec1b1b1b5c --- /dev/null +++ b/changes/bug1739 @@ -0,0 +1,4 @@ + o Minor bugfixes: + - Fix to resume generating CIRC FAILED REASON=TIMEOUT control port + messages, which were disabled by the circuit build timeout changes + in 0.2.2.14-alpha. Bugfix on 0.2.2.14-alpha; fixes bug #1739.