[master] 64c0e1aec Ensure that we always log h2 idle_send_timeout

[Dridi Boukelmoune]

commit 64c0e1aec5145dd1c977f6e53e84e54288447855
Author: Dridi Boukelmoune <dridi.boukelmoune at gmail.com>
Date:   Thu Jun 27 09:49:27 2019 +0200

    Ensure that we always log h2 idle_send_timeout

diff --git a/bin/varnishd/http2/cache_http2_proto.c b/bin/varnishd/http2/cache_http2_proto.c
index e9e626ac1..527fb8e61 100644
--- a/bin/varnishd/http2/cache_http2_proto.c
+++ b/bin/varnishd/http2/cache_http2_proto.c
@@ -975,11 +975,17 @@ 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
+	 * on a lock condwait operation.
+	 */
+	if (isnan(now))
+		AN(r2->t_winupd);
+
 	if (r2->t_winupd == 0 && r2->t_send == 0)
 		return (0);
 
-	if (r2->t_winupd != 0 &&
-	    now - r2->t_winupd > cache_param->idle_send_timeout) {
+	if (isnan(now) || (r2->t_winupd != 0 &&
+	    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);
diff --git a/bin/varnishd/http2/cache_http2_send.c b/bin/varnishd/http2/cache_http2_send.c
index 6b2a34935..87b3ceb00 100644
--- a/bin/varnishd/http2/cache_http2_send.c
+++ b/bin/varnishd/http2/cache_http2_send.c
@@ -58,21 +58,29 @@ h2_cond_wait(pthread_cond_t *cond, struct h2_sess *h2, struct h2_req *r2)
 		when = now + cache_param->idle_send_timeout;
 
 	r = Lck_CondWait(cond, &h2->sess->mtx, when);
+	assert(r == 0 || r == ETIMEDOUT);
 
 	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.
+	 * 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
+	 * force it to log it.
 	 */
-	if (h2_stream_tmo(h2, r2, now) || r == ETIMEDOUT) {
+	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);
 	}
 
-	AZ(r);
 	return (0);
 }
 
diff --git a/bin/varnishtest/tests/t02016.vtc b/bin/varnishtest/tests/t02016.vtc
index 05ad99616..29ffea354 100644
--- a/bin/varnishtest/tests/t02016.vtc
+++ b/bin/varnishtest/tests/t02016.vtc
@@ -8,6 +8,8 @@ server s1 {
 varnish v1 -cliok "param.set feature +http2"
 varnish v1 -vcl+backend "" -start
 
+# coverage for send_timeout with c1
+
 varnish v1 -cliok "param.set send_timeout 1"
 
 logexpect l1 -v v1 {
@@ -42,6 +44,8 @@ client c1 {
 
 logexpect l1 -wait
 
+# coverage for idle_send_timeout with c2
+
 varnish v1 -cliok "param.set idle_send_timeout 1"
 varnish v1 -cliok "param.reset send_timeout"
 
@@ -74,3 +78,42 @@ client c2 {
 } -run
 
 logexpect l2 -wait
+
+# coverage for idle_send_timeout change with c3
+
+barrier b3 cond 2
+
+logexpect l3 -v v1 {
+	expect * * Debug "Hit idle_send_timeout"
+} -start
+
+client c3 {
+	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
+		barrier b3 sync
+		delay 2
+		rxrst
+		expect rst.err == CANCEL
+	} -run
+
+} -start
+
+barrier b3 sync
+varnish v1 -cliok "param.reset idle_send_timeout"
+
+client c3 -wait
+logexpect l3 -wait