MINOR: tevt: Add the termination events log's fundations

Termination events logs will be used to report the events that led to close
a connection. Unlike flags, that reflect a state, the idea here is to store
a log to preserve the order of the events. Most of time, when debugging an
issue, the order of the events is crucial to be able to understand the root
cause of the issue. The traces are trully heplful to do so. But it is not
always possible to active them because it is pretty verbose. On heavily
loaded platforms, it is not acceptable. We hope that the termination events
logs will help us in that situations.

One termination events log will be be store at each layer (connection, mux
connection, mux stream...) as a 32-bits integer. Each event will be store on
8 bits, 4 bits for the location and 4 bits for the type. So the first four
events will be stored only for each layer. It should be enough why a
connection is closed.

In this patch, the enums defining the termination event locations and types
are added. The macro to report a new event is also added and a function to
convert a termination events log to a string that could be display in log
messages for instance.

diff --git a/include/haproxy/connection-t.h b/include/haproxy/connection-t.h
index 42f529e151ab4b31fb0ecbf0d041d39be038923d..f113f0d1368650cfc660446d06730bd6a2cb437e 100644 (file)
--- a/include/haproxy/connection-t.h
+++ b/include/haproxy/connection-t.h
@@ -538,6 +538,44 @@ struct conn_tlv_list {
        char value[0];
 } __attribute__((packed));
 
+
+/* Termination events logs:
+ * Each event is stored on 8 bits: 4 bits bor the event location and
+ * 4 bits for the event type.
+ */
+
+/* Locations for termination event logs (4-bits). But only 7 locations are
+ * supported because 1 bit is reserved to distinguish frontend to backend
+ * events: the msb is set to 1 for backend events.
+ */
+enum term_event_loc {
+       tevt_loc_fd    = 1,
+       tevt_loc_hs    = 2,
+       tevt_loc_xprt  = 3,
+       tevt_loc_muxc  = 4,
+       tevt_loc_se    = 5,
+       tevt_loc_strm  = 6,
+};
+
+/* Types for termination event logs (4-bits) */
+enum term_event_type {
+       /* Events emitted by haproxy */
+       tevt_type_shutw            =  1,
+       tevt_type_intercepted      =  2,
+       tevt_type_tout             =  3,
+
+       /* 4..9 unsued */
+
+       /* Events received by haproxy */
+       tevt_type_shutr            =  10,
+       tevt_type_rcv_err          =  11,
+       tevt_type_truncated_shutr  =  12,
+       tevt_type_truncated_rcv_err=  13,
+       tevt_type_snd_err          =  14,
+
+       /* 15 unsued */
+};
+
 /* This structure describes a connection with its methods and data.
  * A connection may be performed to proxy or server via a local or remote
  * socket, and can also be made to an internal applet. It can support
@@ -588,6 +626,8 @@ struct connection {
                enum obj_type *target; /* Listener for active reverse, server for passive. */
                struct buffer name;    /* Only used for passive reverse. Used as SNI when connection added to server idle pool. */
        } reverse;
+
+       uint32_t term_evts_log;        /* Termination events log: first 4 events reported from fd, handshake or xprt */
        uint32_t mark;                 /* set network mark, if CO_FL_OPT_MARK is set */
        uint8_t tos;                   /* set ip tos, if CO_FL_OPT_TOS is set */
 };

diff --git a/include/haproxy/connection.h b/include/haproxy/connection.h
index e5da2509da8ec1d18f6ce74640192bd121098e65..a5f032785732340bc641b09aa8dd53041b1ddfe9 100644 (file)
--- a/include/haproxy/connection.h
+++ b/include/haproxy/connection.h
@@ -107,6 +107,8 @@ const char *conn_err_code_str(struct connection *c);
 int xprt_add_hs(struct connection *conn);
 void register_mux_proto(struct mux_proto_list *list);
 
