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

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

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,

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;
 

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

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();