Debugging logs for TLS handshake

The big change is to add a function to display the current SSL handshake
state, and to log it everywhere reasonable.  (A failure in
SSL23_ST_CR_SRVR_HELLO_A is different from one in
SSL3_ST_CR_SESSION_TICKET_A.)

This patch also adds a new log domain for OR handshaking, so you can pull out
all the handshake log messages without having to run at debug for everything.
For example, you'd just say "log notice-err [handshake]debug-err file
tor.log".

diff --git a/ChangeLog b/ChangeLog
index 8f36d6773d3d19ba81dd059ceb159559a6d66bbb..1e1a348eec3fe53728ffa60d1cc78380365dd7d7 100644 (file)
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,4 +1,11 @@
 Changes in version 0.2.2.4-alpha - 2009-??-??
+  o Minor features:
+    - Log SSL state transitions at debug level during handshake, and
+      include SSL states in error messages.  This may help debug
+      future SSL handshake issues.
+    - Add a new "Handshake" log domain for activities that happen
+      during the TLS handshake.
+
   o Code simplifications and refactoring:
     - Revise our unit tests to use the "tinytest" framework, so we
       can run tests in their own processes, have smarter setup/teardown

diff --git a/src/common/log.c b/src/common/log.c
index 09efa014c0e1e98cadb3b56b125ce89429d4cabd..a83f945459acfa78f3132fd73befc0b08d8b2c76 100644 (file)
--- a/src/common/log.c
+++ b/src/common/log.c
@@ -745,7 +745,7 @@ log_level_to_string(int level)
 static const char *domain_list[] = {
   "GENERAL", "CRYPTO", "NET", "CONFIG", "FS", "PROTOCOL", "MM",
   "HTTP", "APP", "CONTROL", "CIRC", "REND", "BUG", "DIR", "DIRSERV",
-  "OR", "EDGE", "ACCT", "HIST", NULL
+  "OR", "EDGE", "ACCT", "HIST", "HANDSHAKE", NULL
 };
 
 /** Return a bitmask for the log domain for which <b>domain</b> is the name,

diff --git a/src/common/log.h b/src/common/log.h
index 6745baabc6b117f11a055a56d1df38275070ce15..f1a6164f7d1df8e006847c297cca51628ab43ce5 100644 (file)
--- a/src/common/log.h
+++ b/src/common/log.h
@@ -90,9 +90,10 @@
 #define LD_ACCT     (1u<<17)
 /** Router history */
 #define LD_HIST     (1u<<18)
-
+/** OR handshaking */
+#define LD_HANDSHAKE (1u<<19)
 /** Number of logging domains in the code. */
-#define N_LOGGING_DOMAINS 19
+#define N_LOGGING_DOMAINS 20
 
 typedef uint32_t log_domain_mask_t;
 

diff --git a/src/common/tortls.c b/src/common/tortls.c
index a43c4ea0a34dbe622aa3ce7b0c3c66083b888cef..4d673bf1ec3610504b270c731749fe63c2435e9b 100644 (file)
--- a/src/common/tortls.c
+++ b/src/common/tortls.c
@@ -165,28 +165,182 @@ static int tls_library_is_initialized = 0;
 #define _TOR_TLS_SYSCALL    (_MIN_TOR_TLS_ERROR_VAL - 2)
 #define _TOR_TLS_ZERORETURN (_MIN_TOR_TLS_ERROR_VAL - 1)
 
