[master] 4fe881852 Stabilize s10, again

[Dridi Boukelmoune]

commit 4fe881852b98c9875745963fc0c1ac3a5611b7b7
Author: Dridi Boukelmoune <dridi.boukelmoune at gmail.com>
Date:   Fri Jan 17 17:41:39 2020 +0100

    Stabilize s10, again
    
    The previous stabilization turned out not to reliably work with FreeBSD
    on aarch64 hardware. It was still an improvement overall, but the test
    case turned out to be a bit cryptic and when [idle_]send_timeout support
    landed in VCL it wasn't obvious how to add coverage.
    
    This attempt bites the bullet and defines one pair of client/logexpect
    instances per use case and clearly (I hope) indicates why it is doing
    things or not doing them.
    
    Since we now have two clients that aren't expected to complete before
    the test case itself the server is in dispatch mode instead of repeating
    its scenario. Using barriers in dispatch mode should raise a red flag
    for any reviewer, but in this case the barriers outside the server are
    properly serialized, are systematically used by every single client, and
    as a result should be safe.
    
    As usual, personal testing limited to x86_64 Linux and FreeBSD.

diff --git a/bin/varnishtest/tests/s00010.vtc b/bin/varnishtest/tests/s00010.vtc
index 0aa8b6137..fea3ea89d 100644
--- a/bin/varnishtest/tests/s00010.vtc
+++ b/bin/varnishtest/tests/s00010.vtc
@@ -8,58 +8,47 @@ feature SO_RCVTIMEO_WORKS
 barrier b1 cond 2 -cyclic
 barrier b2 cond 2 -cyclic
 
-server s1 -repeat 2 {
+server s0 {
 	fatal
 	rxreq
 	txresp -nolen -hdr "Transfer-encoding: chunked"
-	chunkedlen 8192
+	chunkedlen 100000
 	# make sure varnish is stuck in delivery
 	barrier b1 sync
-	chunkedlen 57344
+	non_fatal
 	chunkedlen 0
-} -start
+} -dispatch
 
 varnish v1 -cliok "param.set debug +syncvsl"
-varnish v1 -cliok "param.set debug +flush_head"
 varnish v1 -cliok "param.set thread_pools 1"
 varnish v1 -cliok "param.set timeout_idle 1"
