commit b0e078d5af9d30d87060990e3a52fd16c63148e2 Author: Nick Mathewson <nickm@torproject.org> Date: Tue Apr 29 14:02:12 2014 -0400 Log info on ancient one-hop circuits in heartbeat This is an attempt to diagnose 8387. --- changes/diagnose_8387 | 4 ++++ src/or/circuituse.c | 58 +++++++++++++++++++++++++++++++++++++++++++++++++ src/or/circuituse.h | 1 + src/or/status.c | 3 +++ 4 files changed, 66 insertions(+) diff --git a/changes/diagnose_8387 b/changes/diagnose_8387 new file mode 100644 index 0000000..3dfc845 --- /dev/null +++ b/changes/diagnose_8387 @@ -0,0 +1,4 @@ + o Minor features (diagnostic): + - When we log a heartbeat, log how many one-hop circuits we have that + are at least 30 minutes old, and log status information about a + few of them. This is an attempt to track down bug 8387. diff --git a/src/or/circuituse.c b/src/or/circuituse.c index d104306..7820e88 100644 --- a/src/or/circuituse.c +++ b/src/or/circuituse.c @@ -783,6 +783,64 @@ circuit_expire_building(void) } } +/** + * As a diagnostic for bug 8387, log information about how many one-hop + * circuits we have around that have been there for at least <b>age</b> + * seconds. Log a few of them. + */ +void +circuit_log_ancient_one_hop_circuits(int age) +{ +#define MAX_ANCIENT_ONEHOP_CIRCUITS_TO_LOG 10 + time_t cutoff = time(NULL) - age; + int n_found = 0; + smartlist_t *log_these = smartlist_new(); + const circuit_t *circ; + + TOR_LIST_FOREACH(circ, circuit_get_global_list(), head) { + const origin_circuit_t *ocirc; + if (! CIRCUIT_IS_ORIGIN(circ)) + continue; + if (circ->timestamp_created.tv_sec >= cutoff) + continue; + ocirc = CONST_TO_ORIGIN_CIRCUIT(circ); + + if (ocirc->build_state && ocirc->build_state->onehop_tunnel) { + ++n_found; + + if (smartlist_len(log_these) < MAX_ANCIENT_ONEHOP_CIRCUITS_TO_LOG) + smartlist_add(log_these, (origin_circuit_t*) ocirc); + } + } + + if (n_found == 0) + goto done; + + log_notice(LD_HEARTBEAT, + "Problem: Found %d one-hop circuits more than %d seconds old! " + "Logging %d...", + n_found, age, smartlist_len(log_these)); + + SMARTLIST_FOREACH_BEGIN(log_these, const origin_circuit_t *, ocirc) { + char created[ISO_TIME_LEN+1]; + circ = TO_CIRCUIT(ocirc); + format_local_iso_time(created, + circ->timestamp_created.tv_sec); + + log_notice(LD_HEARTBEAT, " #%d created at %s. %s, %s. %s for close. " + "%s for new conns.", + ocirc_sl_idx, + created, + circuit_state_to_string(circ->state), + circuit_purpose_to_string(circ->purpose), + circ->marked_for_close ? "Marked" : "Not marked", + ocirc->unusable_for_new_conns ? "Not usable" : "usable"); + } SMARTLIST_FOREACH_END(ocirc); + + done: + smartlist_free(log_these); +} + /** Remove any elements in <b>needed_ports</b> that are handled by an * open or in-progress circuit. */ diff --git a/src/or/circuituse.h b/src/or/circuituse.h index 11e5a64..f228a67 100644 --- a/src/or/circuituse.h +++ b/src/or/circuituse.h @@ -16,6 +16,7 @@ void circuit_expire_building(void); void circuit_remove_handled_ports(smartlist_t *needed_ports); int circuit_stream_is_being_handled(entry_connection_t *conn, uint16_t port, int min); +void circuit_log_ancient_one_hop_circuits(int age); #if 0 int circuit_conforms_to_options(const origin_circuit_t *circ, const or_options_t *options); diff --git a/src/or/status.c b/src/or/status.c index 7e2afbc..afaa9de 100644 --- a/src/or/status.c +++ b/src/or/status.c @@ -9,6 +9,7 @@ #define STATUS_PRIVATE #include "or.h" +#include "circuituse.h" #include "config.h" #include "status.h" #include "nodelist.h" @@ -135,6 +136,8 @@ log_heartbeat(time_t now) if (public_server_mode(options)) rep_hist_log_circuit_handshake_stats(now); + circuit_log_ancient_one_hop_circuits(1800); + tor_free(uptime); tor_free(bw_sent); tor_free(bw_rcvd);