From 475bb8d8431f69908fce2c3e92ff2d08e33223be Mon Sep 17 00:00:00 2001 From: Remi Tricot-Le Breton Date: Fri, 18 Apr 2025 17:26:51 +0200 Subject: [PATCH] MINOR: ssl: Add traces to recv/send functions Those traces will allow to identify sessions on which early data is used as well as some forcefully closed connections. --- include/haproxy/ssl_trace-t.h | 4 ++++ src/ssl_sock.c | 38 +++++++++++++++++++++++++++-------- src/ssl_trace.c | 19 ++++++++++++++++++ 3 files changed, 53 insertions(+), 8 deletions(-) diff --git a/include/haproxy/ssl_trace-t.h b/include/haproxy/ssl_trace-t.h index 513822f76..4575fda82 100644 --- a/include/haproxy/ssl_trace-t.h +++ b/include/haproxy/ssl_trace-t.h @@ -22,6 +22,10 @@ extern struct trace_source trace_ssl; #define SSL_EV_CONN_CLOSE (1ULL << 1) #define SSL_EV_CONN_END (1ULL << 2) #define SSL_EV_CONN_ERR (1ULL << 3) +#define SSL_EV_CONN_SEND (1ULL << 4) +#define SSL_EV_CONN_SEND_EARLY (1ULL << 5) +#define SSL_EV_CONN_RECV (1ULL << 6) +#define SSL_EV_CONN_RECV_EARLY (1ULL << 7) #define TRACE_SOURCE &trace_ssl diff --git a/src/ssl_sock.c b/src/ssl_sock.c index 20ffe26db..326a5d739 100644 --- a/src/ssl_sock.c +++ b/src/ssl_sock.c @@ -5813,6 +5813,8 @@ static size_t ssl_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu ssize_t ret; size_t try, done = 0; + TRACE_ENTER(SSL_EV_CONN_RECV, conn); + if (!ctx) goto out_error; @@ -5826,13 +5828,16 @@ static size_t ssl_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu b_del(&ctx->early_buf, try); if (b_data(&ctx->early_buf) == 0) b_free(&ctx->early_buf); + TRACE_STATE("read early data", SSL_EV_CONN_RECV|SSL_EV_CONN_RECV_EARLY, conn, &try); return try; } #endif - if (conn->flags & (CO_FL_WAIT_XPRT | CO_FL_SSL_WAIT_HS)) + if (conn->flags & (CO_FL_WAIT_XPRT | CO_FL_SSL_WAIT_HS)) { /* a handshake was requested */ + TRACE_LEAVE(SSL_EV_CONN_RECV, conn); return 0; + } /* read the largest possible block. For this, we perform only one call * to recv() unless the buffer wraps and we exactly fill the first hunk, @@ -5858,6 +5863,7 @@ static size_t ssl_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu b_add(buf, ret); done += ret; count -= ret; + TRACE_DEVEL("Post SSL_read success", SSL_EV_CONN_RECV, conn, &ret); } else { ret = SSL_get_error(ctx->ssl, ret); @@ -5870,6 +5876,7 @@ static size_t ssl_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu if (global_ssl.async) SSL_set_mode(ctx->ssl, SSL_MODE_ASYNC); #endif + TRACE_DEVEL("SSL want write", SSL_EV_CONN_RECV, conn); break; } else if (ret == SSL_ERROR_WANT_READ) { @@ -5886,10 +5893,12 @@ static size_t ssl_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu #endif break; } + TRACE_DEVEL("SSL want read", SSL_EV_CONN_RECV, conn); break; - } else if (ret == SSL_ERROR_ZERO_RETURN) + } else if (ret == SSL_ERROR_ZERO_RETURN) { + TRACE_STATE("SSL read error (zero return)", SSL_EV_CONN_RECV, conn); goto read0; - else if (ret == SSL_ERROR_SSL) { + } else if (ret == SSL_ERROR_SSL) { struct ssl_sock_ctx *ctx = conn_get_ssl_sock_ctx(conn); if (ctx && !ctx->error_code) ctx->error_code = ERR_peek_error(); @@ -5898,13 +5907,17 @@ static size_t ssl_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu /* For SSL_ERROR_SYSCALL, make sure to clear the error * stack before shutting down the connection for * reading. */ - if (ret == SSL_ERROR_SYSCALL && (!errno || errno == EAGAIN || errno == EWOULDBLOCK)) + if (ret == SSL_ERROR_SYSCALL && (!errno || errno == EAGAIN || errno == EWOULDBLOCK)) { + TRACE_PROTO("SSL read error (syscall)", SSL_EV_CONN_RECV, conn); goto clear_ssl_error; + } /* otherwise it's a real error */ + TRACE_ERROR("rx fatal error", SSL_EV_CONN_RECV|SSL_EV_CONN_ERR, conn, &ret); goto out_error; } } leave: + TRACE_LEAVE(SSL_EV_CONN_RECV, conn); return done; clear_ssl_error: @@ -5917,6 +5930,7 @@ static size_t ssl_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu goto leave; out_error: + TRACE_ERROR("rx error", SSL_EV_CONN_RECV, conn); conn_report_term_evt(conn, tevt_loc_xprt, xprt_tevt_type_rcv_err); conn->flags |= CO_FL_ERROR; /* Clear openssl global errors stack */ @@ -5944,14 +5958,18 @@ static size_t ssl_sock_from_buf(struct connection *conn, void *xprt_ctx, const s ssize_t ret; size_t try, done; + TRACE_ENTER(SSL_EV_CONN_SEND, conn); + done = 0; if (!ctx) goto out_error; - if (conn->flags & (CO_FL_WAIT_XPRT | CO_FL_SSL_WAIT_HS | CO_FL_EARLY_SSL_HS)) + if (conn->flags & (CO_FL_WAIT_XPRT | CO_FL_SSL_WAIT_HS | CO_FL_EARLY_SSL_HS)) { /* a handshake was requested */ + TRACE_LEAVE(SSL_EV_CONN_SEND, conn); return 0; + } /* send the largest possible block. For this we perform only one call * to send() unless the buffer wraps and we exactly fill the first hunk, @@ -6017,7 +6035,7 @@ static size_t ssl_sock_from_buf(struct connection *conn, void *xprt_ctx, const s /* Initiate the handshake, now */ tasklet_wakeup(ctx->wait_event.tasklet); } - + TRACE_PROTO("Write early data", SSL_EV_CONN_SEND|SSL_EV_CONN_SEND_EARLY, conn, &ret); } } else @@ -6034,6 +6052,7 @@ static size_t ssl_sock_from_buf(struct connection *conn, void *xprt_ctx, const s ctx->xprt_st &= ~SSL_SOCK_SEND_UNLIMITED; count -= ret; done += ret; + TRACE_DEVEL("Post SSL_write success", SSL_EV_CONN_SEND, conn, &ret); } else { ret = SSL_get_error(ctx->ssl, ret); @@ -6050,7 +6069,7 @@ static size_t ssl_sock_from_buf(struct connection *conn, void *xprt_ctx, const s #endif break; } - + TRACE_DEVEL("SSL want write", SSL_EV_CONN_SEND, conn); break; } else if (ret == SSL_ERROR_WANT_READ) { @@ -6064,6 +6083,7 @@ static size_t ssl_sock_from_buf(struct connection *conn, void *xprt_ctx, const s if (global_ssl.async) SSL_set_mode(ctx->ssl, SSL_MODE_ASYNC); #endif + TRACE_DEVEL("SSL want read", SSL_EV_CONN_SEND, conn); break; } else if (ret == SSL_ERROR_SSL || ret == SSL_ERROR_SYSCALL) { @@ -6072,18 +6092,20 @@ static size_t ssl_sock_from_buf(struct connection *conn, void *xprt_ctx, const s if (ctx && !ctx->error_code) ctx->error_code = ERR_peek_error(); conn->err_code = CO_ER_SSL_FATAL; + TRACE_ERROR("tx fatal error", SSL_EV_CONN_SEND|SSL_EV_CONN_ERR, conn, &ctx->error_code); } goto out_error; } } leave: + TRACE_LEAVE(SSL_EV_CONN_SEND, conn); return done; out_error: + TRACE_ERROR("tx error", SSL_EV_CONN_SEND, conn); /* Clear openssl global errors stack */ ssl_sock_dump_errors(conn, NULL); ERR_clear_error(); - conn_report_term_evt(conn, tevt_loc_xprt, xprt_tevt_type_snd_err); conn->flags |= CO_FL_ERROR; goto leave; diff --git a/src/ssl_trace.c b/src/ssl_trace.c index f6273511e..49a4cb173 100644 --- a/src/ssl_trace.c +++ b/src/ssl_trace.c @@ -30,6 +30,10 @@ static const struct trace_event ssl_trace_events[] = { { .mask = SSL_EV_CONN_CLOSE, .name = "sslc_close", .desc = "close SSL connection" }, { .mask = SSL_EV_CONN_END, .name = "sslc_end", .desc = "SSL connection end" }, { .mask = SSL_EV_CONN_ERR, .name = "sslc_err", .desc = "SSL error"}, + { .mask = SSL_EV_CONN_SEND, .name = "sslc_send", .desc = "Tx on SSL connection" }, + { .mask = SSL_EV_CONN_SEND_EARLY, .name = "sslc_send_early", .desc = "Tx on SSL connection (early data)" }, + { .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)" }, { } }; @@ -93,5 +97,20 @@ static void ssl_trace(enum trace_level level, uint64_t mask, const struct trace_ if (src->verbosity <= SSL_VERB_SIMPLE && !(mask & SSL_EV_CONN_ERR)) return; + + if (mask & SSL_EV_CONN_RECV || mask & SSL_EV_CONN_SEND) { + + if (mask & SSL_EV_CONN_ERR) { + const unsigned int *ssl_err_code = a2; + chunk_appendf(&trace_buf, " : ssl_err_code=%d ssl_err_str=\"%s\"", *ssl_err_code, + ERR_error_string(*ssl_err_code, NULL)); + } else if (src->verbosity > SSL_VERB_SIMPLE) { + const ssize_t *size = a2; + + if (size) + chunk_appendf(&trace_buf, " : size=%ld", *size); + } + } + }