+static const struct { int state; const char *name; } state_map[] = {
+#define S(state) { state, #state }
+  S(DTLS1_ST_CR_HELLO_VERIFY_REQUEST_A),
+  S(DTLS1_ST_CR_HELLO_VERIFY_REQUEST_B),
+  S(DTLS1_ST_SW_HELLO_VERIFY_REQUEST_A),
+  S(DTLS1_ST_SW_HELLO_VERIFY_REQUEST_B),
+  S(SSL23_ST_CR_SRVR_HELLO_A),
+  S(SSL23_ST_CR_SRVR_HELLO_B),
+  S(SSL23_ST_CW_CLNT_HELLO_A),
+  S(SSL23_ST_CW_CLNT_HELLO_B),
+  S(SSL23_ST_SR_CLNT_HELLO_A),
+  S(SSL23_ST_SR_CLNT_HELLO_B),
+  S(SSL2_ST_CLIENT_START_ENCRYPTION),
+  S(SSL2_ST_GET_CLIENT_FINISHED_A),
+  S(SSL2_ST_GET_CLIENT_FINISHED_B),
+  S(SSL2_ST_GET_CLIENT_HELLO_A),
+  S(SSL2_ST_GET_CLIENT_HELLO_B),
+  S(SSL2_ST_GET_CLIENT_HELLO_C),
+  S(SSL2_ST_GET_CLIENT_MASTER_KEY_A),
+  S(SSL2_ST_GET_CLIENT_MASTER_KEY_B),
+  S(SSL2_ST_GET_SERVER_FINISHED_A),
+  S(SSL2_ST_GET_SERVER_FINISHED_B),
+  S(SSL2_ST_GET_SERVER_HELLO_A),
+  S(SSL2_ST_GET_SERVER_HELLO_B),
+  S(SSL2_ST_GET_SERVER_VERIFY_A),
+  S(SSL2_ST_GET_SERVER_VERIFY_B),
+  S(SSL2_ST_SEND_CLIENT_CERTIFICATE_A),
+  S(SSL2_ST_SEND_CLIENT_CERTIFICATE_B),
+  S(SSL2_ST_SEND_CLIENT_CERTIFICATE_C),
+  S(SSL2_ST_SEND_CLIENT_CERTIFICATE_D),
+  S(SSL2_ST_SEND_CLIENT_FINISHED_A),
+  S(SSL2_ST_SEND_CLIENT_FINISHED_B),
+  S(SSL2_ST_SEND_CLIENT_HELLO_A),
+  S(SSL2_ST_SEND_CLIENT_HELLO_B),
+  S(SSL2_ST_SEND_CLIENT_MASTER_KEY_A),
+  S(SSL2_ST_SEND_CLIENT_MASTER_KEY_B),
+  S(SSL2_ST_SEND_REQUEST_CERTIFICATE_A),
+  S(SSL2_ST_SEND_REQUEST_CERTIFICATE_B),
+  S(SSL2_ST_SEND_REQUEST_CERTIFICATE_C),
+  S(SSL2_ST_SEND_REQUEST_CERTIFICATE_D),
+  S(SSL2_ST_SEND_SERVER_FINISHED_A),
+  S(SSL2_ST_SEND_SERVER_FINISHED_B),
+  S(SSL2_ST_SEND_SERVER_HELLO_A),
+  S(SSL2_ST_SEND_SERVER_HELLO_B),
+  S(SSL2_ST_SEND_SERVER_VERIFY_A),
+  S(SSL2_ST_SEND_SERVER_VERIFY_B),
+  S(SSL2_ST_SEND_SERVER_VERIFY_C),
+  S(SSL2_ST_SERVER_START_ENCRYPTION),
+  S(SSL2_ST_X509_GET_CLIENT_CERTIFICATE),
+  S(SSL2_ST_X509_GET_SERVER_CERTIFICATE),
+  S(SSL3_ST_CR_CERT_A),
+  S(SSL3_ST_CR_CERT_B),
+  S(SSL3_ST_CR_CERT_REQ_A),
+  S(SSL3_ST_CR_CERT_REQ_B),
+  S(SSL3_ST_CR_CERT_STATUS_A),
+  S(SSL3_ST_CR_CERT_STATUS_B),
+  S(SSL3_ST_CR_CHANGE_A),
+  S(SSL3_ST_CR_CHANGE_B),
+  S(SSL3_ST_CR_FINISHED_A),
+  S(SSL3_ST_CR_FINISHED_B),
+  S(SSL3_ST_CR_KEY_EXCH_A),
+  S(SSL3_ST_CR_KEY_EXCH_B),
+  S(SSL3_ST_CR_SESSION_TICKET_A),
+  S(SSL3_ST_CR_SESSION_TICKET_B),
+  S(SSL3_ST_CR_SRVR_DONE_A),
+  S(SSL3_ST_CR_SRVR_DONE_B),
+  S(SSL3_ST_CR_SRVR_HELLO_A),
+  S(SSL3_ST_CR_SRVR_HELLO_B),
+  S(SSL3_ST_CW_CERT_A),
+  S(SSL3_ST_CW_CERT_B),
+  S(SSL3_ST_CW_CERT_C),
+  S(SSL3_ST_CW_CERT_D),
+  S(SSL3_ST_CW_CERT_VRFY_A),
+  S(SSL3_ST_CW_CERT_VRFY_B),
+  S(SSL3_ST_CW_CHANGE_A),
+  S(SSL3_ST_CW_CHANGE_B),
+  S(SSL3_ST_CW_CLNT_HELLO_A),
+  S(SSL3_ST_CW_CLNT_HELLO_B),
+  S(SSL3_ST_CW_FINISHED_A),
+  S(SSL3_ST_CW_FINISHED_B),
+  S(SSL3_ST_CW_FLUSH),
+  S(SSL3_ST_CW_KEY_EXCH_A),
+  S(SSL3_ST_CW_KEY_EXCH_B),
+  S(SSL3_ST_SR_CERT_A),
+  S(SSL3_ST_SR_CERT_B),
+  S(SSL3_ST_SR_CERT_VRFY_A),
+  S(SSL3_ST_SR_CERT_VRFY_B),
+  S(SSL3_ST_SR_CHANGE_A),
+  S(SSL3_ST_SR_CHANGE_B),
+  S(SSL3_ST_SR_CLNT_HELLO_A),
+  S(SSL3_ST_SR_CLNT_HELLO_B),
+  S(SSL3_ST_SR_CLNT_HELLO_C),
+  S(SSL3_ST_SR_FINISHED_A),
+  S(SSL3_ST_SR_FINISHED_B),
+  S(SSL3_ST_SR_KEY_EXCH_A),
+  S(SSL3_ST_SR_KEY_EXCH_B),
+  S(SSL3_ST_SW_CERT_A),
+  S(SSL3_ST_SW_CERT_B),
+  S(SSL3_ST_SW_CERT_REQ_A),
+  S(SSL3_ST_SW_CERT_REQ_B),
+  S(SSL3_ST_SW_CERT_STATUS_A),
+  S(SSL3_ST_SW_CERT_STATUS_B),
+  S(SSL3_ST_SW_CHANGE_A),
+  S(SSL3_ST_SW_CHANGE_B),
+  S(SSL3_ST_SW_FINISHED_A),
+  S(SSL3_ST_SW_FINISHED_B),
+  S(SSL3_ST_SW_FLUSH),
+  S(SSL3_ST_SW_HELLO_REQ_A),
+  S(SSL3_ST_SW_HELLO_REQ_B),
+  S(SSL3_ST_SW_HELLO_REQ_C),
+  S(SSL3_ST_SW_KEY_EXCH_A),
+  S(SSL3_ST_SW_KEY_EXCH_B),
+  S(SSL3_ST_SW_SESSION_TICKET_A),
+  S(SSL3_ST_SW_SESSION_TICKET_B),
+  S(SSL3_ST_SW_SRVR_DONE_A),
+  S(SSL3_ST_SW_SRVR_DONE_B),
+  S(SSL3_ST_SW_SRVR_HELLO_A),
+  S(SSL3_ST_SW_SRVR_HELLO_B),
+  S(SSL_CB_ACCEPT_EXIT),
+  S(SSL_CB_ACCEPT_LOOP),
+  S(SSL_CB_CONNECT_EXIT),
+  S(SSL_CB_CONNECT_LOOP),
+  S(SSL_ST_ACCEPT),
+  S(SSL_ST_BEFORE),
+  S(SSL_ST_CONNECT),
+  S(SSL_ST_INIT),
+  S(SSL_ST_MASK),
+  S(SSL_ST_OK),
+  S(SSL_ST_READ_BODY),
+  S(SSL_ST_READ_DONE),
+  S(SSL_ST_READ_HEADER),
+  S(SSL_ST_RENEGOTIATE),
+  { 0, NULL }
+};
+
+/** Return the symbolic name of an OpenSSL state. */
+static const char *
+ssl_state_to_string(int ssl_state)
+{
+  static char buf[40];
+  int i;
+  for (i = 0; state_map[i].name; ++i) {
+    if (state_map[i].state == ssl_state)
+      return state_map[i].name;
+  }
+  tor_snprintf(buf, sizeof(buf), "Unknown state %d", ssl_state);
+  return buf;
+}
+
 /** Log all pending tls errors at level <b>severity</b>.  Use
  * <b>doing</b> to describe our current activities.
  */
 static void