+static inline void conn_report_term_evt(struct connection *conn, enum term_event_loc loc, enum term_event_type type);
+
 extern struct idle_conns idle_conns[MAX_THREADS];
 
 /* set conn->err_code to any CO_ER_* code if it was not set yet, otherwise
@@ -254,6 +256,7 @@ static inline void conn_sock_shutw(struct connection *c, int clean)
                if (!(c->flags & CO_FL_SOCK_RD_SH) && clean)
                        shutdown(c->handle.fd, SHUT_WR);
        }
+       conn_report_term_evt(c, tevt_loc_fd, tevt_type_shutw);
 }
 
 static inline void conn_xprt_shutw(struct connection *c)
@@ -740,6 +743,60 @@ static inline int conn_pr_mode_to_proto_mode(int proxy_mode)
        return mode;
 }
 
+/* Must be used to report add an event in <_evt> termination events log.
+ * For now, it only handles 32-bits integers.
+ */
+#define tevt_report_event(_evts, loc, type) ({ \
+                                               \
+       if (!((_evts) & 0xff000000)) {          \
+               (_evts) <<= 8;                  \
+               (_evts) |= (loc) << 4;          \
+               (_evts) |= (type);              \
+       }                                       \
+       (_evts);                                \
+})
+
+/* Function to convert a termination events log to a string */
+static THREAD_LOCAL char tevt_evts_str[9];
+static inline const char *tevt_evts2str(uint32_t evts)
+{
+       uint32_t evt_msk = 0xff000000;
+       unsigned int evt_bits = 24;
+       int idx;
+
+       for (idx = 0; evt_msk; evt_msk >>= 8, evt_bits -= 8) {
+               unsigned char evt = (evts & evt_msk) >> evt_bits;
+               unsigned int is_back;
+
+               if (!evt)
+                       continue;
+
+               /* Backend location are displayed in captial letter */
+               is_back = !!((evt >> 4) & 0x8);
+               switch ((enum term_event_loc)((evt >> 4) & ~0x8)) {
+                       case tevt_loc_fd:   tevt_evts_str[idx++] = (is_back ? 'F' : 'f'); break;
+                       case tevt_loc_hs:   tevt_evts_str[idx++] = (is_back ? 'H' : 'h'); break;
+                       case tevt_loc_xprt: tevt_evts_str[idx++] = (is_back ? 'X' : 'x'); break;
+                       case tevt_loc_muxc: tevt_evts_str[idx++] = (is_back ? 'M' : 'm'); break;
+                       case tevt_loc_se:   tevt_evts_str[idx++] = (is_back ? 'E' : 'e'); break;
+                       case tevt_loc_strm: tevt_evts_str[idx++] = (is_back ? 'S' : 's'); break;
+                       default:            tevt_evts_str[idx++] = '-';
+               }
+
+               tevt_evts_str[idx++] = hextab[evt & 0xf];
+       }
+       tevt_evts_str[idx] = '\0';
+       return tevt_evts_str;
+}
+
+/* Report a connection event. <loc> may be "tevt_loc_fd", "tevt_loc_hs" or "tevt_loc_xprt" */
+static inline void conn_report_term_evt(struct connection *conn, enum term_event_loc loc, enum term_event_type type)
+{
+       if (conn_is_back(conn))
+               loc |= 0x08;
+       conn->term_evts_log = tevt_report_event(conn->term_evts_log, loc, type);
+}
+
 #endif /* _HAPROXY_CONNECTION_H */
 
 /*

diff --git a/src/connection.c b/src/connection.c
index ec57793ace950afcd7d6811bfe3fd9ac1b597793..759f9687779a6995340d0cab1cd9f95908ef8d93 100644 (file)
--- a/src/connection.c
+++ b/src/connection.c
@@ -455,6 +455,7 @@ void conn_init(struct connection *conn, void *target)
        conn->send_proxy_ofs = 0;
        conn->handle.fd = DEAD_FD_MAGIC;
        conn->err_code = CO_ER_NONE;
+       conn->term_evts_log = 0;
        conn->target = target;
        conn->destroy_cb = NULL;
        conn->proxy_netns = NULL;
@@ -1372,11 +1373,14 @@ int conn_recv_proxy(struct connection *conn, int flag)
        goto fail;
 
  recv_abort:
+       conn_report_term_evt(conn, tevt_loc_hs, tevt_type_truncated_shutr);
        conn->err_code = CO_ER_PRX_ABORT;
        conn->flags |= CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH;
        goto fail;
 
  fail:
+       if (!(conn->flags & CO_FL_SOCK_RD_SH))
+               conn_report_term_evt(conn, tevt_loc_hs, tevt_type_truncated_rcv_err);
        conn->flags |= CO_FL_ERROR;
        return 0;
 }
@@ -1470,6 +1474,7 @@ int conn_send_proxy(struct connection *conn, unsigned int flag)
 
  out_error:
        /* Write error on the file descriptor */
