Lots of logging stuff

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",