commit 4e42a8a2f20e501f9236452b41939964e6d942cf Author: Mike Perry <mikeperry-git@fscked.org> Date: Thu Aug 16 16:29:19 2012 -0700 Address Nick's comments from code review. Also promote log messages to notice and rate-limit them. --- changes/bug6475 | 6 + src/or/circuitbuild.c | 284 ++++++++++++++++++++++++++++++++++--------------- src/or/or.h | 13 ++- 3 files changed, 217 insertions(+), 86 deletions(-) diff --git a/changes/bug6475 b/changes/bug6475 new file mode 100644 index 0000000..67bab99 --- /dev/null +++ b/changes/bug6475 @@ -0,0 +1,6 @@ + o Minor bugfixes: + - Add internal circuit construction state to protect against + the noisy warn message "Unexpectedly high circuit_successes". + Also add some additional rate-limited notice messages to help + determine the root cause of the warn. Fixes bug 6475. + Bugfix against 0.2.3.17-beta. diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c index 7ac2b97..2fa3dd5 100644 --- a/src/or/circuitbuild.c +++ b/src/or/circuitbuild.c @@ -135,6 +135,9 @@ static entry_guard_t *entry_guard_get_by_id_digest(const char *digest); static void bridge_free(bridge_info_t *bridge); +static int entry_guard_inc_first_hop_count(entry_guard_t *guard); +static void pathbias_count_success(origin_circuit_t *circ); + /** * This function decides if CBT learning should be disabled. It returns * true if one or more of the following four conditions are met: @@ -2285,44 +2288,11 @@ circuit_send_next_onion_skin(origin_circuit_t *circ) } log_info(LD_CIRC,"circuit built!"); circuit_reset_failure_count(0); - /* Don't count cannibalized or onehop circs for path bias */ + if (circ->build_state->onehop_tunnel || circ->has_opened) { control_event_bootstrap(BOOTSTRAP_STATUS_REQUESTING_STATUS, 0); - } else { - entry_guard_t *guard = - entry_guard_get_by_id_digest(circ->_base.n_conn->identity_digest); - - if (guard) { - if (circ->path_state == PATH_STATE_DID_FIRST_HOP) { - circ->path_state = PATH_STATE_SUCCEEDED; - guard->circuit_successes++; - - log_info(LD_PROTOCOL, "Got success count %u/%u for guard %s=%s", - guard->circuit_successes, guard->first_hops, - guard->nickname, hex_str(guard->identity, DIGEST_LEN)); - } else { - log_info(LD_BUG, - "Succeeded circuit has strange path state %d. " - "Circuit is a %s currently %s.", - circ->path_state, - circuit_purpose_to_string(circ->_base.purpose), - circuit_state_to_string(circ->_base.state)); - } - - if (guard->first_hops < guard->circuit_successes) { - log_warn(LD_BUG, "Unexpectedly high circuit_successes (%u/%u) " - "for guard %s=%s", - guard->circuit_successes, guard->first_hops, - guard->nickname, hex_str(guard->identity, DIGEST_LEN)); - } - } else { - log_info(LD_BUG, - "Completed circuit has no known guard. " - "Circuit is a %s currently %s.", - circuit_purpose_to_string(circ->_base.purpose), - circuit_state_to_string(circ->_base.state)); - } } + if (!can_complete_circuit && !circ->build_state->onehop_tunnel) { const or_options_t *options = get_options(); can_complete_circuit=1; @@ -2338,6 +2308,8 @@ circuit_send_next_onion_skin(origin_circuit_t *circ) consider_testing_reachability(1, 1); } } + + pathbias_count_success(circ); circuit_rep_hist_note_result(circ); circuit_has_opened(circ); /* do other actions as necessary */ @@ -2637,6 +2609,194 @@ pathbias_get_scale_factor(const or_options_t *options) DFLT_PATH_BIAS_SCALE_THRESHOLD, 1, INT32_MAX); } +const char * +pathbias_state_to_string(path_state_t state) +{ + switch(state) { + case PATH_STATE_NEW_CIRC: + return "new"; + case PATH_STATE_DID_FIRST_HOP: + return "first hop"; + case PATH_STATE_SUCCEEDED: + return "succeeded"; + } + + return "unknown"; +} + + +/** + * Check our circuit state to see if this is a successful first hop. + * If so, record it in the current guard's path bias first_hop count. + * + * Also check for several potential error cases for bug #6475. + */ +static int +pathbias_count_first_hop(origin_circuit_t *circ) +{ +#define FIRST_HOP_NOTICE_INTERVAL (600) + static ratelim_t first_hop_notice_limit = RATELIM_INIT(FIRST_HOP_NOTICE_INTERVAL); + char *rate_msg = NULL; + + /* Completely ignore one hop circuits */ + if (circ->build_state->onehop_tunnel) { + tor_assert(circ->build_state->desired_path_len == 1); + return 0; + } + + if (circ->cpath->state == CPATH_STATE_AWAITING_KEYS) { + /* Help track down the real cause of bug #6475: */ + if (circ->has_opened && circ->path_state != PATH_STATE_DID_FIRST_HOP) { + if ((rate_msg = rate_limit_log(&first_hop_notice_limit, + approx_time()))) { + log_notice(LD_BUG, + "Opened circuit is in strange path state %s. " + "Circuit is a %s currently %s. %s", + pathbias_state_to_string(circ->path_state), + circuit_purpose_to_string(circ->_base.purpose), + circuit_state_to_string(circ->_base.state), + rate_msg); + } + } + + /* Don't count cannibalized circs for path bias */ + if (!circ->has_opened) { + entry_guard_t *guard; + + guard = entry_guard_get_by_id_digest( + circ->_base.n_conn->identity_digest); + if (guard) { + if (circ->path_state == PATH_STATE_NEW_CIRC) { + circ->path_state = PATH_STATE_DID_FIRST_HOP; + + if (entry_guard_inc_first_hop_count(guard) < 0) { + /* Bogus guard; we already warned. */ + return -END_CIRC_REASON_TORPROTOCOL; + } + } else { + if ((rate_msg = rate_limit_log(&first_hop_notice_limit, + approx_time()))) { + log_notice(LD_BUG, + "Unopened circuit has strange path state %s. " + "Circuit is a %s currently %s. %s", + pathbias_state_to_string(circ->path_state), + circuit_purpose_to_string(circ->_base.purpose), + circuit_state_to_string(circ->_base.state), + rate_msg); + } + } + } else { + if ((rate_msg = rate_limit_log(&first_hop_notice_limit, + approx_time()))) { + log_notice(LD_BUG, + "Unopened circuit has no known guard. " + "Circuit is a %s currently %s. %s", + circuit_purpose_to_string(circ->_base.purpose), + circuit_state_to_string(circ->_base.state), + rate_msg); + } + } + } + } else { + /* Help track down the real cause of bug #6475: */ + if (circ->path_state == PATH_STATE_NEW_CIRC) { + if ((rate_msg = rate_limit_log(&first_hop_notice_limit, + approx_time()))) { + log_notice(LD_BUG, + "A %s circuit is in cpath state %d (opened: %d). " + "Circuit is a %s currently %s. %s", + pathbias_state_to_string(circ->path_state), + circ->cpath->state, circ->has_opened, + circuit_purpose_to_string(circ->_base.purpose), + circuit_state_to_string(circ->_base.state), + rate_msg); + } + } + } + + return 0; +} + +/** + * Check our circuit state to see if this is a successful circuit + * completion. If so, record it in the current guard's path bias + * success count. + * + * Also check for several potential error cases for bug #6475. + */ +static void +pathbias_count_success(origin_circuit_t *circ) +{ +#define SUCCESS_NOTICE_INTERVAL (600) + static ratelim_t success_notice_limit = RATELIM_INIT(SUCCESS_NOTICE_INTERVAL); + char *rate_msg = NULL; + + /* Ignore one hop circuits */ + if (circ->build_state->onehop_tunnel) { + tor_assert(circ->build_state->desired_path_len == 1); + return; + } + + /* Don't count cannibalized/reused circs for path bias */ + if (!circ->has_opened) { + entry_guard_t *guard = + entry_guard_get_by_id_digest(circ->_base.n_conn->identity_digest); + + if (guard) { + if (circ->path_state == PATH_STATE_DID_FIRST_HOP) { + circ->path_state = PATH_STATE_SUCCEEDED; + guard->circuit_successes++; + + log_info(LD_PROTOCOL, "Got success count %u/%u for guard %s=%s", + guard->circuit_successes, guard->first_hops, + guard->nickname, hex_str(guard->identity, DIGEST_LEN)); + } else { + if ((rate_msg = rate_limit_log(&success_notice_limit, + approx_time()))) { + log_notice(LD_BUG, + "Succeeded circuit is in strange path state %s. " + "Circuit is a %s currently %s. %s", + pathbias_state_to_string(circ->path_state), + circuit_purpose_to_string(circ->_base.purpose), + circuit_state_to_string(circ->_base.state), + rate_msg); + } + } + + if (guard->first_hops < guard->circuit_successes) { + log_warn(LD_BUG, "Unexpectedly high circuit_successes (%u/%u) " + "for guard %s=%s", + guard->circuit_successes, guard->first_hops, + guard->nickname, hex_str(guard->identity, DIGEST_LEN)); + } + } else { + if ((rate_msg = rate_limit_log(&success_notice_limit, + approx_time()))) { + log_notice(LD_BUG, + "Completed circuit has no known guard. " + "Circuit is a %s currently %s. %s", + circuit_purpose_to_string(circ->_base.purpose), + circuit_state_to_string(circ->_base.state), + rate_msg); + } + } + } else { + if (circ->path_state != PATH_STATE_SUCCEEDED) { + if ((rate_msg = rate_limit_log(&success_notice_limit, + approx_time()))) { + log_notice(LD_BUG, + "Opened circuit is in strange path state %s. " + "Circuit is a %s currently %s. %s", + pathbias_state_to_string(circ->path_state), + circuit_purpose_to_string(circ->_base.purpose), + circuit_state_to_string(circ->_base.state), + rate_msg); + } + } + } +} + + /** Increment the number of times we successfully extended a circuit to * 'guard', first checking if the failure rate is high enough that we should * eliminate the guard. Return -1 if the guard looks no good; return 0 if the @@ -2704,60 +2864,14 @@ circuit_finish_handshake(origin_circuit_t *circ, uint8_t reply_type, { char keys[CPATH_KEY_MATERIAL_LEN]; crypt_path_t *hop; + int rv; + + if((rv = pathbias_count_first_hop(circ)) < 0) + return rv; if (circ->cpath->state == CPATH_STATE_AWAITING_KEYS) { hop = circ->cpath; - - /* Help track down the real cause of bug #6475: */ - if (circ->has_opened && circ->path_state == PATH_STATE_NEW_CIRC) { - log_info(LD_BUG, - "Opened circuit seems new. " - "Circuit is a %s currently %s.", - circuit_purpose_to_string(circ->_base.purpose), - circuit_state_to_string(circ->_base.state)); - } - - /* Don't count cannibalized or onehop circs for path bias */ - if (!circ->has_opened && !circ->build_state->onehop_tunnel) { - entry_guard_t *guard; - - guard = entry_guard_get_by_id_digest( - circ->_base.n_conn->identity_digest); - if (guard) { - if (circ->path_state == PATH_STATE_NEW_CIRC) { - circ->path_state = PATH_STATE_DID_FIRST_HOP; - - if (entry_guard_inc_first_hop_count(guard) < 0) { - /* Bogus guard; we already warned. */ - return -END_CIRC_REASON_TORPROTOCOL; - } - } else { - log_info(LD_BUG, - "Unopened circuit has strange path state %d. " - "Circuit is a %s currently %s.", - circ->path_state, - circuit_purpose_to_string(circ->_base.purpose), - circuit_state_to_string(circ->_base.state)); - } - } else { - log_info(LD_BUG, - "Opened circuit has no known guard. " - "Circuit is a %s currently %s.", - circuit_purpose_to_string(circ->_base.purpose), - circuit_state_to_string(circ->_base.state)); - } - } } else { - /* Help track down the real cause of bug #6475: */ - if (circ->path_state == PATH_STATE_NEW_CIRC) { - log_info(LD_BUG, - "New circuit is in cpath state %d (opened: %d). " - "Circuit is a %s currently %s.", - circ->cpath->state, circ->has_opened, - circuit_purpose_to_string(circ->_base.purpose), - circuit_state_to_string(circ->_base.state)); - } - hop = onion_next_hop_in_cpath(circ->cpath); if (!hop) { /* got an extended when we're all done? */ log_warn(LD_PROTOCOL,"got extended when circ already built? Closing."); diff --git a/src/or/or.h b/src/or/or.h index 0db6137..d2cafb5 100644 --- a/src/or/or.h +++ b/src/or/or.h @@ -2596,9 +2596,20 @@ typedef struct circuit_t { * circuit. */ #define MAX_RELAY_EARLY_CELLS_PER_CIRCUIT 8 +/** + * Describes the circuit building process in simplified terms based + * on the path bias accounting state for a circuit. Created to prevent + * overcounting due to unknown cases of circuit reuse. See Bug #6475. + */ typedef enum { + /** This circuit is "new". It has not yet completed a first hop + * or been counted by the path bias code. */ PATH_STATE_NEW_CIRC = 0, + /** This circuit has completed a first hop, and has been counted by + * the path bias logic. */ PATH_STATE_DID_FIRST_HOP = 1, + /** This circuit has been completely built, and has been counted as + * successful by the path bias logic. */ PATH_STATE_SUCCEEDED = 2, } path_state_t; @@ -2637,7 +2648,7 @@ typedef struct origin_circuit_t { /** Kludge to help us prevent the warn in bug #6475 and eventually * debug why we are not seeing first hops in some cases. */ - path_state_t path_state; + path_state_t path_state : 2; /** Set iff this is a hidden-service circuit which has timed out * according to our current circuit-build timeout, but which has