+       conn_report_term_evt(conn, tevt_loc_hs, tevt_type_snd_err);
        conn->flags |= CO_FL_ERROR;
        return 0;
 
@@ -1672,11 +1677,14 @@ int conn_recv_netscaler_cip(struct connection *conn, int flag)
        goto fail;
 
  recv_abort:
+       conn_report_term_evt(conn, tevt_loc_hs, tevt_type_truncated_shutr);
        conn->err_code = CO_ER_CIP_ABORT;
        conn->flags |= CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH;
        goto fail;
 
  fail:
+       if (!(conn->flags & CO_FL_SOCK_RD_SH))
+               conn_report_term_evt(conn, tevt_loc_hs, tevt_type_truncated_rcv_err);
        conn->flags |= CO_FL_ERROR;
        return 0;
 }
@@ -1750,6 +1758,7 @@ int conn_send_socks4_proxy_request(struct connection *conn)
 
  out_error:
        /* Write error on the file descriptor */
+       conn_report_term_evt(conn, tevt_loc_hs, tevt_type_snd_err);
        conn->flags |= CO_FL_ERROR;
        if (conn->err_code == CO_ER_NONE) {
                conn->err_code = CO_ER_SOCKS4_SEND;
@@ -1870,6 +1879,7 @@ int conn_recv_socks4_proxy_response(struct connection *conn)
        return 0;
 
  recv_abort:
+       conn_report_term_evt(conn, tevt_loc_hs, tevt_type_truncated_shutr);
        if (conn->err_code == CO_ER_NONE) {
                conn->err_code = CO_ER_SOCKS4_ABORT;
        }
@@ -1877,6 +1887,8 @@ int conn_recv_socks4_proxy_response(struct connection *conn)
        goto fail;
 
  fail:
+       if (!(conn->flags & CO_FL_SOCK_RD_SH))
+               conn_report_term_evt(conn, tevt_loc_hs, tevt_type_truncated_rcv_err);
        conn->flags |= CO_FL_ERROR;
        return 0;
 }

