http2_send: Apply h2_window_timeout

It replaces idle_send_timeout when the stream is waiting for window
credits before sending more DATA frames. The idle_send_timeout will
still apply to individual writes to the socket, but triggering it is
considered a failure condition (this was already the case).

The two loops are merged into a single one to better deal with the
lack of ordering guarantees of request vs connection stream control
flow window crediting.

Refs #2980

bin/varnishd/http2/cache_http2_proto.c

@@ -1314,7 +1314,7 @@ h2_stream_tmo(struct h2_sess *h2, const struct h2_req *r2, vtim_real now)
 	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))
@@ -1324,10 +1324,9 @@ h2_stream_tmo(struct h2_sess *h2, const struct h2_req *r2, vtim_real now)
 		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);
+		     "H2: stream %u: Hit h2_window_timeout", r2->stream);
 		h2e = H2SE_BROKE_WINDOW;
 	}
 

bin/varnishd/http2/cache_http2_send.c

@@ -70,20 +70,20 @@ h2_cond_wait(pthread_cond_t *cond, struct h2_sess *h2, struct h2_req *r2)
 
 	Lck_AssertHeld(&h2->sess->mtx);
 
-	if (cache_param->idle_send_timeout > 0.)
-		tmo = cache_param->idle_send_timeout;
+	if (cache_param->h2_window_timeout > 0.)
+		tmo = cache_param->h2_window_timeout;
 
 	r = Lck_CondWaitTimeout(cond, &h2->sess->mtx, tmo);
 	assert(r == 0 || r == ETIMEDOUT);
 
 	now = VTIM_real();
 
-	/* NB: when we grab idle_send_timeout before acquiring the session
+	/* NB: when we grab h2_window_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.
 	 */
 	h2e = h2_stream_tmo(h2, r2, now);
@@ -208,6 +208,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

bin/varnishtest/tests/t02016.vtc

@@ -44,13 +44,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 {
@@ -79,12 +79,12 @@ client c2 {
 
 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 {
@@ -113,7 +113,7 @@ client c3 {
 } -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