From 9bb8d6dcd1fd9cfcd85c756f73d04f2acc5e7703 Mon Sep 17 00:00:00 2001 From: Remi Tricot-Le Breton Date: Fri, 18 Apr 2025 17:26:50 +0200 Subject: [PATCH] MINOR: ssl: Add traces to ssl init/close functions Add a dedicated trace for some unlikely allocation failures and async errors. Those traces will ostly be used to identify the start and end of a given SSL connection. --- Makefile | 7 +-- include/haproxy/ssl_trace-t.h | 28 ++++++++++ src/ssl_sock.c | 20 ++++++++ src/ssl_trace.c | 97 +++++++++++++++++++++++++++++++++++ 4 files changed, 149 insertions(+), 3 deletions(-) create mode 100644 include/haproxy/ssl_trace-t.h create mode 100644 src/ssl_trace.c diff --git a/Makefile b/Makefile index 311d01098..d1893e54d 100644 --- a/Makefile +++ b/Makefile @@ -630,9 +630,10 @@ ifneq ($(USE_OPENSSL:0=),) SSL_LDFLAGS := $(if $(SSL_LIB),-L$(SSL_LIB)) -lssl -lcrypto endif USE_SSL := $(if $(USE_SSL:0=),$(USE_SSL:0=),implicit) - OPTIONS_OBJS += src/ssl_sock.o src/ssl_ckch.o src/ssl_ocsp.o src/ssl_crtlist.o \ - src/ssl_sample.o src/cfgparse-ssl.o src/ssl_gencert.o \ - src/ssl_utils.o src/jwt.o src/ssl_clienthello.o src/jws.o src/acme.o + OPTIONS_OBJS += src/ssl_sock.o src/ssl_ckch.o src/ssl_ocsp.o src/ssl_crtlist.o \ + src/ssl_sample.o src/cfgparse-ssl.o src/ssl_gencert.o \ + src/ssl_utils.o src/jwt.o src/ssl_clienthello.o src/jws.o src/acme.o \ + src/ssl_trace.o endif ifneq ($(USE_ENGINE:0=),) diff --git a/include/haproxy/ssl_trace-t.h b/include/haproxy/ssl_trace-t.h new file mode 100644 index 000000000..513822f76 --- /dev/null +++ b/include/haproxy/ssl_trace-t.h @@ -0,0 +1,28 @@ +/* + * include/haproxy/ssl_trace-t.h + * Definitions for SSL traces internal types, constants and flags. + * + * Copyright (C) 2025 + * + * This program is free software; you can redistribute it and/or + * modify it under the terms of the GNU General Public License + * as published by the Free Software Foundation; either version + * 2 of the License, or (at your option) any later version. + * + */ + +#ifndef _HAPROXY_SSL_TRACE_T_H +#define _HAPROXY_SSL_TRACE_T_H + +#include + +extern struct trace_source trace_ssl; + +#define SSL_EV_CONN_NEW (1ULL << 0) +#define SSL_EV_CONN_CLOSE (1ULL << 1) +#define SSL_EV_CONN_END (1ULL << 2) +#define SSL_EV_CONN_ERR (1ULL << 3) + +#define TRACE_SOURCE &trace_ssl + +#endif /* _HAPROXY_SSL_TRACE_T_H */ diff --git a/src/ssl_sock.c b/src/ssl_sock.c index 8d5122c3c..20ffe26db 100644 --- a/src/ssl_sock.c +++ b/src/ssl_sock.c @@ -86,6 +86,8 @@ #include #include #include +#include +#include /* ***** READ THIS before adding code here! ***** @@ -5024,6 +5026,8 @@ static int ssl_sock_init(struct connection *conn, void **xprt_ctx) struct ssl_sock_ctx *ctx; int next_sslconn = 0; + TRACE_ENTER(SSL_EV_CONN_NEW, conn); + /* already initialized */ if (*xprt_ctx) return 0; @@ -5031,12 +5035,14 @@ static int ssl_sock_init(struct connection *conn, void **xprt_ctx) ctx = pool_alloc(ssl_sock_ctx_pool); if (!ctx) { conn->err_code = CO_ER_SSL_NO_MEM; + TRACE_ERROR("ssl_sock_ctx allocation failure", SSL_EV_CONN_NEW|SSL_EV_CONN_ERR|SSL_EV_CONN_END, conn); return -1; } ctx->wait_event.tasklet = tasklet_new(); if (!ctx->wait_event.tasklet) { conn->err_code = CO_ER_SSL_NO_MEM; pool_free(ssl_sock_ctx_pool, ctx); + TRACE_ERROR("tasklet allocation failure", SSL_EV_CONN_NEW|SSL_EV_CONN_ERR|SSL_EV_CONN_END, conn); return -1; } ctx->wait_event.tasklet->process = ssl_sock_io_cb; @@ -5054,6 +5060,7 @@ static int ssl_sock_init(struct connection *conn, void **xprt_ctx) next_sslconn = increment_sslconn(); if (!next_sslconn) { conn->err_code = CO_ER_SSL_TOO_MANY; + TRACE_ERROR("Too many SSL connections", SSL_EV_CONN_NEW|SSL_EV_CONN_ERR|SSL_EV_CONN_END, conn); goto err; } @@ -5143,6 +5150,8 @@ static int ssl_sock_init(struct connection *conn, void **xprt_ctx) _HA_ATOMIC_INC(&global.totalsslconns); *xprt_ctx = ctx; + + TRACE_LEAVE(SSL_EV_CONN_NEW, conn); return 0; } else if (objt_listener(conn->target)) { @@ -5175,6 +5184,8 @@ static int ssl_sock_init(struct connection *conn, void **xprt_ctx) _HA_ATOMIC_INC(&global.totalsslconns); *xprt_ctx = ctx; + + TRACE_LEAVE(SSL_EV_CONN_NEW, conn); return 0; } /* don't know how to handle such a target */ @@ -5185,6 +5196,7 @@ err: if (ctx && ctx->wait_event.tasklet) tasklet_free(ctx->wait_event.tasklet); pool_free(ssl_sock_ctx_pool, ctx); + TRACE_DEVEL("leaving in error", SSL_EV_CONN_NEW|SSL_EV_CONN_ERR|SSL_EV_CONN_END); return -1; } @@ -6081,6 +6093,7 @@ void ssl_sock_close(struct connection *conn, void *xprt_ctx) { struct ssl_sock_ctx *ctx = xprt_ctx; + TRACE_ENTER(SSL_EV_CONN_CLOSE, conn); if (ctx) { if (ctx->wait_event.events != 0) @@ -6103,6 +6116,7 @@ void ssl_sock_close(struct connection *conn, void *xprt_ctx) { SSL_get_all_async_fds(ctx->ssl, NULL, &num_all_fds); if (num_all_fds > 32) { send_log(NULL, LOG_EMERG, "haproxy: openssl returns too many async fds. It seems a bug. Process may crash\n"); + TRACE_ERROR("Too many async fds", SSL_EV_CONN_CLOSE|SSL_EV_CONN_ERR, conn); return; } @@ -6128,6 +6142,7 @@ void ssl_sock_close(struct connection *conn, void *xprt_ctx) { tasklet_free(ctx->wait_event.tasklet); pool_free(ssl_sock_ctx_pool, ctx); _HA_ATOMIC_INC(&jobs); + TRACE_DEVEL("async end", SSL_EV_CONN_CLOSE, conn); return; } /* Else we can remove the fds from the fdtab @@ -6152,6 +6167,7 @@ void ssl_sock_close(struct connection *conn, void *xprt_ctx) { pool_free(ssl_sock_ctx_pool, ctx); _HA_ATOMIC_DEC(&global.sslconns); } + TRACE_LEAVE(SSL_EV_CONN_CLOSE, conn); } /* This function tries to perform a clean shutdown on an SSL connection, and in @@ -6161,6 +6177,8 @@ static void ssl_sock_shutw(struct connection *conn, void *xprt_ctx, int clean) { struct ssl_sock_ctx *ctx = xprt_ctx; + TRACE_ENTER(SSL_EV_CONN_END, conn); + if (conn->flags & (CO_FL_WAIT_XPRT | CO_FL_SSL_WAIT_HS)) return; conn_report_term_evt(conn, tevt_loc_xprt, xprt_tevt_type_shutw); @@ -6173,6 +6191,8 @@ static void ssl_sock_shutw(struct connection *conn, void *xprt_ctx, int clean) ssl_sock_dump_errors(conn, NULL); ERR_clear_error(); } + + TRACE_LEAVE(SSL_EV_CONN_END, conn); } diff --git a/src/ssl_trace.c b/src/ssl_trace.c new file mode 100644 index 000000000..f6273511e --- /dev/null +++ b/src/ssl_trace.c @@ -0,0 +1,97 @@ +/* + * SSL traces + * + * Copyright 2000-2025 + * + * This program is free software; you can redistribute it and/or + * modify it under the terms of the GNU General Public License + * as published by the Free Software Foundation; either version + * 2 of the License, or (at your option) any later version. + * + */ + +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +static void ssl_trace(enum trace_level level, uint64_t mask, const struct trace_source *src, + const struct ist where, const struct ist func, + const void *a1, const void *a2, const void *a3, const void *a4); + +static const struct trace_event ssl_trace_events[] = { + { .mask = SSL_EV_CONN_NEW, .name = "sslc_new", .desc = "new SSL connection" }, + { .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"}, + { } +}; + + +static const struct name_desc ssl_trace_lockon_args[4] = { + /* arg1 */ { /* already used by the connection */ }, + /* arg2 */ { }, + /* arg3 */ { }, + /* arg4 */ { } +}; + +static const struct name_desc ssl_trace_decoding[] = { +#define SSL_VERB_CLEAN 1 + { .name="clean", .desc="only user-friendly stuff, generally suitable for level \"user\"" }, +#define SSL_VERB_MINIMAL 2 + { .name="minimal", .desc="report only conn, no real decoding" }, +#define SSL_VERB_SIMPLE 3 + { .name="simple", .desc="add error messages" }, +#define SSL_VERB_ADVANCED 4 + { .name="advanced", .desc="add handshake-related details" }, +#define SSL_VERB_COMPLETE 5 + { .name="complete", .desc="add full data dump when available" }, + { /* end */ } +}; + + +struct trace_source trace_ssl = { + .name = IST("ssl"), + .desc = "SSL xprt", + .arg_def = TRC_ARG1_CONN, /* TRACE()'s first argument is always a conn */ + .default_cb = ssl_trace, + .known_events = ssl_trace_events, + .lockon_args = ssl_trace_lockon_args, + .decoding = ssl_trace_decoding, + .report_events = ~0, /* report everything by default */ +}; + +INITCALL1(STG_REGISTER, trace_register_source, &trace_ssl); + +/* Trace callback for SSL. + * These traces always expect that arg1, if non-null, is of type connection. + */ +static void ssl_trace(enum trace_level level, uint64_t mask, const struct trace_source *src, + const struct ist where, const struct ist func, + const void *a1, const void *a2, const void *a3, const void *a4) +{ + struct connection *conn = (struct connection*)a1; + + if (src->verbosity <= SSL_VERB_CLEAN) + return; + + if (conn) { + struct proxy *px = conn_get_proxy(conn); + chunk_appendf(&trace_buf, " : [%c(%s)] conn=%p(0x%08x)", conn_is_back(conn) ? 'B' : 'F', + px ? px->id : "", conn, conn->flags); + } + + if (src->verbosity <= SSL_VERB_MINIMAL) + return; + + if (src->verbosity <= SSL_VERB_SIMPLE && !(mask & SSL_EV_CONN_ERR)) + return; + +} +