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.

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

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

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

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

bin/varnishtest/tests/t02016.vtc

+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