r11957@Kushana: nickm | 2007-01-15 15:25:57 -0500

 Patch from Mike Perry: Track reasons for OR connection failure; display them in control events. Needs review and revision.


svn:r9354

doc/control-spec.txt

@@ -885,7 +885,8 @@ $Id$
 4.1.3. OR Connection status changed
 
   The syntax is:
-    "650" SP "ORCONN" SP (ServerID / Target) SP ORStatus
+    "650" SP "ORCONN" SP (ServerID / Target) SP ORStatus [ SP "REASON=" 
+             Reason ] [ SP "NCIRCS=" NumCircuits ]
 
     ORStatus = "NEW" / "LAUNCHED" / "CONNECTED" / "FAILED" / "CLOSED"
 
@@ -898,6 +899,17 @@ $Id$
   A ServerID is specified unless it's a NEW connection, in which
   case we don't know what server it is yet, so we use Address:Port.
 
+  If extended events are enabled (see 3.19), optional reason and
+  circuit counting information is provided for CLOSED and FAILED
+  events. 
+
+      Reason = "MISC" / "DONE" / "CONNECTREFUSED" /
+               "IDENTITY" / "CONNECTRESET" / "TIMEOUT" / "NOROUTE" /
+               "IOERROR" 
+
+  NumCircuits counts both established and pending circuits.
+
+
 4.1.4. Bandwidth used in the last second
 
   The syntax is:

src/common/tortls.c

@@ -73,8 +73,8 @@ static tor_tls_context_t *global_tls_context = NULL;
 static int tls_library_is_initialized = 0;
 
 /* Module-internal error codes. */
-#define _TOR_TLS_SYSCALL    -6
-#define _TOR_TLS_ZERORETURN -5
+#define _TOR_TLS_SYSCALL    -10
+#define _TOR_TLS_ZERORETURN -9
 
 /* These functions are declared in crypto.c but not exported. */
 EVP_PKEY *_crypto_pk_env_get_evp_pkey(crypto_pk_env_t *env, int private);
@@ -103,6 +103,39 @@ tls_log_errors(int severity, const char *doing)
   }
 }
 
+static int
+tor_errno_to_tls_error(int e) {
+#if defined(MS_WINDOWS) && !defined(USE_BSOCKETS)
+  switch(e) {
+    case WSAECONNRESET: // most common
+      return TOR_TLS_ERROR_CONNRESET;
+    case WSAETIMEDOUT:
+      return TOR_TLS_ERROR_TIMEOUT;
+    case WSAENETUNREACH:
+    case WSAEHOSTUNREACH:
+      return TOR_TLS_ERROR_NO_ROUTE;
+    case WSAECONNREFUSED:
+      return TOR_TLS_ERROR_CONNREFUSED; // least common
+    default:
+      return TOR_TLS_ERROR_MISC;
+  }
+#else 
+  switch(e) {
+    case ECONNRESET: // most common
+      return TOR_TLS_ERROR_CONNRESET;
+    case ETIMEDOUT:
+      return TOR_TLS_ERROR_TIMEOUT;
+    case EHOSTUNREACH:
+    case ENETUNREACH:
+      return TOR_TLS_ERROR_NO_ROUTE;
+    case ECONNREFUSED:
+      return TOR_TLS_ERROR_CONNREFUSED; // least common
+    default:
+      return TOR_TLS_ERROR_MISC;
+  }
+#endif
+}
+
 #define CATCH_SYSCALL 1
 #define CATCH_ZERO    2
 
