From 4f62bf81182ffed7da9d8ca30969da43ab151c7f Mon Sep 17 00:00:00 2001 From: Christopher Baines Date: Mon, 24 Mar 2014 00:39:16 +0000 Subject: Lots of logging stuff --- src/or/channel.c | 10 ++++++++-- src/or/circpathbias.c | 3 ++- src/or/circuitbuild.c | 12 +++++++++++- src/or/circuitlist.c | 8 +++++++- src/or/circuituse.c | 3 +++ src/or/rendclient.c | 2 ++ src/or/rendmid.c | 18 ++++++++++++++++-- src/or/rendservice.c | 14 ++++++++++---- 8 files changed, 59 insertions(+), 11 deletions(-) diff --git a/src/or/channel.c b/src/or/channel.c index 9f6887588..5cf00ab18 100644 --- a/src/or/channel.c +++ b/src/or/channel.c @@ -1295,8 +1295,10 @@ channel_closed(channel_t *chan) /* Inform any pending (not attached) circs that they should * give up. */ - if (! chan->has_been_open) + if (! chan->has_been_open) { + log_info(LD_CIRC, "calling circuit_n_chan_done from channel_closed"); circuit_n_chan_done(chan, 0); + } /* Now close all the attached circuits on it. */ circuit_unlink_all_from_channel(chan, END_CIRC_REASON_CHANNEL_CLOSED); @@ -2370,6 +2372,7 @@ channel_do_open_actions(channel_t *chan) log_debug(LD_OR, "New entry guard was reachable, but closing this " "connection so we can retry the earlier entry guards."); + log_info(LD_CIRC, "calling circuit_n_chan_done from channel_do_open_actions 1"); circuit_n_chan_done(chan, 0); not_using = 1; } @@ -2391,7 +2394,10 @@ channel_do_open_actions(channel_t *chan) } } - if (!not_using) circuit_n_chan_done(chan, 1); + if (!not_using) { + log_info(LD_CIRC, "calling circuit_n_chan_done from channel_do_open_actions 2"); + circuit_n_chan_done(chan, 1); + } } /** diff --git a/src/or/circpathbias.c b/src/or/circpathbias.c index 51a75cf50..21c07fc15 100644 --- a/src/or/circpathbias.c +++ b/src/or/circpathbias.c @@ -921,9 +921,10 @@ pathbias_check_close(origin_circuit_t *ocirc, int reason) if (reason & END_CIRC_REASON_FLAG_REMOTE) { /* Remote circ close reasons on an unused circuit all could be bias */ log_info(LD_CIRC, - "Circuit %d remote-closed without successful use for reason %d. " + "Circuit %d (%u) remote-closed without successful use for reason %d. " "Circuit purpose %d currently %d,%s. Len %d.", ocirc->global_identifier, + ocirc->base_.n_circ_id, reason, circ->purpose, ocirc->has_opened, circuit_state_to_string(circ->state), ocirc->build_state->desired_path_len); diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c index ffcca4666..127ddd5bd 100644 --- a/src/or/circuitbuild.c +++ b/src/or/circuitbuild.c @@ -476,6 +476,10 @@ circuit_n_chan_done(channel_t *chan, int status) chan->nickname ? chan->nickname : "NULL", channel_get_canonical_remote_descr(chan), status); + log_info(LD_REND,"chan to %s/%s, status=%d", + chan->nickname ? chan->nickname : "NULL", + channel_get_canonical_remote_descr(chan), status); + pending_circs = smartlist_new(); circuit_get_all_pending_on_channel(pending_circs, chan); @@ -499,7 +503,10 @@ circuit_n_chan_done(channel_t *chan, int status) continue; } if (!status) { /* chan failed; close circ */ - log_info(LD_CIRC,"Channel failed; closing circ."); + log_info(LD_CIRC,"Channel failed; closing circ (%u).", (unsigned)circ->n_circ_id); + log_info(LD_REND, "calling circuit_mark_for_close on %u chan global %" PRIu64, + (unsigned) circ->n_circ_id, + chan->global_identifier); circuit_mark_for_close(circ, END_CIRC_REASON_CHANNEL_CLOSED); continue; } @@ -872,6 +879,7 @@ circuit_send_next_onion_skin(origin_circuit_t *circ) /* We're done with measurement circuits here. Just close them */ if (circ->base_.purpose == CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) { + log_info(LD_REND, "closing some circuit We're done with measurement circuits here. Just close them"); circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_FINISHED); } return 0; @@ -2154,7 +2162,9 @@ extend_info_free(extend_info_t *info) { if (!info) return; + log_info(LD_REND, "calling crypto_pk_free"); crypto_pk_free(info->onion_key); + log_info(LD_REND, "calling tor_free"); tor_free(info); } diff --git a/src/or/circuitlist.c b/src/or/circuitlist.c index 68c9cd53c..2458ad16e 100644 --- a/src/or/circuitlist.c +++ b/src/or/circuitlist.c @@ -1457,7 +1457,13 @@ circuit_mark_for_close_(circuit_t *circ, int reason, int line, } if (CIRCUIT_IS_ORIGIN(circ)) { - if (pathbias_check_close(TO_ORIGIN_CIRCUIT(circ), reason) == -1) { + origin_circuit_t *ocirc = TO_ORIGIN_CIRCUIT(circ); + log_info(LD_CIRC, + "n_circ_id %u global_identifier %d reason %i calling pathbias_check_close", + (unsigned) circ->n_circ_id, + ocirc->global_identifier, + reason); + if (pathbias_check_close(ocirc, reason) == -1) { /* Don't close it yet, we need to test it first */ return; } diff --git a/src/or/circuituse.c b/src/or/circuituse.c index 54986749e..e31a894ae 100644 --- a/src/or/circuituse.c +++ b/src/or/circuituse.c @@ -1539,6 +1539,9 @@ circuit_launch_by_extend_info(uint8_t purpose, */ /* This must be called before the purpose change */ + log_info(LD_CIRC, + "calling pathbias_check_close from circuit_launch_by_extend_info"); + pathbias_check_close(circ, END_CIRC_REASON_FINISHED); } diff --git a/src/or/rendclient.c b/src/or/rendclient.c index 24d720c91..ab881dd56 100644 --- a/src/or/rendclient.c +++ b/src/or/rendclient.c @@ -1235,6 +1235,8 @@ rend_client_any_intro_points_usable(const rend_cache_entry_t *entry) int rv = (extend_info != NULL); + log_info(LD_REND, "rv %i", rv); + extend_info_free(extend_info); return rv; } diff --git a/src/or/rendmid.c b/src/or/rendmid.c index 81a2f16ec..475358189 100644 --- a/src/or/rendmid.c +++ b/src/or/rendmid.c @@ -31,8 +31,9 @@ rend_mid_establish_intro(or_circuit_t *circ, const uint8_t *request, int reason = END_CIRC_REASON_INTERNAL; log_info(LD_REND, - "Received an ESTABLISH_INTRO request on circuit %u", - (unsigned) circ->p_circ_id); + "Received an ESTABLISH_INTRO request on circuit (p_circ_id %u n_circ_id %u)", + (unsigned) circ->p_circ_id, + (unsigned) circ->base_.n_circ_id); if (circ->base_.purpose != CIRCUIT_PURPOSE_OR || circ->base_.n_chan) { log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL, @@ -181,6 +182,12 @@ rend_mid_introduce(or_circuit_t *circ, const uint8_t *request, "found %i possible introduction circuits for service %s", smartlist_len(intro_circuits), safe_str(serviceid)); + SMARTLIST_FOREACH_BEGIN(intro_circuits, or_circuit_t *, circuit) + { + log_info(LD_REND, "circuit id %u", (unsigned) circuit->p_circ_id); + } + SMARTLIST_FOREACH_END(circuit); + if (smartlist_len(intro_circuits) == 0) { log_info(LD_REND, "No intro circ found for INTRODUCE1 cell (%s) from circuit %u; " @@ -234,22 +241,28 @@ rend_mid_introduce(or_circuit_t *circ, const uint8_t *request, safe_str(serviceid), (unsigned)circ->p_circ_id, (unsigned)intro_circ->p_circ_id); + log_info(LD_REND, "Sending relay cell"); /* Great. Now we just relay the cell down the circuit. */ if (relay_send_command_from_edge(0, TO_CIRCUIT(intro_circ), RELAY_COMMAND_INTRODUCE2, (char*)request, request_len, NULL)) { log_warn(LD_GENERAL, "Unable to send INTRODUCE2 cell to Tor client."); + log_info(LD_REND, + "Unable to send INTRODUCE2 cell to Tor client."); goto err; } + log_info(LD_REND, "Sending ack cell"); /* And sent an ack down Alice's circuit. Empty body means succeeded. */ if (relay_send_command_from_edge(0,TO_CIRCUIT(circ), RELAY_COMMAND_INTRODUCE_ACK, NULL,0,NULL)) { log_warn(LD_GENERAL, "Unable to send INTRODUCE_ACK cell to Tor client."); + log_info(LD_REND, "Unable to send INTRODUCE_ACK cell to Tor client, calling circuit_mark_for_close"); circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_INTERNAL); return -1; } + log_info(LD_REND, "Completed sending introduction request"); return 0; err: @@ -259,6 +272,7 @@ rend_mid_introduce(or_circuit_t *circ, const uint8_t *request, RELAY_COMMAND_INTRODUCE_ACK, nak_body, 1, NULL)) { log_warn(LD_GENERAL, "Unable to send NAK to Tor client."); + log_info(LD_REND, "Unable to send NAK to Tor client, calling circuit_mark_for_close"); /* Is this right? */ circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_INTERNAL); } diff --git a/src/or/rendservice.c b/src/or/rendservice.c index 805b5da61..41b0a3b5d 100644 --- a/src/or/rendservice.c +++ b/src/or/rendservice.c @@ -2327,8 +2327,9 @@ rend_service_launch_establish_intro(rend_service_t *service, return -1; } else { log_info(LD_REND, - "Launched circuit %u to introduction point %s for service %s", + "Launched circuit n_circ_id %u global_identifier %u to introduction point %s for service %s", (unsigned)launched->base_.n_circ_id, + launched->global_identifier, safe_str_client(extend_info_describe(intro->extend_info)), service->service_id); } @@ -3143,9 +3144,6 @@ rend_services_introduce(void) log_info(LD_REND, "n_intro_points_unexpired %i", n_intro_points_unexpired); log_info(LD_REND, "prev_intro_nodes %i", prev_intro_nodes); - rend_cache_entry_t *entry; - int descriptor_available = (rend_cache_lookup_entry(service->service_id, -1, &entry) == 1); - int establish_intros = 1; if (n_intro_points_unexpired == 0) { @@ -3153,6 +3151,14 @@ rend_services_introduce(void) establish_intros = 0; + log_info(LD_REND, "Looking up descriptor for service %s", + safe_str_client(service->service_id)); + + rend_cache_entry_t *entry; + int descriptor_available = (rend_cache_lookup_entry(service->service_id, -1, &entry) == 1); + + log_info(LD_REND, "descriptor available %i", descriptor_available); + if (descriptor_available) { // Need to think about connecting to these introduction points now log_info(LD_REND, "Descriptor available for %s, with %i introduction points", -- cgit v1.2.3