diff options
Diffstat (limited to 'src')
| -rw-r--r-- | src/or/circuitbuild.c | 59 | ||||
| -rw-r--r-- | src/or/circuitbuild.h | 2 | ||||
| -rw-r--r-- | src/or/circuitlist.c | 77 | ||||
| -rw-r--r-- | src/or/circuitlist.h | 5 | ||||
| -rw-r--r-- | src/or/circuitstats.c | 195 | ||||
| -rw-r--r-- | src/or/circuitstats.h | 12 | ||||
| -rw-r--r-- | src/or/circuituse.c | 59 | ||||
| -rw-r--r-- | src/test/Makefile.nmake | 1 | ||||
| -rw-r--r-- | src/test/include.am | 1 | ||||
| -rw-r--r-- | src/test/test.c | 1 | ||||
| -rw-r--r-- | src/test/test.h | 1 | ||||
| -rw-r--r-- | src/test/test_circuitstats.c | 199 |
12 files changed, 536 insertions, 76 deletions
diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c index 8cbf5e3cbb..a350f6c142 100644 --- a/src/or/circuitbuild.c +++ b/src/or/circuitbuild.c @@ -75,7 +75,7 @@ static int onion_pick_cpath_exit(origin_circuit_t *circ, extend_info_t *exit, int is_hs_v3_rp_circuit); static crypt_path_t *onion_next_hop_in_cpath(crypt_path_t *cpath); static int onion_extend_cpath(origin_circuit_t *circ); -static int onion_append_hop(crypt_path_t **head_ptr, extend_info_t *choice); +STATIC int onion_append_hop(crypt_path_t **head_ptr, extend_info_t *choice); static int circuit_send_first_onion_skin(origin_circuit_t *circ); static int circuit_build_no_more_hops(origin_circuit_t *circ); static int circuit_send_intermediate_onion_skin(origin_circuit_t *circ, @@ -824,16 +824,25 @@ should_use_create_fast_for_circuit(origin_circuit_t *circ) return networkstatus_get_param(NULL, "usecreatefast", 0, 0, 1); } -/** Return true if <b>circ</b> 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. +/** + * Return true if <b>circ</b> is the type of circuit we want to count + * timeouts from. + * + * In particular, we want to consider any circuit that plans to build + * at least 3 hops (but maybe more), but has 3 or fewer hops built + * so far. + * + * We still want to consider circuits before 3 hops, because we need + * to decide if we should convert them to a measurement circuit in + * circuit_build_times_handle_completed_hop(), rather than letting + * slow circuits get killed right away. */ int -circuit_timeout_want_to_count_circ(origin_circuit_t *circ) +circuit_timeout_want_to_count_circ(const origin_circuit_t *circ) { return !circ->has_opened - && circ->build_state->desired_path_len == DEFAULT_ROUTE_LEN; + && circ->build_state->desired_path_len >= DEFAULT_ROUTE_LEN + && circuit_get_cpath_opened_len(circ) <= DEFAULT_ROUTE_LEN; } /** Decide whether to use a TAP or ntor handshake for connecting to <b>ei</b> @@ -937,7 +946,9 @@ circuit_send_next_onion_skin(origin_circuit_t *circ) tor_assert(circ->cpath->state == CPATH_STATE_OPEN); tor_assert(circ->base_.state == CIRCUIT_STATE_BUILDING); + crypt_path_t *hop = onion_next_hop_in_cpath(circ->cpath); + circuit_build_times_handle_completed_hop(circ); if (hop) { /* Case two: we're on a hop after the first. */ @@ -1052,38 +1063,6 @@ circuit_build_no_more_hops(origin_circuit_t *circ) * I think I got them right, but more checking would be wise. -NM */ - if (circuit_timeout_want_to_count_circ(circ)) { - struct timeval end; - long timediff; - tor_gettimeofday(&end); - timediff = tv_mdiff(&circ->base_.timestamp_began, &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, - * and we should discard the value. - */ - if (timediff < 0 || - timediff > 2*get_circuit_build_close_time_ms()+1000) { - log_notice(LD_CIRC, "Strange value for circuit build time: %ldmsec. " - "Assuming clock jump. Purpose %d (%s)", timediff, - circ->base_.purpose, - circuit_purpose_to_string(circ->base_.purpose)); - } else if (!circuit_build_times_disabled(get_options())) { - /* Only count circuit times if the network is live */ - if (circuit_build_times_network_check_live( - get_circuit_build_times())) { - circuit_build_times_add_time(get_circuit_build_times_mutable(), - (build_time_t)timediff); - circuit_build_times_set_timeout(get_circuit_build_times_mutable()); - } - - if (circ->base_.purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) { - circuit_build_times_network_circ_success( - get_circuit_build_times_mutable()); - } - } - } log_info(LD_CIRC,"circuit built!"); circuit_reset_failure_count(0); @@ -2606,7 +2585,7 @@ onion_extend_cpath(origin_circuit_t *circ) /** Create a new hop, annotate it with information about its * corresponding router <b>choice</b>, and append it to the * end of the cpath <b>head_ptr</b>. */ -static int +STATIC int onion_append_hop(crypt_path_t **head_ptr, extend_info_t *choice) { crypt_path_t *hop = tor_malloc_zero(sizeof(crypt_path_t)); diff --git a/src/or/circuitbuild.h b/src/or/circuitbuild.h index 9b5fcc71ed..a85ef672f9 100644 --- a/src/or/circuitbuild.h +++ b/src/or/circuitbuild.h @@ -27,7 +27,7 @@ int circuit_handle_first_hop(origin_circuit_t *circ); void circuit_n_chan_done(channel_t *chan, int status, int close_origin_circuits); int inform_testing_reachability(void); -int circuit_timeout_want_to_count_circ(origin_circuit_t *circ); +int circuit_timeout_want_to_count_circ(const 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/circuitlist.c b/src/or/circuitlist.c index 9fac17a2bd..82b9b84c1e 100644 --- a/src/or/circuitlist.c +++ b/src/or/circuitlist.c @@ -109,6 +109,14 @@ static void cpath_ref_decref(crypt_path_reference_t *cpath_ref); static void circuit_about_to_free_atexit(circuit_t *circ); static void circuit_about_to_free(circuit_t *circ); +/** + * A cached value of the current state of the origin circuit list. Has the + * value 1 if we saw any opened circuits recently (since the last call to + * circuit_any_opened_circuits(), which gets called around once a second by + * circuit_expire_building). 0 otherwise. + */ +static int any_opened_circs_cached_val = 0; + /********* END VARIABLES ************/ /** A map from channel and circuit ID to circuit. (Lookup performance is @@ -596,6 +604,56 @@ circuit_get_global_origin_circuit_list(void) return global_origin_circuit_list; } +/** + * Return true if we have any opened general-purpose 3 hop + * origin circuits. + * + * The result from this function is cached for use by + * circuit_any_opened_circuits_cached(). + */ +int +circuit_any_opened_circuits(void) +{ + SMARTLIST_FOREACH_BEGIN(circuit_get_global_origin_circuit_list(), + const origin_circuit_t *, next_circ) { + if (!TO_CIRCUIT(next_circ)->marked_for_close && + next_circ->has_opened && + TO_CIRCUIT(next_circ)->state == CIRCUIT_STATE_OPEN && + TO_CIRCUIT(next_circ)->purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT && + next_circ->build_state && + next_circ->build_state->desired_path_len == DEFAULT_ROUTE_LEN) { + circuit_cache_opened_circuit_state(1); + return 1; + } + } SMARTLIST_FOREACH_END(next_circ); + + circuit_cache_opened_circuit_state(0); + return 0; +} + +/** + * Cache the "any circuits opened" state, as specified in param + * circuits_are_opened. This is a helper function to update + * the circuit opened status whenever we happen to look at the + * circuit list. + */ +void +circuit_cache_opened_circuit_state(int circuits_are_opened) +{ + any_opened_circs_cached_val = circuits_are_opened; +} + +/** + * Return true if there were any opened circuits since the last call to + * circuit_any_opened_circuits(), or since circuit_expire_building() last + * ran (it runs roughly once per second). + */ +int +circuit_any_opened_circuits_cached(void) +{ + return any_opened_circs_cached_val; +} + /** Function to make circ-\>state human-readable */ const char * circuit_state_to_string(int state) @@ -1788,6 +1846,25 @@ circuit_get_cpath_len(origin_circuit_t *circ) return n; } +/** Return the number of opened hops in circuit's path. + * If circ has no entries, or is NULL, returns 0. */ +int +circuit_get_cpath_opened_len(const origin_circuit_t *circ) +{ + int n = 0; + if (circ && circ->cpath) { + crypt_path_t *cpath, *cpath_next = NULL; + for (cpath = circ->cpath; + cpath->state == CPATH_STATE_OPEN + && cpath_next != circ->cpath; + cpath = cpath_next) { + cpath_next = cpath->next; + ++n; + } + } + return n; +} + /** Return the <b>hopnum</b>th hop in <b>circ</b>->cpath, or NULL if there * aren't that many hops in the list. <b>hopnum</b> starts at 1. * Returns NULL if <b>hopnum</b> is 0 or negative. */ diff --git a/src/or/circuitlist.h b/src/or/circuitlist.h index bf3393a941..8868646d59 100644 --- a/src/or/circuitlist.h +++ b/src/or/circuitlist.h @@ -17,6 +17,10 @@ MOCK_DECL(smartlist_t *, circuit_get_global_list, (void)); smartlist_t *circuit_get_global_origin_circuit_list(void); +int circuit_any_opened_circuits(void); +int circuit_any_opened_circuits_cached(void); +void circuit_cache_opened_circuit_state(int circuits_are_opened); + const char *circuit_state_to_string(int state); const char *circuit_purpose_to_controller_string(uint8_t purpose); const char *circuit_purpose_to_controller_hs_state_string(uint8_t purpose); @@ -58,6 +62,7 @@ void circuit_mark_all_dirty_circs_as_unusable(void); MOCK_DECL(void, circuit_mark_for_close_, (circuit_t *circ, int reason, int line, const char *file)); int circuit_get_cpath_len(origin_circuit_t *circ); +int circuit_get_cpath_opened_len(const origin_circuit_t *); void circuit_clear_cpath(origin_circuit_t *circ); crypt_path_t *circuit_get_cpath_hop(origin_circuit_t *circ, int hopnum); void circuit_get_all_pending_on_channel(smartlist_t *out, diff --git a/src/or/circuitstats.c b/src/or/circuitstats.c index b8421a3c7e..f1df19eb25 100644 --- a/src/or/circuitstats.c +++ b/src/or/circuitstats.c @@ -36,6 +36,8 @@ #include "rendclient.h" #include "rendservice.h" #include "statefile.h" +#include "circuitlist.h" +#include "circuituse.h" #undef log #include <math.h> @@ -43,6 +45,7 @@ static void cbt_control_event_buildtimeout_set( const circuit_build_times_t *cbt, buildtimeout_set_event_t type); +static void circuit_build_times_scale_circ_counts(circuit_build_times_t *cbt); #define CBT_BIN_TO_MS(bin) ((bin)*CBT_BIN_WIDTH + (CBT_BIN_WIDTH/2)) @@ -540,6 +543,11 @@ circuit_build_times_reset(circuit_build_times_t *cbt) cbt->total_build_times = 0; cbt->build_times_idx = 0; cbt->have_computed_timeout = 0; + + // Reset timeout and close counts + cbt->num_circ_succeeded = 0; + cbt->num_circ_closed = 0; + cbt->num_circ_timeouts = 0; } /** @@ -616,6 +624,123 @@ circuit_build_times_rewind_history(circuit_build_times_t *cbt, int n) #endif /* 0 */ /** + * Mark this circuit as timed out, but change its purpose + * so that it continues to build, allowing us to measure + * its full build time. + */ +void +circuit_build_times_mark_circ_as_measurement_only(origin_circuit_t *circ) +{ + control_event_circuit_status(circ, + CIRC_EVENT_FAILED, + END_CIRC_REASON_TIMEOUT); + circuit_change_purpose(TO_CIRCUIT(circ), + CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT); + /* Record this event 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. We also want to avoid double-counting + * already "relaxed" circuits, which are counted in + * circuit_expire_building(). */ + if (!circ->relaxed_timeout) { + int first_hop_succeeded = circ->cpath && + circ->cpath->state == CPATH_STATE_OPEN; + + circuit_build_times_count_timeout( + get_circuit_build_times_mutable(), + first_hop_succeeded); + } +} + +/** + * Perform the build time work that needs to be done when a circuit + * completes a hop. + * + * This function decides if we should record a circuit's build time + * in our histogram data and other statistics, and if so, records it. + * It also will mark circuits that have already timed out as + * measurement-only circuits, so they can continue to build but + * not get used. + * + * For this, we want to consider circuits that will eventually make + * it to the third hop. For circuits longer than 3 hops, we want to + * record their build time when they reach the third hop, but let + * them continue (and not count them later). For circuits that are + * exactly 3 hops, this will count them when they are completed. We + * do this so that CBT is always gathering statistics on circuits + * of the same length, regardless of their type. + */ +void +circuit_build_times_handle_completed_hop(origin_circuit_t *circ) +{ + struct timeval end; + long timediff; + + /* If circuit build times are disabled, let circuit_expire_building() + * handle it.. */ + if (circuit_build_times_disabled(get_options())) { + return; + } + + /* Is this a circuit for which the timeout applies in a straight-forward + * way? If so, handle it below. If not, just return (and let + * circuit_expire_building() eventually take care of it). + */ + if (!circuit_timeout_want_to_count_circ(circ)) { + return; + } + + tor_gettimeofday(&end); + timediff = tv_mdiff(&circ->base_.timestamp_began, &end); + + /* Check if we would have timed out already. If so, change the + * purpose here. But don't do any timeout handling here if there + * are no circuits opened yet. Save it for circuit_expire_building() + * (to allow it to handle timeout "relaxing" over there). */ + if (timediff > get_circuit_build_timeout_ms() && + circuit_any_opened_circuits_cached()) { + + /* Circuits are allowed to last longer for measurement. + * Switch their purpose and wait. */ + if (circ->base_.purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) { + log_info(LD_CIRC, + "Deciding to timeout circuit "U64_FORMAT"\n", + U64_PRINTF_ARG(circ->global_identifier)); + circuit_build_times_mark_circ_as_measurement_only(circ); + } + } + + /* If the circuit is built to exactly the DEFAULT_ROUTE_LEN, + * add it to our buildtimes. */ + if (circuit_get_cpath_opened_len(circ) == DEFAULT_ROUTE_LEN) { + /* 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 (timediff < 0 || + timediff > 2*get_circuit_build_close_time_ms()+1000) { + log_notice(LD_CIRC, "Strange value for circuit build time: %ldmsec. " + "Assuming clock jump. Purpose %d (%s)", timediff, + circ->base_.purpose, + circuit_purpose_to_string(circ->base_.purpose)); + } else { + /* Only count circuit times if the network is live */ + if (circuit_build_times_network_check_live( + get_circuit_build_times())) { + circuit_build_times_add_time(get_circuit_build_times_mutable(), + (build_time_t)timediff); + circuit_build_times_set_timeout(get_circuit_build_times_mutable()); + } + + if (circ->base_.purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) { + circuit_build_times_network_circ_success( + get_circuit_build_times_mutable()); + } + } + } +} + +/** * Add a new build time value <b>time</b> to the set of build times. Time * units are milliseconds. * @@ -1290,9 +1415,32 @@ circuit_build_times_network_is_live(circuit_build_times_t *cbt) } /** - * Called to indicate that we completed a circuit. Because this circuit + * Non-destructively scale all of our circuit success, timeout, and close + * counts down by a factor of two. Scaling in this way preserves the + * ratios between succeeded vs timed out vs closed circuits, so that + * our statistics don't change when we scale. + * + * This is used only in the rare event that we build more than + * INT32_MAX circuits. Since the num_circ_* variables are + * uint32_t, we won't even be close to overflowing them. + */ +void +circuit_build_times_scale_circ_counts(circuit_build_times_t *cbt) +{ + cbt->num_circ_succeeded /= 2; + cbt->num_circ_timeouts /= 2; + cbt->num_circ_closed /= 2; +} + +/** + * Called to indicate that we "completed" a circuit. Because this circuit * succeeded, it doesn't count as a timeout-after-the-first-hop. * + * (For the purposes of the cbt code, we consider a circuit "completed" if + * it has 3 hops, regardless of its final hop count. We do this because + * we're trying to answer the question, "how long should a circuit take to + * reach the 3-hop count".) + * * This is used by circuit_build_times_network_check_changed() to determine * if we had too many recent timeouts and need to reset our learned timeout * to something higher. @@ -1300,6 +1448,14 @@ circuit_build_times_network_is_live(circuit_build_times_t *cbt) void circuit_build_times_network_circ_success(circuit_build_times_t *cbt) { + // Count circuit success + cbt->num_circ_succeeded++; + + // If we're going to wrap int32, scale everything + if (cbt->num_circ_succeeded >= INT32_MAX) { + circuit_build_times_scale_circ_counts(cbt); + } + /* Check for NULLness because we might not be using adaptive timeouts */ if (cbt->liveness.timeouts_after_firsthop && cbt->liveness.num_recent_circs > 0) { @@ -1322,6 +1478,14 @@ static void circuit_build_times_network_timeout(circuit_build_times_t *cbt, int did_onehop) { + // Count circuit timeout + cbt->num_circ_timeouts++; + + // If we're going to wrap int32, scale everything + if (cbt->num_circ_timeouts >= INT32_MAX) { + circuit_build_times_scale_circ_counts(cbt); + } + /* Check for NULLness because we might not be using adaptive timeouts */ if (cbt->liveness.timeouts_after_firsthop && cbt->liveness.num_recent_circs > 0) { @@ -1347,6 +1511,15 @@ circuit_build_times_network_close(circuit_build_times_t *cbt, int did_onehop, time_t start_time) { time_t now = time(NULL); + + // Count circuit close + cbt->num_circ_closed++; + + // If we're going to wrap int32, scale everything + if (cbt->num_circ_closed >= INT32_MAX) { + circuit_build_times_scale_circ_counts(cbt); + } + /* * Check if this is a timeout that was for a circuit that spent its * entire existence during a time where we have had no network activity. @@ -1701,6 +1874,8 @@ cbt_control_event_buildtimeout_set(const circuit_build_times_t *cbt, { char *args = NULL; double qnt; + double timeout_rate = 0.0; + double close_rate = 0.0; switch (type) { case BUILDTIMEOUT_SET_EVENT_RESET: @@ -1715,15 +1890,29 @@ cbt_control_event_buildtimeout_set(const circuit_build_times_t *cbt, break; } + /* The timeout rate is the ratio of the timeout count over + * the total number of circuits attempted. The total number of + * circuits is (timeouts+succeeded+closed), since a circuit can + * either timeout, close, or succeed. We cast the denominator + * to promote it to double before the addition, to avoid int32 + * overflow. */ + const double total_circuits = + ((double)cbt->num_circ_timeouts) + cbt->num_circ_succeeded + + cbt->num_circ_closed; + if (total_circuits >= 1.0) { + timeout_rate = cbt->num_circ_timeouts / total_circuits; + close_rate = cbt->num_circ_closed / total_circuits; + } + tor_asprintf(&args, "TOTAL_TIMES=%lu " "TIMEOUT_MS=%lu XM=%lu ALPHA=%f CUTOFF_QUANTILE=%f " "TIMEOUT_RATE=%f CLOSE_MS=%lu CLOSE_RATE=%f", (unsigned long)cbt->total_build_times, (unsigned long)cbt->timeout_ms, (unsigned long)cbt->Xm, cbt->alpha, qnt, - circuit_build_times_timeout_rate(cbt), + timeout_rate, (unsigned long)cbt->close_ms, - circuit_build_times_close_rate(cbt)); + close_rate); control_event_buildtimeout_set(type, args); diff --git a/src/or/circuitstats.h b/src/or/circuitstats.h index 92dc6405ba..86116cb7f8 100644 --- a/src/or/circuitstats.h +++ b/src/or/circuitstats.h @@ -34,6 +34,7 @@ void circuit_build_times_set_timeout(circuit_build_times_t *cbt); int circuit_build_times_add_time(circuit_build_times_t *cbt, build_time_t time); int circuit_build_times_needs_circuits(const circuit_build_times_t *cbt); +void circuit_build_times_handle_completed_hop(origin_circuit_t *circ); int circuit_build_times_needs_circuits_now(const circuit_build_times_t *cbt); void circuit_build_times_init(circuit_build_times_t *cbt); @@ -44,6 +45,7 @@ double circuit_build_times_timeout_rate(const circuit_build_times_t *cbt); double circuit_build_times_close_rate(const circuit_build_times_t *cbt); void circuit_build_times_update_last_circ(circuit_build_times_t *cbt); +void circuit_build_times_mark_circ_as_measurement_only(origin_circuit_t *circ); #ifdef CIRCUITSTATS_PRIVATE STATIC double circuit_build_times_calculate_timeout(circuit_build_times_t *cbt, @@ -94,6 +96,16 @@ struct circuit_build_times_s { double timeout_ms; /** How long we wait before actually closing the circuit. */ double close_ms; + /** Total succeeded counts. Old measurements may be scaled downward if + * we've seen a lot of circuits. */ + uint32_t num_circ_succeeded; + /** Total timeout counts. Old measurements may be scaled downward if + * we've seen a lot of circuits. */ + uint32_t num_circ_timeouts; + /** Total closed counts. Old measurements may be scaled downward if + * we've seen a lot of circuits.*/ + uint32_t num_circ_closed; + }; #endif /* defined(CIRCUITSTATS_PRIVATE) */ diff --git a/src/or/circuituse.c b/src/or/circuituse.c index ebaa46e301..825535739f 100644 --- a/src/or/circuituse.c +++ b/src/or/circuituse.c @@ -412,8 +412,17 @@ circuit_conforms_to_options(const origin_circuit_t *circ, } #endif /* 0 */ -/** Close all circuits that start at us, aren't open, and were born +/** + * Close all circuits that start at us, aren't open, and were born * at least CircuitBuildTimeout seconds ago. + * + * TODO: This function is now partially redundant to + * circuit_build_times_handle_completed_hop(), but that function only + * covers circuits up to and including 3 hops that are still actually + * completing hops. However, circuit_expire_building() also handles longer + * circuits, as well as circuits that are completely stalled. + * In the future (after prop247/other path selection revamping), we probably + * want to eliminate this rats nest in favor of a simpler approach. */ void circuit_expire_building(void) @@ -435,21 +444,7 @@ circuit_expire_building(void) * we want to be more lenient with timeouts, in case the * user has relocated and/or changed network connections. * See bug #3443. */ - SMARTLIST_FOREACH_BEGIN(circuit_get_global_list(), circuit_t *, next_circ) { - if (!CIRCUIT_IS_ORIGIN(next_circ) || /* didn't originate here */ - next_circ->marked_for_close) { /* don't mess with marked circs */ - continue; - } - - if (TO_ORIGIN_CIRCUIT(next_circ)->has_opened && - next_circ->state == CIRCUIT_STATE_OPEN && - TO_ORIGIN_CIRCUIT(next_circ)->build_state && - TO_ORIGIN_CIRCUIT(next_circ)->build_state->desired_path_len - == DEFAULT_ROUTE_LEN) { - any_opened_circs = 1; - break; - } - } SMARTLIST_FOREACH_END(next_circ); + any_opened_circs = circuit_any_opened_circuits(); #define SET_CUTOFF(target, msec) do { \ long ms = tor_lround(msec); \ @@ -493,6 +488,10 @@ circuit_expire_building(void) SET_CUTOFF(general_cutoff, get_circuit_build_timeout_ms()); SET_CUTOFF(begindir_cutoff, get_circuit_build_timeout_ms()); + // TODO: We should probably use route_len_for_purpose() here instead, + // except that does not count the extra round trip for things like server + // intros and rends. + /* > 3hop circs seem to have a 1.0 second delay on their cannibalized * 4th hop. */ SET_CUTOFF(fourhop_cutoff, get_circuit_build_timeout_ms() * (10/6.0) + 1000); @@ -585,7 +584,8 @@ circuit_expire_building(void) TO_ORIGIN_CIRCUIT(victim)->build_state->desired_path_len : -1, circuit_state_to_string(victim->state), - channel_state_to_string(victim->n_chan->state)); + victim->n_chan ? + channel_state_to_string(victim->n_chan->state) : "none"); /* We count the timeout here for CBT, because technically this * was a timeout, and the timeout value needs to reset if we @@ -610,7 +610,8 @@ circuit_expire_building(void) TO_ORIGIN_CIRCUIT(victim)->build_state->desired_path_len : -1, circuit_state_to_string(victim->state), - channel_state_to_string(victim->n_chan->state), + victim->n_chan ? + channel_state_to_string(victim->n_chan->state) : "none", (long)build_close_ms); } } @@ -694,23 +695,17 @@ circuit_expire_building(void) if (circuit_timeout_want_to_count_circ(TO_ORIGIN_CIRCUIT(victim)) && circuit_build_times_enough_to_compute(get_circuit_build_times())) { + + log_info(LD_CIRC, + "Deciding to count the timeout for circuit "U64_FORMAT"\n", + U64_PRINTF_ARG( + TO_ORIGIN_CIRCUIT(victim)->global_identifier)); + /* 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); - circuit_change_purpose(victim, 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. We also want to avoid double-counting - * already "relaxed" circuits, which are counted above. */ - if (!TO_ORIGIN_CIRCUIT(victim)->relaxed_timeout) { - circuit_build_times_count_timeout( - get_circuit_build_times_mutable(), - first_hop_succeeded); - } + circuit_build_times_mark_circ_as_measurement_only(TO_ORIGIN_CIRCUIT( + victim)); continue; } diff --git a/src/test/Makefile.nmake b/src/test/Makefile.nmake index 605f1a92c3..cfbe281b94 100644 --- a/src/test/Makefile.nmake +++ b/src/test/Makefile.nmake @@ -18,6 +18,7 @@ TEST_OBJECTS = test.obj test_addr.obj test_channel.obj test_channeltls.obj \ test_config.obj test_connection.obj \ test_cell_formats.obj test_relay.obj test_replay.obj \ test_channelpadding.obj \ + test_circuitstats.obj \ test_scheduler.obj test_introduce.obj test_hs.obj tinytest.obj tinytest.obj: ..\ext\tinytest.c diff --git a/src/test/include.am b/src/test/include.am index b5c5dd24f7..a4b9705fdd 100644 --- a/src/test/include.am +++ b/src/test/include.am @@ -98,6 +98,7 @@ src_test_test_SOURCES = \ src/test/test_circuitmux.c \ src/test/test_circuitbuild.c \ src/test/test_circuituse.c \ + src/test/test_circuitstats.c \ src/test/test_compat_libevent.c \ src/test/test_config.c \ src/test/test_connection.c \ diff --git a/src/test/test.c b/src/test/test.c index c2e285635c..f225fd277d 100644 --- a/src/test/test.c +++ b/src/test/test.c @@ -1178,6 +1178,7 @@ struct testgroup_t testgroups[] = { { "circuitlist/", circuitlist_tests }, { "circuitmux/", circuitmux_tests }, { "circuituse/", circuituse_tests }, + { "circuitstats/", circuitstats_tests }, { "compat/libevent/", compat_libevent_tests }, { "config/", config_tests }, { "connection/", connection_tests }, diff --git a/src/test/test.h b/src/test/test.h index b37fe25b33..93d527ba17 100644 --- a/src/test/test.h +++ b/src/test/test.h @@ -188,6 +188,7 @@ extern struct testcase_t circuitbuild_tests[]; extern struct testcase_t circuitlist_tests[]; extern struct testcase_t circuitmux_tests[]; extern struct testcase_t circuituse_tests[]; +extern struct testcase_t circuitstats_tests[]; extern struct testcase_t compat_libevent_tests[]; extern struct testcase_t config_tests[]; extern struct testcase_t connection_tests[]; diff --git a/src/test/test_circuitstats.c b/src/test/test_circuitstats.c new file mode 100644 index 0000000000..1c6a2ba28f --- /dev/null +++ b/src/test/test_circuitstats.c @@ -0,0 +1,199 @@ +/* Copyright (c) 2017, The Tor Project, Inc. */ +/* See LICENSE for licensing information */ + +#define CIRCUITBUILD_PRIVATE +#define CIRCUITSTATS_PRIVATE +#define CHANNEL_PRIVATE_ + +#include "or.h" +#include "test.h" +#include "test_helpers.h" +#include "log_test_helpers.h" +#include "config.h" +#include "circuitlist.h" +#include "circuitbuild.h" +#include "circuitstats.h" +#include "circuituse.h" +#include "channel.h" + +void test_circuitstats_timeout(void *arg); +void test_circuitstats_hoplen(void *arg); +origin_circuit_t *subtest_fourhop_circuit(struct timeval, int); +origin_circuit_t *add_opened_threehop(void); +origin_circuit_t *build_unopened_fourhop(struct timeval); + +void circuit_free(circuit_t *circ); +int onion_append_hop(crypt_path_t **head_ptr, extend_info_t *choice); + +static int marked_for_close; +/* Mock function because we are not trying to test the close circuit that does + * an awful lot of checks on the circuit object. */ +static void +mock_circuit_mark_for_close(circuit_t *circ, int reason, int line, + const char *file) +{ + (void) circ; + (void) reason; + (void) line; + (void) file; + marked_for_close = 1; + return; +} + +origin_circuit_t * +add_opened_threehop(void) +{ + origin_circuit_t *or_circ = origin_circuit_new(); + extend_info_t fakehop; + memset(&fakehop, 0, sizeof(fakehop)); + + TO_CIRCUIT(or_circ)->purpose = CIRCUIT_PURPOSE_C_GENERAL; + + or_circ->build_state = tor_malloc_zero(sizeof(cpath_build_state_t)); + or_circ->build_state->desired_path_len = DEFAULT_ROUTE_LEN; + + onion_append_hop(&or_circ->cpath, &fakehop); + onion_append_hop(&or_circ->cpath, &fakehop); + onion_append_hop(&or_circ->cpath, &fakehop); + + or_circ->has_opened = 1; + TO_CIRCUIT(or_circ)->state = CIRCUIT_STATE_OPEN; + TO_CIRCUIT(or_circ)->purpose = CIRCUIT_PURPOSE_C_GENERAL; + + return or_circ; +} + +origin_circuit_t * +build_unopened_fourhop(struct timeval circ_start_time) +{ + origin_circuit_t *or_circ = origin_circuit_new(); + extend_info_t *fakehop = tor_malloc_zero(sizeof(extend_info_t)); + memset(fakehop, 0, sizeof(extend_info_t)); + + TO_CIRCUIT(or_circ)->purpose = CIRCUIT_PURPOSE_C_GENERAL; + TO_CIRCUIT(or_circ)->timestamp_began = circ_start_time; + TO_CIRCUIT(or_circ)->timestamp_created = circ_start_time; + + or_circ->build_state = tor_malloc_zero(sizeof(cpath_build_state_t)); + or_circ->build_state->desired_path_len = 4; + + onion_append_hop(&or_circ->cpath, fakehop); + onion_append_hop(&or_circ->cpath, fakehop); + onion_append_hop(&or_circ->cpath, fakehop); + onion_append_hop(&or_circ->cpath, fakehop); + + return or_circ; +} + +origin_circuit_t * +subtest_fourhop_circuit(struct timeval circ_start_time, int should_timeout) +{ + origin_circuit_t *or_circ = build_unopened_fourhop(circ_start_time); + + // Now make them open one at a time and call + // circuit_build_times_handle_completed_hop(); + or_circ->cpath->state = CPATH_STATE_OPEN; + circuit_build_times_handle_completed_hop(or_circ); + tt_int_op(get_circuit_build_times()->total_build_times, OP_EQ, 0); + + or_circ->cpath->next->state = CPATH_STATE_OPEN; + circuit_build_times_handle_completed_hop(or_circ); + tt_int_op(get_circuit_build_times()->total_build_times, OP_EQ, 0); + + // Third hop: We should count it now. + or_circ->cpath->next->next->state = CPATH_STATE_OPEN; + circuit_build_times_handle_completed_hop(or_circ); + tt_int_op(get_circuit_build_times()->total_build_times, OP_EQ, + !should_timeout); // 1 if counted, 0 otherwise + + // Fourth hop: Don't double count + or_circ->cpath->next->next->next->state = CPATH_STATE_OPEN; + circuit_build_times_handle_completed_hop(or_circ); + tt_int_op(get_circuit_build_times()->total_build_times, OP_EQ, + !should_timeout); + + done: + return or_circ; +} + +void +test_circuitstats_hoplen(void *arg) +{ + /* Plan: + * 0. Test no other opened circs (relaxed timeout) + * 1. Check >3 hop circ building w/o timeout + * 2. Check >3 hop circs w/ timeouts.. + */ + struct timeval circ_start_time; + origin_circuit_t *threehop = NULL; + origin_circuit_t *fourhop = NULL; + (void)arg; + MOCK(circuit_mark_for_close_, mock_circuit_mark_for_close); + + circuit_build_times_init(get_circuit_build_times_mutable()); + + // Let's set a close_ms to 2X the initial timeout, so we can + // test relaxed functionality (which uses the close_ms timeout) + get_circuit_build_times_mutable()->close_ms *= 2; + + tor_gettimeofday(&circ_start_time); + circ_start_time.tv_sec -= 119; // make us hit "relaxed" cutoff + + // Test 1: Build a fourhop circuit that should get marked + // as relaxed and eventually counted by circuit_expire_building + // (but not before) + fourhop = subtest_fourhop_circuit(circ_start_time, 0); + tt_int_op(fourhop->relaxed_timeout, OP_EQ, 0); + tt_int_op(marked_for_close, OP_EQ, 0); + circuit_expire_building(); + tt_int_op(marked_for_close, OP_EQ, 0); + tt_int_op(fourhop->relaxed_timeout, OP_EQ, 1); + TO_CIRCUIT(fourhop)->timestamp_began.tv_sec -= 119; + circuit_expire_building(); + tt_int_op(get_circuit_build_times()->total_build_times, OP_EQ, 1); + tt_int_op(marked_for_close, OP_EQ, 1); + + circuit_free(TO_CIRCUIT(fourhop)); + circuit_build_times_reset(get_circuit_build_times_mutable()); + + // Test 2: Add a threehop circuit for non-relaxed timeouts + threehop = add_opened_threehop(); + + /* This circuit should not timeout */ + tor_gettimeofday(&circ_start_time); + circ_start_time.tv_sec -= 59; + fourhop = subtest_fourhop_circuit(circ_start_time, 0); + circuit_expire_building(); + tt_int_op(get_circuit_build_times()->total_build_times, OP_EQ, 1); + tt_int_op(TO_CIRCUIT(fourhop)->purpose, OP_NE, + CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT); + + circuit_free((circuit_t *)fourhop); + circuit_build_times_reset(get_circuit_build_times_mutable()); + + /* Test 3: This circuit should now time out and get marked as a + * measurement circuit, but still get counted (and counted only once) + */ + circ_start_time.tv_sec -= 2; + fourhop = subtest_fourhop_circuit(circ_start_time, 0); + tt_int_op(TO_CIRCUIT(fourhop)->purpose, OP_EQ, + CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT); + tt_int_op(get_circuit_build_times()->total_build_times, OP_EQ, 1); + circuit_expire_building(); + tt_int_op(get_circuit_build_times()->total_build_times, OP_EQ, 1); + + done: + UNMOCK(circuit_mark_for_close_); + circuit_free(TO_CIRCUIT(threehop)); + circuit_free(TO_CIRCUIT(fourhop)); + circuit_build_times_free_timeouts(get_circuit_build_times_mutable()); +} + +#define TEST_CIRCUITSTATS(name, flags) \ + { #name, test_##name, (flags), NULL, NULL } + +struct testcase_t circuitstats_tests[] = { + TEST_CIRCUITSTATS(circuitstats_hoplen, TT_FORK), + END_OF_TESTCASES +}; + |