@@ -121,6 +154,7 @@ tor_tls_get_error(tor_tls_t *tls, int r, int extra,
                   const char *doing, int severity)
 {
   int err = SSL_get_error(tls->ssl, r);
+  int tor_error = TOR_TLS_ERROR_MISC;
   switch (err) {
     case SSL_ERROR_NONE:
       return TOR_TLS_DONE;
@@ -131,25 +165,27 @@ tor_tls_get_error(tor_tls_t *tls, int r, int extra,
     case SSL_ERROR_SYSCALL:
       if (extra&CATCH_SYSCALL)
         return _TOR_TLS_SYSCALL;
-      if (r == 0)
+      if (r == 0) {
         log(severity, LD_NET, "TLS error: unexpected close while %s", doing);
-      else {
+        tor_error = TOR_TLS_ERROR_IO;
+      } else {
         int e = tor_socket_errno(tls->socket);
         log(severity, LD_NET,
             "TLS error: <syscall error while %s> (errno=%d: %s)",
             doing, e, tor_socket_strerror(e));
+        tor_error = tor_errno_to_tls_error(e);
       }
       tls_log_errors(severity, doing);
-      return TOR_TLS_ERROR;
+      return tor_error;
     case SSL_ERROR_ZERO_RETURN:
       if (extra&CATCH_ZERO)
         return _TOR_TLS_ZERORETURN;
       log(severity, LD_NET, "TLS error: Zero return");
       tls_log_errors(severity, doing);
-      return TOR_TLS_ERROR;
+      return TOR_TLS_ERROR_MISC;
     default:
       tls_log_errors(severity, doing);
-      return TOR_TLS_ERROR;
+      return TOR_TLS_ERROR_MISC;
   }
 }
 
@@ -547,7 +583,7 @@ tor_tls_handshake(tor_tls_t *tls)
   if (ERR_peek_error() != 0) {
     tls_log_errors(tls->isServer ? LOG_INFO : LOG_WARN,
                    "handshaking");
-    return TOR_TLS_ERROR;
+    return TOR_TLS_ERROR_MISC;
   }
   if (r == TOR_TLS_DONE) {
     tls->state = TOR_TLS_ST_OPEN;
@@ -607,7 +643,7 @@ tor_tls_shutdown(tor_tls_t *tls)
          tls->state == TOR_TLS_ST_SENTCLOSE) {
         log(LOG_WARN, LD_NET,
             "TLS returned \"half-closed\" value while already half-closed");
-        return TOR_TLS_ERROR;
+        return TOR_TLS_ERROR_MISC;
       }
       tls->state = TOR_TLS_ST_SENTCLOSE;
       /* fall through ... */

src/common/tortls.h

@@ -19,11 +19,16 @@
 typedef struct tor_tls_t tor_tls_t;
 
 /* Possible return values for most tor_tls_* functions. */
-#define TOR_TLS_ERROR       -4
-#define TOR_TLS_CLOSE       -3
-#define TOR_TLS_WANTREAD    -2
-#define TOR_TLS_WANTWRITE   -1
-#define TOR_TLS_DONE         0
+#define TOR_TLS_ERROR_MISC         -9
+#define TOR_TLS_ERROR_IO           -8
+#define TOR_TLS_ERROR_CONNREFUSED  -7
+#define TOR_TLS_ERROR_CONNRESET    -6
+#define TOR_TLS_ERROR_NO_ROUTE     -5
+#define TOR_TLS_ERROR_TIMEOUT      -4
+#define TOR_TLS_CLOSE              -3
+#define TOR_TLS_WANTREAD           -2
+#define TOR_TLS_WANTWRITE          -1
+#define TOR_TLS_DONE                0
 
 void tor_tls_free_all(void);
 int tor_tls_context_new(crypto_pk_env_t *rsa,

src/or/buffers.c

@@ -543,7 +543,7 @@ read_to_buf_tls(tor_tls_t *tls, size_t at_most, buf_t *buf)
             (int)at_most);
 
   if (buf_ensure_capacity(buf, at_most+buf->datalen))
-    return TOR_TLS_ERROR;
+    return TOR_TLS_ERROR_MISC;
 
   if (at_most + buf->datalen > buf->len)
     at_most = buf->len - buf->datalen;

src/or/circuitbuild.c

@@ -897,7 +897,8 @@ 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_REASON_OR_CONN_CLOSED);
+  circuit_mark_for_close(TO_CIRCUIT(circ), 
+          END_CIRC_REASON_FLAG_REMOTE|END_CIRC_REASON_OR_CONN_CLOSED);
   return 0;
 
 #if 0

src/or/connection.c

@@ -435,7 +435,8 @@ connection_about_to_close_connection(connection_t *conn)
           rep_hist_note_connect_failed(or_conn->identity_digest, now);
           entry_guard_register_connect_status(or_conn->identity_digest,0,now);
           router_set_status(or_conn->identity_digest, 0);
-          control_event_or_conn_status(or_conn, OR_CONN_EVENT_FAILED);
+          control_event_or_conn_status(or_conn, OR_CONN_EVENT_FAILED, 
+                  control_tls_error_to_reason(or_conn->tls_error));
         }
         /* Inform any pending (not attached) circs that they should
          * give up. */
