r8972@totoro: nickm | 2006-10-09 10:36:22 -0400

 Patch from Mike Perry: add a REASON field to closed and failed circ events.


svn:r8671

ChangeLog

@@ -1,4 +1,7 @@
 Changes in version 0.1.2.3-alpha - 2006-10-??
+  o Minor features, controller:
+    - Add a REASON field to CIRC events. (Patch from Mike Perry)
+
   o Minor bugfixes:
     - Change NT service functions to be loaded on demand.  This lets us
       build with mingw without breaking Tor for Windows 98 users.

doc/control-spec.txt

@@ -751,7 +751,8 @@ $Id$
 
    The syntax is:
 
-     "650" SP "CIRC" SP CircuitID SP CircStatus [SP Path]
+     "650" SP "CIRC" SP CircuitID SP CircStatus [SP Path] 
+          [SP "REASON=" Reason] CRLF
 
       CircStatus =
                "LAUNCHED" / ; circuit ID assigned to new circuit
@@ -762,9 +763,15 @@ $Id$
 
       Path = ServerID *("," ServerID)
 
+      Reason = "NONE" / "TORPROTOCOL" / "INTERNAL" / "REQUESTED" / 
+               "HIBERNATING" / "RESOURCELIMIT" / "CONNECTFAILED" /
+               "OR_IDENTITY" / "OR_CONN_CLOSED"
+
    The path is provided only when the circuit has been extended at least one
    hop.
 
+   Reason is provided only for FAILED and CLOSED events.
+
 4.1.2. Stream status changed
 
     The syntax is:

src/or/circuitbuild.c

@@ -299,19 +299,20 @@ circuit_establish_circuit(uint8_t purpose, extend_info_t *info,
                           int need_uptime, int need_capacity, int internal)
 {
   origin_circuit_t *circ;
+  int err_reason = 0;
 
   circ = origin_circuit_init(purpose, need_uptime, need_capacity, internal);
 
   if (onion_pick_cpath_exit(circ, info) < 0 ||
       onion_populate_cpath(circ) < 0) {
-    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_INTERNAL);
     return NULL;
   }
 
-  control_event_circuit_status(circ, CIRC_EVENT_LAUNCHED);
+  control_event_circuit_status(circ, CIRC_EVENT_LAUNCHED, 0);
 