diff --git a/src/raw_sock.c b/src/raw_sock.c
index 9da2647c473488fda8bf54bea688122f286f1250..401e4cee9c11de6555cbd4def939e794e6262ae9 100644 (file)
--- a/src/raw_sock.c
+++ b/src/raw_sock.c
@@ -77,6 +77,7 @@ int raw_sock_to_pipe(struct connection *conn, void *xprt_ctx, struct pipe *pipe,
 
                /* report error on POLL_ERR before connection establishment */
                if ((fdtab[conn->handle.fd].state & FD_POLL_ERR) && (conn->flags & CO_FL_WAIT_L4_CONN)) {
+                       conn_report_term_evt(conn, tevt_loc_fd, tevt_type_rcv_err);
                        conn->flags |= CO_FL_ERROR | CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH;
                        conn_set_errcode(conn, CO_ER_POLLERR);
                        errno = 0; /* let the caller do a getsockopt() if it wants it */
@@ -127,6 +128,7 @@ int raw_sock_to_pipe(struct connection *conn, void *xprt_ctx, struct pipe *pipe,
                                continue;
                        }
                        /* here we have another error */
+                       conn_report_term_evt(conn, tevt_loc_fd, tevt_type_rcv_err);
                        conn->flags |= CO_FL_ERROR;
                        conn_set_errno(conn, errno);
                        break;
@@ -155,6 +157,7 @@ int raw_sock_to_pipe(struct connection *conn, void *xprt_ctx, struct pipe *pipe,
        return retval;
 
  out_read0:
+       conn_report_term_evt(conn, tevt_loc_fd, tevt_type_shutr);
        conn_sock_read0(conn);
        conn->flags &= ~CO_FL_WAIT_L4_CONN;
        goto leave;
@@ -176,6 +179,7 @@ int raw_sock_from_pipe(struct connection *conn, void *xprt_ctx, struct pipe *pip
 
        if (conn->flags & CO_FL_SOCK_WR_SH) {
                /* it's already closed */
+               conn_report_term_evt(conn, tevt_loc_fd, tevt_type_snd_err);
                conn->flags |= CO_FL_ERROR | CO_FL_SOCK_RD_SH;
                errno = EPIPE;
                conn_set_errno(conn, errno);
@@ -199,6 +203,7 @@ int raw_sock_from_pipe(struct connection *conn, void *xprt_ctx, struct pipe *pip
                                continue;
 
                        /* here we have another error */
+                       conn_report_term_evt(conn, tevt_loc_fd, tevt_type_snd_err);
                        conn->flags |= CO_FL_ERROR;
                        conn_set_errno(conn, errno);
                        break;
@@ -251,6 +256,7 @@ static size_t raw_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu
 
                /* report error on POLL_ERR before connection establishment */
                if ((fdtab[conn->handle.fd].state & FD_POLL_ERR) && (conn->flags & CO_FL_WAIT_L4_CONN)) {
+                       conn_report_term_evt(conn, tevt_loc_fd, tevt_type_rcv_err);
                        conn->flags |= CO_FL_ERROR | CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH;
                        conn_set_errcode(conn, CO_ER_POLLERR);
                        goto leave;
@@ -310,6 +316,7 @@ static size_t raw_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu
                        break;
                }
                else if (errno != EINTR) {
+                       conn_report_term_evt(conn, tevt_loc_fd, tevt_type_rcv_err);
                        conn->flags |= CO_FL_ERROR | CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH;
                        conn_set_errno(conn, errno);
                        break;
@@ -323,6 +330,7 @@ static size_t raw_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu
        return done;
 
  read0:
+       conn_report_term_evt(conn, tevt_loc_fd, tevt_type_shutr);
        conn_sock_read0(conn);
        conn->flags &= ~CO_FL_WAIT_L4_CONN;
 
@@ -334,6 +342,7 @@ static size_t raw_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu
         * an error without checking.
         */
        if (unlikely(!done && fdtab[conn->handle.fd].state & FD_POLL_ERR)) {
+               conn_report_term_evt(conn, tevt_loc_fd, tevt_type_rcv_err);
                conn->flags |= CO_FL_ERROR | CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH;
                conn_set_errcode(conn, CO_ER_POLLERR);
        }
@@ -368,6 +377,7 @@ static size_t raw_sock_from_buf(struct connection *conn, void *xprt_ctx, const s
 
        if (unlikely(fdtab[conn->handle.fd].state & FD_POLL_ERR)) {
                /* an error was reported on the FD, we can't send anymore */
+               conn_report_term_evt(conn, tevt_loc_fd, tevt_type_snd_err);
                conn->flags |= CO_FL_ERROR | CO_FL_SOCK_WR_SH | CO_FL_SOCK_RD_SH;
                conn_set_errcode(conn, CO_ER_POLLERR);
                errno = EPIPE;
@@ -376,6 +386,7 @@ static size_t raw_sock_from_buf(struct connection *conn, void *xprt_ctx, const s
 
        if (conn->flags & CO_FL_SOCK_WR_SH) {
                /* it's already closed */
+               conn_report_term_evt(conn, tevt_loc_fd, tevt_type_snd_err);
                conn->flags |= CO_FL_ERROR | CO_FL_SOCK_RD_SH;
                errno = EPIPE;
                conn_set_errno(conn, errno);
@@ -416,6 +427,7 @@ static size_t raw_sock_from_buf(struct connection *conn, void *xprt_ctx, const s
                        break;
                }
                else if (errno != EINTR) {
+                       conn_report_term_evt(conn, tevt_loc_fd, tevt_type_snd_err);
                        conn->flags |= CO_FL_ERROR | CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH;
                        conn_set_errno(conn, errno);
                        break;

diff --git a/src/sock.c b/src/sock.c
index 41f0d5acf3eb6ccdb1621b91e6411313b8fa3c51..6750c1ac9ffdda5a05c4b01279a747eaa7f99898 100644 (file)
--- a/src/sock.c
+++ b/src/sock.c
@@ -1007,6 +1007,7 @@ int sock_conn_check(struct connection *conn)
        /* Write error on the file descriptor. Report it to the connection
         * and disable polling on this FD.
         */
+       conn_report_term_evt(conn, tevt_loc_fd, tevt_type_truncated_rcv_err);
        conn->flags |= CO_FL_ERROR | CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH;
        HA_ATOMIC_AND(&fdtab[fd].state, ~FD_LINGER_RISK);
        fd_stop_both(fd);

diff --git a/src/ssl_sock.c b/src/ssl_sock.c
index 8e5063e5fd00cfd3b542dccf245d7b10306b3615..a76232fae31866c2828381f3144f8a74023f3395 100644 (file)
--- a/src/ssl_sock.c
+++ b/src/ssl_sock.c
@@ -5531,6 +5531,10 @@ reneg_ok:
                HA_ATOMIC_INC(&counters_px->failed_handshake);
        }
 
+       /* Report an HS error only on SSL error */
+       if (!(conn->flags & (CO_FL_ERROR | CO_FL_SOCK_RD_SH | CO_FL_SOCK_WR_SH)))
+               conn_report_term_evt(conn, tevt_loc_hs, tevt_type_truncated_rcv_err);
+
        /* Fail on all other handshake errors */
        conn->flags |= CO_FL_ERROR;
        if (!conn->err_code)
@@ -5882,10 +5886,12 @@ static size_t ssl_sock_to_buf(struct connection *conn, void *xprt_ctx, struct bu
        ssl_sock_dump_errors(conn, NULL);
        ERR_clear_error();
  read0:
+       conn_report_term_evt(conn, tevt_loc_xprt, tevt_type_shutr);
        conn_sock_read0(conn);
        goto leave;
 
  out_error:
+       conn_report_term_evt(conn, tevt_loc_xprt, tevt_type_rcv_err);
        conn->flags |= CO_FL_ERROR;
        /* Clear openssl global errors stack */
        ssl_sock_dump_errors(conn, NULL);
@@ -6052,6 +6058,7 @@ static size_t ssl_sock_from_buf(struct connection *conn, void *xprt_ctx, const s
        ssl_sock_dump_errors(conn, NULL);
        ERR_clear_error();
 
+       conn_report_term_evt(conn, tevt_loc_xprt, tevt_type_snd_err);
        conn->flags |= CO_FL_ERROR;
        goto leave;
 }
@@ -6142,6 +6149,7 @@ static void ssl_sock_shutw(struct connection *conn, void *xprt_ctx, int clean)
 
        if (conn->flags & (CO_FL_WAIT_XPRT | CO_FL_SSL_WAIT_HS))
                return;
+       conn_report_term_evt(conn, tevt_loc_xprt, tevt_type_shutw);
        if (!clean)
                /* don't sent notify on SSL_shutdown */
                SSL_set_quiet_shutdown(ctx->ssl, 1);