-tls_log_errors(tor_tls_t *tls, int severity, const char *doing)
+tls_log_errors(tor_tls_t *tls, int severity, int domain, const char *doing)
 {
+  const char *state = NULL;
+  int st;
   unsigned long err;
   const char *msg, *lib, *func, *addr;
   addr = tls ? tls->address : NULL;
+  st = (tls && tls->ssl) ? tls->ssl->state : -1;
   while ((err = ERR_get_error()) != 0) {
     msg = (const char*)ERR_reason_error_string(err);
     lib = (const char*)ERR_lib_error_string(err);
     func = (const char*)ERR_func_error_string(err);
+    if (!state)
+      state = (st>=0)?ssl_state_to_string(st):"---";
     if (!msg) msg = "(null)";
     if (doing) {
-      log(severity, LD_NET, "TLS error while %s%s%s: %s (in %s:%s)",
+      log(severity, domain, "TLS error while %s%s%s: %s (in %s:%s:%s)",
           doing, addr?" with ":"", addr?addr:"",
-          msg, lib, func);
+          msg, lib, func, state);
     } else {
-      log(severity, LD_NET, "TLS error%s%s: %s (in %s:%s)",
+      log(severity, domain, "TLS error%s%s: %s (in %s:%s:%s)",
           addr?" with ":"", addr?addr:"",
-          msg, lib, func);
+          msg, lib, func, state);
     }
   }
 }
