From cc641ff5b05b2f8bc831ff28fa5d4226933d18a0 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Wed, 27 Mar 2013 15:33:58 -0700 Subject: [PATCH 1/4] Add changes file for bug 7799's log message changes. Note this does not close bug 7799. --- changes/bug7799 | 3 +++ 1 file changed, 3 insertions(+) create mode 100644 changes/bug7799 diff --git a/changes/bug7799 b/changes/bug7799 new file mode 100644 index 0000000000..1bb5597c1b --- /dev/null +++ b/changes/bug7799 @@ -0,0 +1,3 @@ + o Minor changes (log clarification) + - Add more detail to a log message about relaxed timeouts. Hopefully + this additional detail will allow us to diagnose the cause of bug 7799. From 66586da9bc023bf60b2d18e02004a4e278b73359 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Wed, 27 Mar 2013 15:34:54 -0700 Subject: [PATCH 2/4] Add detail to log messages related to bug 7799. Note this does not solve bug 7799, it is only to help us diagnose it. --- src/or/circuituse.c | 21 +++++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/src/or/circuituse.c b/src/or/circuituse.c index 14576f13d6..bbf219a1ef 100644 --- a/src/or/circuituse.c +++ b/src/or/circuituse.c @@ -536,8 +536,13 @@ circuit_expire_building(void) int first_hop_succeeded = TO_ORIGIN_CIRCUIT(victim)->cpath->state == CPATH_STATE_OPEN; log_info(LD_CIRC, - "No circuits are opened. Relaxing timeout for " - "a circuit with channel state %s. %d guards are live.", + "No circuits are opened. Relaxing timeout for circuit %d " + "(a %s %d-hop circuit in state %s with channel state %s). " + "%d guards are live.", + TO_ORIGIN_CIRCUIT(victim)->global_identifier, + circuit_purpose_to_string(victim->purpose), + TO_ORIGIN_CIRCUIT(victim)->build_state->desired_path_len, + circuit_state_to_string(victim->state), channel_state_to_string(victim->n_chan->state), num_live_entry_guards(0)); @@ -552,10 +557,14 @@ circuit_expire_building(void) } else { static ratelim_t relax_timeout_limit = RATELIM_INIT(3600); log_fn_ratelim(&relax_timeout_limit, LOG_NOTICE, LD_CIRC, - "No circuits are opened. Relaxed timeout for " - "a circuit with channel state %s to %ldms. " - "However, it appears the circuit has timed out anyway. " - "%d guards are live.", + "No circuits are opened. Relaxed timeout for circuit %d " + "(a %s %d-hop circuit in state %s with channel state %s) to " + "%ldms. However, it appears the circuit has timed out " + "anyway. %d guards are live.", + TO_ORIGIN_CIRCUIT(victim)->global_identifier, + circuit_purpose_to_string(victim->purpose), + TO_ORIGIN_CIRCUIT(victim)->build_state->desired_path_len, + circuit_state_to_string(victim->state), channel_state_to_string(victim->n_chan->state), (long)circ_times.close_ms, num_live_entry_guards(0)); } From 1d49ba84a82c6dfb8873cf32fdecdf5af0b65c90 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Wed, 27 Mar 2013 17:43:05 -0700 Subject: [PATCH 3/4] Update the changes file for bug7799. Still not sure it's actually fixed yet... --- changes/bug7799 | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/changes/bug7799 b/changes/bug7799 index 1bb5597c1b..ed4570129c 100644 --- a/changes/bug7799 +++ b/changes/bug7799 @@ -1,3 +1,7 @@ o Minor changes (log clarification) - Add more detail to a log message about relaxed timeouts. Hopefully this additional detail will allow us to diagnose the cause of bug 7799. + o Minor bugfixes + - Don't attempt to relax the timeout of already opened 1-hop circuits. + They might never timeout. This should eliminate some/all cases of + the relaxed timeout log message. From d39e6736fe1608028223604f49d5d091ef23bb27 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Wed, 27 Mar 2013 17:43:27 -0700 Subject: [PATCH 4/4] Don't relax the timeout for already opened 1-hop circuits. --- src/or/circuituse.c | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/src/or/circuituse.c b/src/or/circuituse.c index bbf219a1ef..8fb70f5853 100644 --- a/src/or/circuituse.c +++ b/src/or/circuituse.c @@ -529,7 +529,12 @@ circuit_expire_building(void) if (timercmp(&victim->timestamp_began, &cutoff, >)) continue; /* it's still young, leave it alone */ - if (!any_opened_circs) { + /* We need to double-check the opened state here because + * we don't want to consider opened 1-hop dircon circuits for + * deciding when to relax the timeout, but we *do* want to relax + * those circuits too if nothing else is opened *and* they still + * aren't either. */ + if (!any_opened_circs && victim->state != CIRCUIT_STATE_OPEN) { /* It's still young enough that we wouldn't close it, right? */ if (timercmp(&victim->timestamp_began, &close_cutoff, >)) { if (!TO_ORIGIN_CIRCUIT(victim)->relaxed_timeout) {