-  if (circuit_handle_first_hop(circ) < 0) {
-    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+  if ((err_reason = circuit_handle_first_hop(circ)) < 0) {
+    circuit_mark_for_close(TO_CIRCUIT(circ), -err_reason);
     return NULL;
   }
   return circ;
@@ -320,7 +321,7 @@ circuit_establish_circuit(uint8_t purpose, extend_info_t *info,
 /** Start establishing the first hop of our circuit. Figure out what
  * OR we should connect to, and if necessary start the connection to
  * it. If we're already connected, then send the 'create' cell.
- * Return 0 for ok, -1 if circ should be marked-for-close. */
+ * Return 0 for ok, -reason if circ should be marked-for-close. */
 int
 circuit_handle_first_hop(origin_circuit_t *circ)
 {
@@ -328,6 +329,7 @@ circuit_handle_first_hop(origin_circuit_t *circ)
   or_connection_t *n_conn;
   char tmpbuf[INET_NTOA_BUF_LEN];
   struct in_addr in;
+  int err_reason = 0;
 
   firsthop = onion_next_hop_in_cpath(circ->cpath);
   tor_assert(firsthop);
@@ -360,7 +362,7 @@ circuit_handle_first_hop(origin_circuit_t *circ)
                                      firsthop->extend_info->identity_digest);
       if (!n_conn) { /* connect failed, forget the whole thing */
         log_info(LD_CIRC,"connect to firsthop failed. Closing.");
-        return -1;
+        return -END_CIRC_REASON_CONNECTFAILED;
       }
     }
 
@@ -375,9 +377,9 @@ circuit_handle_first_hop(origin_circuit_t *circ)
     circ->_base.n_port = n_conn->_base.port;
     circ->_base.n_conn = n_conn;
     log_debug(LD_CIRC,"Conn open. Delivering first onion skin.");
-    if (circuit_send_next_onion_skin(circ) < 0) {
+    if ((err_reason = circuit_send_next_onion_skin(circ)) < 0) {
       log_info(LD_CIRC,"circuit_send_next_onion_skin failed.");
-      return -1;
+      return err_reason;
     }
   }
   return 0;
@@ -394,6 +396,7 @@ void
 circuit_n_conn_done(or_connection_t *or_conn, int status)
 {
   smartlist_t *changed_circs;
+  int err_reason = 0;
 
   log_debug(LD_CIRC,"or_conn to %s, status=%d",
             or_conn->nickname ? or_conn->nickname : "NULL", status);
@@ -422,10 +425,10 @@ circuit_n_conn_done(or_connection_t *or_conn, int status)
        * set_circid_orconn here. */
       circ->n_conn = or_conn;
       if (CIRCUIT_IS_ORIGIN(circ)) {
-        if (circuit_send_next_onion_skin(TO_ORIGIN_CIRCUIT(circ)) < 0) {
+        if ((err_reason = circuit_send_next_onion_skin(TO_ORIGIN_CIRCUIT(circ))) < 0) {
           log_info(LD_CIRC,
                    "send_next_onion_skin failed; circuit marked for closing.");
-          circuit_mark_for_close(circ, END_CIRC_AT_ORIGIN);
+          circuit_mark_for_close(circ, -err_reason);
           continue;
           /* XXX could this be bad, eg if next_onion_skin failed because conn
            *     died? */
@@ -865,7 +868,7 @@ circuit_finish_handshake(origin_circuit_t *circ, uint8_t reply_type,
   log_info(LD_CIRC,"Finished building %scircuit hop:",
            (reply_type == CELL_CREATED_FAST) ? "fast " : "");
   circuit_log_path(LOG_INFO,LD_CIRC,circ);
-  control_event_circuit_status(circ, CIRC_EVENT_EXTENDED);
+  control_event_circuit_status(circ, CIRC_EVENT_EXTENDED, 0);
 
   return 0;
 }
@@ -889,7 +892,7 @@ circuit_truncated(origin_circuit_t *circ, crypt_path_t *layer)
    *     means that a connection broke or an extend failed. For now,
    *     just give up.
    */
-  circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+  circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_TORPROTOCOL);
   return 0;
 
 #if 0
@@ -1393,12 +1396,13 @@ circuit_append_new_exit(origin_circuit_t *circ, extend_info_t *info)
 int
 circuit_extend_to_new_exit(origin_circuit_t *circ, extend_info_t *info)
 {
+  int err_reason = 0;
   circuit_append_new_exit(circ, info);
   circuit_set_state(TO_CIRCUIT(circ), CIRCUIT_STATE_BUILDING);
-  if (circuit_send_next_onion_skin(circ)<0) {
+  if ((err_reason = circuit_send_next_onion_skin(circ))<0) {
     log_warn(LD_CIRC, "Couldn't extend circuit to new point '%s'.",
              info->nickname);
-    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+    circuit_mark_for_close(TO_CIRCUIT(circ), -err_reason);
     return -1;
   }
   return 0;

src/or/circuitlist.c

@@ -780,7 +780,7 @@ circuit_mark_all_unused_circs(void)
     if (CIRCUIT_IS_ORIGIN(circ) &&
         !circ->marked_for_close &&
         !circ->timestamp_dirty)
-      circuit_mark_for_close(circ, END_CIRC_AT_ORIGIN);
+      circuit_mark_for_close(circ, END_CIRC_REASON_REQUESTED);
   }
 }
 
@@ -824,6 +824,7 @@ void
 _circuit_mark_for_close(circuit_t *circ, int reason, int line,
                         const char *file)
 {
+  int orig_reason = reason;
   assert_circuit_ok(circ);
   tor_assert(line);
   tor_assert(file);
@@ -845,11 +846,13 @@ _circuit_mark_for_close(circuit_t *circ, int reason, int line,
   } else if (CIRCUIT_IS_ORIGIN(circ) && reason != END_CIRC_REASON_NONE) {
     /* Don't warn about this; there are plenty of places where our code
      * is origin-agnostic. */
+    /* In fact, due to the desire to export reason information to the 
+     * controller, it has been made even more "origin-agnostic" than before */
     reason = END_CIRC_REASON_NONE;
   }
   if (reason < _END_CIRC_REASON_MIN || reason > _END_CIRC_REASON_MAX) {
     log_warn(LD_BUG, "Reason %d out of range at %s:%d", reason, file, line);
-    reason = END_CIRC_REASON_NONE;
+    orig_reason = reason = END_CIRC_REASON_NONE;
   }
 
   if (circ->state == CIRCUIT_STATE_ONIONSKIN_PENDING) {
@@ -872,7 +875,8 @@ _circuit_mark_for_close(circuit_t *circ, int reason, int line,
   }
   if (CIRCUIT_IS_ORIGIN(circ)) {
     control_event_circuit_status(TO_ORIGIN_CIRCUIT(circ),
-     (circ->state == CIRCUIT_STATE_OPEN)?CIRC_EVENT_CLOSED:CIRC_EVENT_FAILED);
+     (circ->state == CIRCUIT_STATE_OPEN)?CIRC_EVENT_CLOSED:CIRC_EVENT_FAILED,
+     orig_reason);
   }
   if (circ->purpose == CIRCUIT_PURPOSE_C_INTRODUCE_ACK_WAIT) {
     origin_circuit_t *ocirc = TO_ORIGIN_CIRCUIT(circ);

src/or/circuituse.c

@@ -265,7 +265,7 @@ circuit_expire_building(time_t now)
                circuit_state_to_string(victim->state), victim->purpose);
 
     circuit_log_path(LOG_INFO,LD_CIRC,TO_ORIGIN_CIRCUIT(victim));
-    circuit_mark_for_close(victim, END_CIRC_AT_ORIGIN);
+    circuit_mark_for_close(victim, END_CIRC_REASON_CONNECTFAILED);
   }
 }
 
@@ -583,7 +583,7 @@ circuit_expire_old_circuits(time_t now)
       log_debug(LD_CIRC, "Closing n_circ_id %d (dirty %d secs ago, purp %d)",
                 circ->n_circ_id, (int)(now - circ->timestamp_dirty),
                 circ->purpose);
-      circuit_mark_for_close(circ, END_CIRC_AT_ORIGIN);
+      circuit_mark_for_close(circ, END_CIRC_REASON_REQUESTED);
     } else if (!circ->timestamp_dirty &&
                circ->state == CIRCUIT_STATE_OPEN &&
                circ->purpose == CIRCUIT_PURPOSE_C_GENERAL) {
@@ -591,7 +591,7 @@ circuit_expire_old_circuits(time_t now)
         log_debug(LD_CIRC,
                   "Closing circuit that has been unused for %d seconds.",
                   (int)(now - circ->timestamp_created));
-        circuit_mark_for_close(circ, END_CIRC_AT_ORIGIN);
+        circuit_mark_for_close(circ, END_CIRC_REASON_REQUESTED);
       }
     }
   }