@@ -262,7 +416,7 @@ tor_tls_err_to_string(int err)
  */
 static int
 tor_tls_get_error(tor_tls_t *tls, int r, int extra,
-                  const char *doing, int severity)
+                  const char *doing, int severity, int domain)
 {
   int err = SSL_get_error(tls->ssl, r);
   int tor_error = TOR_TLS_ERROR_MISC;
@@ -277,25 +431,28 @@ tor_tls_get_error(tor_tls_t *tls, int r, int extra,
       if (extra&CATCH_SYSCALL)
         return _TOR_TLS_SYSCALL;
       if (r == 0) {
-        log(severity, LD_NET, "TLS error: unexpected close while %s", doing);
+        log(severity, LD_NET, "TLS error: unexpected close while %s (%s)",
+            doing, ssl_state_to_string(tls->ssl->state));
         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));
+            "TLS error: <syscall error while %s> (errno=%d: %s; state=%s)",
+            doing, e, tor_socket_strerror(e),
+            ssl_state_to_string(tls->ssl->state));
         tor_error = tor_errno_to_tls_error(e);
       }
-      tls_log_errors(tls, severity, doing);
+      tls_log_errors(tls, severity, domain, doing);
       return tor_error;
     case SSL_ERROR_ZERO_RETURN:
       if (extra&CATCH_ZERO)
         return _TOR_TLS_ZERORETURN;
-      log(severity, LD_NET, "TLS connection closed while %s", doing);
-      tls_log_errors(tls, severity, doing);
+      log(severity, LD_NET, "TLS connection closed while %s in state %s",
+          doing, ssl_state_to_string(tls->ssl->state));
+      tls_log_errors(tls, severity, domain, doing);
       return TOR_TLS_CLOSE;
     default:
-      tls_log_errors(tls, severity, doing);
+      tls_log_errors(tls, severity, domain, doing);
       return TOR_TLS_ERROR_MISC;
   }
 }
@@ -427,7 +584,7 @@ tor_tls_create_certificate(crypto_pk_env_t *rsa,
     x509 = NULL;
   }
  done:
-  tls_log_errors(NULL, LOG_WARN, "generating certificate");
+  tls_log_errors(NULL, LOG_WARN, LD_NET, "generating certificate");
   if (sign_pkey)
     EVP_PKEY_free(sign_pkey);
   if (pkey)
@@ -615,7 +772,7 @@ tor_tls_context_new(crypto_pk_env_t *identity, unsigned int key_lifetime)
   return 0;
 
  error:
-  tls_log_errors(NULL, LOG_WARN, "creating TLS context");
+  tls_log_errors(NULL, LOG_WARN, LD_NET, "creating TLS context");
   tor_free(nickname);
   tor_free(nn2);
   if (pkey)
