diff --git a/bin/varnishd/VSC_main.vsc b/bin/varnishd/VSC_main.vsc index 0978c2f..a9a1431 100644 --- a/bin/varnishd/VSC_main.vsc +++ b/bin/varnishd/VSC_main.vsc @@ -648,6 +648,14 @@ configured limits for the number of permitted rapid stream resets. +.. varnish_vsc:: sc_bankrupt + :level: diag + :oneliner: Session Err BANKRUPT + + Number of times we failed an http/2 session because all the streams + were waiting for their windows to be credited when h2_window_timeout + triggered. + .. varnish_vsc:: client_resp_500 :level: diag :group: wrk diff --git a/bin/varnishd/http2/cache_http2.h b/bin/varnishd/http2/cache_http2.h index 9088e21..78d7824 100644 --- a/bin/varnishd/http2/cache_http2.h +++ b/bin/varnishd/http2/cache_http2.h @@ -44,15 +44,17 @@ struct h2_error_s { uint32_t val; int stream; int connection; + int send_goaway; enum sess_close reason; }; typedef const struct h2_error_s *h2_error; -#define H2EC1(U,v,r,d) extern const struct h2_error_s H2CE_##U[1]; -#define H2EC2(U,v,r,d) extern const struct h2_error_s H2SE_##U[1]; -#define H2EC3(U,v,r,d) H2EC1(U,v,r,d) H2EC2(U,v,r,d) -#define H2_ERROR(NAME, val, sc, reason, desc) H2EC##sc(NAME, val, reason, desc) +#define H2EC1(U,v,g,r,d) extern const struct h2_error_s H2CE_##U[1]; +#define H2EC2(U,v,g,r,d) extern const struct h2_error_s H2SE_##U[1]; +#define H2EC3(U,v,g,r,d) H2EC1(U,v,g,r,d) H2EC2(U,v,g,r,d) +#define H2_ERROR(NAME, val, sc, goaway, reason, desc) \ + H2EC##sc(NAME, val, goaway, reason, desc) #include "tbl/h2_error.h" #undef H2EC1 #undef H2EC2 @@ -153,8 +155,10 @@ struct h2_sess { struct sess *sess; int refcnt; - unsigned open_streams; + int open_streams; + int winup_streams; uint32_t highest_stream; + int goaway; int bogosity; int do_sweep; @@ -238,7 +242,7 @@ void H2_Send(struct worker *, struct h2_req *, h2_frame type, uint8_t flags, /* cache_http2_proto.c */ struct h2_req * h2_new_req(const struct worker *, struct h2_sess *, unsigned stream, struct req *); -int h2_stream_tmo(struct h2_sess *, const struct h2_req *, vtim_real); +h2_error h2_stream_tmo(struct h2_sess *, const struct h2_req *, vtim_real); void h2_del_req(struct worker *, const struct h2_req *); void h2_kill_req(struct worker *, struct h2_sess *, struct h2_req *, h2_error); int h2_rxframe(struct worker *, struct h2_sess *); diff --git a/bin/varnishd/http2/cache_http2_proto.c b/bin/varnishd/http2/cache_http2_proto.c index 408acad..d4e04ce 100644 --- a/bin/varnishd/http2/cache_http2_proto.c +++ b/bin/varnishd/http2/cache_http2_proto.c @@ -46,10 +46,13 @@ #include "vtim.h" #define H2_CUSTOM_ERRORS -#define H2EC1(U,v,r,d) const struct h2_error_s H2CE_##U[1] = {{#U,d,v,0,1,r}}; -#define H2EC2(U,v,r,d) const struct h2_error_s H2SE_##U[1] = {{#U,d,v,1,0,r}}; -#define H2EC3(U,v,r,d) H2EC1(U,v,r,d) H2EC2(U,v,r,d) -#define H2_ERROR(NAME, val, sc, reason, desc) H2EC##sc(NAME, val, reason, desc) +#define H2EC1(U,v,g,r,d) \ + const struct h2_error_s H2CE_##U[1] = {{#U,d,v,0,1,g,r}}; +#define H2EC2(U,v,g,r,d) \ + const struct h2_error_s H2SE_##U[1] = {{#U,d,v,1,0,g,r}}; +#define H2EC3(U,v,g,r,d) H2EC1(U,v,g,r,d) H2EC2(U,v,g,r,d) +#define H2_ERROR(NAME, val, sc, goaway, reason, desc) \ + H2EC##sc(NAME, val, goaway, reason, desc) #include "tbl/h2_error.h" #undef H2EC1 #undef H2EC2 @@ -61,6 +64,7 @@ static const struct h2_error_s H2NN_ERROR[1] = {{ 0xffffffff, 1, 1, + 0, SC_RX_JUNK }}; @@ -88,10 +92,11 @@ h2_framename(enum h2frame h2f) */ static const h2_error stream_errors[] = { -#define H2EC1(U,v,r,d) -#define H2EC2(U,v,r,d) [v] = H2SE_##U, -#define H2EC3(U,v,r,d) H2EC1(U,v,r,d) H2EC2(U,v,r,d) -#define H2_ERROR(NAME, val, sc, reason, desc) H2EC##sc(NAME, val, reason, desc) +#define H2EC1(U,v,g,r,d) +#define H2EC2(U,v,g,r,d) [v] = H2SE_##U, +#define H2EC3(U,v,g,r,d) H2EC1(U,v,g,r,d) H2EC2(U,v,g,r,d) +#define H2_ERROR(NAME, val, sc, goaway, reason, desc) \ + H2EC##sc(NAME, val, goaway, reason, desc) #include "tbl/h2_error.h" #undef H2EC1 #undef H2EC2 @@ -113,10 +118,11 @@ h2_streamerror(uint32_t u) */ static const h2_error conn_errors[] = { -#define H2EC1(U,v,r,d) [v] = H2CE_##U, -#define H2EC2(U,v,r,d) -#define H2EC3(U,v,r,d) H2EC1(U,v,r,d) H2EC2(U,v,r,d) -#define H2_ERROR(NAME, val, sc, reason, desc) H2EC##sc(NAME, val, reason, desc) +#define H2EC1(U,v,g,r,d) [v] = H2CE_##U, +#define H2EC2(U,v,g,r,d) +#define H2EC3(U,v,g,r,d) H2EC1(U,v,g,r,d) H2EC2(U,v,g,r,d) +#define H2_ERROR(NAME, val, sc, goaway, reason, desc) \ + H2EC##sc(NAME, val, goaway, reason, desc) #include "tbl/h2_error.h" #undef H2EC1 #undef H2EC2 @@ -371,6 +377,7 @@ h2_rx_goaway(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2) CHECK_OBJ_NOTNULL(r2, H2_REQ_MAGIC); assert(r2 == h2->req0); + h2->goaway = 1; h2->goaway_last_stream = vbe32dec(h2->rxf_data); h2->error = h2_connectionerror(vbe32dec(h2->rxf_data + 4)); Lck_Lock(&h2->sess->mtx); @@ -379,6 +386,25 @@ h2_rx_goaway(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2) return (h2->error); } +static void +h2_tx_goaway(struct worker *wrk, struct h2_sess *h2, h2_error h2e) +{ + char b[8]; + + ASSERT_RXTHR(h2); + AN(h2e); + + if (h2->goaway || !h2e->send_goaway) + return; + + h2->goaway = 1; + vbe32enc(b, h2->highest_stream); + vbe32enc(b + 4, h2e->val); + H2_Send_Get(wrk, h2, h2->req0); + H2_Send_Frame(wrk, h2, H2_F_GOAWAY, 0, 8, 0, b); + H2_Send_Rel(h2, h2->req0); +} + /********************************************************************** */ @@ -799,9 +825,9 @@ h2_rx_data(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2) Lck_Lock(&h2->sess->mtx); while (h2->mailcall != NULL && h2->error == 0 && r2->error == 0) AZ(Lck_CondWait(h2->cond, &h2->sess->mtx, 0)); - if (h2->error || r2->error) { + if (h2->error != NULL || r2->error != NULL) { Lck_Unlock(&h2->sess->mtx); - return (h2->error ? h2->error : r2->error); + return (h2->error != NULL ? h2->error : r2->error); } r2->reqbody_bytes += h2->rxf_len; @@ -879,7 +905,7 @@ h2_vfp_body(struct vfp_ctx *vc, struct vfp_entry *vfe, void *ptr, ssize_t *lp) while (h2->mailcall != r2 && h2->error == 0 && r2->error == 0) AZ(Lck_CondWait(r2->cond, &h2->sess->mtx, 0)); r2->cond = NULL; - if (h2->error || r2->error) { + if (h2->error != NULL || r2->error != NULL) { retval = VFP_ERROR; } else { assert(h2->mailcall == r2); @@ -1013,82 +1039,91 @@ h2_procframe(struct worker *wrk, struct h2_sess *h2, h2_frame h2f) if (r2->stream == h2->rxf_stream) break; - if (h2->new_req != NULL && - !(r2 && h2->new_req == r2->req && h2f == H2_F_CONTINUATION)) + if (h2->new_req != NULL && h2f != H2_F_CONTINUATION) return (H2CE_PROTOCOL_ERROR); // rfc7540,l,1859,1863 h2e = h2f->rxfunc(wrk, h2, r2); - if (h2e == 0) - return (0); + if (h2e == NULL) + return (NULL); if (h2->rxf_stream == 0 || h2e->connection) return (h2e); // Connection errors one level up H2_Send_Get(wrk, h2, h2->req0); H2_Send_RST(wrk, h2, h2->req0, h2->rxf_stream, h2e); H2_Send_Rel(h2, h2->req0); - return (0); + return (NULL); } -int +h2_error h2_stream_tmo(struct h2_sess *h2, const struct h2_req *r2, vtim_real now) { - int r = 0; + h2_error h2e = NULL; CHECK_OBJ_NOTNULL(h2, H2_SESS_MAGIC); CHECK_OBJ_NOTNULL(r2, H2_REQ_MAGIC); Lck_AssertHeld(&h2->sess->mtx); - /* NB: when now is NAN, it means that idle_send_timeout was hit + /* NB: when now is NAN, it means that h2_window_timeout was hit * on a lock condwait operation. */ if (isnan(now)) AN(r2->t_winupd); - + + if (h2->error != NULL && h2->error->connection && + !h2->error->send_goaway) + return (h2->error); + if (r2->t_winupd == 0 && r2->t_send == 0) - return (0); + return (NULL); if (isnan(now) || (r2->t_winupd != 0 && - now - r2->t_winupd > SESS_TMO(h2->sess, idle_send_timeout))) { + now - r2->t_winupd > cache_param->h2_window_timeout)) { VSLb(h2->vsl, SLT_Debug, - "H2: stream %u: Hit idle_send_timeout waiting for" - " WINDOW_UPDATE", r2->stream); - r = 1; + "H2: stream %u: Hit h2_window_timeout", r2->stream); + h2e = H2SE_BROKE_WINDOW; } - if (r == 0 && r2->t_send != 0 && + if (h2e == NULL && r2->t_send != 0 && now - r2->t_send > SESS_TMO(h2->sess, send_timeout)) { VSLb(h2->vsl, SLT_Debug, "H2: stream %u: Hit send_timeout", r2->stream); - r = 1; + h2e = H2SE_CANCEL; } - return (r); + return (h2e); } -static int +static h2_error h2_stream_tmo_unlocked(struct h2_sess *h2, const struct h2_req *r2) { - int r; + h2_error h2e; Lck_Lock(&h2->sess->mtx); - r = h2_stream_tmo(h2, r2, h2->sess->t_idle); + h2e = h2_stream_tmo(h2, r2, h2->sess->t_idle); Lck_Unlock(&h2->sess->mtx); - return (r); + return (h2e); } /* * This is the janitorial task of cleaning up any closed & refused * streams, and checking if the session is timed out. */ -static int +static h2_error h2_sweep(struct worker *wrk, struct h2_sess *h2) { - int tmo = 0; struct h2_req *r2, *r22; + h2_error h2e, tmo; + vtim_real now; ASSERT_RXTHR(h2); + h2e = h2->error; + now = VTIM_real(); + if (h2e == NULL && h2->open_streams == 0 && + h2->sess->t_idle + cache_param->timeout_idle < now) + h2e = H2CE_NO_ERROR; + h2->do_sweep = 0; VTAILQ_FOREACH_SAFE(r2, &h2->streams, list, r22) { if (r2 == h2->req0) { @@ -1112,10 +1147,9 @@ h2_sweep(struct worker *wrk, struct h2_sess *h2) /* FALLTHROUGH */ case H2_S_CLOS_LOC: case H2_S_OPEN: - if (h2_stream_tmo_unlocked(h2, r2)) { - tmo = 1; - continue; - } + tmo = h2_stream_tmo_unlocked(h2, r2); + if (h2e == NULL) + h2e = tmo; break; case H2_S_IDLE: /* Current code make this unreachable: h2_new_req is @@ -1127,9 +1161,7 @@ h2_sweep(struct worker *wrk, struct h2_sess *h2) break; } } - if (tmo) - return (0); - return (h2->refcnt > 1); + return (h2e); } @@ -1154,34 +1186,38 @@ h2_rxframe(struct worker *wrk, struct h2_sess *h2) enum htc_status_e hs; h2_frame h2f; h2_error h2e; - char b[8]; ASSERT_RXTHR(h2); + + if (h2->goaway && h2->open_streams == 0) + return (0); + VTCP_blocking(*h2->htc->rfd); - h2->sess->t_idle = VTIM_real(); - hs = HTC_RxStuff(h2->htc, h2_frame_complete, - NULL, NULL, NAN, - h2->sess->t_idle + SESS_TMO(h2->sess, timeout_idle), - NAN, h2->local_settings.max_frame_size + 9); + hs = HTC_RxStuff(h2->htc, h2_frame_complete, NULL, NULL, NAN, + VTIM_real() + 0.5, NAN, h2->local_settings.max_frame_size + 9); + + h2e = NULL; switch (hs) { case HTC_S_COMPLETE: + h2->sess->t_idle = VTIM_real(); + if (h2->do_sweep) + h2e = h2_sweep(wrk, h2); break; case HTC_S_TIMEOUT: - if (h2_sweep(wrk, h2)) - return (1); - - /* FALLTHROUGH */ + h2e = h2_sweep(wrk, h2); + break; default: - /* XXX: HTC_S_OVERFLOW / FRAME_SIZE_ERROR handling */ - Lck_Lock(&h2->sess->mtx); - VSLb(h2->vsl, SLT_Debug, "H2: No frame (hs=%d)", hs); - h2->error = H2CE_NO_ERROR; - Lck_Unlock(&h2->sess->mtx); + h2e = H2CE_ENHANCE_YOUR_CALM; + } + + if (h2e != NULL && h2e->connection) { + h2->error = h2e; + h2_tx_goaway(wrk, h2, h2e); return (0); } - if (h2->do_sweep) - (void)h2_sweep(wrk, h2); + if (hs != HTC_S_COMPLETE) + return (1); h2->rxf_len = vbe32dec(h2->htc->rxbuf_b) >> 8; h2->rxf_type = h2->htc->rxbuf_b[3]; @@ -1226,13 +1262,10 @@ h2_rxframe(struct worker *wrk, struct h2_sess *h2) } h2e = h2_procframe(wrk, h2, h2f); - if (h2->error == 0 && h2e) { + if (h2->error == NULL && h2e != NULL) { h2->error = h2e; - vbe32enc(b, h2->highest_stream); - vbe32enc(b + 4, h2e->val); - H2_Send_Get(wrk, h2, h2->req0); - H2_Send_Frame(wrk, h2, H2_F_GOAWAY, 0, 8, 0, b); - H2_Send_Rel(h2, h2->req0); + h2_tx_goaway(wrk, h2, h2e); } - return (h2->error ? 0 : 1); + + return (h2->error != NULL ? 0 : 1); } diff --git a/bin/varnishd/http2/cache_http2_send.c b/bin/varnishd/http2/cache_http2_send.c index a684b94..9043901 100644 --- a/bin/varnishd/http2/cache_http2_send.c +++ b/bin/varnishd/http2/cache_http2_send.c @@ -43,10 +43,24 @@ #define H2_SEND_HELD(h2, r2) (VTAILQ_FIRST(&(h2)->txqueue) == (r2)) +static h2_error +h2_errcheck(const struct h2_req *r2, const struct h2_sess *h2) +{ + CHECK_OBJ_NOTNULL(r2, H2_REQ_MAGIC); + CHECK_OBJ_NOTNULL(h2, H2_SESS_MAGIC); + + if (r2->error != NULL) + return (r2->error); + if (h2->error != NULL && r2->stream > h2->goaway_last_stream) + return (h2->error); + return (NULL); +} + static int h2_cond_wait(pthread_cond_t *cond, struct h2_sess *h2, struct h2_req *r2) { vtim_real now, when = 0.; + h2_error h2e; int r; AN(cond); @@ -56,8 +70,8 @@ h2_cond_wait(pthread_cond_t *cond, struct h2_sess *h2, struct h2_req *r2) Lck_AssertHeld(&h2->sess->mtx); now = VTIM_real(); - if (cache_param->idle_send_timeout > 0.) - when = now + cache_param->idle_send_timeout; + if (cache_param->h2_window_timeout > 0.) + when = now + cache_param->h2_window_timeout; r = Lck_CondWait(cond, &h2->sess->mtx, when); assert(r == 0 || r == ETIMEDOUT); @@ -66,24 +80,23 @@ h2_cond_wait(pthread_cond_t *cond, struct h2_sess *h2, struct h2_req *r2) /* NB: when we grab idle_send_timeout before acquiring the session * lock we may time out, but once we wake up both send_timeout and - * idle_send_timeout may have changed meanwhile. For this reason + * h2_window_timeout may have changed meanwhile. For this reason * h2_stream_tmo() may not log what timed out and we need to call * again with a magic NAN "now" that indicates to h2_stream_tmo() - * that the stream reached the idle_send_timeout via the lock and + * that the stream reached the h2_window_timeout via the lock and * force it to log it. */ - if (h2_stream_tmo(h2, r2, now)) - r = ETIMEDOUT; - else if (r == ETIMEDOUT) - AN(h2_stream_tmo(h2, r2, NAN)); - - if (r == ETIMEDOUT) { - if (r2->error == NULL) - r2->error = H2SE_CANCEL; - return (-1); + h2e = h2_stream_tmo(h2, r2, now); + + if (h2e == NULL && r == ETIMEDOUT) { + h2e = h2_stream_tmo(h2, r2, NAN); + AN(h2e); } - return (0); + if (r2->error == NULL) + r2->error = h2e; + + return (h2e != NULL ? -1 : 0); } static void @@ -196,6 +209,10 @@ H2_Send_Frame(struct worker *wrk, struct h2_sess *h2, iov[1].iov_len = len; s = writev(h2->sess->fd, iov, len == 0 ? 1 : 2); if (s != sizeof hdr + len) { + if (errno == EWOULDBLOCK) { + VSLb(h2->vsl, SLT_Debug, + "H2: stream %u: Hit idle_send_timeout", stream); + } /* * There is no point in being nice here, we will be unable * to send a GOAWAY once the code unrolls, so go directly @@ -237,19 +254,6 @@ h2_win_charge(struct h2_req *r2, const struct h2_sess *h2, uint32_t w) h2->req0->t_window -= w; } -static h2_error -h2_errcheck(const struct h2_req *r2, const struct h2_sess *h2) -{ - CHECK_OBJ_NOTNULL(r2, H2_REQ_MAGIC); - CHECK_OBJ_NOTNULL(h2, H2_SESS_MAGIC); - - if (r2->error) - return (r2->error); - if (h2->error && r2->stream > h2->goaway_last_stream) - return (h2->error); - return (0); -} - static int64_t h2_do_window(struct worker *wrk, struct h2_req *r2, struct h2_sess *h2, int64_t wanted) @@ -267,25 +271,35 @@ h2_do_window(struct worker *wrk, struct h2_req *r2, if (r2->t_window <= 0 || h2->req0->t_window <= 0) { r2->t_winupd = VTIM_real(); h2_send_rel_locked(h2, r2); - while (r2->t_window <= 0 && h2_errcheck(r2, h2) == 0) { + + assert(h2->winup_streams >= 0); + h2->winup_streams++; + + while (r2->t_window <= 0 && h2_errcheck(r2, h2) == NULL) { r2->cond = &wrk->cond; (void)h2_cond_wait(r2->cond, h2, r2); r2->cond = NULL; } - while (h2->req0->t_window <= 0 && h2_errcheck(r2, h2) == 0) + while (h2->req0->t_window <= 0 && h2_errcheck(r2, h2) == NULL) (void)h2_cond_wait(h2->winupd_cond, h2, r2); - if (h2_errcheck(r2, h2) == 0) { - w = h2_win_limit(r2, h2); - if (w > wanted) - w = wanted; + if (h2_errcheck(r2, h2) == NULL) { + w = vmin_t(int64_t, h2_win_limit(r2, h2), wanted); h2_win_charge(r2, h2, w); assert (w > 0); } + + if (r2->error == H2SE_BROKE_WINDOW && + h2->open_streams <= h2->winup_streams) + h2->error = r2->error = H2CE_BANKRUPT; + + assert(h2->winup_streams > 0); + h2->winup_streams--; + h2_send_get_locked(wrk, h2, r2); } - if (w == 0 && h2_errcheck(r2, h2) == 0) { + if (w == 0 && h2_errcheck(r2, h2) == NULL) { assert(r2->t_window > 0); assert(h2->req0->t_window > 0); w = h2_win_limit(r2, h2); @@ -322,7 +336,7 @@ h2_send(struct worker *wrk, struct h2_req *r2, h2_frame ftyp, uint8_t flags, AN(H2_SEND_HELD(h2, r2)); - if (h2_errcheck(r2, h2)) + if (h2_errcheck(r2, h2) != NULL) return; AN(ftyp); @@ -368,7 +382,7 @@ h2_send(struct worker *wrk, struct h2_req *r2, h2_frame ftyp, uint8_t flags, if (ftyp->respect_window && p != ptr) { tf = h2_do_window(wrk, r2, h2, (len > mfs) ? mfs : len); - if (h2_errcheck(r2, h2)) + if (h2_errcheck(r2, h2) != NULL) return; AN(H2_SEND_HELD(h2, r2)); } @@ -389,7 +403,7 @@ h2_send(struct worker *wrk, struct h2_req *r2, h2_frame ftyp, uint8_t flags, ftyp = ftyp->continuation; flags &= ftyp->flags; final_flags &= ftyp->flags; - } while (!h2->error && len > 0); + } while (h2->error == NULL && len > 0); } } @@ -402,6 +416,7 @@ H2_Send_RST(struct worker *wrk, struct h2_sess *h2, const struct h2_req *r2, CHECK_OBJ_NOTNULL(h2, H2_SESS_MAGIC); CHECK_OBJ_NOTNULL(r2, H2_REQ_MAGIC); AN(H2_SEND_HELD(h2, r2)); + AN(h2e); Lck_Lock(&h2->sess->mtx); VSLb(h2->vsl, SLT_Debug, "H2: stream %u: %s", stream, h2e->txt); @@ -416,12 +431,15 @@ H2_Send(struct worker *wrk, struct h2_req *r2, h2_frame ftyp, uint8_t flags, uint32_t len, const void *ptr, uint64_t *counter) { uint64_t dummy_counter; + h2_error h2e; if (counter == NULL) counter = &dummy_counter; h2_send(wrk, r2, ftyp, flags, len, ptr, counter); - if (h2_errcheck(r2, r2->h2sess) == H2SE_CANCEL) - H2_Send_RST(wrk, r2->h2sess, r2, r2->stream, H2SE_CANCEL); + h2e = h2_errcheck(r2, r2->h2sess); + if (h2e != NULL && h2e->val == H2SE_CANCEL->val) + H2_Send_RST(wrk, r2->h2sess, r2, r2->stream, h2e); + } diff --git a/bin/varnishtest/tests/t02003.vtc b/bin/varnishtest/tests/t02003.vtc index 1d62ac9..fe30e82 100644 --- a/bin/varnishtest/tests/t02003.vtc +++ b/bin/varnishtest/tests/t02003.vtc @@ -233,17 +233,28 @@ client c1 { } -run client c1 { + stream 0 { + rxgoaway + expect goaway.err == NO_ERROR + expect goaway.laststream == 3 + } -start stream 1 { - txreq -nohdrend + txreq -nostrend txrst -err 2 } -run stream 3 { - txreq -nohdrend + txreq -nostrend txrst -err 0x666 } -run + stream 0 -wait } -run client c1 { + stream 0 { + rxgoaway + expect goaway.err == NO_ERROR + expect goaway.laststream == 1 + } -start stream 1 { txreq rxresp @@ -252,6 +263,7 @@ client c1 { # RST_STREAM on closed stream txrst } -run + stream 0 -wait } -run diff --git a/bin/varnishtest/tests/t02005.vtc b/bin/varnishtest/tests/t02005.vtc index 03c9a85..9aff481 100644 --- a/bin/varnishtest/tests/t02005.vtc +++ b/bin/varnishtest/tests/t02005.vtc @@ -27,7 +27,7 @@ varnish v1 -cliok "param.set debug +syncvsl" logexpect l1 -v v1 -g raw { expect * 1001 ReqAcct "80 7 87 106 8 114" - expect * 1000 ReqAcct "45 8 53 54 20 74" + expect * 1000 ReqAcct "45 8 53 63 28 91" } -start client c1 { diff --git a/bin/varnishtest/tests/t02016.vtc b/bin/varnishtest/tests/t02016.vtc index 29ffea3..1e5a7dc 100644 --- a/bin/varnishtest/tests/t02016.vtc +++ b/bin/varnishtest/tests/t02016.vtc @@ -6,7 +6,13 @@ server s1 { } -start varnish v1 -cliok "param.set feature +http2" -varnish v1 -vcl+backend "" -start +varnish v1 -vcl+backend { + sub vcl_recv { + if (req.url ~ "synth") { + return (synth(200)); + } + } +} -start # coverage for send_timeout with c1 @@ -44,13 +50,13 @@ client c1 { logexpect l1 -wait -# coverage for idle_send_timeout with c2 +# coverage for h2_window_timeout with c2 -varnish v1 -cliok "param.set idle_send_timeout 1" +varnish v1 -cliok "param.set h2_window_timeout 1" varnish v1 -cliok "param.reset send_timeout" logexpect l2 -v v1 { - expect * * Debug "Hit idle_send_timeout" + expect * * Debug "Hit h2_window_timeout" } -start client c2 { @@ -66,6 +72,10 @@ client c2 { } -run stream 1 { + txreq -nostrend -url "/synth" + } -run + + stream 3 { txreq rxhdrs rxdata @@ -75,16 +85,19 @@ client c2 { expect rst.err == CANCEL } -run + stream 1 { + txdata + } -run } -run logexpect l2 -wait -# coverage for idle_send_timeout change with c3 +# coverage for h2_window_timeout change with c3 barrier b3 cond 2 logexpect l3 -v v1 { - expect * * Debug "Hit idle_send_timeout" + expect * * Debug "Hit h2_window_timeout" } -start client c3 { @@ -100,6 +113,10 @@ client c3 { } -run stream 1 { + txreq -nostrend -url "/synth" + } -run + + stream 3 { txreq rxhdrs rxdata @@ -110,10 +127,13 @@ client c3 { expect rst.err == CANCEL } -run + stream 1 { + txdata + } -run } -start barrier b3 sync -varnish v1 -cliok "param.reset idle_send_timeout" +varnish v1 -cliok "param.reset h2_window_timeout" client c3 -wait logexpect l3 -wait diff --git a/bin/varnishtest/tests/t02025.vtc b/bin/varnishtest/tests/t02025.vtc index 3b7e90e..9a502a7 100644 --- a/bin/varnishtest/tests/t02025.vtc +++ b/bin/varnishtest/tests/t02025.vtc @@ -25,11 +25,17 @@ logexpect l1 -v v1 -g raw -i Debug { } -start client c1 { + stream 0 { + rxgoaway + expect goaway.err == NO_ERROR + expect goaway.laststream == 1 + } -start stream 1 { txreq barrier b1 sync txrst } -run + stream 0 -wait } -start logexpect l1 -wait diff --git a/bin/varnishtest/vtc_http2.c b/bin/varnishtest/vtc_http2.c index be80d32..23ffc5d 100644 --- a/bin/varnishtest/vtc_http2.c +++ b/bin/varnishtest/vtc_http2.c @@ -52,7 +52,7 @@ #define BUF_SIZE (1024*2048) static const char *const h2_errs[] = { -#define H2_ERROR(n,v,sc,r,t) [v] = #n, +#define H2_ERROR(n,v,sc,g,r,t) [v] = #n, #include NULL }; @@ -1228,7 +1228,7 @@ cmd_var_resolve(const struct stream *s, const char *spec, char *buf) else return (NULL); } -#define H2_ERROR(U,v,sc,r,t) \ +#define H2_ERROR(U,v,sc,g,r,t) \ if (!strcmp(spec, #U)) { return (#v); } #include "tbl/h2_error.h" return (spec); diff --git a/include/tbl/h2_error.h b/include/tbl/h2_error.h index 11051de..ef34caa 100644 --- a/include/tbl/h2_error.h +++ b/include/tbl/h2_error.h @@ -39,6 +39,7 @@ H2_ERROR( /* name */ NO_ERROR, /* val */ 0, /* types */ 3, + /* goaway */ 1, /* reason */ SC_REM_CLOSE, /* descr */ "Graceful shutdown" ) @@ -47,6 +48,7 @@ H2_ERROR( /* name */ PROTOCOL_ERROR, /* val */ 1, /* types */ 3, + /* goaway */ 1, /* reason */ SC_RX_JUNK, /* descr */ "Protocol error detected" ) @@ -55,6 +57,7 @@ H2_ERROR( /* name */ INTERNAL_ERROR, /* val */ 2, /* types */ 3, + /* goaway */ 1, /* reason */ SC_VCL_FAILURE, /* descr */ "Implementation fault" ) @@ -63,6 +66,7 @@ H2_ERROR( /* name */ FLOW_CONTROL_ERROR, /* val */ 3, /* types */ 3, + /* goaway */ 1, /* reason */ SC_OVERLOAD, /* descr */ "Flow-control limits exceeded" ) @@ -71,6 +75,7 @@ H2_ERROR( /* name */ SETTINGS_TIMEOUT, /* val */ 4, /* types */ 1, + /* goaway */ 1, /* reason */ SC_RX_TIMEOUT, /* descr */ "Settings not acknowledged" ) @@ -79,6 +84,7 @@ H2_ERROR( /* name */ STREAM_CLOSED, /* val */ 5, /* types */ 2, + /* goaway */ 1, /* reason */ SC_NULL, /* descr */ "Frame received for closed stream" ) @@ -87,6 +93,7 @@ H2_ERROR( /* name */ FRAME_SIZE_ERROR, /* val */ 6, /* types */ 3, + /* goaway */ 1, /* reason */ SC_RX_JUNK, /* descr */ "Frame size incorrect" ) @@ -95,6 +102,7 @@ H2_ERROR( /* name */ REFUSED_STREAM, /* val */ 7, /* types */ 2, + /* goaway */ 1, /* reason */ SC_NULL, /* descr */ "Stream not processed" ) @@ -103,6 +111,7 @@ H2_ERROR( /* name */ CANCEL, /* val */ 8, /* types */ 2, + /* goaway */ 1, /* reason */ SC_NULL, /* descr */ "Stream cancelled" ) @@ -111,6 +120,7 @@ H2_ERROR( /* name */ COMPRESSION_ERROR, /* val */ 9, /* types */ 1, + /* goaway */ 1, /* reason */ SC_RX_JUNK, /* descr */ "Compression state not updated" ) @@ -119,6 +129,7 @@ H2_ERROR( /* name */ CONNECT_ERROR, /* val */ 10, /* types */ 2, + /* goaway */ 1, /* reason */ SC_NULL, /* descr */ "TCP connection error for CONNECT method" ) @@ -127,6 +138,7 @@ H2_ERROR( /* name */ ENHANCE_YOUR_CALM, /* val */ 11, /* types */ 3, + /* goaway */ 1, /* reason */ SC_OVERLOAD, /* descr */ "Processing capacity exceeded" ) @@ -135,6 +147,7 @@ H2_ERROR( /* name */ INADEQUATE_SECURITY, /* val */ 12, /* types */ 1, + /* goaway */ 1, /* reason */ SC_RX_JUNK, /* descr */ "Negotiated TLS parameters not acceptable" ) @@ -143,6 +156,7 @@ H2_ERROR( /* name */ HTTP_1_1_REQUIRED, /* val */ 13, /* types */ 1, + /* goaway */ 1, /* reason */ SC_REQ_HTTP20, /* descr */ "Use HTTP/1.1 for the request" ) @@ -152,10 +166,28 @@ H2_ERROR( /* name */ RAPID_RESET, /* val */ 11, /* ENHANCE_YOUR_CALM */ /* types */ 1, + /* goaway */ 1, /* reason */ SC_RAPID_RESET, /* descr */ "http/2 rapid reset detected" ) +H2_ERROR( + /* name */ BROKE_WINDOW, + /* val */ 8, /* CANCEL */ + /* types */ 2, + /* goaway */ 0, + /* reason */ SC_NULL, + /* descr */ "http/2 stream out of window credits" +) + +H2_ERROR( + /* name */ BANKRUPT, + /* val */ 11, /* ENHANCE_YOUR_CALM */ + /* types */ 1, + /* goaway */ 0, + /* reason */ SC_BANKRUPT, + /* descr */ "http/2 bankrupt connection" +) # undef H2_CUSTOM_ERRORS #endif diff --git a/include/tbl/params.h b/include/tbl/params.h index 4014dd6..49e2cdd 100644 --- a/include/tbl/params.h +++ b/include/tbl/params.h @@ -309,7 +309,7 @@ PARAM_SIMPLE( /* type */ bytes_u, /* min */ "128b", /* max */ "99999999b", - /* def */ "48k", + /* def */ "64k", /* units */ "bytes", /* descr */ "Maximum size of CLI response. If the response exceeds this " @@ -1158,6 +1158,20 @@ PARAM_SIMPLE( /* flags */ WIZARD ) +PARAM_SIMPLE( + /* name */ h2_window_timeout, + /* type */ timeout, + /* min */ "0", + /* max */ NULL, + /* def */ "5", + /* units */ "seconds", + /* descr */ + "HTTP2 time limit without window credits. How long a stream may " + "wait for the client to credit the window and allow for more DATA " + "frames to be sent.", + /* flags */ WIZARD +) + PARAM_SIMPLE( /* name */ h2_header_table_size, /* type */ bytes_u, diff --git a/include/tbl/sess_close.h b/include/tbl/sess_close.h index 6d2f635..ef54760 100644 --- a/include/tbl/sess_close.h +++ b/include/tbl/sess_close.h @@ -51,6 +51,7 @@ 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 /*lint -restore */ diff --git a/bin/varnishd/http2/cache_http2.h b/bin/varnishd/http2/cache_http2.h index 78d7824..a36bf14 100644 --- a/bin/varnishd/http2/cache_http2.h +++ b/bin/varnishd/http2/cache_http2.h @@ -50,6 +50,7 @@ struct h2_error_s { typedef const struct h2_error_s *h2_error; +#define H2_CUSTOM_ERRORS #define H2EC1(U,v,g,r,d) extern const struct h2_error_s H2CE_##U[1]; #define H2EC2(U,v,g,r,d) extern const struct h2_error_s H2SE_##U[1]; #define H2EC3(U,v,g,r,d) H2EC1(U,v,g,r,d) H2EC2(U,v,g,r,d) diff --git a/bin/varnishtest/tests/t02025.vtc b/bin/varnishtest/tests/t02025.vtc index 9a502a7..5e02b13 100644 --- a/bin/varnishtest/tests/t02025.vtc +++ b/bin/varnishtest/tests/t02025.vtc @@ -49,7 +49,7 @@ varnish v1 -expect req_reset == 1 # 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}" { +shell -expect "1000 ${localhost} 408" { varnishncsa -n ${v1_name} -d \ - -q 'Timestamp:Reset[2] < 1.0' -F '%{VSL:Begin[2]}x %h' + -q 'Timestamp:Reset[2] < 1.0' -F '%{VSL:Begin[2]}x %h %s' } diff --git a/bin/varnishtest/tests/t02025.vtc b/bin/varnishtest/tests/t02025.vtc index 5e02b13..39f987a 100644 --- a/bin/varnishtest/tests/t02025.vtc +++ b/bin/varnishtest/tests/t02025.vtc @@ -41,6 +41,8 @@ client c1 { logexpect l1 -wait barrier b2 sync +client c1 -wait + varnish v1 -vsl_catchup varnish v1 -expect req_reset == 1 diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c index 24eac15..42b0b5f 100644 --- a/bin/varnishd/cache/cache_req_fsm.c +++ b/bin/varnishd/cache/cache_req_fsm.c @@ -279,8 +279,13 @@ cnt_vclfail(struct worker *wrk, struct req *req) Req_Rollback(ctx); - req->err_code = 503; - req->err_reason = "VCL failed"; + if (req->req_reset) { + req->err_code = 408; + req->err_reason = "Client disconnected"; + } else { + req->err_code = 503; + req->err_reason = "VCL failed"; + } req->req_step = R_STP_SYNTH; req->doclose = SC_VCL_FAILURE; req->filter_list = NULL; diff --git a/doc/sphinx/reference/vsl.rst b/doc/sphinx/reference/vsl.rst index f1ed987..845f50b 100644 --- a/doc/sphinx/reference/vsl.rst +++ b/doc/sphinx/reference/vsl.rst @@ -77,9 +77,10 @@ Restart Client request is being restarted. Reset - 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. + 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, with a 408 + "Request Timeout" status code. Pipe handling timestamps ~~~~~~~~~~~~~~~~~~~~~~~~