-varnish v1 -cliok "param.set idle_send_timeout 1"
-varnish v1 -cliok "param.set send_timeout 1"
+varnish v1 -cliok "param.set idle_send_timeout .1"
+varnish v1 -cliok "param.set send_timeout .1"
 
 varnish v1 -vcl+backend {
+	import std;
 	import debug;
 	sub vcl_recv {
-		if (req.url == "/longsend") {
-			# client -rcvbuf 256 is super inefficient, so
-			# we need a very long timeout
-			set sess.send_timeout = 20s;
-		} else
-		if (req.url == "/longidlesend") {
-			set sess.idle_send_timeout = 20s;
+		if (req.http.send_timeout) {
+			set sess.send_timeout =
+			    std.duration(req.http.send_timeout);
 		}
+		if (req.http.idle_send_timeout) {
+			set sess.idle_send_timeout =
+			    std.duration(req.http.idle_send_timeout);
+		}
+		return (pass);
 	}
-
-	sub vcl_hash {
-		hash_data("/");
-		return (lookup);
-	}
-
 	sub vcl_deliver {
 		debug.sndbuf(256b);
 	}
 } -start
 
-# l0 signals when to raise the barrier
-# l1 checks for the TX_ERROR in the same session
-
-logexpect l0 -v v1 -g raw {
-	expect * * ReqURL	"^/$"
-	expect * = Debug	"^Hit total send timeout"
-} -start
+# case 1: send_timeout parameter
 
-logexpect l1 -v v1 -g session -q "ReqURL ~ \"^/$\"" {
-	expect * * SessClose "^TX_ERROR"
-	expect * * Debug "^Hit total send timeout"
+logexpect l1 -v v1 -g raw {
+	expect * 1001 Debug	"Hit total send timeout"
+	expect * 1000 SessClose	TX_ERROR
 } -start
 
 client c1 -rcvbuf 256 {
@@ -69,64 +58,79 @@ client c1 -rcvbuf 256 {
 	barrier b1 sync
 	# wait for the timeout to kick in
 	barrier b2 sync
-} -start
-
-client c2 -rcvbuf 256 {
-	txreq -url /longsend
-	rxresphdrs
-	delay 0.8
+	non_fatal
 	rxrespbody
-	expect resp.bodylen == 65536
+	expect_close
 } -start
 
-logexpect l0 -wait
-barrier b2 sync
 logexpect l1 -wait
+barrier b2 sync
 client c1 -wait
-client c2 -wait
 
-varnish v1 -cliok "param.reset send_timeout"
-
-varnish v1 -cliok "ban obj.status != 0"
+# case 2: send_timeout overriden in VCL
 
-# l2 signals when to raise the barrier
-# l3 checks the idle send timeout in the right transaction
-# l4 checks for no idle send timeout with the prolonged timeout
+varnish v1 -cliok "param.reset send_timeout"
 
 logexpect l2 -v v1 -g raw {
-	expect * * ReqURL	"^/$"
-	expect * = Debug	"^Hit idle send timeout"
+	expect * 1004 Debug	"Hit total send timeout"
+	expect * 1003 SessClose	TX_ERROR
 } -start
 
-
-logexpect l3 -v v1 -X RespHeader:Transfer-Encoding \
-    -q "ReqURL ~ \"^/$\"" {
-	expect * * ReqURL	"^/$"
-	expect * = RespHeader	"^Connection"
-	expect 0 = Debug	"^Hit idle send timeout"
+client c2 -rcvbuf 256 {
+	txreq -hdr "send_timeout: 100ms"
+	rxresphdrs
+	# varnish is stuck sending the chunk
+	barrier b1 sync
+	# wait for the timeout to kick in
+	barrier b2 sync
+	# expect the transaction to be interrupted
+	non_fatal
+	rxrespbody
+	expect_close
 } -start
 
-logexpect l4 -v v1 -X RespHeader:Transfer-Encoding \
-    -q "ReqURL ~ \"^/longidlesend$\"" {
-	expect * * ReqURL	"^/longidlesend$"
-	expect * = RespHeader	"^Connection"
-	# no Hit idle send ...
-	expect 0 = Timestamp	"^Resp"
-} -start
+logexpect l2 -wait
+barrier b2 sync
+client c2 -wait
 
-client c1 -start
+# case 3: idle_send_timeout parameter
+
+logexpect l3 -v v1 -g raw {
+	expect * 1007 Debug "Hit idle send timeout"
+} -start
 
 client c3 -rcvbuf 256 {
-	txreq -url /longidlesend
+	txreq
 	rxresphdrs
-	delay 1.8
-	rxrespbody
-	expect resp.bodylen == 65536
+	# varnish is stuck sending the chunk
+	barrier b1 sync
+	# wait for the timeout to kick in
+	barrier b2 sync
+	# don't wait for the transaction to complete
 } -start
 
-logexpect l2 -wait
+logexpect l3 -wait
 barrier b2 sync
-client c1 -wait
 client c3 -wait
-logexpect l3 -wait
+
+# case 4: idle_send_timeout overriden in VCL
+
+varnish v1 -cliok "param.reset idle_send_timeout"
+
+logexpect l4 -v v1 -g raw {
+	expect * 1010 Debug "Hit idle send timeout"
+} -start
+
+client c4 -rcvbuf 256 {
+	txreq -hdr "idle_send_timeout: 100ms"
+	rxresphdrs
+	# varnish is stuck sending the chunk
+	barrier b1 sync
+	# wait for the timeout to kick in
+	barrier b2 sync
+	# don't wait for the transaction to complete
+} -start
+
 logexpect l4 -wait
+barrier b2 sync
+client c4 -wait