@@ -811,7 +968,7 @@ tor_tls_new(int sock, int isServer)
 
   tor_assert(global_tls_context); /* make sure somebody made it first */
   if (!(result->ssl = SSL_new(global_tls_context->ctx))) {
-    tls_log_errors(NULL, LOG_WARN, "generating TLS context");
+    tls_log_errors(NULL, LOG_WARN, LD_NET, "generating TLS context");
     tor_free(result);
     return NULL;
   }
@@ -827,7 +984,7 @@ tor_tls_new(int sock, int isServer)
 
   if (!SSL_set_cipher_list(result->ssl,
                      isServer ? SERVER_CIPHER_LIST : CLIENT_CIPHER_LIST)) {
-    tls_log_errors(NULL, LOG_WARN, "setting ciphers");
+    tls_log_errors(NULL, LOG_WARN, LD_NET, "setting ciphers");
 #ifdef SSL_set_tlsext_host_name
     SSL_set_tlsext_host_name(result->ssl, NULL);
 #endif
@@ -840,7 +997,7 @@ tor_tls_new(int sock, int isServer)
   result->socket = sock;
   bio = BIO_new_socket(sock, BIO_NOCLOSE);
   if (! bio) {
-    tls_log_errors(NULL, LOG_WARN, "opening BIO");
+    tls_log_errors(NULL, LOG_WARN, LD_NET, "opening BIO");
 #ifdef SSL_set_tlsext_host_name
     SSL_set_tlsext_host_name(result->ssl, NULL);
 #endif
@@ -867,7 +1024,7 @@ tor_tls_new(int sock, int isServer)
   }
 #endif
   /* Not expected to get called. */
-  tls_log_errors(NULL, LOG_WARN, "generating TLS context");
+  tls_log_errors(NULL, LOG_WARN, LD_NET, "generating TLS context");
   return result;
 }
 
@@ -962,7 +1119,7 @@ tor_tls_read(tor_tls_t *tls, char *cp, size_t len)
 #endif
     return r;
   }
-  err = tor_tls_get_error(tls, r, CATCH_ZERO, "reading", LOG_DEBUG);
+  err = tor_tls_get_error(tls, r, CATCH_ZERO, "reading", LOG_DEBUG, LD_NET);
   if (err == _TOR_TLS_ZERORETURN || err == TOR_TLS_CLOSE) {
     log_debug(LD_NET,"read returned r=%d; TLS is closed",r);
     tls->state = TOR_TLS_ST_CLOSED;
@@ -998,7 +1155,7 @@ tor_tls_write(tor_tls_t *tls, const char *cp, size_t n)
     tls->wantwrite_n = 0;
   }
   r = SSL_write(tls->ssl, cp, (int)n);
-  err = tor_tls_get_error(tls, r, 0, "writing", LOG_INFO);
+  err = tor_tls_get_error(tls, r, 0, "writing", LOG_INFO, LD_NET);
   if (err == TOR_TLS_DONE) {
     return r;
   }
@@ -1016,18 +1173,27 @@ int
 tor_tls_handshake(tor_tls_t *tls)
 {
   int r;
+  int oldstate;
   tor_assert(tls);
   tor_assert(tls->ssl);
   tor_assert(tls->state == TOR_TLS_ST_HANDSHAKE);
   check_no_tls_errors();
+  oldstate = tls->ssl->state;
   if (tls->isServer) {
+    log_debug(LD_HANDSHAKE, "About to call SSL_accept on %p (%s)", tls,
+              ssl_state_to_string(tls->ssl->state));
     r = SSL_accept(tls->ssl);
   } else {
+    log_debug(LD_HANDSHAKE, "About to call SSL_connect on %p (%s)", tls,
+              ssl_state_to_string(tls->ssl->state));
     r = SSL_connect(tls->ssl);
   }
-  r = tor_tls_get_error(tls,r,0, "handshaking", LOG_INFO);
+  if (oldstate != tls->ssl->state)
+    log_debug(LD_HANDSHAKE, "After call, %p was in state %s",
+              tls, ssl_state_to_string(tls->ssl->state));
+  r = tor_tls_get_error(tls,r,0, "handshaking", LOG_INFO, LD_HANDSHAKE);
   if (ERR_peek_error() != 0) {
-    tls_log_errors(tls, tls->isServer ? LOG_INFO : LOG_WARN,
+    tls_log_errors(tls, tls->isServer ? LOG_INFO : LOG_WARN, LD_HANDSHAKE,
                    "handshaking");
     return TOR_TLS_ERROR_MISC;
   }
@@ -1048,7 +1214,8 @@ tor_tls_handshake(tor_tls_t *tls)
                    " get set. Fixing that.");
         }
         tls->wasV2Handshake = 1;