@@ -444,10 +445,12 @@ connection_about_to_close_connection(connection_t *conn)
         /* We only set hold_open_until_flushed when we're intentionally
          * closing a connection. */
         rep_hist_note_disconnect(or_conn->identity_digest, now);
-        control_event_or_conn_status(or_conn, OR_CONN_EVENT_CLOSED);
+        control_event_or_conn_status(or_conn, OR_CONN_EVENT_CLOSED,
+                control_tls_error_to_reason(or_conn->tls_error));
       } else if (or_conn->identity_digest) {
         rep_hist_note_connection_died(or_conn->identity_digest, now);
-        control_event_or_conn_status(or_conn, OR_CONN_EVENT_CLOSED);
+        control_event_or_conn_status(or_conn, OR_CONN_EVENT_CLOSED,
+                control_tls_error_to_reason(or_conn->tls_error));
       }
       /* Now close all the attached circuits on it. */
       circuit_unlink_all_from_or_conn(TO_OR_CONN(conn),
@@ -824,7 +827,7 @@ connection_init_accepted_conn(connection_t *conn, uint8_t listener_type)
 
   switch (conn->type) {
     case CONN_TYPE_OR:
-      control_event_or_conn_status(TO_OR_CONN(conn), OR_CONN_EVENT_NEW);
+      control_event_or_conn_status(TO_OR_CONN(conn), OR_CONN_EVENT_NEW, 0);
       return connection_tls_start_handshake(TO_OR_CONN(conn), 1);
     case CONN_TYPE_AP:
       switch (listener_type) {
@@ -1457,6 +1460,7 @@ connection_read_to_buf(connection_t *conn, int *max_to_read)
 
     /* else open, or closing */
     result = read_to_buf_tls(or_conn->tls, at_most, conn->inbuf);
+    or_conn->tls_error = result;
 
     switch (result) {
       case TOR_TLS_CLOSE:
@@ -1464,12 +1468,17 @@ connection_read_to_buf(connection_t *conn, int *max_to_read)
                  "(Nickname %s, address %s",
                  or_conn->nickname ? or_conn->nickname : "not set",
                  conn->address);
-        return -1;
-      case TOR_TLS_ERROR:
+        return result;
+      case TOR_TLS_ERROR_IO:
+      case TOR_TLS_ERROR_CONNREFUSED:
+      case TOR_TLS_ERROR_CONNRESET:
+      case TOR_TLS_ERROR_NO_ROUTE:
+      case TOR_TLS_ERROR_TIMEOUT:
+      case TOR_TLS_ERROR_MISC:
         log_info(LD_NET,"tls error. breaking (nickname %s, address %s).",
                  or_conn->nickname ? or_conn->nickname : "not set",
                  conn->address);
-        return -1;
+        return result;
       case TOR_TLS_WANTWRITE:
         connection_start_writing(conn);
         return 0;
@@ -1662,9 +1671,14 @@ connection_handle_write(connection_t *conn, int force)
     result = flush_buf_tls(or_conn->tls, conn->outbuf,
                            max_to_write, &conn->outbuf_flushlen);
     switch (result) {
-      case TOR_TLS_ERROR:
+      case TOR_TLS_ERROR_IO:
+      case TOR_TLS_ERROR_CONNREFUSED:
+      case TOR_TLS_ERROR_CONNRESET:
+      case TOR_TLS_ERROR_NO_ROUTE:
+      case TOR_TLS_ERROR_TIMEOUT:
+      case TOR_TLS_ERROR_MISC:
       case TOR_TLS_CLOSE:
-        log_info(LD_NET,result==TOR_TLS_ERROR?
+        log_info(LD_NET,result!=TOR_TLS_CLOSE?
                  "tls error. breaking.":"TLS connection closed on flush");
         /* Don't flush; connection is dead. */
         connection_close_immediate(conn);

src/or/connection_or.c

@@ -435,7 +435,7 @@ connection_or_connect(uint32_t addr, uint16_t port, const char *id_digest)
   /* set up conn so it's got all the data we need to remember */
   connection_or_init_conn_from_address(conn, addr, port, id_digest, 1);
   conn->_base.state = OR_CONN_STATE_CONNECTING;
-  control_event_or_conn_status(conn, OR_CONN_EVENT_LAUNCHED);
+  control_event_or_conn_status(conn, OR_CONN_EVENT_LAUNCHED, 0);
 
   if (options->HttpsProxy) {
     /* we shouldn't connect directly. use the https proxy instead. */
@@ -453,7 +453,8 @@ connection_or_connect(uint32_t addr, uint16_t port, const char *id_digest)
                                             time(NULL));
         router_set_status(conn->identity_digest, 0);
       }
-      control_event_or_conn_status(conn, OR_CONN_EVENT_FAILED);
+      control_event_or_conn_status(conn, OR_CONN_EVENT_FAILED, 
+              END_OR_CONN_REASON_TCP_REFUSED);
       connection_free(TO_CONN(conn));
       return NULL;
     case 0:
@@ -508,7 +509,12 @@ connection_tls_continue_handshake(or_connection_t *conn)
 {
   check_no_tls_errors();
   switch (tor_tls_handshake(conn->tls)) {
-    case TOR_TLS_ERROR:
+    case TOR_TLS_ERROR_IO:
+    case TOR_TLS_ERROR_CONNREFUSED:
+    case TOR_TLS_ERROR_CONNRESET:
+    case TOR_TLS_ERROR_NO_ROUTE:
+    case TOR_TLS_ERROR_TIMEOUT:
+    case TOR_TLS_ERROR_MISC:
     case TOR_TLS_CLOSE:
       log_info(LD_OR,"tls error. breaking connection.");
       return -1;
@@ -628,7 +634,8 @@ connection_or_check_valid_handshake(or_connection_t *conn, char *digest_rcvd)
              conn->_base.address, conn->_base.port, expected, seen);
       entry_guard_register_connect_status(conn->identity_digest,0,time(NULL));
       router_set_status(conn->identity_digest, 0);
-      control_event_or_conn_status(conn, OR_CONN_EVENT_FAILED);
+      control_event_or_conn_status(conn, OR_CONN_EVENT_FAILED,
+              END_OR_CONN_REASON_OR_IDENTITY);
       as_advertised = 0;
     }
     if (authdir_mode(options)) {
@@ -672,7 +679,7 @@ connection_tls_finish_handshake(or_connection_t *conn)
 
   directory_set_dirty();
   conn->_base.state = OR_CONN_STATE_OPEN;
-  control_event_or_conn_status(conn, OR_CONN_EVENT_CONNECTED);
+  control_event_or_conn_status(conn, OR_CONN_EVENT_CONNECTED, 0);
   if (started_here) {
     rep_hist_note_connect_succeeded(conn->identity_digest, time(NULL));
     if (entry_guard_register_connect_status(conn->identity_digest, 1,
@@ -791,3 +798,31 @@ connection_or_send_destroy(uint16_t circ_id, or_connection_t *conn, int reason)
   return 0;
 }
 
+/** Count number of pending circs on an or_conn */
+int 
+connection_or_count_pending_circs(or_connection_t *or_conn)
+{
+  extern smartlist_t *circuits_pending_or_conns;
+  int cnt = 0;
+
+  if (!circuits_pending_or_conns)
+    return 0;
+
+  SMARTLIST_FOREACH(circuits_pending_or_conns, circuit_t *, circ,
+  {
+    if (circ->marked_for_close)
+      continue;
+    tor_assert(circ->state == CIRCUIT_STATE_OR_WAIT);
+    if (!circ->n_conn &&
+        !memcmp(or_conn->identity_digest, circ->n_conn_id_digest,
+                DIGEST_LEN)) {
+      cnt++;
+    }
+  });
+
+  log_debug(LD_CIRC,"or_conn to %s, %d pending circs",
+            or_conn->nickname ? or_conn->nickname : "NULL", cnt);
+  return cnt;
+}
+
+

src/or/control.c

@@ -3247,13 +3247,65 @@ orconn_target_get_name(int long_names,
   }
 }
 
+int
+control_tls_error_to_reason(int e) {
+  switch(e) {
+    case TOR_TLS_ERROR_IO:
+      return END_OR_CONN_REASON_TLS_IO_ERROR;
+    case TOR_TLS_ERROR_CONNREFUSED:
+      return END_OR_CONN_REASON_TCP_REFUSED;
+    case TOR_TLS_ERROR_CONNRESET:
+      return END_OR_CONN_REASON_TLS_CONNRESET;
+    case TOR_TLS_ERROR_NO_ROUTE:
+      return END_OR_CONN_REASON_TLS_NO_ROUTE;
+    case TOR_TLS_ERROR_TIMEOUT:
+      return END_OR_CONN_REASON_TLS_TIMEOUT;
+    case TOR_TLS_WANTREAD:
+    case TOR_TLS_WANTWRITE:
+    case TOR_TLS_CLOSE:
+    case TOR_TLS_DONE:
+      return END_OR_CONN_REASON_DONE;
+    default:
+      return END_OR_CONN_REASON_TLS_MISC;
+  }
+}
+
+const char *
+or_conn_end_reason_to_string(int r) {
+  switch(r) {
+    case END_OR_CONN_REASON_DONE:
+      return "REASON=DONE";
+    case END_OR_CONN_REASON_TCP_REFUSED:
+      return "REASON=CONNECTREFUSED";
+    case END_OR_CONN_REASON_OR_IDENTITY:
+      return "REASON=IDENTITY";
+    case END_OR_CONN_REASON_TLS_CONNRESET:
+      return "REASON=CONNECTRESET";
+    case END_OR_CONN_REASON_TLS_TIMEOUT:
+      return "REASON=TIMEOUT";
+    case END_OR_CONN_REASON_TLS_NO_ROUTE:
+      return "REASON=NOROUTE";
+    case END_OR_CONN_REASON_TLS_IO_ERROR:
+      return "REASON=IOERROR";
+    case END_OR_CONN_REASON_TLS_MISC:
+      return "REASON=MISC";
+    case 0:
+      return "";
+    default:
+      log_warn(LD_BUG, "Unrecognized or_conn reason code %d", r);
+      return "REASON=BOGUS";
+  }
+}
+
 /** Something has happened to the OR connection <b>conn</b>: tell any
  * interested control connections. */
 int
-control_event_or_conn_status(or_connection_t *conn,or_conn_status_event_t tp)
+control_event_or_conn_status(or_connection_t *conn,or_conn_status_event_t tp, 
+        int reason)
 {
   char buf[HEX_DIGEST_LEN+3]; /* status, dollar, identity, NUL */
   size_t len;
+  int ncircs = 0;
 
   if (!EVENT_IS_INTERESTING(EVENT_OR_CONN_STATUS))
     return 0;
@@ -3267,6 +3319,7 @@ control_event_or_conn_status(or_connection_t *conn,or_conn_status_event_t tp)
   if (EVENT_IS_INTERESTING1(EVENT_OR_CONN_STATUS)) {
     const char *status;
     char name[128];
+    char ncircs_buf[32] = {0}; /* > 8 + log10(2^32)=10 + 2 */
     switch (tp)
       {
       case OR_CONN_EVENT_LAUNCHED: status = "LAUNCHED"; break;
@@ -3278,17 +3331,26 @@ control_event_or_conn_status(or_connection_t *conn,or_conn_status_event_t tp)
         log_warn(LD_BUG, "Unrecognized status code %d", (int)tp);
         return 0;
       }
+    ncircs = connection_or_count_pending_circs(conn);
+    ncircs += conn->n_circuits;
+    if(ncircs && (tp == OR_CONN_EVENT_FAILED || tp == OR_CONN_EVENT_CLOSED)) {
+        tor_snprintf(ncircs_buf, sizeof(ncircs_buf), "%sNCIRCS=%d", 
+                reason ? " " : "", ncircs);
+    }
+
     if (EVENT_IS_INTERESTING1S(EVENT_OR_CONN_STATUS)) {
       orconn_target_get_name(0, name, sizeof(name), conn);
-      send_control1_event(EVENT_OR_CONN_STATUS, SHORT_NAMES,
-                          "650 ORCONN %s %s\r\n",
-                          name, status);
+      send_control1_event_extended(EVENT_OR_CONN_STATUS, SHORT_NAMES,
+                          "650 ORCONN %s %s@%s%s\r\n",
+                          name, status,
+                          or_conn_end_reason_to_string(reason), ncircs_buf);
     }
     if (EVENT_IS_INTERESTING1L(EVENT_OR_CONN_STATUS)) {
       orconn_target_get_name(1, name, sizeof(name), conn);
-      send_control1_event(EVENT_OR_CONN_STATUS, LONG_NAMES,
-                          "650 ORCONN %s %s\r\n",
-                          name, status);
+      send_control1_event_extended(EVENT_OR_CONN_STATUS, LONG_NAMES,
+                          "650 ORCONN %s %s@%s%s\r\n",
+                          name, status,
+                          or_conn_end_reason_to_string(reason), ncircs_buf);
     }
   }
   return 0;

src/or/or.h

@@ -476,6 +476,16 @@ typedef enum {
 #define RELAY_COMMAND_RENDEZVOUS_ESTABLISHED 39
 #define RELAY_COMMAND_INTRODUCE_ACK 40
 
+/* Reasons why an OR connection is closed */
+#define END_OR_CONN_REASON_DONE 1
+#define END_OR_CONN_REASON_TCP_REFUSED  2
+#define END_OR_CONN_REASON_OR_IDENTITY  3
+#define END_OR_CONN_REASON_TLS_CONNRESET 4 /* tls connection reset by peer */
+#define END_OR_CONN_REASON_TLS_TIMEOUT  5
+#define END_OR_CONN_REASON_TLS_NO_ROUTE  6 /* no route to host/net */
+#define END_OR_CONN_REASON_TLS_IO_ERROR  7 /* tls read/write error */
+#define END_OR_CONN_REASON_TLS_MISC  8
+
 /* Reasons why we (or a remote OR) might close a stream. See tor-spec.txt for
  * documentation of these. */
 #define END_STREAM_REASON_MISC 1
@@ -723,6 +733,7 @@ typedef struct or_connection_t {
   char *nickname; /**< Nickname of OR on other side (if any). */
 
   tor_tls_t *tls; /**< TLS connection state */
+  int tls_error; /**< Last tor_tls error code */
 
   time_t timestamp_lastempty; /**< When was the outbuf last completely empty?*/
 
@@ -837,7 +848,7 @@ typedef struct control_connection_t {
 } control_connection_t;
 
 /** Cast a connection_t subtype pointer to a connection_t **/
-#define TO_CONN(c) &(((c)->_base))
+#define TO_CONN(c) (&(((c)->_base)))
 /** Helper macro: Given a pointer to to._base, of type from*, return &to. */
 #define DOWNCAST(to, ptr) \
   (to*) (((char*)(ptr)) - STRUCT_OFFSET(to, _base))
@@ -2150,6 +2161,7 @@ void connection_or_write_cell_to_buf(const cell_t *cell,
                                      or_connection_t *conn);
 int connection_or_send_destroy(uint16_t circ_id, or_connection_t *conn,
                                int reason);
+int connection_or_count_pending_circs(or_connection_t *or_conn);
 
 /********************************* control.c ***************************/
 
@@ -2216,8 +2228,9 @@ int control_event_circuit_status(origin_circuit_t *circ,
 int control_event_stream_status(edge_connection_t *conn,
                                 stream_status_event_t e,
                                 int reason);
+int control_tls_error_to_reason(int e);
 int control_event_or_conn_status(or_connection_t *conn,
-                                 or_conn_status_event_t e);
+                                 or_conn_status_event_t e, int reason);
 int control_event_bandwidth_used(uint32_t n_read, uint32_t n_written);
 void control_event_logmsg(int severity, unsigned int domain, const char *msg);
 int control_event_descriptors_changed(smartlist_t *routers);