bugfix: When we were checking to see if an ap_conn should time out

waiting for its connected cell, we were calculating time from when the
ap_conn was created. So if it waited say 20 seconds before being attached,
then we would immediately decide that the circuit had timed out.

Also, make circuit_dump_by_conn() display actual circuit progress,
including circuits that haven't been attached to the conn yet but
hope to when it finishes connecting.


svn:r3072

src/or/circuitbuild.c

@@ -179,22 +179,11 @@ void circuit_rep_hist_note_result(circuit_t *circ) {
 static void
 circuit_dump_details(int severity, circuit_t *circ, int poll_index,
                      const char *type, int this_circid, int other_circid) {
-  struct crypt_path_t *hop;
-  log(severity,"Conn %d has %s circuit: circID %d (other side %d), state %d (%s), born %d",
+  log(severity,"Conn %d has %s circuit: circID %d (other side %d), state %d (%s), born %d:",
       poll_index, type, this_circid, other_circid, circ->state,
       circuit_state_to_string[circ->state], (int)circ->timestamp_created);
   if (CIRCUIT_IS_ORIGIN(circ)) { /* circ starts at this node */
-    if (circ->state == CIRCUIT_STATE_BUILDING)
-      log(severity,"Building: desired len %d, planned exit node %s.",
-          circ->build_state->desired_path_len, circ->build_state->chosen_exit_name);
-    hop = circ->cpath;
-    do {
-      if (!hop) break;
-      log(severity,"hop: state %d, addr 0x%.8x, port %d", hop->state,
-          (unsigned int)hop->addr,
-          (int)hop->port);
-      hop = hop->next;
-    } while (hop != circ->cpath);
+    circuit_log_path(severity, circ);
   }
 }
 
@@ -206,6 +195,8 @@ void circuit_dump_by_conn(connection_t *conn, int severity) {
   connection_t *tmpconn;
 
   for (circ=global_circuitlist;circ;circ = circ->next) {
+    if (circ->marked_for_close)
+      continue;
     if (circ->p_conn == conn)
       circuit_dump_details(severity, circ, conn->poll_index, "App-ward",
                            circ->p_circ_id, circ->n_circ_id);
@@ -224,6 +215,13 @@ void circuit_dump_by_conn(connection_t *conn, int severity) {
                              circ->n_circ_id, circ->p_circ_id);
       }
     }
+    if (!circ->n_conn &&
+        circ->n_addr == conn->addr &&
+        circ->n_port == conn->port &&
+        !memcmp(conn->identity_digest, circ->n_conn_id_digest, DIGEST_LEN)) {
+      circuit_dump_details(severity, circ, conn->poll_index, "Pending",
+                           circ->n_circ_id, circ->p_circ_id);
+    }
   }
 }
 

src/or/circuituse.c

@@ -758,6 +758,7 @@ circuit_get_open_circ_or_launch(connection_t *conn,
 static void link_apconn_to_circ(connection_t *apconn, circuit_t *circ) {
   /* add it into the linked list of streams on this circuit */
   log_fn(LOG_DEBUG,"attaching new conn to circ. n_circ_id %d.", circ->n_circ_id);
+  apconn->timestamp_lastread = time(NULL); /* reset it, so we can measure circ timeouts */
   apconn->next_stream = circ->p_streams;
   /* assert_connection_ok(conn, time(NULL)); */
   circ->p_streams = apconn;

src/or/connection_edge.c

@@ -274,8 +274,8 @@ void connection_ap_expire_beginning(void) {
     }
     tor_assert(circ->purpose == CIRCUIT_PURPOSE_C_GENERAL);
     if (conn->num_retries >= MAX_STREAM_RETRIES) {
-      log_fn(LOG_WARN,"Stream is %d seconds late. Giving up.",
-             15*conn->num_retries); /* XXX this number is not accurate */
+      log_fn(LOG_WARN,"Stream is %d seconds old. Giving up.",
+             (int)(now - conn->timestamp_created));
       circuit_log_path(LOG_WARN, circ);
       connection_edge_end(conn, END_STREAM_REASON_TIMEOUT, conn->cpath_layer);
       connection_mark_for_close(conn);