-        log_debug(LD_NET, "Completed V2 TLS handshake with client; waiting "
+        log_debug(LD_HANDSHAKE,
+                  "Completed V2 TLS handshake with client; waiting "
                   "for renegotiation.");
       } else {
         tls->wasV2Handshake = 0;
@@ -1060,10 +1227,13 @@ tor_tls_handshake(tor_tls_t *tls)
       X509 *cert = SSL_get_peer_certificate(tls->ssl);
       STACK_OF(X509) *chain = SSL_get_peer_cert_chain(tls->ssl);
       int n_certs = sk_X509_num(chain);
-      if (n_certs > 1 || (n_certs == 1 && cert != sk_X509_value(chain, 0)))
+      if (n_certs > 1 || (n_certs == 1 && cert != sk_X509_value(chain, 0))) {
+        log_debug(LD_HANDSHAKE, "Server sent back multiple certificates; it "
+                  "looks like a v1 handshake on %p", tls);
         tls->wasV2Handshake = 0;
-      else {
-        log_debug(LD_NET, "Server sent back a single certificate; looks like "
+      } else {
+        log_debug(LD_HANDSHAKE,
+                  "Server sent back a single certificate; looks like "
                   "a v2 handshake on %p.", tls);
         tls->wasV2Handshake = 1;
       }
@@ -1071,7 +1241,7 @@ tor_tls_handshake(tor_tls_t *tls)
         X509_free(cert);
 #endif
       if (SSL_set_cipher_list(tls->ssl, SERVER_CIPHER_LIST) == 0) {
-        tls_log_errors(NULL, LOG_WARN, "re-setting ciphers");
+        tls_log_errors(NULL, LOG_WARN, LD_HANDSHAKE, "re-setting ciphers");
         r = TOR_TLS_ERROR_MISC;
       }
     }
@@ -1094,7 +1264,8 @@ tor_tls_renegotiate(tor_tls_t *tls)
   if (tls->state != TOR_TLS_ST_RENEGOTIATE) {
     int r = SSL_renegotiate(tls->ssl);
     if (r <= 0) {
-      return tor_tls_get_error(tls, r, 0, "renegotiating", LOG_WARN);
+      return tor_tls_get_error(tls, r, 0, "renegotiating", LOG_WARN,
+                               LD_HANDSHAKE);
     }
     tls->state = TOR_TLS_ST_RENEGOTIATE;
   }
@@ -1103,7 +1274,8 @@ tor_tls_renegotiate(tor_tls_t *tls)
     tls->state = TOR_TLS_ST_OPEN;
     return TOR_TLS_DONE;
   } else
-    return tor_tls_get_error(tls, r, 0, "renegotiating handshake", LOG_INFO);
+    return tor_tls_get_error(tls, r, 0, "renegotiating handshake", LOG_INFO,
+                             LD_HANDSHAKE);
 }
 
 /** Shut down an open tls connection <b>tls</b>.  When finished, returns
@@ -1127,7 +1299,7 @@ tor_tls_shutdown(tor_tls_t *tls)
         r = SSL_read(tls->ssl, buf, 128);
       } while (r>0);
       err = tor_tls_get_error(tls, r, CATCH_ZERO, "reading to shut down",
-                              LOG_INFO);
+                              LOG_INFO, LD_NET);
       if (err == _TOR_TLS_ZERORETURN) {
         tls->state = TOR_TLS_ST_GOTCLOSE;
         /* fall through... */