@@ -674,7 +674,7 @@ circuit_testing_failed(origin_circuit_t *circ, int at_last_hop)
 void
 circuit_has_opened(origin_circuit_t *circ)
 {
-  control_event_circuit_status(circ, CIRC_EVENT_BUILT);
+  control_event_circuit_status(circ, CIRC_EVENT_BUILT, 0);
 
   switch (TO_CIRCUIT(circ)->purpose) {
     case CIRCUIT_PURPOSE_C_ESTABLISH_REND:

src/or/command.c

@@ -273,18 +273,19 @@ command_process_created_cell(cell_t *cell, or_connection_t *conn)
 
   if (CIRCUIT_IS_ORIGIN(circ)) { /* we're the OP. Handshake this. */
     origin_circuit_t *origin_circ = TO_ORIGIN_CIRCUIT(circ);
+    int err_reason = 0;
     log_debug(LD_OR,"at OP. Finishing handshake.");
-    if (circuit_finish_handshake(origin_circ, cell->command,
-                                 cell->payload) < 0) {
+    if ((err_reason = circuit_finish_handshake(origin_circ, cell->command,
+                                 cell->payload)) < 0) {
       log_warn(LD_OR,"circuit_finish_handshake failed.");
-      circuit_mark_for_close(circ, END_CIRC_AT_ORIGIN);
+      circuit_mark_for_close(circ, -err_reason);
       return;
     }
     log_debug(LD_OR,"Moving to next skin.");
-    if (circuit_send_next_onion_skin(origin_circ) < 0) {
+    if ((err_reason = circuit_send_next_onion_skin(origin_circ)) < 0) {
       log_info(LD_OR,"circuit_send_next_onion_skin failed.");
       /* XXX push this circuit_close lower */
-      circuit_mark_for_close(circ, END_CIRC_AT_ORIGIN);
+      circuit_mark_for_close(circ, -err_reason);
       return;
     }
   } else { /* pack it into an extended relay cell, and send it. */

src/or/control.c

@@ -1867,8 +1867,9 @@ handle_control_extendcircuit(control_connection_t *conn, uint32_t len,
 
   /* now that we've populated the cpath, start extending */
   if (zero_circ) {
-    if (circuit_handle_first_hop(circ) < 0) {
-      circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+    int err_reason = 0;
+    if ((err_reason = circuit_handle_first_hop(circ)) < 0) {
+      circuit_mark_for_close(TO_CIRCUIT(circ), -err_reason);
       if (v0)
         send_control0_error(conn, ERR_INTERNAL, "couldn't start circuit");
       else
@@ -1877,11 +1878,12 @@ handle_control_extendcircuit(control_connection_t *conn, uint32_t len,
     }
   } else {
     if (circ->_base.state == CIRCUIT_STATE_OPEN) {
+      int err_reason = 0;
       circuit_set_state(TO_CIRCUIT(circ), CIRCUIT_STATE_BUILDING);
-      if (circuit_send_next_onion_skin(circ) < 0) {
+      if ((err_reason = circuit_send_next_onion_skin(circ)) < 0) {
         log_info(LD_CONTROL,
                  "send_next_onion_skin failed; circuit marked for closing.");
-        circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+        circuit_mark_for_close(TO_CIRCUIT(circ), -err_reason);
         if (v0)
           send_control0_error(conn, ERR_INTERNAL, "couldn't send onion skin");
         else
@@ -2745,7 +2747,8 @@ connection_control_process_inbuf(control_connection_t *conn)
 /** Something has happened to circuit <b>circ</b>: tell any interested
  * control connections. */
 int
-control_event_circuit_status(origin_circuit_t *circ, circuit_status_event_t tp)
+control_event_circuit_status(origin_circuit_t *circ, circuit_status_event_t tp,
+        int rsn)
 {
   char *path=NULL, *msg;
   if (!EVENT_IS_INTERESTING(EVENT_CIRCUIT_STATUS))
@@ -2767,6 +2770,7 @@ control_event_circuit_status(origin_circuit_t *circ, circuit_status_event_t tp)
   }
   if (EVENT_IS_INTERESTING1(EVENT_CIRCUIT_STATUS)) {
     const char *status;
+    const char *reason = "";
     switch (tp)
       {
       case CIRC_EVENT_LAUNCHED: status = "LAUNCHED"; break;
@@ -2778,18 +2782,37 @@ control_event_circuit_status(origin_circuit_t *circ, circuit_status_event_t tp)
         log_warn(LD_BUG, "Unrecognized status code %d", (int)tp);
         return 0;
       }
+
+    if(tp == CIRC_EVENT_FAILED || tp == CIRC_EVENT_CLOSED) {
+        switch (rsn)
+          {
+          case END_CIRC_AT_ORIGIN: reason = " REASON=ORIGIN"; break;
+          case END_CIRC_REASON_NONE: reason = " REASON=NONE"; break;
+          case END_CIRC_REASON_TORPROTOCOL: reason = " REASON=TORPROTOCOL"; break;
+          case END_CIRC_REASON_INTERNAL: reason = " REASON=INTERNAL"; break;
+          case END_CIRC_REASON_REQUESTED: reason = " REASON=REQUESTED"; break;
+          case END_CIRC_REASON_HIBERNATING: reason = " REASON=HIBERNATING"; break;
+          case END_CIRC_REASON_RESOURCELIMIT: reason = " REASON=RESOURCELIMIT"; break;
+          case END_CIRC_REASON_CONNECTFAILED: reason = " REASON=CONNECTFAILED"; break;
+          case END_CIRC_REASON_OR_IDENTITY: reason = " REASON=OR_IDENTITY"; break;
+          case END_CIRC_REASON_OR_CONN_CLOSED: reason = " REASON=OR_CONN_CLOSED"; break;
+          default:
+            log_warn(LD_BUG, "Unrecognized reason code %d", (int)rsn);
+          }
+    }
+
     if (EVENT_IS_INTERESTING1S(EVENT_CIRCUIT_STATUS)) {
       send_control1_event(EVENT_CIRCUIT_STATUS, SHORT_NAMES,
-                          "650 CIRC %lu %s %s\r\n",
+                          "650 CIRC %lu %s %s%s\r\n",
                           (unsigned long)circ->global_identifier,
-                          status, path);
+                          status, path, reason);
     }
     if (EVENT_IS_INTERESTING1L(EVENT_CIRCUIT_STATUS)) {
       char *vpath = circuit_list_path_for_controller(circ);
       send_control1_event(EVENT_CIRCUIT_STATUS, LONG_NAMES,
-                          "650 CIRC %lu %s %s\r\n",
+                          "650 CIRC %lu %s %s%s\r\n",
                           (unsigned long)circ->global_identifier,
-                          status, vpath);
+                          status, vpath, reason);
       tor_free(vpath);
     }
   }

src/or/or.h

@@ -2069,7 +2069,7 @@ int connection_control_reached_eof(control_connection_t *conn);
 int connection_control_process_inbuf(control_connection_t *conn);
 
 int control_event_circuit_status(origin_circuit_t *circ,
-                                 circuit_status_event_t e);
+                                 circuit_status_event_t e, int rsn);
 int control_event_stream_status(edge_connection_t *conn,
                                 stream_status_event_t e);
 int control_event_or_conn_status(or_connection_t *conn,

src/or/rendclient.c

@@ -34,7 +34,7 @@ rend_client_send_establish_rendezvous(origin_circuit_t *circ)
 
   if (crypto_rand(circ->rend_cookie, REND_COOKIE_LEN) < 0) {
     log_warn(LD_BUG, "Internal error: Couldn't produce random cookie.");
-    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_INTERNAL);
     return -1;
   }
   if (connection_edge_send_command(NULL,TO_CIRCUIT(circ),
@@ -157,8 +157,8 @@ rend_client_send_introduction(origin_circuit_t *introcirc,
 
   return 0;
 err:
-  circuit_mark_for_close(TO_CIRCUIT(introcirc), END_CIRC_AT_ORIGIN);
-  circuit_mark_for_close(TO_CIRCUIT(rendcirc), END_CIRC_AT_ORIGIN);
+  circuit_mark_for_close(TO_CIRCUIT(introcirc), END_CIRC_REASON_INTERNAL);
+  circuit_mark_for_close(TO_CIRCUIT(rendcirc), END_CIRC_REASON_INTERNAL);
   return -1;
 }
 
@@ -190,7 +190,7 @@ rend_client_introduction_acked(origin_circuit_t *circ,
     log_warn(LD_PROTOCOL,
              "Received REND_INTRODUCE_ACK on unexpected circuit %d.",
              circ->_base.n_circ_id);
-    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_TORPROTOCOL);
     return -1;
   }
 
@@ -229,7 +229,7 @@ rend_client_introduction_acked(origin_circuit_t *circ,
       if (!extend_info) {
         log_warn(LD_REND, "No introduction points left for %s. Closing.",
                  escaped_safe_str(circ->rend_query));
-        circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+        circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_INTERNAL);
         return -1;
       }
       log_info(LD_REND,
@@ -349,7 +349,7 @@ rend_client_rendezvous_acked(origin_circuit_t *circ, const char *request,
   if (circ->_base.purpose != CIRCUIT_PURPOSE_C_ESTABLISH_REND) {
     log_warn(LD_PROTOCOL,"Got a rendezvous ack when we weren't expecting one. "
              "Closing circ.");
-    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_TORPROTOCOL);
     return -1;
   }
   log_info(LD_REND,"Got rendezvous ack. This circuit is now ready for "
@@ -371,7 +371,7 @@ rend_client_receive_rendezvous(origin_circuit_t *circ, const char *request,
       || !circ->build_state->pending_final_cpath) {
     log_warn(LD_PROTOCOL,"Got rendezvous2 cell from hidden service, but not "
              "expecting it. Closing.");
-    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+    circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_TORPROTOCOL);
     return -1;
   }
 
@@ -417,7 +417,7 @@ rend_client_receive_rendezvous(origin_circuit_t *circ, const char *request,
   circ->build_state->pending_final_cpath = NULL; /* prevent double-free */
   return 0;
  err:
-  circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_AT_ORIGIN);
+  circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_TORPROTOCOL);
   return -1;
 }
 

src/or/rendservice.c

@@ -612,7 +612,7 @@ rend_service_introduce(origin_circuit_t *circuit, const char *request,
  err:
   if (dh) crypto_dh_free(dh);
   if (launched)
-    circuit_mark_for_close(TO_CIRCUIT(launched), END_CIRC_AT_ORIGIN);
+    circuit_mark_for_close(TO_CIRCUIT(launched), END_CIRC_REASON_TORPROTOCOL);
   if (extend_info) extend_info_free(extend_info);
   return -1;
 }
@@ -763,7 +763,7 @@ rend_service_intro_has_opened(origin_circuit_t *circuit)
 
   return;
  err:
-  circuit_mark_for_close(TO_CIRCUIT(circuit), END_CIRC_AT_ORIGIN);
+  circuit_mark_for_close(TO_CIRCUIT(circuit), END_CIRC_REASON_TORPROTOCOL);
 }
 
 /** Called when we get an INTRO_ESTABLISHED cell; mark the circuit as a
@@ -793,7 +793,7 @@ rend_service_intro_established(origin_circuit_t *circuit, const char *request,
 
   return 0;
  err:
-  circuit_mark_for_close(TO_CIRCUIT(circuit), END_CIRC_AT_ORIGIN);
+  circuit_mark_for_close(TO_CIRCUIT(circuit), END_CIRC_REASON_TORPROTOCOL);
   return -1;
 }
 
@@ -869,7 +869,7 @@ rend_service_rendezvous_has_opened(origin_circuit_t *circuit)
 
   return;
  err:
-  circuit_mark_for_close(TO_CIRCUIT(circuit), END_CIRC_AT_ORIGIN);
+  circuit_mark_for_close(TO_CIRCUIT(circuit), END_CIRC_REASON_TORPROTOCOL);
 }
 
 /*