mirrors/haproxy
1
0
Fork 0
mirror of https://git.haproxy.org/git/haproxy.git/ synced 2025-08-06 15:17:01 +02:00
Code Issues Projects Releases Wiki Activity

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

Browse Source 
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.
This commit is contained in:
Christopher Faulet 2024-12-23 10:43:54 +01:00
parent 4ccca7efcf
commit e944944990
6 changed files with 130 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

40
include/haproxy/connection-t.h
View File

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

57
include/haproxy/connection.h
View File

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

12
src/connection.c
View File

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

12
src/raw_sock.c
View File

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

1
src/sock.c
View File

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

8
src/ssl_sock.c
View File

@ -5531,6 +5531,10 @@ static int ssl_sock_handshake(struct connection *conn, unsigned int flag)
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);