@@ -1143,7 +1315,7 @@ tor_tls_shutdown(tor_tls_t *tls)
       return TOR_TLS_DONE;
     }
     err = tor_tls_get_error(tls, r, CATCH_SYSCALL|CATCH_ZERO, "shutting down",
-                            LOG_INFO);
+                            LOG_INFO, LD_NET);
     if (err == _TOR_TLS_SYSCALL) {
       /* The underlying TCP connection closed while we were shutting down. */
       tls->state = TOR_TLS_ST_CLOSED;
@@ -1175,7 +1347,7 @@ tor_tls_peer_has_cert(tor_tls_t *tls)
 {
   X509 *cert;
   cert = SSL_get_peer_certificate(tls->ssl);
-  tls_log_errors(tls, LOG_WARN, "getting peer certificate");
+  tls_log_errors(tls, LOG_WARN, LD_HANDSHAKE, "getting peer certificate");
   if (!cert)
     return 0;
   X509_free(cert);
@@ -1202,7 +1374,7 @@ log_cert_lifetime(X509 *cert, const char *problem)
     log_warn(LD_GENERAL, "Couldn't allocate BIO!"); goto end;
   }
   if (!(ASN1_TIME_print(bio, X509_get_notBefore(cert)))) {
-    tls_log_errors(NULL, LOG_WARN, "printing certificate lifetime");
+    tls_log_errors(NULL, LOG_WARN, LD_NET, "printing certificate lifetime");
     goto end;
   }
   BIO_get_mem_ptr(bio, &buf);
@@ -1210,7 +1382,7 @@ log_cert_lifetime(X509 *cert, const char *problem)
 
   (void)BIO_reset(bio);
   if (!(ASN1_TIME_print(bio, X509_get_notAfter(cert)))) {
-    tls_log_errors(NULL, LOG_WARN, "printing certificate lifetime");
+    tls_log_errors(NULL, LOG_WARN, LD_NET, "printing certificate lifetime");
     goto end;
   }
   BIO_get_mem_ptr(bio, &buf);
@@ -1224,7 +1396,7 @@ log_cert_lifetime(X509 *cert, const char *problem)
 
  end:
   /* Not expected to get invoked */
-  tls_log_errors(NULL, LOG_WARN, "getting certificate lifetime");
+  tls_log_errors(NULL, LOG_WARN, LD_NET, "getting certificate lifetime");
   if (bio)
     BIO_free(bio);
   if (s1)
@@ -1298,7 +1470,7 @@ tor_tls_verify(int severity, tor_tls_t *tls, crypto_pk_env_t **identity_key)
   if (!(id_pkey = X509_get_pubkey(id_cert)) ||
       X509_verify(cert, id_pkey) <= 0) {
     log_fn(severity,LD_PROTOCOL,"X509_verify on cert and pkey returned <= 0");
-    tls_log_errors(tls, severity,"verifying certificate");
+    tls_log_errors(tls, severity, LD_HANDSHAKE, "verifying certificate");
     goto done;
   }
 
@@ -1317,7 +1489,7 @@ tor_tls_verify(int severity, tor_tls_t *tls, crypto_pk_env_t **identity_key)
 
   /* This should never get invoked, but let's make sure in case OpenSSL
    * acts unexpectedly. */
-  tls_log_errors(tls, LOG_WARN, "finishing tor_tls_verify");
+  tls_log_errors(tls, LOG_WARN, LD_HANDSHAKE, "finishing tor_tls_verify");
 
   return r;
 }
@@ -1356,7 +1528,7 @@ tor_tls_check_lifetime(tor_tls_t *tls, int tolerance)
   if (cert)
     X509_free(cert);
   /* Not expected to get invoked */
-  tls_log_errors(tls, LOG_WARN, "checking certificate lifetime");
+  tls_log_errors(tls, LOG_WARN, LD_NET, "checking certificate lifetime");
 
   return r;
 }
@@ -1424,7 +1596,7 @@ _check_no_tls_errors(const char *fname, int line)
     return;
   log(LOG_WARN, LD_CRYPTO, "Unhandled OpenSSL errors found at %s:%d: ",
       tor_fix_source_file(fname), line);
