From e0eaad42bb064c7e81862fc6e7a65d831adceaa8 Mon Sep 17 00:00:00 2001 From: Dridi Boukelmoune Date: Wed, 18 Oct 2023 12:21:17 +0200 Subject: [PATCH 1/6] vtc: mv t02025.vtc t02026.vtc Not sure why 6fbb937758dfa7ad131d5a40d2c9b7b5929dc7dd does not originate from trunk. --- bin/varnishtest/tests/{t02025.vtc => t02026.vtc} | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename bin/varnishtest/tests/{t02025.vtc => t02026.vtc} (100%) diff --git a/bin/varnishtest/tests/t02025.vtc b/bin/varnishtest/tests/t02026.vtc similarity index 100% rename from bin/varnishtest/tests/t02025.vtc rename to bin/varnishtest/tests/t02026.vtc From 4b047cc7ec700402b6d495a098eb01580cebd310 Mon Sep 17 00:00:00 2001 From: Dridi Boukelmoune Date: Thu, 12 Oct 2023 11:17:09 +0200 Subject: [PATCH 2/6] vtc: Avoid cycling the barrier in t02014 It was particularly hard to follow once we reach client c3. --- bin/varnishtest/tests/t02014.vtc | 29 +++++++++++++++++------------ 1 file changed, 17 insertions(+), 12 deletions(-) diff --git a/bin/varnishtest/tests/t02014.vtc b/bin/varnishtest/tests/t02014.vtc index f47eed65767..8add78a0d37 100644 --- a/bin/varnishtest/tests/t02014.vtc +++ b/bin/varnishtest/tests/t02014.vtc @@ -1,6 +1,9 @@ varnishtest "Exercise h/2 sender flow control code" -barrier b1 sock 3 -cyclic +barrier b1 sock 3 +barrier b2 sock 3 +barrier b3 sock 3 +barrier b4 sock 3 server s1 { rxreq @@ -23,7 +26,9 @@ varnish v1 -vcl+backend { } sub vcl_deliver { - vtc.barrier_sync("${b1_sock}"); + if (req.http.barrier) { + vtc.barrier_sync(req.http.barrier); + } } } -start @@ -43,7 +48,7 @@ client c1 { } -start stream 1 { - txreq + txreq -hdr barrier ${b1_sock} barrier b1 sync delay .5 txwinup -size 256 @@ -61,15 +66,15 @@ client c1 { client c2 { stream 0 { - barrier b1 sync + barrier b2 sync } -start stream 1 { - txreq + txreq -hdr barrier ${b2_sock} txdata -data "fail" rxrst expect rst.err == STREAM_CLOSED - barrier b1 sync + barrier b2 sync } -run stream 0 -wait @@ -77,8 +82,8 @@ client c2 { client c3 { stream 0 { - barrier b1 sync - barrier b1 sync + barrier b3 sync + barrier b4 sync delay .5 txwinup -size 256 delay .5 @@ -89,17 +94,17 @@ client c3 { } -start stream 1 { - txreq -req "POST" -nostrend + txreq -req "POST" -hdr barrier ${b3_sock} -nostrend txdata -data "ok" txdata -data "fail" rxrst expect rst.err == STREAM_CLOSED - barrier b1 sync + barrier b3 sync } -run stream 3 { - txreq - barrier b1 sync + txreq -hdr barrier ${b4_sock} + barrier b4 sync delay .5 txwinup -size 256 delay .5 From 77d50cb92d4ef6ce4f59c6b3baddb5a97cc6b681 Mon Sep 17 00:00:00 2001 From: Dridi Boukelmoune Date: Wed, 11 Oct 2023 11:57:48 +0200 Subject: [PATCH 3/6] transport: New poll method The goal is for top-level transports to report whether the client is still present or not. --- bin/varnishd/cache/cache_transport.h | 2 ++ 1 file changed, 2 insertions(+) diff --git a/bin/varnishd/cache/cache_transport.h b/bin/varnishd/cache/cache_transport.h index 5da5e35018d..85464111f46 100644 --- a/bin/varnishd/cache/cache_transport.h +++ b/bin/varnishd/cache/cache_transport.h @@ -42,6 +42,7 @@ typedef void vtr_sess_panic_f (struct vsb *, const struct sess *); typedef void vtr_req_panic_f (struct vsb *, const struct req *); typedef void vtr_req_fail_f (struct req *, enum sess_close); typedef void vtr_reembark_f (struct worker *, struct req *); +typedef int vtr_poll_f (struct req *); typedef int vtr_minimal_response_f (struct req *, uint16_t status); struct transport { @@ -62,6 +63,7 @@ struct transport { vtr_sess_panic_f *sess_panic; vtr_req_panic_f *req_panic; vtr_reembark_f *reembark; + vtr_poll_f *poll; vtr_minimal_response_f *minimal_response; VTAILQ_ENTRY(transport) list; From 933d3a9102b69e66fe485eac753adfe860be1473 Mon Sep 17 00:00:00 2001 From: Dridi Boukelmoune Date: Wed, 11 Oct 2023 19:51:58 +0200 Subject: [PATCH 4/6] vcl_vrt: Skip VCL execution if the client is gone Once a client is reportedly gone, processing its VCL task(s) is just a waste of resources. The execution of client-facing VCL is intercepted and an artificial return(fail) is returned in that scenario. Thanks to the introduction of the universal return(fail) proper error handling and resource tear down is already in place, which makes this change safe modulus unknown bugs. This adds a circuit breaker anywhere in the client state machine where there is VCL execution. A new Reset time stamp is logged to convey when a task does not complete because the client is gone. This is a good complement to the walk away feature and its original circuit breaker for the waiting list, but this has not been integrated yet. While the request is technically failed, it won't increase the vcl_fail counter, and a new req_reset counter is incremented. This new behavior is guarded by a new vcl_req_reset feature flag, enabled by default. Refs #3835 Refs 61a15cbffe1141c13b87e30d48ce1402f84433bf Refs e5efc2c8dc0d003e5f0fa1a30b598f5949112897 Refs ba54dc919076b1ddb85434d886ce82a6553d926b Refs 6f50a00f80c7f74b2a8b18bb80593f58b74816fd Refs b8816994cfab58261d8000ea8e6941cb5de640fa Conflicts: bin/varnishd/cache/cache_vrt_vcl.c bin/varnishd/cache/cache_vcl_vrt.c bin/varnishd/mgt/mgt_param_bits.c include/tbl/params.h --- bin/varnishd/VSC_main.vsc | 7 +++++++ bin/varnishd/cache/cache_vcl_vrt.c | 33 ++++++++++++++++++++++++++++++ bin/varnishd/mgt/mgt_param_bits.c | 9 ++++++-- doc/sphinx/reference/vsl.rst | 4 ++++ include/tbl/feature_bits.h | 6 ++++++ include/tbl/req_flags.h | 1 + 6 files changed, 58 insertions(+), 2 deletions(-) diff --git a/bin/varnishd/VSC_main.vsc b/bin/varnishd/VSC_main.vsc index d03144367c9..027245d8822 100644 --- a/bin/varnishd/VSC_main.vsc +++ b/bin/varnishd/VSC_main.vsc @@ -330,6 +330,13 @@ Number of times an HTTP/2 stream was refused because the queue was too long already. See also parameter thread_queue_limit. +.. varnish_vsc:: req_reset + :group: wrk + :oneliner: Requests reset + + Number of times a client left before the VCL processing of its + requests completed. + .. varnish_vsc:: n_object :type: gauge :group: wrk diff --git a/bin/varnishd/cache/cache_vcl_vrt.c b/bin/varnishd/cache/cache_vcl_vrt.c index 5f3bfeec06c..e35ae59f8b2 100644 --- a/bin/varnishd/cache/cache_vcl_vrt.c +++ b/bin/varnishd/cache/cache_vcl_vrt.c @@ -37,8 +37,10 @@ #include "cache_varnishd.h" #include "vcl.h" +#include "vtim.h" #include "cache_director.h" +#include "cache_transport.h" #include "cache_vcl.h" /*--------------------------------------------------------------------*/ @@ -338,6 +340,35 @@ VRT_rel_vcl(VRT_CTX, struct vclref **refp) * The workspace argument is where random VCL stuff gets space from. */ +static int +req_poll(struct worker *wrk, struct req *req) +{ + + CHECK_OBJ_NOTNULL(req->top, REQ_MAGIC); + CHECK_OBJ_NOTNULL(req->top->transport, TRANSPORT_MAGIC); + + /* NB: Since a fail transition leads to vcl_synth, the request may be + * short-circuited twice. + */ + if (req->req_reset) { + wrk->handling = VCL_RET_FAIL; + return (-1); + } + + if (!FEATURE(FEATURE_VCL_REQ_RESET)) + return (0); + if (req->top->transport->poll == NULL) + return (0); + if (req->top->transport->poll(req->top) >= 0) + return (0); + + VSLb_ts_req(req, "Reset", W_TIM_real(wrk)); + wrk->stats->req_reset++; + wrk->handling = VCL_RET_FAIL; + req->req_reset = 1; + return (-1); +} + static void vcl_call_method(struct worker *wrk, struct req *req, struct busyobj *bo, void *specific, unsigned method, vcl_func_f *func) @@ -351,6 +382,8 @@ vcl_call_method(struct worker *wrk, struct req *req, struct busyobj *bo, CHECK_OBJ_NOTNULL(req, REQ_MAGIC); CHECK_OBJ_NOTNULL(req->sp, SESS_MAGIC); CHECK_OBJ_NOTNULL(req->vcl, VCL_MAGIC); + if (req_poll(wrk, req)) + return; VCL_Req2Ctx(&ctx, req); } if (bo != NULL) { diff --git a/bin/varnishd/mgt/mgt_param_bits.c b/bin/varnishd/mgt/mgt_param_bits.c index 7ea66d7e1a6..2767ede0a68 100644 --- a/bin/varnishd/mgt/mgt_param_bits.c +++ b/bin/varnishd/mgt/mgt_param_bits.c @@ -220,7 +220,12 @@ tweak_feature(struct vsb *vsb, const struct parspec *par, const char *arg) (void)par; if (arg != NULL && arg != JSON_FMT) { - if (!strcmp(arg, "none")) { + if (!strcmp(arg, "default")) { + AZ(bit_tweak(vsb, mgt_param.feature_bits, + FEATURE_Reserved, + "+vcl_req_reset", + feature_tags, "feature bit", "+")); + }else if (!strcmp(arg, "none")) { memset(mgt_param.feature_bits, 0, sizeof mgt_param.feature_bits); } else { @@ -272,6 +277,6 @@ struct parspec VSL_parspec[] = { #define FEATURE_BIT(U, l, d, ld) "\n\t" #l "\t" d #include "tbl/feature_bits.h" #undef FEATURE_BIT - , 0, "none", "" }, + , 0, "default", "" }, { NULL, NULL, NULL } }; diff --git a/doc/sphinx/reference/vsl.rst b/doc/sphinx/reference/vsl.rst index 4d01f5ba82c..ec1814ff85b 100644 --- a/doc/sphinx/reference/vsl.rst +++ b/doc/sphinx/reference/vsl.rst @@ -71,6 +71,10 @@ Resp Restart Client request is being restarted. +Reset + The client closed its connection or reset its stream. Request + processing is interrupted and considered failed. + Pipe handling timestamps ~~~~~~~~~~~~~~~~~~~~~~~~ diff --git a/include/tbl/feature_bits.h b/include/tbl/feature_bits.h index 23f1b01f879..844ecfa32e0 100644 --- a/include/tbl/feature_bits.h +++ b/include/tbl/feature_bits.h @@ -83,6 +83,12 @@ FEATURE_BIT(HTTP_DATE_POSTEL, http_date_postel, "like Date:, Last-Modified:, Expires: etc." ) +FEATURE_BIT(VCL_REQ_RESET, vcl_req_reset, + "Stop processing client VCL once the client is gone.", + "Stop processing client VCL once the client is gone. " + "When this happens MAIN.req_reset is incremented." +) + #undef FEATURE_BIT /*lint -restore */ diff --git a/include/tbl/req_flags.h b/include/tbl/req_flags.h index 2c0dbe80397..3d3f05fdbd9 100644 --- a/include/tbl/req_flags.h +++ b/include/tbl/req_flags.h @@ -39,6 +39,7 @@ REQ_FLAG(is_hitpass, 1, 0, "") REQ_FLAG(waitinglist, 0, 0, "") REQ_FLAG(want100cont, 0, 0, "") REQ_FLAG(late100cont, 0, 0, "") +REQ_FLAG(req_reset, 0, 0, "") #undef REQ_FLAG /*lint -restore */ From f9ad6f45532008fcdd504fdef6800b758642a448 Mon Sep 17 00:00:00 2001 From: Dridi Boukelmoune Date: Wed, 11 Oct 2023 12:38:21 +0200 Subject: [PATCH 5/6] http2_session: Implement transport polling The error check is not performed in a critical section to avoid contention, at the risk of not seeing the error until the next transport poll. Conflicts: bin/varnishd/http2/cache_http2_session.c --- bin/varnishd/VSC_main.vsc | 4 +- bin/varnishd/http2/cache_http2_session.c | 11 +++++ bin/varnishtest/tests/t02014.vtc | 31 +++++++++++++- bin/varnishtest/tests/t02025.vtc | 52 ++++++++++++++++++++++++ doc/sphinx/reference/vsl.rst | 3 +- 5 files changed, 97 insertions(+), 4 deletions(-) create mode 100644 bin/varnishtest/tests/t02025.vtc diff --git a/bin/varnishd/VSC_main.vsc b/bin/varnishd/VSC_main.vsc index 027245d8822..8d6277ed7d7 100644 --- a/bin/varnishd/VSC_main.vsc +++ b/bin/varnishd/VSC_main.vsc @@ -335,7 +335,9 @@ :oneliner: Requests reset Number of times a client left before the VCL processing of its - requests completed. + requests completed. For HTTP/2 sessions, either the stream was + reset by an RST_STREAM frame from the client, or a stream or + connection error occurred. .. varnish_vsc:: n_object :type: gauge diff --git a/bin/varnishd/http2/cache_http2_session.c b/bin/varnishd/http2/cache_http2_session.c index 8665761c325..add9b7d6c65 100644 --- a/bin/varnishd/http2/cache_http2_session.c +++ b/bin/varnishd/http2/cache_http2_session.c @@ -442,6 +442,16 @@ h2_new_session(struct worker *wrk, void *arg) wrk->vsl = NULL; } +static int v_matchproto_(vtr_poll_f) +h2_poll(struct req *req) +{ + struct h2_req *r2; + + CHECK_OBJ_NOTNULL(req, REQ_MAGIC); + CAST_OBJ_NOTNULL(r2, req->transport_priv, H2_REQ_MAGIC); + return (r2->error ? -1 : 1); +} + struct transport H2_transport = { .name = "H2", .magic = TRANSPORT_MAGIC, @@ -451,4 +461,5 @@ struct transport H2_transport = { .req_body = h2_req_body, .req_fail = h2_req_fail, .sess_panic = h2_sess_panic, + .poll = h2_poll, }; diff --git a/bin/varnishtest/tests/t02014.vtc b/bin/varnishtest/tests/t02014.vtc index 8add78a0d37..f4083c89077 100644 --- a/bin/varnishtest/tests/t02014.vtc +++ b/bin/varnishtest/tests/t02014.vtc @@ -5,6 +5,9 @@ barrier b2 sock 3 barrier b3 sock 3 barrier b4 sock 3 +barrier b2_err cond 2 +barrier b3_err cond 2 + server s1 { rxreq txresp -bodylen 66300 @@ -64,6 +67,13 @@ client c1 { stream 0 -wait } -run +varnish v1 -vsl_catchup + +logexpect l2 -v v1 -g raw { + expect * * ReqMethod GET + expect * = VCL_call DELIVER +} -start + client c2 { stream 0 { barrier b2 sync @@ -71,6 +81,7 @@ client c2 { stream 1 { txreq -hdr barrier ${b2_sock} + barrier b2_err sync txdata -data "fail" rxrst expect rst.err == STREAM_CLOSED @@ -78,7 +89,17 @@ client c2 { } -run stream 0 -wait -} -run +} -start + +logexpect l2 -wait +barrier b2_err sync + +client c2 -wait + +logexpect l3 -v v1 -g raw { + expect * * ReqMethod POST + expect * = VCL_call DELIVER +} -start client c3 { stream 0 { @@ -96,6 +117,7 @@ client c3 { stream 1 { txreq -req "POST" -hdr barrier ${b3_sock} -nostrend txdata -data "ok" + barrier b3_err sync txdata -data "fail" rxrst expect rst.err == STREAM_CLOSED @@ -117,4 +139,9 @@ client c3 { } -run stream 0 -wait -} -run +} -start + +logexpect l3 -wait +barrier b3_err sync + +client c3 -wait diff --git a/bin/varnishtest/tests/t02025.vtc b/bin/varnishtest/tests/t02025.vtc new file mode 100644 index 00000000000..578dbf5c84b --- /dev/null +++ b/bin/varnishtest/tests/t02025.vtc @@ -0,0 +1,52 @@ +varnishtest "h2 reset interrupt" + +barrier b1 sock 2 +barrier b2 sock 2 + +varnish v1 -cliok "param.set feature +http2" +varnish v1 -cliok "param.set debug +syncvsl" +varnish v1 -vcl { + import vtc; + + backend be none; + + sub vcl_recv { + vtc.barrier_sync("${b1_sock}"); + vtc.barrier_sync("${b2_sock}"); + } + + sub vcl_miss { + vtc.panic("unreachable"); + } +} -start + +logexpect l1 -v v1 -g raw -i Debug { + expect * * Debug "^H2RXF RST_STREAM" +} -start + +client c1 { + stream 1 { + txreq + barrier b1 sync + txrst + } -run + expect_close +} -start + +logexpect l1 -wait +barrier b2 sync + +client c1 -wait + +varnish v1 -vsl_catchup +varnish v1 -expect req_reset == 1 + +# NB: The varnishncsa command below shows a minimal pattern to collect +# "rapid reset" suspects per session, with the IP address. Here rapid +# is interpreted as before a second elapsed. Session VXIDs showing up +# numerous times become increasingly more suspicious. The format can of +# course be extended to add anything else useful for data mining. +shell -expect "1000 ${localhost}" { + varnishncsa -n ${v1_name} -d \ + -q 'Timestamp:Reset[2] < 1.0' -F '%{VSL:Begin[2]}x %h' +} diff --git a/doc/sphinx/reference/vsl.rst b/doc/sphinx/reference/vsl.rst index ec1814ff85b..b52956226e1 100644 --- a/doc/sphinx/reference/vsl.rst +++ b/doc/sphinx/reference/vsl.rst @@ -72,7 +72,8 @@ Restart Client request is being restarted. Reset - The client closed its connection or reset its stream. Request + The client closed its connection, reset its stream or caused + a stream error that forced Varnish to reset the stream. Request processing is interrupted and considered failed. Pipe handling timestamps From 0d1928f625c72a46ab13d0a1e8f0d0e257296a23 Mon Sep 17 00:00:00 2001 From: Dridi Boukelmoune Date: Tue, 31 Aug 2021 07:32:13 +0200 Subject: [PATCH 6/6] stevedore: Set up nuke_limit for buffer allocations --- bin/varnishd/storage/stevedore.c | 1 + 1 file changed, 1 insertion(+) diff --git a/bin/varnishd/storage/stevedore.c b/bin/varnishd/storage/stevedore.c index a6c124fc46b..1f79fca43a3 100644 --- a/bin/varnishd/storage/stevedore.c +++ b/bin/varnishd/storage/stevedore.c @@ -120,6 +120,7 @@ STV_AllocBuf(struct worker *wrk, const struct stevedore *stv, size_t size) if (stv->allocbuf == NULL) return (NULL); + wrk->strangelove = cache_param->nuke_limit; buf = stv->allocbuf(wrk, stv, size + PRNDUP(sizeof *stvbuf), &priv); if (buf == NULL) return (NULL);