diff options
| -rw-r--r-- | ChangeLog | 7 | ||||
| -rw-r--r-- | src/common/log.c | 2 | ||||
| -rw-r--r-- | src/common/log.h | 5 | ||||
| -rw-r--r-- | src/common/tortls.c | 252 | ||||
| -rw-r--r-- | src/or/connection_or.c | 21 |
5 files changed, 234 insertions, 53 deletions
@@ -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 09efa014c0..a83f945459 100644 --- 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 6745baabc6..f1a6164f7d 100644 --- 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 a43c4ea0a3..4d673bf1ec 100644 --- 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 aa26bf8f4b..c3d35e1df6 100644 --- 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(); |