1berry/haproxy
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

MINOR: ssl: Add traces around SSL_do_handshake call

Browse Source 
Those traces dump information about the multiple SSL_do_handshake calls
(renegotiation and regular call). Some errors coud also be dumped in
case of rejected early data.
Depending on the chosen verbosity, some information about the current
handshake can be dumped as well (servername, tls version, chosen cipher
for instance).
In case of failed handshake, the error codes and messages will also be
dumped in the log to ease debugging.
This commit is contained in:
Remi Tricot-Le Breton 2025-04-18 17:26:53 +02:00 committed by William Lallemand
parent 9f146bdab3
commit 4a8fa28e36
3 changed files with 79 additions and 4 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
include/haproxy/ssl_trace-t.h
View File

@ -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

36
src/ssl_sock.c
View File

@ -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;
}

46
src/ssl_trace.c
View File

@ -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));
}
}
}
}