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.

diff --git a/include/haproxy/ssl_trace-t.h b/include/haproxy/ssl_trace-t.h
index 513822f763ddb0099d6858a55fa2e2f58028336d..4575fda82aa1f38a9b979d076d967d31d3b58cdb 100644 (file)
--- 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 20ffe26db6d82a500978371c54723a72af859988..326a5d7395a8fa974b599e0676ee45d6c9c1f649 100644 (file)
--- 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 f6273511ea384851d3033b833f55fe086be9fa4c..49a4cb173e197e4bbafaf11274e4e5d3a0ad408b 100644 (file)
--- 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);
+               }
+       }
+
 }