From f3415f3b3a9c797d98d32d34c331e785147dc658 Mon Sep 17 00:00:00 2001 From: Asad Sajjad Ahmed Date: Wed, 21 May 2025 15:27:27 +0200 Subject: [PATCH 1/7] sess_close: restrict the range of stream_close_t For backends not all stream_close_t values make sense. Therefore, do not allow these to be specified as `doclose` attribute for failed backend transaction. No change is needed for existing errors. We should ideally split them up, but this is not possible as some functions are used by both sessions and fetches. One example of such function: - stream_close_t http_DoConnection(struct http *hp, stream_close_t sc_close); This patch is best viewed with --ignore-all-space Signed-off-by: Asad Sajjad Ahmed --- bin/varnishd/cache/cache.h | 2 +- bin/varnishd/cache/cache_session.c | 8 ++++---- include/tbl/sess_close.h | 21 ++++++++++++++------- 3 files changed, 19 insertions(+), 12 deletions(-) diff --git a/bin/varnishd/cache/cache.h b/bin/varnishd/cache/cache.h index fc5b9cf933d..7224bca2bde 100644 --- a/bin/varnishd/cache/cache.h +++ b/bin/varnishd/cache/cache.h @@ -95,7 +95,7 @@ struct stream_close { const char *desc; }; extern const struct stream_close SC_NULL[1]; -#define SESS_CLOSE(nm, stat, err, desc) \ +#define SESS_CLOSE_C(nm, stat, err, desc) \ extern const struct stream_close SC_##nm[1]; #include "tbl/sess_close.h" diff --git a/bin/varnishd/cache/cache_session.c b/bin/varnishd/cache/cache_session.c index c031cb665fb..68954357a9b 100644 --- a/bin/varnishd/cache/cache_session.c +++ b/bin/varnishd/cache/cache_session.c @@ -61,7 +61,7 @@ static const struct { enum sess_close { SCE_NULL = 0, -#define SESS_CLOSE(nm, stat, err, desc) SCE_##nm, +#define SESS_CLOSE_C(nm, stat, err, desc) SCE_##nm, #include "tbl/sess_close.h" SCE_MAX, }; @@ -74,7 +74,7 @@ const struct stream_close SC_NULL[1] = {{ .desc = "Not Closing", }}; -#define SESS_CLOSE(nm, stat, err, text) \ +#define SESS_CLOSE_C(nm, stat, err, text) \ const struct stream_close SC_##nm[1] = {{ \ .magic = STREAM_CLOSE_MAGIC, \ .idx = SCE_##nm, \ @@ -86,7 +86,7 @@ const struct stream_close SC_NULL[1] = {{ static const stream_close_t sc_lookup[SCE_MAX] = { [SCE_NULL] = SC_NULL, -#define SESS_CLOSE(nm, stat, err, desc) \ +#define SESS_CLOSE_C(nm, stat, err, desc) \ [SCE_##nm] = SC_##nm, #include "tbl/sess_close.h" }; @@ -556,7 +556,7 @@ ses_close_acct(stream_close_t reason) CHECK_OBJ_NOTNULL(reason, STREAM_CLOSE_MAGIC); switch (reason->idx) { -#define SESS_CLOSE(reason, stat, err, desc) \ +#define SESS_CLOSE_C(reason, stat, err, desc) \ case SCE_ ## reason: \ VSC_C_main->sc_ ## stat++; \ break; diff --git a/include/tbl/sess_close.h b/include/tbl/sess_close.h index 009b5b20b03..4147d317bff 100644 --- a/include/tbl/sess_close.h +++ b/include/tbl/sess_close.h @@ -31,6 +31,10 @@ /*lint -save -e525 -e539 */ +#ifdef SESS_CLOSE_C + #define SESS_CLOSE(nm, stat, err, desc) SESS_CLOSE_C(nm, stat, err, desc) +#endif + // stream_close_t sc_* stat is_err Description SESS_CLOSE(REM_CLOSE, rem_close, 0, "Peer Closed") SESS_CLOSE(REQ_CLOSE, req_close, 0, "Peer requested close") @@ -40,18 +44,21 @@ SESS_CLOSE(RX_BODY, rx_body, 1, "Failure receiving body") SESS_CLOSE(RX_JUNK, rx_junk, 1, "Received junk data") SESS_CLOSE(RX_OVERFLOW, rx_overflow, 1, "Received buffer overflow") SESS_CLOSE(RX_TIMEOUT, rx_timeout, 1, "Receive timeout") -SESS_CLOSE(RX_CLOSE_IDLE, rx_close_idle,0, "timeout_idle reached") SESS_CLOSE(TX_PIPE, tx_pipe, 0, "Piped transaction") SESS_CLOSE(TX_ERROR, tx_error, 1, "Error transaction") SESS_CLOSE(TX_EOF, tx_eof, 0, "EOF transmission") SESS_CLOSE(RESP_CLOSE, resp_close, 0, "Backend/VCL requested close") SESS_CLOSE(OVERLOAD, overload, 1, "Out of some resource") -SESS_CLOSE(PIPE_OVERFLOW, pipe_overflow,1, "Session pipe overflow") -SESS_CLOSE(RANGE_SHORT, range_short, 1, "Insufficient data for range") -SESS_CLOSE(REQ_HTTP20, req_http20, 1, "HTTP2 not accepted") -SESS_CLOSE(VCL_FAILURE, vcl_failure, 1, "VCL failure") -SESS_CLOSE(RAPID_RESET, rapid_reset, 1, "HTTP2 rapid reset") -SESS_CLOSE(BANKRUPT, bankrupt, 1, "HTTP2 credit bankruptcy") +#ifdef SESS_CLOSE_C + SESS_CLOSE(RX_CLOSE_IDLE, rx_close_idle, 0, "timeout_idle reached") + SESS_CLOSE(PIPE_OVERFLOW, pipe_overflow, 1, "Session pipe overflow") + SESS_CLOSE(RANGE_SHORT, range_short, 1, "Insufficient data for range") + SESS_CLOSE(REQ_HTTP20, req_http20, 1, "HTTP2 not accepted") + SESS_CLOSE(VCL_FAILURE, vcl_failure, 1, "VCL failure") + SESS_CLOSE(RAPID_RESET, rapid_reset, 1, "HTTP2 rapid reset") + SESS_CLOSE(BANKRUPT, bankrupt, 1, "HTTP2 credit bankruptcy") + #undef SESS_CLOSE_C +#endif #undef SESS_CLOSE /*lint -restore */ From 836454a2f648e8233e21c6c0245073e461286589 Mon Sep 17 00:00:00 2001 From: Asad Sajjad Ahmed Date: Wed, 21 May 2025 15:11:47 +0200 Subject: [PATCH 2/7] backend: add VSCs for backend errors Abstract vbe_close_acct, this is supposed to mimic the ses_close_acct for backends. We have up until now not exposed `htc->doclose` (backend errors) to any counters as we do for `req->doclose` (session errors). That is unfortunate as these errors code are useful when trubleshooting fetches, so expose them as `bc_*` counters which is a subset of the `sc_*` counters. Also add counters for backend closes: `backend_closed` and `backend_closed_err`. Signed-off-by: Asad Sajjad Ahmed --- bin/varnishd/cache/cache_backend.c | 31 ++++++++++ bin/varnishtest/tests/c00036.vtc | 6 ++ lib/libvsc/VSC_main.vsc | 94 ++++++++++++++++++++++++++++++ 3 files changed, 131 insertions(+) diff --git a/bin/varnishd/cache/cache_backend.c b/bin/varnishd/cache/cache_backend.c index bdb6fefd7c2..9fae300a4b9 100644 --- a/bin/varnishd/cache/cache_backend.c +++ b/bin/varnishd/cache/cache_backend.c @@ -181,6 +181,35 @@ vbe_connwait_fini(struct connwait *cw) FINI_OBJ(cw); } +/*-------------------------------------------------------------------- + * Update bc_ counters by reason (implementing ses_close_acct for backends) + * + * assuming that the approximation of non-atomic global counters is sufficient. + * if not: update to per-wrk + */ + +static void +vbe_close_acct(const struct pfd *pfd, const stream_close_t reason) +{ + + if (reason == SC_NULL) { + assert(PFD_State(pfd) == PFD_STATE_USED); + VSC_C_main->bc_tx_proxy++; + return; + } + +#define SESS_CLOSE(U, l, err, desc) \ + if (reason == SC_ ## U) { \ + VSC_C_main->bc_ ## l++; \ + if (err) \ + VSC_C_main->backend_closed_err++; \ + return; \ + } +#include "tbl/sess_close.h" + + WRONG("Wrong event in vbe_close_acct"); +} + /*-------------------------------------------------------------------- * Get a connection to the backend * @@ -369,11 +398,13 @@ vbe_dir_finish(VRT_CTX, VCL_BACKEND d) pfd = bo->htc->priv; bo->htc->priv = NULL; if (bo->htc->doclose != SC_NULL || bp->proxy_header != 0) { + vbe_close_acct(pfd, bo->htc->doclose); VSLb(bo->vsl, SLT_BackendClose, "%d %s close %s", *PFD_Fd(pfd), VRT_BACKEND_string(d), bo->htc->doclose->name); VCP_Close(&pfd); AZ(pfd); Lck_Lock(bp->director->mtx); + VSC_C_main->backend_closed++; } else { assert (PFD_State(pfd) == PFD_STATE_USED); VSLb(bo->vsl, SLT_BackendClose, "%d %s recycle", *PFD_Fd(pfd), diff --git a/bin/varnishtest/tests/c00036.vtc b/bin/varnishtest/tests/c00036.vtc index a229b74f0ac..f65ae3178ad 100644 --- a/bin/varnishtest/tests/c00036.vtc +++ b/bin/varnishtest/tests/c00036.vtc @@ -53,4 +53,10 @@ client c1 { } -run varnish v1 -expect backend_retry == 1 +varnish v1 -expect MAIN.backend_closed == 1 +varnish v1 -expect MAIN.backend_closed_err == 1 +varnish v1 -expect MAIN.bc_rx_bad == 1 +varnish v1 -expect MAIN.bc_rx_timeout == 0 +varnish v1 -expect MAIN.bc_rem_close == 0 + logexpect l1 -wait diff --git a/lib/libvsc/VSC_main.vsc b/lib/libvsc/VSC_main.vsc index dc989dfb982..33970dcbe00 100644 --- a/lib/libvsc/VSC_main.vsc +++ b/lib/libvsc/VSC_main.vsc @@ -211,6 +211,100 @@ The maximum time to wait in the queue is defined by the backend wait_timeout property. +.. varnish_vsc:: backend_closed + :group: wrk + :oneliner: Backend Closed + +.. varnish_vsc:: backend_closed_err + :oneliner: Backend Closed with error + + Total number of backends closed with errors. See bc_* diag counters + for detailed breakdown + +.. varnish_vsc:: bc_rem_close + :level: diag + :oneliner: Backend Close OK REM_CLOSE + + Number of backend closes with REM_CLOSE (Server Closed) + +.. varnish_vsc:: bc_req_close + :level: diag + :oneliner: Backend Close OK REQ_CLOSE + + Number of backend closes with REQ_CLOSE (Server requested close) + +.. varnish_vsc:: bc_req_http10 + :level: diag + :oneliner: Backend Close Err REQ_HTTP10 + + Number of backend closes with Error REQ_HTTP10 (Proto < HTTP/1.1) + +.. varnish_vsc:: bc_rx_bad + :level: diag + :oneliner: Backend Close Err RX_BAD + + Number of backend closes with Error RX_BAD (Received bad req/resp) + +.. varnish_vsc:: bc_rx_body + :level: diag + :oneliner: Backend Close Err RX_BODY + + Number of backend closes with Error RX_BODY (Failure receiving request body) + +.. varnish_vsc:: bc_rx_junk + :level: diag + :oneliner: Backend Close Err RX_JUNK + + Number of backend closes with Error RX_JUNK (Received junk data) + +.. varnish_vsc:: bc_rx_overflow + :level: diag + :oneliner: Backend Close Err RX_OVERFLOW + + Number of backend closes with Error RX_OVERFLOW (Received buffer overflow) + +.. varnish_vsc:: bc_rx_timeout + :level: diag + :oneliner: Backend Close Err RX_TIMEOUT + + Number of backend closes with Error RX_TIMEOUT (Receive timeout) + +.. varnish_vsc:: bc_tx_proxy + :level: diag + :oneliner: Backend Close OK TX_PROXY + + Number of backend closes with TX_PROXY (Proxy transaction). + +.. varnish_vsc:: bc_tx_pipe + :level: diag + :oneliner: Backend Close OK TX_PIPE + + Number of backend closes with TX_PIPE (Piped transaction) + +.. varnish_vsc:: bc_tx_error + :level: diag + :oneliner: Backend Close Err TX_ERROR + + Number of backend closes with Error TX_ERROR (Error transaction) + +.. varnish_vsc:: bc_tx_eof + :level: diag + :oneliner: Backend Close OK TX_EOF + + Number of backend closes with TX_EOF (EOF transmission) + +.. varnish_vsc:: bc_resp_close + :level: diag + :oneliner: Backend Close OK RESP_CLOSE + + Number of backend closes with RESP_CLOSE (Backend/VCL requested close) + +.. varnish_vsc:: bc_overload + :level: diag + :oneliner: Backend Close Err OVERLOAD + + Number of backend closes with Error OVERLOAD (Out of some resource) + .. varnish_vsc:: fetch_head :group: wrk :oneliner: Fetch no body (HEAD) From 85938f3dc44b9c5646f2e5ffe54d070f7fb8b773 Mon Sep 17 00:00:00 2001 From: Asad Sajjad Ahmed Date: Wed, 21 May 2025 15:38:07 +0200 Subject: [PATCH 3/7] v1f: report HTC_S_EOF as SC_REM_CLOSE HTC_S_EOF is returned when the backend close the connection on us. Since RxStuff() no longer reports `HTC_S_CLOSE` we can reuse it for EOF. To be consistent with sessions (client disconnect) use the `SC_REM_CLOSE`. Signed-off-by: Asad Sajjad Ahmed --- bin/varnishd/http1/cache_http1_fetch.c | 4 ++-- bin/varnishtest/tests/c00036.vtc | 8 ++++---- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/bin/varnishd/http1/cache_http1_fetch.c b/bin/varnishd/http1/cache_http1_fetch.c index f8bcf43cd49..75036a519b2 100644 --- a/bin/varnishd/http1/cache_http1_fetch.c +++ b/bin/varnishd/http1/cache_http1_fetch.c @@ -229,9 +229,9 @@ V1F_FetchRespHdr(struct busyobj *bo) VSLb(bo->vsl, SLT_FetchError, "Received junk"); htc->doclose = SC_RX_JUNK; break; - case HTC_S_CLOSE: + case HTC_S_EOF: VSLb(bo->vsl, SLT_FetchError, "backend closed"); - htc->doclose = SC_RESP_CLOSE; + htc->doclose = SC_REM_CLOSE; break; case HTC_S_TIMEOUT: VSLb(bo->vsl, SLT_FetchError, "timeout"); diff --git a/bin/varnishtest/tests/c00036.vtc b/bin/varnishtest/tests/c00036.vtc index f65ae3178ad..3a0128a31c7 100644 --- a/bin/varnishtest/tests/c00036.vtc +++ b/bin/varnishtest/tests/c00036.vtc @@ -27,7 +27,7 @@ logexpect l1 -v v1 -q "vxid == 1004" { # purpose of this vtc: test the internal retry when the # backend goes away on a keepalive TCP connection: - expect 0 1004 FetchError {^HTC eof .Unexpected end of input.} + expect 0 1004 FetchError {^backend closed} expect 0 1004 BackendClose {^\d+ s1} expect 0 1004 Timestamp {^Connected:} expect 0 1004 BackendOpen {^\d+ s1} @@ -54,9 +54,9 @@ client c1 { varnish v1 -expect backend_retry == 1 varnish v1 -expect MAIN.backend_closed == 1 -varnish v1 -expect MAIN.backend_closed_err == 1 -varnish v1 -expect MAIN.bc_rx_bad == 1 +varnish v1 -expect MAIN.backend_closed_err == 0 +varnish v1 -expect MAIN.bc_rx_bad == 0 varnish v1 -expect MAIN.bc_rx_timeout == 0 -varnish v1 -expect MAIN.bc_rem_close == 0 +varnish v1 -expect MAIN.bc_rem_close == 1 logexpect l1 -wait From cc612f0e49559f838ac26208b2f415e6fb167e16 Mon Sep 17 00:00:00 2001 From: Asad Sajjad Ahmed Date: Tue, 10 Jun 2025 11:29:55 +0200 Subject: [PATCH 4/7] varnishd: introduce debug bit for PROXY_ERROR This new debug bit enable us to test proxy send error for VRT backends. Signed-off-by: Asad Sajjad Ahmed --- bin/varnishd/proxy/cache_proxy_proto.c | 5 ++++ bin/varnishtest/tests/o00007.vtc | 41 ++++++++++++++++++++++++++ include/tbl/debug_bits.h | 1 + 3 files changed, 47 insertions(+) create mode 100644 bin/varnishtest/tests/o00007.vtc diff --git a/bin/varnishd/proxy/cache_proxy_proto.c b/bin/varnishd/proxy/cache_proxy_proto.c index f8e317a0c48..3f47c6a4755 100644 --- a/bin/varnishd/proxy/cache_proxy_proto.c +++ b/bin/varnishd/proxy/cache_proxy_proto.c @@ -757,6 +757,11 @@ VPX_Send_Proxy(int fd, int version, const struct sess *sp) r = write(fd, VSB_data(vsb), VSB_len(vsb)); VTCP_Assert(r); + if (DO_DEBUG(DBG_PROXY_ERROR)) { + errno = EINTR; + return (-1); + } + if (!DO_DEBUG(DBG_PROTOCOL)) return (r); diff --git a/bin/varnishtest/tests/o00007.vtc b/bin/varnishtest/tests/o00007.vtc new file mode 100644 index 00000000000..efec20874c8 --- /dev/null +++ b/bin/varnishtest/tests/o00007.vtc @@ -0,0 +1,41 @@ +varnishtest "Failing to send proxy headers to backend" + +server s1 {} -start + +varnish v1 -vcl { + backend default { + .host = "${s1_addr}"; + .port = "${s1_port}"; + .proxy_header = 2; + } +} -start + +varnish v1 -cliok "param.set debug +proxy_error" + +logexpect l1 -v v1 { + expect * 1002 Timestamp {^Connected:} + expect * 1002 FetchError {^backend default: proxy write errno} +} -start + +client c1 { + txreq + rxresphdrs + expect resp.status == 503 +} -run + +logexpect l1 -wait + +varnish v1 -expect MAIN.backend_conn == 1 +varnish v1 -expect MAIN.backend_req == 0 +varnish v1 -expect MAIN.backend_closed == 0 +varnish v1 -expect MAIN.backend_closed_err == 0 + +varnish v1 -expect MAIN.bc_rx_bad == 0 +varnish v1 -expect MAIN.bc_rem_close == 0 +varnish v1 -expect MAIN.bc_rx_timeout == 0 +varnish v1 -expect MAIN.bc_tx_error == 0 +varnish v1 -expect MAIN.bc_tx_proxy == 0 + +varnish v1 -expect VBE.vcl1.default.conn == 0 +varnish v1 -expect VBE.vcl1.default.req == 0 +varnish v1 -expect VBE.vcl1.default.fail == 0 diff --git a/include/tbl/debug_bits.h b/include/tbl/debug_bits.h index 2c6a980c468..172738cf3d3 100644 --- a/include/tbl/debug_bits.h +++ b/include/tbl/debug_bits.h @@ -52,6 +52,7 @@ DEBUG_BIT(PROCESSORS, processors, "Fetch/Deliver processors") DEBUG_BIT(PROTOCOL, protocol, "Protocol debugging") DEBUG_BIT(VCL_KEEP, vcl_keep, "Keep VCL C and so files") DEBUG_BIT(LCK, lck, "Additional lock statistics") +DEBUG_BIT(PROXY_ERROR, proxy_error, "Proxy send error to backend") #undef DEBUG_BIT /*lint -restore */ From 268b18286a1a3fd50800af25ad6acfb43aa9528f Mon Sep 17 00:00:00 2001 From: Asad Sajjad Ahmed Date: Tue, 7 Oct 2025 13:48:24 +0200 Subject: [PATCH 5/7] backend: move vbe_dir_finish for what comes next No modifications are done to the vbe_dir_finish function. Signed-off-by: Asad Sajjad Ahmed --- bin/varnishd/cache/cache_backend.c | 90 +++++++++++++++--------------- 1 file changed, 45 insertions(+), 45 deletions(-) diff --git a/bin/varnishd/cache/cache_backend.c b/bin/varnishd/cache/cache_backend.c index 9fae300a4b9..e6658b4bd2d 100644 --- a/bin/varnishd/cache/cache_backend.c +++ b/bin/varnishd/cache/cache_backend.c @@ -210,6 +210,51 @@ vbe_close_acct(const struct pfd *pfd, const stream_close_t reason) WRONG("Wrong event in vbe_close_acct"); } +static void v_matchproto_(vdi_finish_f) +vbe_dir_finish(VRT_CTX, VCL_BACKEND d) +{ + struct backend *bp; + struct busyobj *bo; + struct pfd *pfd; + + CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC); + CHECK_OBJ_NOTNULL(d, DIRECTOR_MAGIC); + bo = ctx->bo; + CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC); + CAST_OBJ_NOTNULL(bp, d->priv, BACKEND_MAGIC); + + CHECK_OBJ_NOTNULL(bo->htc, HTTP_CONN_MAGIC); + CHECK_OBJ_NOTNULL(bo->htc->doclose, STREAM_CLOSE_MAGIC); + + pfd = bo->htc->priv; + bo->htc->priv = NULL; + if (bo->htc->doclose != SC_NULL || bp->proxy_header != 0) { + vbe_close_acct(pfd, bo->htc->doclose); + VSLb(bo->vsl, SLT_BackendClose, "%d %s close %s", *PFD_Fd(pfd), + VRT_BACKEND_string(d), bo->htc->doclose->name); + VCP_Close(&pfd); + AZ(pfd); + Lck_Lock(bp->director->mtx); + VSC_C_main->backend_closed++; + } else { + assert (PFD_State(pfd) == PFD_STATE_USED); + VSLb(bo->vsl, SLT_BackendClose, "%d %s recycle", *PFD_Fd(pfd), + VRT_BACKEND_string(d)); + Lck_Lock(bp->director->mtx); + VSC_C_main->backend_recycle++; + VCP_Recycle(bo->wrk, &pfd); + } + assert(bp->n_conn > 0); + bp->n_conn--; + AN(bp->vsc); + bp->vsc->conn--; +#define ACCT(foo) bp->vsc->foo += bo->acct.foo; +#include "tbl/acct_fields_bereq.h" + vbe_connwait_signal_locked(bp); + Lck_Unlock(bp->director->mtx); + bo->htc = NULL; +} + /*-------------------------------------------------------------------- * Get a connection to the backend * @@ -379,51 +424,6 @@ vbe_dir_getfd(VRT_CTX, struct worker *wrk, VCL_BACKEND dir, struct backend *bp, return (pfd); } -static void v_matchproto_(vdi_finish_f) -vbe_dir_finish(VRT_CTX, VCL_BACKEND d) -{ - struct backend *bp; - struct busyobj *bo; - struct pfd *pfd; - - CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC); - CHECK_OBJ_NOTNULL(d, DIRECTOR_MAGIC); - bo = ctx->bo; - CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC); - CAST_OBJ_NOTNULL(bp, d->priv, BACKEND_MAGIC); - - CHECK_OBJ_NOTNULL(bo->htc, HTTP_CONN_MAGIC); - CHECK_OBJ_NOTNULL(bo->htc->doclose, STREAM_CLOSE_MAGIC); - - pfd = bo->htc->priv; - bo->htc->priv = NULL; - if (bo->htc->doclose != SC_NULL || bp->proxy_header != 0) { - vbe_close_acct(pfd, bo->htc->doclose); - VSLb(bo->vsl, SLT_BackendClose, "%d %s close %s", *PFD_Fd(pfd), - VRT_BACKEND_string(d), bo->htc->doclose->name); - VCP_Close(&pfd); - AZ(pfd); - Lck_Lock(bp->director->mtx); - VSC_C_main->backend_closed++; - } else { - assert (PFD_State(pfd) == PFD_STATE_USED); - VSLb(bo->vsl, SLT_BackendClose, "%d %s recycle", *PFD_Fd(pfd), - VRT_BACKEND_string(d)); - Lck_Lock(bp->director->mtx); - VSC_C_main->backend_recycle++; - VCP_Recycle(bo->wrk, &pfd); - } - assert(bp->n_conn > 0); - bp->n_conn--; - AN(bp->vsc); - bp->vsc->conn--; -#define ACCT(foo) bp->vsc->foo += bo->acct.foo; -#include "tbl/acct_fields_bereq.h" - vbe_connwait_signal_locked(bp); - Lck_Unlock(bp->director->mtx); - bo->htc = NULL; -} - static int v_matchproto_(vdi_gethdrs_f) vbe_dir_gethdrs(VRT_CTX, VCL_BACKEND d) { From 725e7164758a6086a0d35a423a650f87137f447e Mon Sep 17 00:00:00 2001 From: Asad Sajjad Ahmed Date: Tue, 10 Jun 2025 11:37:04 +0200 Subject: [PATCH 6/7] varnishd: minor refractory for PROXY send error There is no need to special case VPX_Send_Proxy with its own error handling. We can instead reuse vbe_dir_finish. We will now report BackendClosed tag in VSL as well (from vbe_dir_finish). To accomplish this we need to initialize the HTC struct a little bit earlier. Finally, we change the doclose reason to be an error transmission (SC_TX_ERROR). Signed-off-by: Asad Sajjad Ahmed --- bin/varnishd/cache/cache_backend.c | 21 ++++++++------------- bin/varnishtest/tests/o00007.vtc | 7 ++++--- 2 files changed, 12 insertions(+), 16 deletions(-) diff --git a/bin/varnishd/cache/cache_backend.c b/bin/varnishd/cache/cache_backend.c index e6658b4bd2d..87e424fac1c 100644 --- a/bin/varnishd/cache/cache_backend.c +++ b/bin/varnishd/cache/cache_backend.c @@ -380,27 +380,26 @@ vbe_dir_getfd(VRT_CTX, struct worker *wrk, VCL_BACKEND dir, struct backend *bp, bp->vsc->req++; Lck_Unlock(bp->director->mtx); + INIT_OBJ(bo->htc, HTTP_CONN_MAGIC); + bo->htc->priv = pfd; + bo->htc->rfd = fdp; + bo->htc->doclose = SC_NULL; CHECK_OBJ_NOTNULL(bo->htc->doclose, STREAM_CLOSE_MAGIC); err = 0; if (bp->proxy_header != 0) - err += VPX_Send_Proxy(*fdp, bp->proxy_header, bo->sp); + err = VPX_Send_Proxy(*fdp, bp->proxy_header, bo->sp); if (err < 0) { VSLb(bo->vsl, SLT_FetchError, "backend %s: proxy write errno %d (%s)", VRT_BACKEND_string(dir), errno, VAS_errtxt(errno)); - // account as if connect failed - good idea? - VSC_C_main->backend_fail++; - bo->htc = NULL; - VCP_Close(&pfd); - AZ(pfd); + bo->htc->doclose = SC_TX_ERROR; Lck_Lock(bp->director->mtx); - bp->n_conn--; - bp->vsc->conn--; + VSC_C_main->backend_fail++; bp->vsc->req--; - vbe_connwait_signal_locked(bp); Lck_Unlock(bp->director->mtx); + vbe_dir_finish(ctx, dir); vbe_connwait_fini(cw); return (NULL); } @@ -412,10 +411,6 @@ vbe_dir_getfd(VRT_CTX, struct worker *wrk, VCL_BACKEND dir, struct backend *bp, *fdp, VRT_BACKEND_string(dir), abuf2, pbuf2, abuf1, pbuf1, PFD_State(pfd) == PFD_STATE_STOLEN ? "reuse" : "connect"); - INIT_OBJ(bo->htc, HTTP_CONN_MAGIC); - bo->htc->priv = pfd; - bo->htc->rfd = fdp; - bo->htc->doclose = SC_NULL; FIND_TMO(first_byte_timeout, bo->htc->first_byte_timeout, bo, bp); FIND_TMO(between_bytes_timeout, diff --git a/bin/varnishtest/tests/o00007.vtc b/bin/varnishtest/tests/o00007.vtc index efec20874c8..a99c89b1e21 100644 --- a/bin/varnishtest/tests/o00007.vtc +++ b/bin/varnishtest/tests/o00007.vtc @@ -15,6 +15,7 @@ varnish v1 -cliok "param.set debug +proxy_error" logexpect l1 -v v1 { expect * 1002 Timestamp {^Connected:} expect * 1002 FetchError {^backend default: proxy write errno} + expect * 1002 BackendClose {default close TX_ERROR} } -start client c1 { @@ -27,13 +28,13 @@ logexpect l1 -wait varnish v1 -expect MAIN.backend_conn == 1 varnish v1 -expect MAIN.backend_req == 0 -varnish v1 -expect MAIN.backend_closed == 0 -varnish v1 -expect MAIN.backend_closed_err == 0 +varnish v1 -expect MAIN.backend_closed == 1 +varnish v1 -expect MAIN.backend_closed_err == 1 varnish v1 -expect MAIN.bc_rx_bad == 0 varnish v1 -expect MAIN.bc_rem_close == 0 varnish v1 -expect MAIN.bc_rx_timeout == 0 -varnish v1 -expect MAIN.bc_tx_error == 0 +varnish v1 -expect MAIN.bc_tx_error == 1 varnish v1 -expect MAIN.bc_tx_proxy == 0 varnish v1 -expect VBE.vcl1.default.conn == 0 From 8a872b04f1ff11ad0adbdab337574bf8217e1ea5 Mon Sep 17 00:00:00 2001 From: Asad Sajjad Ahmed Date: Tue, 10 Jun 2025 13:18:10 +0200 Subject: [PATCH 7/7] varnishd: add VSC per backend connection closed Change vbe_close_acct to update counters for the specific backend as well as the existing global counters. This addition allows a user to easily pinpoint the problematic backend. As some backends can come and go (dynamic backends), we should maintain the global counters as is. Signed-off-by: Asad Sajjad Ahmed --- bin/varnishd/cache/cache_backend.c | 13 +++-- bin/varnishtest/tests/o00007.vtc | 8 +++ bin/varnishtest/tests/u00008.vtc | 2 + lib/libvsc/VSC_vbe.vsc | 80 ++++++++++++++++++++++++++++++ 4 files changed, 100 insertions(+), 3 deletions(-) diff --git a/bin/varnishd/cache/cache_backend.c b/bin/varnishd/cache/cache_backend.c index 87e424fac1c..b72f343ff64 100644 --- a/bin/varnishd/cache/cache_backend.c +++ b/bin/varnishd/cache/cache_backend.c @@ -189,20 +189,25 @@ vbe_connwait_fini(struct connwait *cw) */ static void -vbe_close_acct(const struct pfd *pfd, const stream_close_t reason) +vbe_close_acct(const struct pfd *pfd, struct VSC_vbe *vsc, + const stream_close_t reason) { if (reason == SC_NULL) { assert(PFD_State(pfd) == PFD_STATE_USED); VSC_C_main->bc_tx_proxy++; + vsc->tx_proxy++; return; } #define SESS_CLOSE(U, l, err, desc) \ if (reason == SC_ ## U) { \ VSC_C_main->bc_ ## l++; \ - if (err) \ + vsc->l++; \ + if (err) { \ VSC_C_main->backend_closed_err++; \ + vsc->closed_err++; \ + } \ return; \ } #include "tbl/sess_close.h" @@ -222,6 +227,7 @@ vbe_dir_finish(VRT_CTX, VCL_BACKEND d) bo = ctx->bo; CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC); CAST_OBJ_NOTNULL(bp, d->priv, BACKEND_MAGIC); + AN(bp->vsc); CHECK_OBJ_NOTNULL(bo->htc, HTTP_CONN_MAGIC); CHECK_OBJ_NOTNULL(bo->htc->doclose, STREAM_CLOSE_MAGIC); @@ -229,13 +235,14 @@ vbe_dir_finish(VRT_CTX, VCL_BACKEND d) pfd = bo->htc->priv; bo->htc->priv = NULL; if (bo->htc->doclose != SC_NULL || bp->proxy_header != 0) { - vbe_close_acct(pfd, bo->htc->doclose); + vbe_close_acct(pfd, bp->vsc, bo->htc->doclose); VSLb(bo->vsl, SLT_BackendClose, "%d %s close %s", *PFD_Fd(pfd), VRT_BACKEND_string(d), bo->htc->doclose->name); VCP_Close(&pfd); AZ(pfd); Lck_Lock(bp->director->mtx); VSC_C_main->backend_closed++; + bp->vsc->closed++; } else { assert (PFD_State(pfd) == PFD_STATE_USED); VSLb(bo->vsl, SLT_BackendClose, "%d %s recycle", *PFD_Fd(pfd), diff --git a/bin/varnishtest/tests/o00007.vtc b/bin/varnishtest/tests/o00007.vtc index a99c89b1e21..7ddb1743023 100644 --- a/bin/varnishtest/tests/o00007.vtc +++ b/bin/varnishtest/tests/o00007.vtc @@ -40,3 +40,11 @@ varnish v1 -expect MAIN.bc_tx_proxy == 0 varnish v1 -expect VBE.vcl1.default.conn == 0 varnish v1 -expect VBE.vcl1.default.req == 0 varnish v1 -expect VBE.vcl1.default.fail == 0 +varnish v1 -expect VBE.vcl1.default.closed == 1 +varnish v1 -expect VBE.vcl1.default.closed_err == 1 + +varnish v1 -expect VBE.vcl1.default.rx_bad == 0 +varnish v1 -expect VBE.vcl1.default.rem_close == 0 +varnish v1 -expect VBE.vcl1.default.rx_timeout == 0 +varnish v1 -expect VBE.vcl1.default.tx_error == 1 +varnish v1 -expect VBE.vcl1.default.tx_proxy == 0 diff --git a/bin/varnishtest/tests/u00008.vtc b/bin/varnishtest/tests/u00008.vtc index 61de2981829..a5cd6a2a0a0 100644 --- a/bin/varnishtest/tests/u00008.vtc +++ b/bin/varnishtest/tests/u00008.vtc @@ -70,10 +70,12 @@ process p1 -winsz 25 132 process p1 -expect-text 4 124 "AVG_1000" process p1 -expect-text 22 108 "UNSEEN DIAG" +process p1 -key NPAGE process p1 -key NPAGE process p1 -expect-text 0 0 "VBE.vcl1.s1.helddown" process p1 -screen_dump +process p1 -key PPAGE process p1 -key PPAGE process p1 -expect-text 0 0 "VBE.vcl1.s1.happy" process p1 -screen_dump diff --git a/lib/libvsc/VSC_vbe.vsc b/lib/libvsc/VSC_vbe.vsc index b2374519293..d4609477d3d 100644 --- a/lib/libvsc/VSC_vbe.vsc +++ b/lib/libvsc/VSC_vbe.vsc @@ -104,6 +104,86 @@ Number of times the max_connections limit was reached +.. varnish_vsc:: closed + :type: counter + :level: info + :oneliner: Connection closed + +.. varnish_vsc:: closed_err + :type: counter + :level: info + :oneliner: Connection closed with error + +.. varnish_vsc:: rem_close + :type: counter + :level: info + :oneliner: Connection closed by backend + +.. varnish_vsc:: req_close + :type: counter + :level: info + :oneliner: Connection closure requested by backend + +.. varnish_vsc:: req_http10 + :type: counter + :level: info + :oneliner: Connection closed for proto < HTTP/1.1 + +.. varnish_vsc:: rx_bad + :type: counter + :level: info + :oneliner: Connection closed for received bad response + +.. varnish_vsc:: rx_body + :type: counter + :level: info + :oneliner: Connection closed for failed receiving request body + +.. varnish_vsc:: rx_junk + :type: counter + :level: info + :oneliner: Connection closed for received junk data + +.. varnish_vsc:: rx_overflow + :type: counter + :level: info + :oneliner: Connection closed for receive buffer overflow + +.. varnish_vsc:: rx_timeout + :type: counter + :level: info + :oneliner: Connection closed for receive timeout + +.. varnish_vsc:: tx_proxy + :type: counter + :level: info + :oneliner: Connection closed for proxy transaction + +.. varnish_vsc:: tx_pipe + :type: counter + :level: info + :oneliner: Connection closed for piped transaction + +.. varnish_vsc:: tx_error + :type: counter + :level: info + :oneliner: Connection closed for error transaction + +.. varnish_vsc:: tx_eof + :type: counter + :level: info + :oneliner: Connection closed for EOF transmission + +.. varnish_vsc:: resp_close + :type: counter + :level: info + :oneliner: Connection closed for backend/VCL requested close + +.. varnish_vsc:: overload + :type: counter + :level: info + :oneliner: Connection closed for out of some resource + .. === Anything below is actually per VCP entry, but collected per === backend for simplicity