diff --git a/include/haproxy/ssl_trace-t.h b/include/haproxy/ssl_trace-t.h index 8652ff4d4..efd7dcbd7 100644 --- a/include/haproxy/ssl_trace-t.h +++ b/include/haproxy/ssl_trace-t.h @@ -27,6 +27,7 @@ extern struct trace_source trace_ssl; #define SSL_EV_CONN_RECV (1ULL << 6) #define SSL_EV_CONN_RECV_EARLY (1ULL << 7) #define SSL_EV_CONN_IO_CB (1ULL << 8) +#define SSL_EV_CONN_HNDSHK (1ULL << 9) #define TRACE_SOURCE &trace_ssl diff --git a/src/ssl_sock.c b/src/ssl_sock.c index 77fbc4055..238d093c5 100644 --- a/src/ssl_sock.c +++ b/src/ssl_sock.c @@ -5218,6 +5218,7 @@ static int ssl_sock_handshake(struct connection *conn, unsigned int flag) socklen_t lskerr; int skerr; + TRACE_ENTER(SSL_EV_CONN_HNDSHK, conn); if (!conn_ctrl_ready(conn)) return 0; @@ -5246,8 +5247,10 @@ static int ssl_sock_handshake(struct connection *conn, unsigned int flag) goto out_error; /* don't start calculating a handshake on a dead connection */ - if (conn->flags & (CO_FL_ERROR | CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH)) + if (conn->flags & (CO_FL_ERROR | CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH)) { + TRACE_ERROR("Trying to perform handshake on dead connection", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); goto out_error; + } /* FIXME/WT: for now we don't have a clear way to inspect the connection * status from the lower layers, so let's check the FD directly. Ideally @@ -5275,9 +5278,12 @@ static int ssl_sock_handshake(struct connection *conn, unsigned int flag) ret = SSL_read_early_data(ctx->ssl, b_tail(&ctx->early_buf), b_room(&ctx->early_buf), &read_data); - if (ret == SSL_READ_EARLY_DATA_ERROR) + if (ret == SSL_READ_EARLY_DATA_ERROR) { + TRACE_ERROR("Read early data error", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); goto check_error; + } if (read_data > 0) { + TRACE_DEVEL("Early data read", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); conn->flags |= CO_FL_EARLY_DATA; b_add(&ctx->early_buf, read_data); } @@ -5285,6 +5291,7 @@ static int ssl_sock_handshake(struct connection *conn, unsigned int flag) conn->flags &= ~CO_FL_EARLY_SSL_HS; if (!b_data(&ctx->early_buf)) b_free(&ctx->early_buf); + TRACE_STATE("Read early data finish", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); break; } } @@ -5299,6 +5306,8 @@ static int ssl_sock_handshake(struct connection *conn, unsigned int flag) if (!(conn->flags & CO_FL_WAIT_L6_CONN) && SSL_renegotiate_pending(ctx->ssl)) { char c; + TRACE_STATE("Renegotiate pending", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); + ret = SSL_peek(ctx->ssl, &c, 1); if (ret <= 0) { /* handshake may have not been completed, let's find why */ @@ -5308,6 +5317,7 @@ static int ssl_sock_handshake(struct connection *conn, unsigned int flag) /* SSL handshake needs to write, L4 connection may not be ready */ if (!(ctx->wait_event.events & SUB_RETRY_SEND)) ctx->xprt->subscribe(conn, ctx->xprt_ctx, SUB_RETRY_SEND, &ctx->wait_event); + TRACE_DEVEL("Renegotiate pending: want write", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); return 0; } else if (ret == SSL_ERROR_WANT_READ) { @@ -5316,16 +5326,19 @@ static int ssl_sock_handshake(struct connection *conn, unsigned int flag) */ if (!SSL_renegotiate_pending(ctx->ssl)) { ret = 1; + TRACE_DEVEL("Renegotiate pending: reneg ok", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); goto reneg_ok; } /* SSL handshake needs to read, L4 connection is ready */ if (!(ctx->wait_event.events & SUB_RETRY_RECV)) ctx->xprt->subscribe(conn, ctx->xprt_ctx, SUB_RETRY_RECV, &ctx->wait_event); + TRACE_DEVEL("Renegotiate pending: want read", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); return 0; } #ifdef SSL_MODE_ASYNC else if (ret == SSL_ERROR_WANT_ASYNC) { ssl_async_process_fds(ctx); + TRACE_ERROR("Renegotiate pending: want async error", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); return 0; } #endif @@ -5369,6 +5382,7 @@ static int ssl_sock_handshake(struct connection *conn, unsigned int flag) } #endif /* BoringSSL or LibreSSL */ } + TRACE_ERROR("Renegotiate pending: syscall error", SSL_EV_CONN_HNDSHK|SSL_EV_CONN_ERR, conn, ctx->ssl, &conn->err_code); goto out_error; } else { @@ -5382,9 +5396,11 @@ static int ssl_sock_handshake(struct connection *conn, unsigned int flag) if (!conn->err_code) conn->err_code = (ctx->xprt_st & SSL_SOCK_RECV_HEARTBEAT) ? CO_ER_SSL_KILLED_HB : CO_ER_SSL_HANDSHAKE; + TRACE_ERROR("Renegotiate pending: other error", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); goto out_error; } } + TRACE_STATE("Renegotiate pending: reneg ok", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); /* read some data: consider handshake completed */ goto reneg_ok; } @@ -5401,6 +5417,7 @@ check_error: /* SSL handshake needs to write, L4 connection may not be ready */ if (!(ctx->wait_event.events & SUB_RETRY_SEND)) ctx->xprt->subscribe(conn, ctx->xprt_ctx, SUB_RETRY_SEND, &ctx->wait_event); + TRACE_DEVEL("Want write (post SSL_do_handshake)", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); return 0; } else if (ret == SSL_ERROR_WANT_READ) { @@ -5408,11 +5425,13 @@ check_error: if (!(ctx->wait_event.events & SUB_RETRY_RECV)) ctx->xprt->subscribe(conn, ctx->xprt_ctx, SUB_RETRY_RECV, &ctx->wait_event); + TRACE_DEVEL("Want read (post SSL_do_handshake)", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); return 0; } #ifdef SSL_MODE_ASYNC else if (ret == SSL_ERROR_WANT_ASYNC) { ssl_async_process_fds(ctx); + TRACE_ERROR("Want async error", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); return 0; } #endif @@ -5456,6 +5475,7 @@ check_error: } #endif /* BoringSSL or LibreSSL */ } + TRACE_ERROR("Syscall error", SSL_EV_CONN_HNDSHK|SSL_EV_CONN_ERR, conn, ctx->ssl, &conn->err_code, &ctx->error_code); goto out_error; } else if (ret == SSL_ERROR_ZERO_RETURN) { @@ -5463,6 +5483,7 @@ check_error: * sending a close_notify alert */ conn_ctrl_drain(conn); conn->err_code = CO_ER_SSL_EMPTY; + TRACE_ERROR("Zero return error", SSL_EV_CONN_HNDSHK|SSL_EV_CONN_ERR, conn, ctx->ssl, &conn->err_code, &ctx->error_code); goto out_error; } @@ -5477,11 +5498,13 @@ check_error: if (!conn->err_code) conn->err_code = (ctx->xprt_st & SSL_SOCK_RECV_HEARTBEAT) ? CO_ER_SSL_KILLED_HB : CO_ER_SSL_HANDSHAKE; + TRACE_ERROR("Other error", SSL_EV_CONN_HNDSHK|SSL_EV_CONN_ERR, conn, ctx->ssl, &conn->err_code, &ctx->error_code); goto out_error; } } -#ifdef SSL_READ_EARLY_DATA_SUCCESS else { + TRACE_STATE("Successful SSL_do_handshake", SSL_EV_CONN_HNDSHK, conn, ctx->ssl); +#ifdef SSL_READ_EARLY_DATA_SUCCESS /* * If the server refused the early data, we have to send a * 425 to the client, as we no longer have the data to sent @@ -5490,11 +5513,12 @@ check_error: if ((conn->flags & CO_FL_EARLY_DATA) && (objt_server(conn->target))) { if (SSL_get_early_data_status(ctx->ssl) == SSL_EARLY_DATA_REJECTED) { conn->err_code = CO_ER_SSL_EARLY_FAILED; + TRACE_ERROR("Early data rejected", SSL_EV_CONN_HNDSHK|SSL_EV_CONN_ERR, conn, ctx->ssl, &conn->err_code); goto out_error; } } - } #endif + } reneg_ok: @@ -5530,6 +5554,8 @@ reneg_ok: HA_ATOMIC_INC(&counters_px->reused_sess); } + TRACE_LEAVE(SSL_EV_CONN_HNDSHK, conn, ctx->ssl); + /* The connection is now established at both layers, it's time to leave */ conn->flags &= ~(flag | CO_FL_WAIT_L4_CONN | CO_FL_WAIT_L6_CONN); return 1; @@ -5565,6 +5591,8 @@ reneg_ok: conn->flags |= CO_FL_ERROR; if (!conn->err_code) conn->err_code = CO_ER_SSL_HANDSHAKE; + + TRACE_ERROR("handshake error", SSL_EV_CONN_HNDSHK|SSL_EV_CONN_ERR, conn, ctx->ssl, &conn->err_code, &ctx->error_code); return 0; } diff --git a/src/ssl_trace.c b/src/ssl_trace.c index 3c00f73c6..558e10880 100644 --- a/src/ssl_trace.c +++ b/src/ssl_trace.c @@ -35,6 +35,7 @@ static const struct trace_event ssl_trace_events[] = { { .mask = SSL_EV_CONN_RECV, .name = "sslc_recv", .desc = "Rx on SSL connection" }, { .mask = SSL_EV_CONN_RECV_EARLY, .name = "sslc_recv_early", .desc = "Rx on SSL connection (early data)" }, { .mask = SSL_EV_CONN_IO_CB, .name = "sslc_io_cb", .desc = "SSL io callback"}, + { .mask = SSL_EV_CONN_HNDSHK, .name = "sslc_hndshk", .desc = "SSL handshake"}, { } }; @@ -113,5 +114,50 @@ static void ssl_trace(enum trace_level level, uint64_t mask, const struct trace_ } } + if (mask & SSL_EV_CONN_HNDSHK) { + const SSL *ssl = a2; + + if (ssl && src->verbosity > SSL_VERB_SIMPLE) { + const char *servername = SSL_get_servername(ssl, TLSEXT_NAMETYPE_host_name); + struct buffer *alpn = get_trash_chunk(); + unsigned int len = 0; + + chunk_appendf(&trace_buf, " servername=%s", servername); + + SSL_get0_alpn_selected(ssl, (const unsigned char**)&alpn->area, &len); + chunk_appendf(&trace_buf, " alpn=%.*s", len, alpn->area); + + chunk_appendf(&trace_buf, " tls_vers=%s", (char *)SSL_get_version(ssl)); + + chunk_appendf(&trace_buf, " cipher=%s", (char*)SSL_get_cipher_name(ssl)); + + { + X509 *crt = SSL_get_certificate(ssl); + + if (crt) { + X509_NAME *name = X509_get_subject_name(crt); + if (name) + chunk_appendf(&trace_buf, " subject=\"%s\"", + X509_NAME_oneline(name, 0, 0)); + } + } + } + + if (mask & SSL_EV_CONN_ERR) { + /* Try to give more information about the specific handshake + * error we had. */ + if (a3) { + const unsigned int *err_code = a3; + chunk_appendf(&trace_buf, " err_code=%u err_str=\"%s\"", *err_code, conn_err_code_str(conn)); + } + + if (a4) { + const unsigned int *ssl_err_code = a4; + chunk_appendf(&trace_buf, " ssl_err_code=%u ssl_err_str=\"%s\"", *ssl_err_code, + ERR_error_string(*ssl_err_code, NULL)); + } + } + } + }