[master] e1a1fdc76 Start honoring [idle_]send_timeout of h2 streams
Dridi Boukelmoune
dridi.boukelmoune at gmail.com
Mon Jun 24 11:45:10 UTC 2019
commit e1a1fdc7688de5f37e35fc528639019d5bd3efbf
Author: Dridi Boukelmoune <dridi.boukelmoune at gmail.com>
Date: Fri Apr 19 11:58:14 2019 +0200
Start honoring [idle_]send_timeout of h2 streams
Unlike HTTP/1 that relies on the underlying transport, we can time
streams out simply by not crediting them. This is our first usage of
the CANCEL error with the RST frame, even though this change is not
comprehensive since the window only applies to DATA frames.
In addition to the session send timeouts, we can now kill streams that
aren't making progress and free the resources they hold onto even when
the session is continuously active.
There is one caveat though, there is currently no timeout for trying
to write to the session, so unless a client maintains a stream forever
by not crediting it we won't catch it.
For that to happen the next step could be to change this pattern:
H2_Send_Get(...);
/* send something */
H2_Send_Rel(...);
And instead check a return value:
if (H2_Send_Get(...) == 0) {
/* send something */
H2_Send_Rel(...);
} else {
/* error handling */
}
But unfortunately, not all uses of get/rel enclose an attempt to send
something.
diff --git a/bin/varnishd/http2/cache_http2.h b/bin/varnishd/http2/cache_http2.h
index 44bd91783..a7a1001f5 100644
--- a/bin/varnishd/http2/cache_http2.h
+++ b/bin/varnishd/http2/cache_http2.h
@@ -232,6 +232,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);
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_deliver.c b/bin/varnishd/http2/cache_http2_deliver.c
index 025d431d2..f5faedce8 100644
--- a/bin/varnishd/http2/cache_http2_deliver.c
+++ b/bin/varnishd/http2/cache_http2_deliver.c
@@ -87,6 +87,10 @@ h2_fini(struct req *req, void **priv)
CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
TAKE_OBJ_NOTNULL(r2, priv, H2_REQ_MAGIC);
+
+ if (r2->error)
+ return (0);
+
H2_Send_Get(req->wrk, r2->h2sess, r2);
H2_Send(req->wrk, r2, H2_F_DATA, H2FF_DATA_END_STREAM, 0, "", NULL);
H2_Send_Rel(r2->h2sess, r2);
diff --git a/bin/varnishd/http2/cache_http2_proto.c b/bin/varnishd/http2/cache_http2_proto.c
index 577f777c2..e9e626ac1 100644
--- a/bin/varnishd/http2/cache_http2_proto.c
+++ b/bin/varnishd/http2/cache_http2_proto.c
@@ -966,21 +966,20 @@ h2_procframe(struct worker *wrk, struct h2_sess *h2, h2_frame h2f)
return (0);
}
-static int
-h2_stream_tmo(struct h2_sess *h2, const struct h2_req *r2)
+int
+h2_stream_tmo(struct h2_sess *h2, const struct h2_req *r2, vtim_real now)
{
int r = 0;
CHECK_OBJ_NOTNULL(h2, H2_SESS_MAGIC);
CHECK_OBJ_NOTNULL(r2, H2_REQ_MAGIC);
+ Lck_AssertHeld(&h2->sess->mtx);
if (r2->t_winupd == 0 && r2->t_send == 0)
return (0);
- Lck_Lock(&h2->sess->mtx);
if (r2->t_winupd != 0 &&
- h2->sess->t_idle - r2->t_winupd >
- cache_param->idle_send_timeout) {
+ now - r2->t_winupd > cache_param->idle_send_timeout) {
VSLb(h2->vsl, SLT_Debug,
"H2: stream %u: Hit idle_send_timeout waiting for"
" WINDOW_UPDATE", r2->stream);
@@ -988,11 +987,22 @@ h2_stream_tmo(struct h2_sess *h2, const struct h2_req *r2)
}
if (r == 0 && r2->t_send != 0 &&
- h2->sess->t_idle - r2->t_send > cache_param->send_timeout) {
+ now - r2->t_send > cache_param->send_timeout) {
VSLb(h2->vsl, SLT_Debug,
"H2: stream %u: Hit send_timeout", r2->stream);
r = 1;
}
+
+ return (r);
+}
+
+static int
+h2_stream_tmo_unlocked(struct h2_sess *h2, const struct h2_req *r2)
+{
+ int r;
+
+ Lck_Lock(&h2->sess->mtx);
+ r = h2_stream_tmo(h2, r2, h2->sess->t_idle);
Lck_Unlock(&h2->sess->mtx);
return (r);
@@ -1033,7 +1043,7 @@ h2_sweep(struct worker *wrk, struct h2_sess *h2)
/* FALLTHROUGH */
case H2_S_CLOS_LOC:
case H2_S_OPEN:
- if (h2_stream_tmo(h2, r2)) {
+ if (h2_stream_tmo_unlocked(h2, r2)) {
tmo = 1;
continue;
}
diff --git a/bin/varnishd/http2/cache_http2_send.c b/bin/varnishd/http2/cache_http2_send.c
index a778b35ea..6b2a34935 100644
--- a/bin/varnishd/http2/cache_http2_send.c
+++ b/bin/varnishd/http2/cache_http2_send.c
@@ -41,6 +41,41 @@
#define H2_SEND_HELD(h2, r2) (VTAILQ_FIRST(&(h2)->txqueue) == (r2))
+static int
+h2_cond_wait(pthread_cond_t *cond, struct h2_sess *h2, struct h2_req *r2)
+{
+ vtim_real now, when = 0.;
+ int r;
+
+ AN(cond);
+ CHECK_OBJ_NOTNULL(h2, H2_SESS_MAGIC);
+ CHECK_OBJ_NOTNULL(r2, H2_REQ_MAGIC);
+
+ Lck_AssertHeld(&h2->sess->mtx);
+
+ now = VTIM_real();
+ if (cache_param->idle_send_timeout > 0.)
+ when = now + cache_param->idle_send_timeout;
+
+ r = Lck_CondWait(cond, &h2->sess->mtx, when);
+
+ now = VTIM_real();
+ /* 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_stream_tmo() may not log what timed out and we need to check
+ * both conditions to decide whether we cancel the stream or not.
+ */
+ if (h2_stream_tmo(h2, r2, now) || r == ETIMEDOUT) {
+ if (r2->error == NULL)
+ r2->error = H2SE_CANCEL;
+ return (-1);
+ }
+
+ AZ(r);
+ return (0);
+}
+
static void
h2_send_get_locked(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2)
{
@@ -224,12 +259,11 @@ h2_do_window(struct worker *wrk, struct h2_req *r2,
h2_send_rel_locked(h2, r2);
while (r2->t_window <= 0 && h2_errcheck(r2, h2) == 0) {
r2->cond = &wrk->cond;
- AZ(Lck_CondWait(r2->cond, &h2->sess->mtx, 0));
+ (void)h2_cond_wait(r2->cond, h2, r2);
r2->cond = NULL;
}
- while (h2->req0->t_window <= 0 && h2_errcheck(r2, h2) == 0) {
- AZ(Lck_CondWait(h2->winupd_cond, &h2->sess->mtx, 0));
- }
+ while (h2->req0->t_window <= 0 && h2_errcheck(r2, h2) == 0)
+ (void)h2_cond_wait(h2->winupd_cond, h2, r2);
if (h2_errcheck(r2, h2) == 0) {
w = h2_win_limit(r2, h2);
@@ -377,4 +411,7 @@ H2_Send(struct worker *wrk, struct h2_req *r2, h2_frame ftyp, uint8_t flags,
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);
}
diff --git a/bin/varnishtest/tests/t02016.vtc b/bin/varnishtest/tests/t02016.vtc
new file mode 100644
index 000000000..05ad99616
--- /dev/null
+++ b/bin/varnishtest/tests/t02016.vtc
@@ -0,0 +1,76 @@
+varnishtest "client h2 send timeouts"
+
+server s1 {
+ rxreq
+ txresp -bodylen 12345
+} -start
+
+varnish v1 -cliok "param.set feature +http2"
+varnish v1 -vcl+backend "" -start
+
+varnish v1 -cliok "param.set send_timeout 1"
+
+logexpect l1 -v v1 {
+ expect * * Debug "Hit send_timeout"
+} -start
+
+client c1 {
+ txpri
+
+ stream 0 {
+ rxsettings
+ expect settings.ack == false
+ txsettings -ack
+ txsettings -winsize 1000
+ rxsettings
+ expect settings.ack == true
+ } -run
+
+ stream 1 {
+ txreq
+ rxhdrs
+ rxdata
+ # keep the stream idle for 2 seconds
+ delay 2
+ txwinup -size 256
+ # too late
+ rxrst
+ expect rst.err == CANCEL
+ } -run
+
+} -run
+
+logexpect l1 -wait
+
+varnish v1 -cliok "param.set idle_send_timeout 1"
+varnish v1 -cliok "param.reset send_timeout"
+
+logexpect l2 -v v1 {
+ expect * * Debug "Hit idle_send_timeout"
+} -start
+
+client c2 {
+ txpri
+
+ stream 0 {
+ rxsettings
+ expect settings.ack == false
+ txsettings -ack
+ txsettings -winsize 1000
+ rxsettings
+ expect settings.ack == true
+ } -run
+
+ stream 1 {
+ txreq
+ rxhdrs
+ rxdata
+ # keep the stream idle for 2 seconds
+ delay 2
+ rxrst
+ expect rst.err == CANCEL
+ } -run
+
+} -run
+
+logexpect l2 -wait
More information about the varnish-commit
mailing list