-  tls_log_errors(NULL, LOG_WARN, NULL);
+  tls_log_errors(NULL, LOG_WARN, LD_NET, NULL);
 }
 
 /** Return true iff the initial TLS connection at <b>tls</b> did not use a v2

diff --git a/src/or/connection_or.c b/src/or/connection_or.c
index aa26bf8f4b0b76169d7d0496d2d2ca72c99953e3..c3d35e1df6b54636e259e9fe6d5d8be142f93c4d 100644 (file)
--- a/src/or/connection_or.c
+++ b/src/or/connection_or.c
@@ -289,7 +289,7 @@ connection_or_finished_connecting(or_connection_t *or_conn)
   conn = TO_CONN(or_conn);
   tor_assert(conn->state == OR_CONN_STATE_CONNECTING);
 
-  log_debug(LD_OR,"OR connect() to router at %s:%u finished.",
+  log_debug(LD_HANDSHAKE,"OR connect() to router at %s:%u finished.",
             conn->address,conn->port);
   control_event_bootstrap(BOOTSTRAP_STATUS_HANDSHAKE, 0);
 
@@ -780,7 +780,7 @@ connection_tls_start_handshake(or_connection_t *conn, int receiving)
     return -1;
   }
   connection_start_reading(TO_CONN(conn));
-  log_debug(LD_OR,"starting TLS handshake on fd %d", conn->_base.s);
+  log_debug(LD_HANDSHAKE,"starting TLS handshake on fd %d", conn->_base.s);
   note_crypto_pk_op(receiving ? TLS_HANDSHAKE_S : TLS_HANDSHAKE_C);
 
   if (connection_tls_continue_handshake(conn) < 0) {
@@ -920,12 +920,12 @@ connection_or_check_valid_tls_handshake(or_connection_t *conn,
   check_no_tls_errors();
   has_cert = tor_tls_peer_has_cert(conn->tls);
   if (started_here && !has_cert) {
-    log_info(LD_PROTOCOL,"Tried connecting to router at %s:%d, but it didn't "
+    log_info(LD_HANDSHAKE,"Tried connecting to router at %s:%d, but it didn't "
              "send a cert! Closing.",
              safe_address, conn->_base.port);
     return -1;
   } else if (!has_cert) {
-    log_debug(LD_PROTOCOL,"Got incoming connection with no certificate. "
+    log_debug(LD_HANDSHAKE,"Got incoming connection with no certificate. "
               "That's ok.");
   }
   check_no_tls_errors();
@@ -934,15 +934,16 @@ connection_or_check_valid_tls_handshake(or_connection_t *conn,
     int v = tor_tls_verify(started_here?severity:LOG_INFO,
                            conn->tls, &identity_rcvd);
     if (started_here && v<0) {
-      log_fn(severity,LD_OR,"Tried connecting to router at %s:%d: It"
+      log_fn(severity,LD_HANDSHAKE,"Tried connecting to router at %s:%d: It"
              " has a cert but it's invalid. Closing.",
              safe_address, conn->_base.port);
         return -1;
     } else if (v<0) {
-      log_info(LD_PROTOCOL,"Incoming connection gave us an invalid cert "
+      log_info(LD_HANDSHAKE,"Incoming connection gave us an invalid cert "
                "chain; ignoring.");
     } else {
-      log_debug(LD_OR,"The certificate seems to be valid on %s connection "
+      log_debug(LD_HANDSHAKE,
+                "The certificate seems to be valid on %s connection "
                 "with %s:%d", conn_type, safe_address, conn->_base.port);
     }
     check_no_tls_errors();
@@ -969,7 +970,7 @@ connection_or_check_valid_tls_handshake(or_connection_t *conn,
     conn->nickname[0] = '$';
     base16_encode(conn->nickname+1, HEX_DIGEST_LEN+1,
                   conn->identity_digest, DIGEST_LEN);
-    log_info(LD_OR, "Connected to router %s at %s:%d without knowing "
+    log_info(LD_HANDSHAKE, "Connected to router %s at %s:%d without knowing "
                     "its key. Hoping for the best.",
                     conn->nickname, conn->_base.address, conn->_base.port);
   }
@@ -985,7 +986,7 @@ connection_or_check_valid_tls_handshake(or_connection_t *conn,
       base16_encode(seen, sizeof(seen), digest_rcvd_out, DIGEST_LEN);
       base16_encode(expected, sizeof(expected), conn->identity_digest,
                     DIGEST_LEN);
-      log_fn(severity, LD_OR,
+      log_fn(severity, LD_HANDSHAKE,
              "Tried connecting to router at %s:%d, but identity key was not "
              "as expected: wanted %s but got %s.",
              conn->_base.address, conn->_base.port, expected, seen);
@@ -1027,7 +1028,7 @@ connection_tls_finish_handshake(or_connection_t *conn)
   char digest_rcvd[DIGEST_LEN];
   int started_here = connection_or_nonopen_was_started_here(conn);
 
-  log_debug(LD_OR,"tls handshake with %s done. verifying.",
+  log_debug(LD_HANDSHAKE,"tls handshake with %s done. verifying.",
             safe_str(conn->_base.address));
 
   directory_set_dirty();