VCL failed
**** c1 c-l|XID: 1001
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 21 ** c1 Ending **** dT 7.680 ** top === varnish v1 -expect vcl_fail == 1 **** dT 7.690 ** v1 as expected: vcl_fail (1) == 1 (1) ** top === varnish v1 -expect sc_vcl_failure == 1 **** dT 7.691 **** l1001 match| 1001 VCL_call c RECV *** l1001 test | expect 0 1001 VCL_Error Forced failure **** l1001 match| 1001 VCL_Error c Forced failure *** l1001 test | expect 0 1001 VCL_return fail **** l1001 match| 1001 VCL_return c fail **** l1001 done | **** dT 7.692 ** v1 as expected: sc_vcl_failure (1) == 1 (1) ** top === logexpect l1003 -v v1 -g raw { **** dT 7.693 ** l1003 === expect * 1003 VCL_call "RECV" ** l1003 === expect 0 1003 VCL_Error "Forced failure" **** dT 7.694 ** l1003 === expect 0 1003 VCL_return "fail" ** l1003 === expect * 1003 VCL_call "SYNTH" ** l1003 === expect 0 1003 VCL_return "restart" **** dT 7.696 **** v1 vsl| 0 CLI - Rd debug.xid 1000 **** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 61732 **** v1 vsl| 1000 Begin c sess 0 HTTP/1 **** v1 vsl| 1000 SessOpen c 127.0.0.1 64260 a0 127.0.0.1 61732 1695125893.204878 22 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_SNDTIMEO non heredity for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_RCVTIMEO non heredity for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: Test confirmed TCP_NODELAY non heredity for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1000 Link c req 1001 rxreq **** v1 vsl| 1001 Begin c req 1000 rxreq **** v1 vsl| 1001 Timestamp c Start: 1695125893.205732 0.000000 0.000000 **** v1 vsl| 1001 Timestamp c Req: 1695125893.205732 0.000000 0.000000 **** v1 vsl| 1001 VCL_use c vcl1 **** v1 vsl| 1001 ReqStart c 127.0.0.1 64260 a0 **** v1 vsl| 1001 ReqMethod c GET **** v1 vsl| 1001 ReqURL c / **** v1 vsl| 1001 ReqProtocol c HTTP/1.1 **** v1 vsl| 1001 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1001 ReqHeader c User-Agent: c1 **** v1 vsl| 1001 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1001 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1001 VCL_call c RECV **** v1 vsl| 1001 VCL_Error c Forced failure **** v1 vsl| 1001 VCL_return c fail **** v1 vsl| 1001 RespProtocol c HTTP/1.1 **** v1 vsl| 1001 RespStatus c 503 **** v1 vsl| 1001 RespReason c VCL failed **** v1 vsl| 1001 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1001 RespHeader c Server: Varnish **** v1 vsl| 1001 RespHeader c X-Varnish: 1001 **** v1 vsl| 1001 VCL_call c SYNTH **** v1 vsl| 1001 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1001 RespHeader c Retry-After: 5 **** v1 vsl| 1001 VCL_return c deliver **** v1 vsl| 1001 Timestamp c Process: 1695125893.207995 0.002262 0.002262 **** v1 vsl| 1001 RespHeader c Content-Length: 251 **** v1 vsl| 1001 Storage c malloc Transient **** v1 vsl| 1001 Filters c **** v1 vsl| 1001 RespHeader c Connection: close **** v1 vsl| 1001 Timestamp c Resp: 1695125893.215229 0.009496 0.007234 **** v1 vsl| 1001 ReqAcct c 51 0 51 194 251 445 **** v1 vsl| 1001 End c **** v1 vsl| 1000 SessClose c VCL_FAILURE 0.011 **** v1 vsl| 1000 End c **** dT 7.697 **** l1003 begin| *** l1003 test | expect * 1003 VCL_call RECV ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 7.698 ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 7.699 *** c1 connected fd 28 from 127.0.0.1 27615 to 127.0.0.1:61732 ** c1 === txreq -url /hit -hdr "foo: restart" **** c1 txreq|GET /hit HTTP/1.1\r **** c1 txreq|foo: restart\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.702 ** c1 === rxresp **** dT 7.704 *** s1 accepted fd 4 127.0.0.1 38829 **** dT 7.705 ** s1 === rxreq **** dT 7.706 **** s1 rxhdr|GET /hit HTTP/1.1\r **** s1 rxhdr|foo: restart\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|User-Agent: c1\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1005\r **** s1 rxhdr|\r **** s1 rxhdrlen = 108 **** s1 http[ 0] |GET **** s1 http[ 1] |/hit **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |foo: restart **** s1 http[ 4] |Host: 127.0.0.1 **** s1 http[ 5] |User-Agent: c1 **** s1 http[ 6] |Accept-Encoding: gzip **** s1 http[ 7] |X-Varnish: 1005 **** s1 bodylen = 0 ** s1 === expect req.url == /hit **** s1 EXPECT req.url (/hit) == "/hit" match ** s1 === txresp **** dT 7.708 **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Tue, 19 Sep 2023 12:18:13 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r *** s1 shutting fd 4 ** s1 Ending **** dT 7.711 **** l1003 match| 1003 VCL_call c RECV *** l1003 test | expect 0 1003 VCL_Error Forced failure **** l1003 match| 1003 VCL_Error c Forced failure *** l1003 test | expect 0 1003 VCL_return fail **** l1003 match| 1003 VCL_return c fail *** l1003 test | expect * 1003 VCL_call SYNTH **** l1003 match| 1003 VCL_call c SYNTH *** l1003 test | expect 0 1003 VCL_return restart **** l1003 match| 1003 VCL_return c restart **** l1003 done | **** dT 7.726 **** c1 rxhdr|HTTP/1.1 200 OK\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:13 GMT\r **** c1 rxhdr|Server: s1\r **** c1 rxhdr|Content-Length: 0\r **** c1 rxhdr|X-Varnish: 1004\r **** c1 rxhdr|Age: 0\r **** c1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r **** c1 rxhdr|Accept-Ranges: bytes\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 182 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |200 **** c1 http[ 2] |OK **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:13 GMT **** c1 http[ 4] |Server: s1 **** c1 http[ 5] |Content-Length: 0 **** c1 http[ 6] |X-Varnish: 1004 **** c1 http[ 7] |Age: 0 **** c1 http[ 8] |Via: 1.1 v1 (Varnish/trunk) **** c1 http[ 9] |Accept-Ranges: bytes **** c1 http[10] |Connection: close **** c1 bodylen = 0 ** c1 === expect resp.status == 200 **** c1 EXPECT resp.status (200) == "200" match ** c1 === expect resp.reason == "OK" **** c1 EXPECT resp.reason (OK) == "OK" match *** c1 closing fd 28 ** c1 Ending **** dT 7.728 ** top === varnish v1 -expect vcl_fail == 2 ** v1 as expected: vcl_fail (2) == 2 (2) ** top === varnish v1 -expect sc_vcl_failure == 2 **** dT 7.729 ** v1 as expected: sc_vcl_failure (2) == 2 (2) ** top === logexpect l1007 -v v1 -g raw { **** dT 7.730 ** l1007 === expect * 1007 VCL_call "SYNTH" ** l1007 === expect * 1007 VCL_Error "Forced failure" **** dT 7.731 ** l1007 === expect 0 1007 VCL_return "fail" **** dT 7.732 ** top === client c1 { ** c1 Starting client **** dT 7.733 ** c1 Waiting for client **** l1007 begin| *** l1007 test | expect * 1007 VCL_call SYNTH **** dT 7.734 ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 7.735 *** c1 connected fd 32 from 127.0.0.1 14322 to 127.0.0.1:61732 ** c1 === txreq -hdr "foo: synth" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: synth\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.737 ** c1 === rxresp **** c1 rxhdr|HTTP/1.1 500 Internal Server Error\r **** c1 rxhdr|\r **** c1 rxhdrlen = 38 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |500 **** c1 http[ 2] |Internal Server Error **** c1 bodylen = 0 ** c1 === expect resp.status == 500 **** c1 EXPECT resp.status (500) == "500" match ** c1 === expect_close **** dT 7.738 **** c1 Expecting close (fd = 32) **** c1 fd=32 EOF, as expected *** c1 closing fd 32 ** c1 Ending **** dT 7.739 ** top === varnish v1 -expect vcl_fail == 3 **** dT 7.740 ** v1 as expected: vcl_fail (3) == 3 (3) ** top === varnish v1 -expect sc_vcl_failure == 3 ** v1 as expected: sc_vcl_failure (3) == 3 (3) ** top === logexpect l1009 -v v1 -g raw { **** dT 7.742 ** l1009 === expect * 1009 VCL_call "HASH" ** l1009 === expect 0 1009 VCL_Error "Forced failure" ** l1009 === expect 0 1009 VCL_return "fail" **** dT 7.744 **** l1007 match| 1007 VCL_call c SYNTH *** l1007 test | expect * 1007 VCL_Error Forced failure **** l1007 match| 1007 VCL_Error c Forced failure *** l1007 test | expect 0 1007 VCL_return fail **** l1007 match| 1007 VCL_return c fail **** l1007 done | **** l1009 begin| *** l1009 test | expect * 1009 VCL_call HASH ** top === client c1 { ** c1 Starting client **** dT 7.745 ** c1 Waiting for client ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 7.746 *** c1 connected fd 37 from 127.0.0.1 33538 to 127.0.0.1:61732 ** c1 === txreq -hdr "foo: hash" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: hash\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.749 ** c1 === rxresp **** dT 7.751 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:13 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1009\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:13 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1009 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1009
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 37 **** dT 7.752 ** c1 Ending **** dT 7.753 ** top === varnish v1 -expect vcl_fail == 4 **** dT 7.754 ** v1 as expected: vcl_fail (4) == 4 (4) ** top === varnish v1 -expect sc_vcl_failure == 4 ** v1 as expected: sc_vcl_failure (4) == 4 (4) ** top === logexpect l1012 -v v1 -g vxid -q "vxid == 1012" { **** dT 7.755 **** l1009 match| 1009 VCL_call c HASH *** l1009 test | expect 0 1009 VCL_Error Forced failure **** l1009 match| 1009 VCL_Error c Forced failure *** l1009 test | expect 0 1009 VCL_return fail **** l1009 match| 1009 VCL_return c fail **** l1009 done | **** dT 7.756 ** l1012 === expect 0 1012 Begin {^bereq 1011 pipe} **** dT 7.757 ** l1012 === expect 0 = Timestamp {^Start:} ** l1012 === expect 0 = BereqMethod {^GET} ** l1012 === expect 0 = BereqURL {^/} ** l1012 === expect 0 = BereqProtocol {^HTTP/1.1} ** l1012 === expect 0 = BereqHeader {^foo: pipe} ** l1012 === expect 0 = BereqHeader {^Host: } **** dT 7.758 ** l1012 === expect 0 = BereqHeader {^User-Agent: c1} ** l1012 === expect 0 = BereqHeader {^X-Forwarded-For: } ** l1012 === expect 0 = BereqHeader {^Via: } ** l1012 === expect 0 = BereqHeader {^X-Varnish: 1011} ** l1012 === expect 0 = BereqHeader {^Connection: close} ** l1012 === expect 0 = BereqAcct {^0 0 0 0 0 0} **** dT 7.759 ** l1012 === expect 0 = End **** dT 7.760 ** top === logexpect l1011 -v v1 -g vxid -q "vxid == 1011" { **** dT 7.761 ** l1011 === expect 0 1011 Begin {^req 1010 rxreq} ** l1011 === expect 0 = Timestamp {^Start: } ** l1011 === expect 0 = Timestamp {^Req: } **** dT 7.762 ** l1011 === expect 0 = VCL_use {^vcl1} ** l1011 === expect 0 = ReqStart ** l1011 === expect 0 = ReqMethod {^GET} ** l1011 === expect 0 = ReqURL {^/} ** l1011 === expect 0 = ReqProtocol {^HTTP/1.1} ** l1011 === expect 0 = ReqHeader {^foo: pipe} ** l1011 === expect 0 = ReqHeader {^Host: } ** l1011 === expect 0 = reqHeader {^User-Agent: c1} **** dT 7.763 ** l1011 === expect 0 = ReqHeader {^X-Forwarded-For: } ** l1011 === expect 0 = ReqHeader {^Via: } ** l1011 === expect 0 = VCL_call {^RECV} ** l1011 === expect 0 = VCL_return {^pipe} ** l1011 === expect 0 = VCL_call {^HASH} ** l1011 === expect 0 = VCL_return {^lookup} ** l1011 === expect 0 = Link {^bereq 1012 pipe} ** l1011 === expect 0 = VCL_call {^PIPE} **** dT 7.764 ** l1011 === expect 0 = VCL_Error {^Forced failure} ** l1011 === expect 0 = VCL_return {^fail} ** l1011 === expect 0 = RespProtocol {^HTTP/1.1} ** l1011 === expect 0 = RespStatus {^503} ** l1011 === expect 0 = RespReason {^VCL failed} **** dT 7.765 ** top === client c1 { ** c1 Starting client **** dT 7.766 ** c1 Waiting for client **** l1012 begin| **** l1012 qry | vxid == 1012 *** l1012 test | expect 0 1012 Begin ^bereq 1011 pipe **** l1011 begin| **** l1011 qry | vxid == 1011 *** l1011 test | expect 0 1011 Begin ^req 1010 rxreq ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 7.767 *** c1 connected fd 47 from 127.0.0.1 43636 to 127.0.0.1:61732 ** c1 === txreq -hdr "foo: pipe" **** dT 7.768 **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: pipe\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.770 ** c1 === rxresp **** dT 7.772 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:13 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1011\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:13 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1011 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1011
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match **** dT 7.773 *** c1 closing fd 47 ** c1 Ending **** dT 7.774 ** top === varnish v1 -expect vcl_fail == 5 **** dT 7.775 ** v1 as expected: vcl_fail (5) == 5 (5) ** top === varnish v1 -expect sc_vcl_failure == 5 ** v1 as expected: sc_vcl_failure (5) == 5 (5) ** top === logexpect l1014 -v v1 -g raw { **** dT 7.778 **** l1012 match| 1012 Begin b bereq 1011 pipe *** l1012 test | expect 0 = Timestamp ^Start: **** l1012 match| 1012 Timestamp b Start: 1695125893.302058 0.000000 0.000000 *** l1012 test | expect 0 = BereqMethod ^GET **** l1012 match| 1012 BereqMethod b GET *** l1012 test | expect 0 = BereqURL ^/ **** l1012 match| 1012 BereqURL b / *** l1012 test | expect 0 = BereqProtocol ^HTTP/1.1 **** l1012 match| 1012 BereqProtocol b HTTP/1.1 *** l1012 test | expect 0 = BereqHeader ^foo: pipe **** l1012 match| 1012 BereqHeader b foo: pipe *** l1012 test | expect 0 = BereqHeader ^Host: **** l1012 match| 1012 BereqHeader b Host: 127.0.0.1 *** l1012 test | expect 0 = BereqHeader ^User-Agent: c1 **** l1012 match| 1012 BereqHeader b User-Agent: c1 *** l1012 test | expect 0 = BereqHeader ^X-Forwarded-For: **** l1012 match| 1012 BereqHeader b X-Forwarded-For: 127.0.0.1 *** l1012 test | expect 0 = BereqHeader ^Via: **** l1012 match| 1012 BereqHeader b Via: 1.1 v1 (Varnish/trunk) *** l1012 test | expect 0 = BereqHeader ^X-Varnish: 1011 **** l1012 match| 1012 BereqHeader b X-Varnish: 1011 *** l1012 test | expect 0 = BereqHeader ^Connection: close **** l1012 match| 1012 BereqHeader b Connection: close *** l1012 test | expect 0 = BereqAcct ^0 0 0 0 0 0 **** l1012 match| 1012 BereqAcct b 0 0 0 0 0 0 *** l1012 test | expect 0 = End **** l1012 match| 1012 End b **** l1012 done | **** dT 7.779 **** l1011 match| 1011 Begin c req 1010 rxreq *** l1011 test | expect 0 = Timestamp ^Start: **** l1011 match| 1011 Timestamp c Start: 1695125893.301541 0.000000 0.000000 *** l1011 test | expect 0 = Timestamp ^Req: **** l1011 match| 1011 Timestamp c Req: 1695125893.301541 0.000000 0.000000 *** l1011 test | expect 0 = VCL_use ^vcl1 **** l1011 match| 1011 VCL_use c vcl1 *** l1011 test | expect 0 = ReqStart **** l1011 match| 1011 ReqStart c 127.0.0.1 43636 a0 *** l1011 test | expect 0 = ReqMethod ^GET **** l1011 match| 1011 ReqMethod c GET **** dT 7.780 *** l1011 test | expect 0 = ReqURL ^/ **** l1011 match| 1011 ReqURL c / *** l1011 test | expect 0 = ReqProtocol ^HTTP/1.1 **** l1011 match| 1011 ReqProtocol c HTTP/1.1 *** l1011 test | expect 0 = ReqHeader ^foo: pipe **** l1011 match| 1011 ReqHeader c foo: pipe *** l1011 test | expect 0 = ReqHeader ^Host: **** l1011 match| 1011 ReqHeader c Host: 127.0.0.1 *** l1011 test | expect 0 = reqHeader ^User-Agent: c1 **** l1011 match| 1011 ReqHeader c User-Agent: c1 *** l1011 test | expect 0 = ReqHeader ^X-Forwarded-For: **** l1011 match| 1011 ReqHeader c X-Forwarded-For: 127.0.0.1 *** l1011 test | expect 0 = ReqHeader ^Via: **** l1011 match| 1011 ReqHeader c Via: 1.1 v1 (Varnish/trunk) *** l1011 test | expect 0 = VCL_call ^RECV **** l1011 match| 1011 VCL_call c RECV *** l1011 test | expect 0 = VCL_return ^pipe **** l1011 match| 1011 VCL_return c pipe *** l1011 test | expect 0 = VCL_call ^HASH **** l1011 match| 1011 VCL_call c HASH *** l1011 test | expect 0 = VCL_return ^lookup **** l1011 match| 1011 VCL_return c lookup *** l1011 test | expect 0 = Link ^bereq 1012 pipe **** l1011 match| 1011 Link c bereq 1012 pipe *** l1011 test | expect 0 = VCL_call ^PIPE **** l1011 match| 1011 VCL_call c PIPE *** l1011 test | expect 0 = VCL_Error ^Forced failure **** l1011 match| 1011 VCL_Error c Forced failure *** l1011 test | expect 0 = VCL_return ^fail **** l1011 match| 1011 VCL_return c fail *** l1011 test | expect 0 = RespProtocol ^HTTP/1.1 **** l1011 match| 1011 RespProtocol c HTTP/1.1 *** l1011 test | expect 0 = RespStatus ^503 **** l1011 match| 1011 RespStatus c 503 *** l1011 test | expect 0 = RespReason ^VCL failed **** l1011 match| 1011 RespReason c VCL failed **** l1011 done | **** dT 7.781 ** l1014 === expect * 1014 VCL_call "PASS" ** l1014 === expect 0 1014 VCL_Error "Forced failure" **** dT 7.782 ** l1014 === expect 0 1014 VCL_return "fail" **** dT 7.783 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1014 begin| *** l1014 test | expect * 1014 VCL_call PASS ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 7.784 *** c1 connected fd 52 from 127.0.0.1 38819 to 127.0.0.1:61732 **** dT 7.785 ** c1 === txreq -hdr "foo: pass" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: pass\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.787 ** c1 === rxresp **** dT 7.789 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:13 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1014\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:13 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1014 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1014
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 52 **** dT 7.790 ** c1 Ending **** dT 7.791 ** top === varnish v1 -expect vcl_fail == 6 **** dT 7.792 ** v1 as expected: vcl_fail (6) == 6 (6) ** top === varnish v1 -expect sc_vcl_failure == 6 ** v1 as expected: sc_vcl_failure (6) == 6 (6) ** top === logexpect l1016 -v v1 -g raw { **** dT 7.794 **** l1014 match| 1014 VCL_call c PASS *** l1014 test | expect 0 1014 VCL_Error Forced failure **** l1014 match| 1014 VCL_Error c Forced failure *** l1014 test | expect 0 1014 VCL_return fail **** l1014 match| 1014 VCL_return c fail **** l1014 done | **** dT 7.795 ** l1016 === expect * 1016 VCL_call "PURGE" ** l1016 === expect 0 1016 VCL_Error "Forced failure" ** l1016 === expect 0 1016 VCL_return "fail" **** dT 7.796 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 7.797 **** l1016 begin| *** l1016 test | expect * 1016 VCL_call PURGE ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 7.798 *** c1 connected fd 57 from 127.0.0.1 30335 to 127.0.0.1:61732 ** c1 === txreq -hdr "foo: purge" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: purge\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.799 **** v1 vsl| 1002 Begin c sess 0 HTTP/1 **** v1 vsl| 1002 SessOpen c 127.0.0.1 27615 a0 127.0.0.1 61732 1695125893.232502 23 **** v1 vsl| 1002 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1002 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1002 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1002 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1002 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1002 Link c req 1003 rxreq **** v1 vsl| 1003 Begin c req 1002 rxreq **** v1 vsl| 1003 Timestamp c Start: 1695125893.233234 0.000000 0.000000 **** v1 vsl| 1003 Timestamp c Req: 1695125893.233234 0.000000 0.000000 **** v1 vsl| 1003 VCL_use c vcl1 **** v1 vsl| 1003 ReqStart c 127.0.0.1 27615 a0 **** v1 vsl| 1003 ReqMethod c GET **** v1 vsl| 1003 ReqURL c /hit **** v1 vsl| 1003 ReqProtocol c HTTP/1.1 **** v1 vsl| 1003 ReqHeader c foo: restart **** v1 vsl| 1003 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1003 ReqHeader c User-Agent: c1 **** v1 vsl| 1003 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1003 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1003 VCL_call c RECV **** v1 vsl| 1003 VCL_Error c Forced failure **** v1 vsl| 1003 VCL_return c fail **** v1 vsl| 1003 RespProtocol c HTTP/1.1 **** v1 vsl| 1003 RespStatus c 503 **** v1 vsl| 1003 RespReason c VCL failed **** v1 vsl| 1003 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1003 RespHeader c Server: Varnish **** v1 vsl| 1003 RespHeader c X-Varnish: 1003 **** v1 vsl| 1003 VCL_call c SYNTH **** v1 vsl| 1003 VCL_return c restart **** v1 vsl| 1003 Timestamp c Process: 1695125893.234037 0.000802 0.000802 **** v1 vsl| 1003 Timestamp c Restart: 1695125893.234079 0.000844 0.000041 **** v1 vsl| 1003 Link c req 1004 restart **** v1 vsl| 1003 End c **** v1 vsl| 1004 Begin c req 1003 restart **** v1 vsl| 1004 Timestamp c Start: 1695125893.234079 0.000844 0.000000 **** v1 vsl| 1004 ReqStart c 127.0.0.1 27615 a0 **** v1 vsl| 1004 ReqMethod c GET **** v1 vsl| 1004 ReqURL c /hit **** v1 vsl| 1004 ReqProtocol c HTTP/1.1 **** v1 vsl| 1004 ReqHeader c foo: restart **** v1 vsl| 1004 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1004 ReqHeader c User-Agent: c1 **** v1 vsl| 1004 VCL_call c RECV **** v1 vsl| 1004 VCL_return c hash **** v1 vsl| 1004 VCL_call c HASH **** v1 vsl| 1004 VCL_return c lookup **** v1 vsl| 1004 VCL_call c MISS **** v1 vsl| 1004 VCL_return c fetch **** v1 vsl| 1004 Link c bereq 1005 fetch **** v1 vsl| 1004 Timestamp c Fetch: 1695125893.255973 0.022739 0.021894 **** v1 vsl| 1004 RespProtocol c HTTP/1.1 **** v1 vsl| 1004 RespStatus c 200 **** dT 7.800 **** v1 vsl| 1004 RespReason c OK **** v1 vsl| 1004 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1004 RespHeader c Server: s1 **** v1 vsl| 1004 RespHeader c Content-Length: 0 **** v1 vsl| 1004 RespHeader c X-Varnish: 1004 **** v1 vsl| 1004 RespHeader c Age: 0 **** v1 vsl| 1004 RespHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1004 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1004 VCL_call c DELIVER **** v1 vsl| 1004 VCL_return c deliver **** v1 vsl| 1004 Timestamp c Process: 1695125893.256331 0.023096 0.000357 **** v1 vsl| 1004 Filters c **** v1 vsl| 1004 RespHeader c Connection: close **** v1 vsl| 1004 Timestamp c Resp: 1695125893.259562 0.026327 0.003230 **** v1 vsl| 1004 ReqAcct c 68 0 68 182 0 182 **** v1 vsl| 1004 End c **** v1 vsl| 1002 SessClose c VCL_FAILURE 0.028 **** v1 vsl| 1002 End c **** v1 vsl| 1005 Begin b bereq 1004 fetch **** v1 vsl| 1005 VCL_use b vcl1 **** v1 vsl| 1005 Timestamp b Start: 1695125893.235046 0.000000 0.000000 **** v1 vsl| 1005 BereqMethod b GET **** v1 vsl| 1005 BereqURL b /hit **** v1 vsl| 1005 BereqProtocol b HTTP/1.1 **** v1 vsl| 1005 BereqHeader b foo: restart **** v1 vsl| 1005 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1005 BereqHeader b User-Agent: c1 **** v1 vsl| 1005 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1005 BereqHeader b X-Varnish: 1005 **** v1 vsl| 1005 VCL_call b BACKEND_FETCH **** v1 vsl| 1005 VCL_return b fetch **** v1 vsl| 1005 Timestamp b Fetch: 1695125893.235237 0.000191 0.000191 **** v1 vsl| 1005 Timestamp b Connected: 1695125893.236330 0.001284 0.001092 **** v1 vsl| 1005 BackendOpen b 22 s1 127.0.0.1 61588 127.0.0.1 38829 connect **** v1 vsl| 1005 Timestamp b Bereq: 1695125893.241714 0.006667 0.005383 **** v1 vsl| 1005 BerespProtocol b HTTP/1.1 **** v1 vsl| 1005 BerespStatus b 200 **** v1 vsl| 1005 BerespReason b OK **** v1 vsl| 1005 BerespHeader b Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1005 BerespHeader b Server: s1 **** v1 vsl| 1005 BerespHeader b Content-Length: 0 **** v1 vsl| 1005 Timestamp b Beresp: 1695125893.242023 0.006976 0.000308 **** v1 vsl| 1005 TTL b RFC 120 10 0 1695125893 1695125893 1695125893 0 0 cacheable **** v1 vsl| 1005 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1005 VCL_return b deliver **** v1 vsl| 1005 Timestamp b Process: 1695125893.242456 0.007410 0.000433 **** v1 vsl| 1005 Filters b **** v1 vsl| 1005 Storage b malloc s0 **** v1 vsl| 1005 Fetch_Body b 0 none - **** v1 vsl| 1005 BackendClose b 22 s1 recycle **** v1 vsl| 1005 Timestamp b BerespBody: 1695125893.264555 0.029508 0.022098 **** v1 vsl| 1005 Length b 0 **** v1 vsl| 1005 BereqAcct b 108 0 108 87 0 87 **** v1 vsl| 1005 End b **** v1 vsl| 1006 Begin c sess 0 HTTP/1 **** v1 vsl| 1006 SessOpen c 127.0.0.1 14322 a0 127.0.0.1 61732 1695125893.268132 24 **** v1 vsl| 1006 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1006 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1006 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1006 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1006 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** dT 7.801 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1006 Link c req 1007 rxreq **** v1 vsl| 1007 Begin c req 1006 rxreq **** v1 vsl| 1007 Timestamp c Start: 1695125893.268801 0.000000 0.000000 **** v1 vsl| 1007 Timestamp c Req: 1695125893.268801 0.000000 0.000000 **** v1 vsl| 1007 VCL_use c vcl1 **** v1 vsl| 1007 ReqStart c 127.0.0.1 14322 a0 **** v1 vsl| 1007 ReqMethod c GET **** v1 vsl| 1007 ReqURL c / **** v1 vsl| 1007 ReqProtocol c HTTP/1.1 **** v1 vsl| 1007 ReqHeader c foo: synth **** v1 vsl| 1007 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1007 ReqHeader c User-Agent: c1 **** v1 vsl| 1007 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1007 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1007 VCL_call c RECV **** v1 vsl| 1007 VCL_return c synth **** v1 vsl| 1007 VCL_call c HASH **** v1 vsl| 1007 VCL_return c lookup **** v1 vsl| 1007 RespProtocol c HTTP/1.1 **** v1 vsl| 1007 RespStatus c 748 **** v1 vsl| 1007 RespReason c Unknown HTTP Status **** v1 vsl| 1007 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1007 RespHeader c Server: Varnish **** v1 vsl| 1007 RespHeader c X-Varnish: 1007 **** v1 vsl| 1007 VCL_call c SYNTH **** v1 vsl| 1007 VCL_Error c Forced failure **** v1 vsl| 1007 VCL_return c fail **** v1 vsl| 1007 Timestamp c Process: 1695125893.269442 0.000641 0.000641 **** v1 vsl| 1007 RespProtocol c HTTP/1.1 **** v1 vsl| 1007 RespStatus c 500 **** v1 vsl| 1007 RespReason c Internal Server Error **** v1 vsl| 1007 Timestamp c Resp: 1695125893.270431 0.001630 0.000988 **** v1 vsl| 1007 ReqAcct c 63 0 63 38 0 38 **** v1 vsl| 1007 End c **** v1 vsl| 1006 SessClose c VCL_FAILURE 0.004 **** v1 vsl| 1006 End c **** v1 vsl| 1008 Begin c sess 0 HTTP/1 **** v1 vsl| 1008 SessOpen c 127.0.0.1 33538 a0 127.0.0.1 61732 1695125893.279458 25 **** v1 vsl| 1008 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1008 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1008 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1008 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1008 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1008 Link c req 1009 rxreq **** v1 vsl| 1009 Begin c req 1008 rxreq **** v1 vsl| 1009 Timestamp c Start: 1695125893.280094 0.000000 0.000000 **** v1 vsl| 1009 Timestamp c Req: 1695125893.280094 0.000000 0.000000 **** v1 vsl| 1009 VCL_use c vcl1 **** v1 vsl| 1009 ReqStart c 127.0.0.1 33538 a0 **** v1 vsl| 1009 ReqMethod c GET **** v1 vsl| 1009 ReqURL c / **** v1 vsl| 1009 ReqProtocol c HTTP/1.1 **** v1 vsl| 1009 ReqHeader c foo: hash **** v1 vsl| 1009 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1009 ReqHeader c User-Agent: c1 **** v1 vsl| 1009 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1009 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1009 VCL_call c RECV **** v1 vsl| 1009 VCL_return c hash **** v1 vsl| 1009 VCL_call c HASH **** dT 7.802 **** v1 vsl| 1009 VCL_Error c Forced failure **** v1 vsl| 1009 VCL_return c fail **** v1 vsl| 1009 RespProtocol c HTTP/1.1 **** v1 vsl| 1009 RespStatus c 503 **** v1 vsl| 1009 RespReason c VCL failed **** v1 vsl| 1009 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1009 RespHeader c Server: Varnish **** v1 vsl| 1009 RespHeader c X-Varnish: 1009 **** v1 vsl| 1009 VCL_call c SYNTH **** v1 vsl| 1009 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1009 RespHeader c Retry-After: 5 **** v1 vsl| 1009 VCL_return c deliver **** v1 vsl| 1009 Timestamp c Process: 1695125893.281066 0.000972 0.000972 **** v1 vsl| 1009 RespHeader c Content-Length: 251 **** v1 vsl| 1009 Storage c malloc Transient **** v1 vsl| 1009 Filters c **** v1 vsl| 1009 RespHeader c Connection: close **** v1 vsl| 1009 Timestamp c Resp: 1695125893.285104 0.005009 0.004037 **** v1 vsl| 1009 ReqAcct c 62 0 62 194 251 445 **** v1 vsl| 1009 End c **** v1 vsl| 1008 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1008 End c **** v1 vsl| 1010 Begin c sess 0 HTTP/1 **** v1 vsl| 1010 SessOpen c 127.0.0.1 43636 a0 127.0.0.1 61732 1695125893.300871 22 **** v1 vsl| 1010 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1010 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1010 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1010 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1010 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1010 Link c req 1011 rxreq **** v1 vsl| 1012 Begin b bereq 1011 pipe **** v1 vsl| 1012 Timestamp b Start: 1695125893.302058 0.000000 0.000000 **** v1 vsl| 1012 BereqMethod b GET **** v1 vsl| 1012 BereqURL b / **** v1 vsl| 1012 BereqProtocol b HTTP/1.1 **** v1 vsl| 1012 BereqHeader b foo: pipe **** v1 vsl| 1012 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1012 BereqHeader b User-Agent: c1 **** v1 vsl| 1012 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1012 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1012 BereqHeader b X-Varnish: 1011 **** v1 vsl| 1012 BereqHeader b Connection: close **** v1 vsl| 1012 BereqAcct b 0 0 0 0 0 0 **** v1 vsl| 1012 End b **** v1 vsl| 1011 Begin c req 1010 rxreq **** v1 vsl| 1011 Timestamp c Start: 1695125893.301541 0.000000 0.000000 **** v1 vsl| 1011 Timestamp c Req: 1695125893.301541 0.000000 0.000000 **** v1 vsl| 1011 VCL_use c vcl1 **** v1 vsl| 1011 ReqStart c 127.0.0.1 43636 a0 **** v1 vsl| 1011 ReqMethod c GET **** v1 vsl| 1011 ReqURL c / **** v1 vsl| 1011 ReqProtocol c HTTP/1.1 **** v1 vsl| 1011 ReqHeader c foo: pipe **** v1 vsl| 1011 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1011 ReqHeader c User-Agent: c1 **** v1 vsl| 1011 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1011 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1011 VCL_call c RECV **** v1 vsl| 1011 VCL_return c pipe **** v1 vsl| 1011 VCL_call c HASH **** v1 vsl| 1011 VCL_return c lookup **** dT 7.803 **** v1 vsl| 1011 Link c bereq 1012 pipe **** v1 vsl| 1011 VCL_call c PIPE **** v1 vsl| 1011 VCL_Error c Forced failure **** v1 vsl| 1011 VCL_return c fail **** v1 vsl| 1011 RespProtocol c HTTP/1.1 **** v1 vsl| 1011 RespStatus c 503 **** v1 vsl| 1011 RespReason c VCL failed **** v1 vsl| 1011 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1011 RespHeader c Server: Varnish **** v1 vsl| 1011 RespHeader c X-Varnish: 1011 **** v1 vsl| 1011 VCL_call c SYNTH **** v1 vsl| 1011 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1011 RespHeader c Retry-After: 5 **** v1 vsl| 1011 VCL_return c deliver **** v1 vsl| 1011 Timestamp c Process: 1695125893.302498 0.000956 0.000956 **** v1 vsl| 1011 RespHeader c Content-Length: 251 **** v1 vsl| 1011 Storage c malloc Transient **** v1 vsl| 1011 Filters c **** v1 vsl| 1011 RespHeader c Connection: close **** v1 vsl| 1011 Timestamp c Resp: 1695125893.306325 0.004783 0.003826 **** v1 vsl| 1011 ReqAcct c 62 0 62 194 251 445 **** v1 vsl| 1011 End c **** v1 vsl| 1010 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1010 End c **** v1 vsl| 1013 Begin c sess 0 HTTP/1 **** v1 vsl| 1013 SessOpen c 127.0.0.1 38819 a0 127.0.0.1 61732 1695125893.317948 23 **** v1 vsl| 1013 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1013 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1013 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1013 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1013 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1013 Link c req 1014 rxreq **** v1 vsl| 1014 Begin c req 1013 rxreq **** v1 vsl| 1014 Timestamp c Start: 1695125893.318622 0.000000 0.000000 **** v1 vsl| 1014 Timestamp c Req: 1695125893.318622 0.000000 0.000000 **** v1 vsl| 1014 VCL_use c vcl1 **** v1 vsl| 1014 ReqStart c 127.0.0.1 38819 a0 **** v1 vsl| 1014 ReqMethod c GET **** v1 vsl| 1014 ReqURL c / **** v1 vsl| 1014 ReqProtocol c HTTP/1.1 **** v1 vsl| 1014 ReqHeader c foo: pass **** v1 vsl| 1014 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1014 ReqHeader c User-Agent: c1 **** v1 vsl| 1014 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1014 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1014 VCL_call c RECV **** v1 vsl| 1014 VCL_return c pass **** v1 vsl| 1014 VCL_call c HASH **** v1 vsl| 1014 VCL_return c lookup **** v1 vsl| 1014 VCL_call c PASS **** v1 vsl| 1014 VCL_Error c Forced failure **** v1 vsl| 1014 VCL_return c fail **** v1 vsl| 1014 RespProtocol c HTTP/1.1 **** v1 vsl| 1014 RespStatus c 503 **** v1 vsl| 1014 RespReason c VCL failed **** v1 vsl| 1014 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1014 RespHeader c Server: Varnish **** v1 vsl| 1014 RespHeader c X-Varnish: 1014 **** v1 vsl| 1014 VCL_call c SYNTH **** v1 vsl| 1014 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1014 RespHeader c Retry-After: 5 **** dT 7.804 **** v1 vsl| 1014 VCL_return c deliver **** v1 vsl| 1014 Timestamp c Process: 1695125893.319368 0.000745 0.000745 **** v1 vsl| 1014 RespHeader c Content-Length: 251 **** v1 vsl| 1014 Storage c malloc Transient **** v1 vsl| 1014 Filters c **** v1 vsl| 1014 RespHeader c Connection: close **** v1 vsl| 1014 Timestamp c Resp: 1695125893.323182 0.004559 0.003813 **** v1 vsl| 1014 ReqAcct c 62 0 62 194 251 445 **** v1 vsl| 1014 End c **** v1 vsl| 1013 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1013 End c **** dT 7.806 ** c1 === rxresp **** dT 7.809 **** l1016 match| 1016 VCL_call c PURGE *** l1016 test | expect 0 1016 VCL_Error Forced failure **** l1016 match| 1016 VCL_Error c Forced failure *** l1016 test | expect 0 1016 VCL_return fail **** l1016 match| 1016 VCL_return c fail **** l1016 done | **** dT 7.810 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:13 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1016\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:13 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1016 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1016
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match **** dT 7.811 ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 57 ** c1 Ending ** top === varnish v1 -expect vcl_fail == 7 **** dT 7.812 ** v1 as expected: vcl_fail (7) == 7 (7) ** top === varnish v1 -expect sc_vcl_failure == 7 ** v1 as expected: sc_vcl_failure (7) == 7 (7) ** top === logexpect l1018 -v v1 -g raw { **** dT 7.814 ** l1018 === expect * 1018 VCL_call "MISS" ** l1018 === expect 0 1018 VCL_Error "Forced failure" ** l1018 === expect 0 1018 VCL_return "fail" **** dT 7.815 ** top === client c1 { ** c1 Starting client **** dT 7.816 ** c1 Waiting for client **** l1018 begin| *** l1018 test | expect * 1018 VCL_call MISS ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 7.817 *** c1 connected fd 62 from 127.0.0.1 30442 to 127.0.0.1:61732 ** c1 === txreq -url /miss -hdr "foo: miss" **** c1 txreq|GET /miss HTTP/1.1\r **** c1 txreq|foo: miss\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.820 ** c1 === rxresp **** dT 7.822 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:13 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1018\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:13 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1018 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1018
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 62 ** c1 Ending **** dT 7.824 ** top === varnish v1 -expect vcl_fail == 8 ** v1 as expected: vcl_fail (8) == 8 (8) ** top === varnish v1 -expect sc_vcl_failure == 8 **** dT 7.825 ** v1 as expected: sc_vcl_failure (8) == 8 (8) ** top === logexpect l1020 -v v1 -g raw { **** dT 7.826 ** l1020 === expect * 1020 VCL_call "HIT" **** dT 7.827 **** l1018 match| 1018 VCL_call c MISS *** l1018 test | expect 0 1018 VCL_Error Forced failure **** l1018 match| 1018 VCL_Error c Forced failure *** l1018 test | expect 0 1018 VCL_return fail **** l1018 match| 1018 VCL_return c fail **** l1018 done | ** l1020 === expect 0 1020 VCL_Error "Forced failure" **** dT 7.828 ** l1020 === expect 0 1020 VCL_return "fail" **** dT 7.829 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1020 begin| *** l1020 test | expect * 1020 VCL_call HIT **** dT 7.830 ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 7.831 *** c1 connected fd 67 from 127.0.0.1 46861 to 127.0.0.1:61732 ** c1 === txreq -url /hit -hdr "foo: hit" **** c1 txreq|GET /hit HTTP/1.1\r **** c1 txreq|foo: hit\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.834 ** c1 === rxresp **** dT 7.836 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:13 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1020\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:13 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1020 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1020
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 67 ** c1 Ending **** dT 7.838 ** top === varnish v1 -expect vcl_fail == 9 ** v1 as expected: vcl_fail (9) == 9 (9) ** top === varnish v1 -expect sc_vcl_failure == 9 **** dT 7.839 ** v1 as expected: sc_vcl_failure (9) == 9 (9) ** top === logexpect l1022 -v v1 -g raw { **** dT 7.840 ** l1022 === expect * 1022 VCL_call "DELIVER" **** dT 7.841 **** l1020 match| 1020 VCL_call c HIT *** l1020 test | expect 0 1020 VCL_Error Forced failure **** l1020 match| 1020 VCL_Error c Forced failure *** l1020 test | expect 0 1020 VCL_return fail **** l1020 match| 1020 VCL_return c fail **** l1020 done | ** l1022 === expect 0 1022 VCL_Error "Forced failure" **** dT 7.842 ** l1022 === expect 0 1022 VCL_return "fail" **** dT 7.843 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1022 begin| *** l1022 test | expect * 1022 VCL_call DELIVER **** dT 7.844 ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 *** c1 connected fd 72 from 127.0.0.1 25506 to 127.0.0.1:61732 **** dT 7.845 ** c1 === txreq -url /hit -hdr "foo: deliver" **** c1 txreq|GET /hit HTTP/1.1\r **** c1 txreq|foo: deliver\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.848 ** c1 === rxresp **** dT 7.849 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:13 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1022\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** dT 7.850 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:13 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1022 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1022
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 72 ** c1 Ending **** dT 7.852 ** top === varnish v1 -expect vcl_fail == 10 ** v1 as expected: vcl_fail (10) == 10 (10) ** top === varnish v1 -expect sc_vcl_failure == 10 **** dT 7.853 ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1001 -wait ** l1001 Waiting for logexp ** top === logexpect l1003 -wait ** l1003 Waiting for logexp ** top === logexpect l1007 -wait ** l1007 Waiting for logexp ** top === logexpect l1009 -wait ** l1009 Waiting for logexp ** top === logexpect l1012 -wait ** l1012 Waiting for logexp **** dT 7.854 **** l1022 match| 1022 VCL_call c DELIVER *** l1022 test | expect 0 1022 VCL_Error Forced failure **** l1022 match| 1022 VCL_Error c Forced failure *** l1022 test | expect 0 1022 VCL_return fail **** l1022 match| 1022 VCL_return c fail **** l1022 done | **** dT 7.855 ** top === logexpect l1011 -wait ** l1011 Waiting for logexp ** top === logexpect l1014 -wait ** l1014 Waiting for logexp ** top === logexpect l1016 -wait ** l1016 Waiting for logexp ** top === logexpect l1018 -wait ** l1018 Waiting for logexp ** top === logexpect l1020 -wait ** l1020 Waiting for logexp ** top === logexpect l1022 -wait ** l1022 Waiting for logexp ** top === varnish v1 -vcl+backend { **** dT 7.856 **** v1 CLI TX|vcl.inline vcl2 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "61588"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tsub vcl_backend_fetch { **** v1 CLI TX|\t\tdebug.fail(); **** v1 CLI TX|\t\tset bereq.http.not = "Should not happen"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 7.905 **** v1 vsl| 1015 Begin c sess 0 HTTP/1 **** v1 vsl| 1015 SessOpen c 127.0.0.1 30335 a0 127.0.0.1 61732 1695125893.336999 22 **** v1 vsl| 1015 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1015 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1015 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1015 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1015 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1015 Link c req 1016 rxreq **** v1 vsl| 1016 Begin c req 1015 rxreq **** v1 vsl| 1016 Timestamp c Start: 1695125893.337683 0.000000 0.000000 **** v1 vsl| 1016 Timestamp c Req: 1695125893.337683 0.000000 0.000000 **** v1 vsl| 1016 VCL_use c vcl1 **** v1 vsl| 1016 ReqStart c 127.0.0.1 30335 a0 **** v1 vsl| 1016 ReqMethod c GET **** v1 vsl| 1016 ReqURL c / **** v1 vsl| 1016 ReqProtocol c HTTP/1.1 **** v1 vsl| 1016 ReqHeader c foo: purge **** v1 vsl| 1016 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1016 ReqHeader c User-Agent: c1 **** v1 vsl| 1016 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1016 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1016 VCL_call c RECV **** v1 vsl| 1016 VCL_return c purge **** v1 vsl| 1016 VCL_call c HASH **** v1 vsl| 1016 VCL_return c lookup **** v1 vsl| 1016 VCL_call c PURGE **** v1 vsl| 1016 VCL_Error c Forced failure **** v1 vsl| 1016 VCL_return c fail **** v1 vsl| 1016 RespProtocol c HTTP/1.1 **** v1 vsl| 1016 RespStatus c 503 **** v1 vsl| 1016 RespReason c VCL failed **** v1 vsl| 1016 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1016 RespHeader c Server: Varnish **** v1 vsl| 1016 RespHeader c X-Varnish: 1016 **** v1 vsl| 1016 VCL_call c SYNTH **** v1 vsl| 1016 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1016 RespHeader c Retry-After: 5 **** v1 vsl| 1016 VCL_return c deliver **** v1 vsl| 1016 Timestamp c Process: 1695125893.338608 0.000925 0.000925 **** v1 vsl| 1016 RespHeader c Content-Length: 251 **** v1 vsl| 1016 Storage c malloc Transient **** v1 vsl| 1016 Filters c **** v1 vsl| 1016 RespHeader c Connection: close **** v1 vsl| 1016 Timestamp c Resp: 1695125893.340257 0.002574 0.001648 **** v1 vsl| 1016 ReqAcct c 63 0 63 194 251 445 **** v1 vsl| 1016 End c **** v1 vsl| 1015 SessClose c VCL_FAILURE 0.004 **** dT 7.906 **** v1 vsl| 1015 End c **** v1 vsl| 1017 Begin c sess 0 HTTP/1 **** v1 vsl| 1017 SessOpen c 127.0.0.1 30442 a0 127.0.0.1 61732 1695125893.350456 23 **** v1 vsl| 1017 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1017 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1017 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1017 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1017 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1017 Link c req 1018 rxreq **** v1 vsl| 1018 Begin c req 1017 rxreq **** v1 vsl| 1018 Timestamp c Start: 1695125893.351096 0.000000 0.000000 **** v1 vsl| 1018 Timestamp c Req: 1695125893.351096 0.000000 0.000000 **** v1 vsl| 1018 VCL_use c vcl1 **** v1 vsl| 1018 ReqStart c 127.0.0.1 30442 a0 **** v1 vsl| 1018 ReqMethod c GET **** v1 vsl| 1018 ReqURL c /miss **** v1 vsl| 1018 ReqProtocol c HTTP/1.1 **** v1 vsl| 1018 ReqHeader c foo: miss **** v1 vsl| 1018 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1018 ReqHeader c User-Agent: c1 **** v1 vsl| 1018 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1018 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1018 VCL_call c RECV **** v1 vsl| 1018 VCL_return c hash **** v1 vsl| 1018 VCL_call c HASH **** v1 vsl| 1018 VCL_return c lookup **** v1 vsl| 1018 VCL_call c MISS **** v1 vsl| 1018 VCL_Error c Forced failure **** v1 vsl| 1018 VCL_return c fail **** v1 vsl| 1018 RespProtocol c HTTP/1.1 **** v1 vsl| 1018 RespStatus c 503 **** v1 vsl| 1018 RespReason c VCL failed **** v1 vsl| 1018 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1018 RespHeader c Server: Varnish **** v1 vsl| 1018 RespHeader c X-Varnish: 1018 **** v1 vsl| 1018 VCL_call c SYNTH **** v1 vsl| 1018 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1018 RespHeader c Retry-After: 5 **** v1 vsl| 1018 VCL_return c deliver **** v1 vsl| 1018 Timestamp c Process: 1695125893.352010 0.000913 0.000913 **** v1 vsl| 1018 RespHeader c Content-Length: 251 **** v1 vsl| 1018 Storage c malloc Transient **** v1 vsl| 1018 Filters c **** v1 vsl| 1018 RespHeader c Connection: close **** v1 vsl| 1018 Timestamp c Resp: 1695125893.355681 0.004584 0.003670 **** v1 vsl| 1018 ReqAcct c 66 0 66 194 251 445 **** v1 vsl| 1018 End c **** v1 vsl| 1017 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1017 End c **** v1 vsl| 1019 Begin c sess 0 HTTP/1 **** v1 vsl| 1019 SessOpen c 127.0.0.1 46861 a0 127.0.0.1 61732 1695125893.364429 22 **** v1 vsl| 1019 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1019 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1019 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1019 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1019 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** dT 7.907 **** v1 vsl| 1019 Link c req 1020 rxreq **** v1 vsl| 1020 Begin c req 1019 rxreq **** v1 vsl| 1020 Timestamp c Start: 1695125893.365076 0.000000 0.000000 **** v1 vsl| 1020 Timestamp c Req: 1695125893.365076 0.000000 0.000000 **** v1 vsl| 1020 VCL_use c vcl1 **** v1 vsl| 1020 ReqStart c 127.0.0.1 46861 a0 **** v1 vsl| 1020 ReqMethod c GET **** v1 vsl| 1020 ReqURL c /hit **** v1 vsl| 1020 ReqProtocol c HTTP/1.1 **** v1 vsl| 1020 ReqHeader c foo: hit **** v1 vsl| 1020 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1020 ReqHeader c User-Agent: c1 **** v1 vsl| 1020 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1020 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1020 VCL_call c RECV **** v1 vsl| 1020 VCL_return c hash **** v1 vsl| 1020 VCL_call c HASH **** v1 vsl| 1020 VCL_return c lookup **** v1 vsl| 1020 Hit c 1005 119.876947 10.000000 0.000000 **** v1 vsl| 1020 VCL_call c HIT **** v1 vsl| 1020 VCL_Error c Forced failure **** v1 vsl| 1020 VCL_return c fail **** v1 vsl| 1020 RespProtocol c HTTP/1.1 **** v1 vsl| 1020 RespStatus c 503 **** v1 vsl| 1020 RespReason c VCL failed **** v1 vsl| 1020 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1020 RespHeader c Server: Varnish **** v1 vsl| 1020 RespHeader c X-Varnish: 1020 **** v1 vsl| 1020 VCL_call c SYNTH **** v1 vsl| 1020 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1020 RespHeader c Retry-After: 5 **** v1 vsl| 1020 VCL_return c deliver **** v1 vsl| 1020 Timestamp c Process: 1695125893.366007 0.000931 0.000931 **** v1 vsl| 1020 RespHeader c Content-Length: 251 **** v1 vsl| 1020 Storage c malloc Transient **** v1 vsl| 1020 Filters c **** v1 vsl| 1020 RespHeader c Connection: close **** v1 vsl| 1020 Timestamp c Resp: 1695125893.369648 0.004571 0.003640 **** v1 vsl| 1020 ReqAcct c 64 0 64 194 251 445 **** v1 vsl| 1020 End c **** v1 vsl| 1019 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1019 End c **** v1 vsl| 1021 Begin c sess 0 HTTP/1 **** v1 vsl| 1021 SessOpen c 127.0.0.1 25506 a0 127.0.0.1 61732 1695125893.378028 23 **** v1 vsl| 1021 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1021 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1021 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1021 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1021 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1021 Link c req 1022 rxreq **** v1 vsl| 1022 Begin c req 1021 rxreq **** v1 vsl| 1022 Timestamp c Start: 1695125893.378696 0.000000 0.000000 **** v1 vsl| 1022 Timestamp c Req: 1695125893.378696 0.000000 0.000000 **** v1 vsl| 1022 VCL_use c vcl1 **** v1 vsl| 1022 ReqStart c 127.0.0.1 25506 a0 **** v1 vsl| 1022 ReqMethod c GET **** v1 vsl| 1022 ReqURL c /hit **** v1 vsl| 1022 ReqProtocol c HTTP/1.1 **** v1 vsl| 1022 ReqHeader c foo: deliver **** v1 vsl| 1022 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1022 ReqHeader c User-Agent: c1 **** dT 7.908 **** v1 vsl| 1022 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1022 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1022 VCL_call c RECV **** v1 vsl| 1022 VCL_return c hash **** v1 vsl| 1022 VCL_call c HASH **** v1 vsl| 1022 VCL_return c lookup **** v1 vsl| 1022 Hit c 1005 119.863327 10.000000 0.000000 **** v1 vsl| 1022 VCL_call c HIT **** v1 vsl| 1022 VCL_return c deliver **** v1 vsl| 1022 RespProtocol c HTTP/1.1 **** v1 vsl| 1022 RespStatus c 200 **** v1 vsl| 1022 RespReason c OK **** v1 vsl| 1022 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1022 RespHeader c Server: s1 **** v1 vsl| 1022 RespHeader c Content-Length: 0 **** v1 vsl| 1022 RespHeader c X-Varnish: 1022 1005 **** v1 vsl| 1022 RespHeader c Age: 0 **** v1 vsl| 1022 RespHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1022 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1022 VCL_call c DELIVER **** v1 vsl| 1022 VCL_Error c Forced failure **** v1 vsl| 1022 VCL_return c fail **** v1 vsl| 1022 Timestamp c Process: 1695125893.379541 0.000845 0.000845 **** v1 vsl| 1022 RespProtocol c HTTP/1.1 **** v1 vsl| 1022 RespStatus c 503 **** v1 vsl| 1022 RespReason c VCL failed **** v1 vsl| 1022 RespHeader c Date: Tue, 19 Sep 2023 12:18:13 GMT **** v1 vsl| 1022 RespHeader c Server: Varnish **** v1 vsl| 1022 RespHeader c X-Varnish: 1022 **** v1 vsl| 1022 VCL_call c SYNTH **** v1 vsl| 1022 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1022 RespHeader c Retry-After: 5 **** v1 vsl| 1022 VCL_return c deliver **** v1 vsl| 1022 Timestamp c Process: 1695125893.379805 0.001109 0.000263 **** v1 vsl| 1022 RespHeader c Content-Length: 251 **** v1 vsl| 1022 Storage c malloc Transient **** v1 vsl| 1022 Filters c **** v1 vsl| 1022 RespHeader c Connection: close **** v1 vsl| 1022 Timestamp c Resp: 1695125893.383585 0.004889 0.003779 **** v1 vsl| 1022 ReqAcct c 68 0 68 194 251 445 **** v1 vsl| 1022 End c **** v1 vsl| 1021 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1021 End c **** dT 8.543 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_LINGER for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPIDLE for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPCNT for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPINTVL for a0=127.0.0.1:61732 **** dT 9.560 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_LINGER for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPIDLE for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPCNT for a0=127.0.0.1:61732 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPINTVL for a0=127.0.0.1:61732 **** dT 13.316 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl2 **** dT 13.340 **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1695125893.389347/vgc.so 1auto **** v1 vsl| 0 Debug - vcl2: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl2.1695125893.389347/vgc.so" as "vcl2" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695125898 1.0 **** dT 13.359 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** top === logexpect l1 -v v1 -g raw { **** dT 13.361 ** l1 === expect * 1025 VCL_call "BACKEND_FETCH" ** l1 === expect 0 1025 VCL_Error "Forced failure" ** l1 === expect 0 1025 VCL_return "fail" **** dT 13.362 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 13.363 **** l1 begin| *** l1 test | expect * 1025 VCL_call BACKEND_FETCH ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 13.364 *** c1 connected fd 77 from 127.0.0.1 25507 to 127.0.0.1:61732 ** c1 === txreq -url /backend_fetch **** dT 13.365 **** c1 txreq|GET /backend_fetch HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 13.366 ** c1 === rxresp **** dT 13.370 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:18 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1024\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 278\r **** c1 rxhdr|Connection: keep-alive\r **** c1 rxhdr|\r **** c1 rxhdrlen = 208 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |Service Unavailable **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:18 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1024 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 278 **** c1 http[ 9] |Connection: keep-alive **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|Service Unavailable
**** c1 c-l|XID: 1024
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 278 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "Service Unavailable" **** dT 13.371 **** c1 EXPECT resp.reason (Service Unavailable) == "Service Unavailable" match *** c1 closing fd 77 **** dT 13.372 ** c1 Ending ** top === varnish v1 -expect vcl_fail == 11 **** dT 13.373 ** v1 as expected: vcl_fail (11) == 11 (11) ** top === varnish v1 -expect sc_vcl_failure == 10 **** dT 13.374 **** l1 match| 1025 VCL_call b BACKEND_FETCH *** l1 test | expect 0 1025 VCL_Error Forced failure **** l1 match| 1025 VCL_Error b Forced failure *** l1 test | expect 0 1025 VCL_return fail **** l1 match| 1025 VCL_return b fail **** l1 done | ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1 -wait ** l1 Waiting for logexp **** dT 13.375 ** top === server s1 { ** s1 Waiting for server (3/-1) ** s1 Starting server **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=61588 **** s1 macro def s1_sock=127.0.0.1:61588 * s1 Listen on 127.0.0.1:61588 ** top === varnish v1 -vcl+backend { **** dT 13.376 **** v1 CLI TX|vcl.inline vcl3 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "61588"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tsub vcl_backend_error { **** v1 CLI TX|\t\tdebug.fail(); **** v1 CLI TX|\t\tset bereq.http.not = "Should not happen"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 13.381 ** s1 Started on 127.0.0.1:61588 (1 iterations) **** dT 13.442 **** v1 vsl| 0 CLI - Rd vcl.use vcl2 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 1023 Begin c sess 0 HTTP/1 **** v1 vsl| 1023 SessOpen c 127.0.0.1 25507 a0 127.0.0.1 61732 1695125898.897681 22 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1023 Link c req 1024 rxreq **** v1 vsl| 1025 Begin b bereq 1024 fetch **** v1 vsl| 1025 VCL_use b vcl2 **** v1 vsl| 1025 Timestamp b Start: 1695125898.899385 0.000000 0.000000 **** v1 vsl| 1025 BereqMethod b GET **** v1 vsl| 1025 BereqURL b /backend_fetch **** v1 vsl| 1025 BereqProtocol b HTTP/1.1 **** v1 vsl| 1025 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1025 BereqHeader b User-Agent: c1 **** v1 vsl| 1025 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1025 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1025 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1025 BereqHeader b X-Varnish: 1025 **** v1 vsl| 1025 VCL_call b BACKEND_FETCH **** v1 vsl| 1025 VCL_Error b Forced failure **** v1 vsl| 1025 VCL_return b fail **** v1 vsl| 1025 BereqAcct b 0 0 0 0 0 0 **** v1 vsl| 1025 End b **** v1 vsl| 1024 Begin c req 1023 rxreq **** v1 vsl| 1024 Timestamp c Start: 1695125898.898393 0.000000 0.000000 **** v1 vsl| 1024 Timestamp c Req: 1695125898.898393 0.000000 0.000000 **** v1 vsl| 1024 VCL_use c vcl2 **** v1 vsl| 1024 ReqStart c 127.0.0.1 25507 a0 **** v1 vsl| 1024 ReqMethod c GET **** v1 vsl| 1024 ReqURL c /backend_fetch **** v1 vsl| 1024 ReqProtocol c HTTP/1.1 **** v1 vsl| 1024 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1024 ReqHeader c User-Agent: c1 **** v1 vsl| 1024 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1024 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1024 VCL_call c RECV **** v1 vsl| 1024 VCL_return c hash **** v1 vsl| 1024 VCL_call c HASH **** v1 vsl| 1024 VCL_return c lookup **** v1 vsl| 1024 VCL_call c MISS **** v1 vsl| 1024 VCL_return c fetch **** v1 vsl| 1024 Link c bereq 1025 fetch **** v1 vsl| 1024 Timestamp c Fetch: 1695125898.899822 0.001429 0.001429 **** v1 vsl| 1024 RespProtocol c HTTP/1.1 **** v1 vsl| 1024 RespStatus c 503 **** v1 vsl| 1024 RespReason c Service Unavailable **** dT 13.443 **** v1 vsl| 1024 RespHeader c Date: Tue, 19 Sep 2023 12:18:18 GMT **** v1 vsl| 1024 RespHeader c Server: Varnish **** v1 vsl| 1024 RespHeader c X-Varnish: 1024 **** v1 vsl| 1024 VCL_call c SYNTH **** v1 vsl| 1024 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1024 RespHeader c Retry-After: 5 **** v1 vsl| 1024 VCL_return c deliver **** v1 vsl| 1024 Timestamp c Process: 1695125898.900278 0.001885 0.000455 **** v1 vsl| 1024 RespHeader c Content-Length: 278 **** v1 vsl| 1024 Storage c malloc Transient **** v1 vsl| 1024 Filters c **** v1 vsl| 1024 RespHeader c Connection: keep-alive **** v1 vsl| 1024 Timestamp c Resp: 1695125898.903778 0.005385 0.003499 **** v1 vsl| 1024 ReqAcct c 64 0 64 208 278 486 **** v1 vsl| 1024 End c **** v1 vsl| 1023 SessClose c REM_CLOSE 0.007 **** v1 vsl| 1023 End c **** dT 18.862 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl3 **** dT 18.904 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl3' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1028 VCL_call "BACKEND_ERROR" ** l1 === expect 0 1028 VCL_Error "Forced failure" **** dT 18.905 ** l1 === expect 0 1028 VCL_return "fail" **** dT 18.906 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1028 VCL_call BACKEND_ERROR **** dT 18.907 ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 18.908 *** c1 connected fd 78 from 127.0.0.1 25508 to 127.0.0.1:61732 **** dT 18.909 ** c1 === txreq -url /backend_error **** c1 txreq|GET /backend_error HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 18.912 ** c1 === rxresp *** s1 accepted fd 77 127.0.0.1 25509 ** s1 === rxreq **** dT 18.914 **** s1 rxhdr|GET /backend_error HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|User-Agent: c1\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r **** s1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1028\r **** s1 rxhdr|\r **** s1 rxhdrlen = 161 **** s1 http[ 0] |GET **** s1 http[ 1] |/backend_error **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |User-Agent: c1 **** s1 http[ 5] |X-Forwarded-For: 127.0.0.1 **** s1 http[ 6] |Via: 1.1 v1 (Varnish/trunk) **** s1 http[ 7] |Accept-Encoding: gzip **** s1 http[ 8] |X-Varnish: 1028 **** s1 bodylen = 0 ** s1 === expect req.url == /backend_error **** s1 EXPECT req.url (/backend_error) == "/backend_error" match *** s1 shutting fd 77 **** dT 18.918 **** v1 vsl| 0 CLI - Rd vcl.load vcl3 vcl_vcl3.1695125898.909115/vgc.so 1auto **** v1 vsl| 0 Debug - vcl3: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl3.1695125898.909115/vgc.so" as "vcl3" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695125904 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl3 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 1026 Begin c sess 0 HTTP/1 **** v1 vsl| 1026 SessOpen c 127.0.0.1 25508 a0 127.0.0.1 61732 1695125904.440591 24 **** v1 vsl| 1026 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1026 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1026 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1026 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1026 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1026 Link c req 1027 rxreq **** v1 vsl| 1028 Begin b bereq 1027 fetch **** v1 vsl| 1028 VCL_use b vcl3 **** v1 vsl| 1028 Timestamp b Start: 1695125904.442995 0.000000 0.000000 **** v1 vsl| 1028 BereqMethod b GET **** v1 vsl| 1028 BereqURL b /backend_error **** v1 vsl| 1028 BereqProtocol b HTTP/1.1 **** v1 vsl| 1028 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1028 BereqHeader b User-Agent: c1 **** v1 vsl| 1028 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1028 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1028 BereqHeader b Accept-Encoding: gzip **** dT 18.919 **** v1 vsl| 1028 BereqHeader b X-Varnish: 1028 **** v1 vsl| 1028 VCL_call b BACKEND_FETCH **** v1 vsl| 1028 VCL_return b fetch **** v1 vsl| 1028 Timestamp b Fetch: 1695125904.443225 0.000229 0.000229 **** v1 vsl| 1028 Timestamp b Connected: 1695125904.444033 0.001037 0.000807 **** v1 vsl| 1028 BackendOpen b 25 s1 127.0.0.1 61588 127.0.0.1 25509 connect **** v1 vsl| 1028 Timestamp b Bereq: 1695125904.444426 0.001430 0.000393 **** v1 vsl| 1028 FetchError b HTC eof (-1) **** v1 vsl| 1028 BackendClose b 25 s1 close Received bad req/resp **** v1 vsl| 1028 Timestamp b Beresp: 1695125904.447718 0.004722 0.003291 **** v1 vsl| 1028 Timestamp b Error: 1695125904.447761 0.004765 0.000043 **** v1 vsl| 1028 BerespProtocol b HTTP/1.1 **** v1 vsl| 1028 BerespStatus b 503 **** v1 vsl| 1028 BerespReason b Backend fetch failed **** v1 vsl| 1028 BerespHeader b Date: Tue, 19 Sep 2023 12:18:24 GMT **** v1 vsl| 1028 BerespHeader b Server: Varnish **** v1 vsl| 1028 VCL_call b BACKEND_ERROR **** v1 vsl| 1028 VCL_Error b Forced failure **** v1 vsl| 1028 VCL_return b fail **** v1 vsl| 1028 BereqAcct b 161 0 161 0 0 0 **** v1 vsl| 1028 End b **** v1 vsl| 1027 Begin c req 1026 rxreq **** v1 vsl| 1027 Timestamp c Start: 1695125904.442105 0.000000 0.000000 **** v1 vsl| 1027 Timestamp c Req: 1695125904.442105 0.000000 0.000000 **** v1 vsl| 1027 VCL_use c vcl3 **** v1 vsl| 1027 ReqStart c 127.0.0.1 25508 a0 **** v1 vsl| 1027 ReqMethod c GET **** v1 vsl| 1027 ReqURL c /backend_error **** v1 vsl| 1027 ReqProtocol c HTTP/1.1 **** v1 vsl| 1027 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1027 ReqHeader c User-Agent: c1 **** v1 vsl| 1027 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1027 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1027 VCL_call c RECV **** v1 vsl| 1027 VCL_return c hash **** v1 vsl| 1027 VCL_call c HASH **** v1 vsl| 1027 VCL_return c lookup **** v1 vsl| 1027 VCL_call c MISS **** v1 vsl| 1027 VCL_return c fetch **** v1 vsl| 1027 Link c bereq 1028 fetch **** v1 vsl| 1027 Timestamp c Fetch: 1695125904.448278 0.006172 0.006172 **** v1 vsl| 1027 RespProtocol c HTTP/1.1 **** v1 vsl| 1027 RespStatus c 503 **** v1 vsl| 1027 RespReason c Service Unavailable **** v1 vsl| 1027 RespHeader c Date: Tue, 19 Sep 2023 12:18:24 GMT **** v1 vsl| 1027 RespHeader c Server: Varnish **** v1 vsl| 1027 RespHeader c X-Varnish: 1027 **** v1 vsl| 1027 VCL_call c SYNTH **** v1 vsl| 1027 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1027 RespHeader c Retry-After: 5 **** v1 vsl| 1027 VCL_return c deliver **** v1 vsl| 1027 Timestamp c Process: 1695125904.448736 0.006630 0.000457 **** v1 vsl| 1027 RespHeader c Content-Length: 278 **** v1 vsl| 1027 Storage c malloc Transient **** v1 vsl| 1027 Filters c **** v1 vsl| 1027 RespHeader c Connection: keep-alive **** v1 vsl| 1027 Timestamp c Resp: 1695125904.450479 0.008373 0.001743 **** v1 vsl| 1027 ReqAcct c 64 0 64 208 278 486 **** v1 vsl| 1027 End c **** dT 18.921 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:24 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1027\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 278\r **** c1 rxhdr|Connection: keep-alive\r **** c1 rxhdr|\r **** c1 rxhdrlen = 208 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |Service Unavailable **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:24 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1027 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 278 **** c1 http[ 9] |Connection: keep-alive **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|Service Unavailable
**** c1 c-l|XID: 1027
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 278 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match **** dT 18.922 ** c1 === expect resp.reason == "Service Unavailable" **** c1 EXPECT resp.reason (Service Unavailable) == "Service Unavailable" match *** c1 closing fd 78 **** dT 18.923 ** c1 Ending ** s1 Ending **** dT 18.924 **** l1 match| 1028 VCL_call b BACKEND_ERROR *** l1 test | expect 0 1028 VCL_Error Forced failure **** l1 match| 1028 VCL_Error b Forced failure *** l1 test | expect 0 1028 VCL_return fail **** l1 match| 1028 VCL_return b fail **** l1 done | ** top === varnish v1 -expect vcl_fail == 12 **** dT 18.925 ** v1 as expected: vcl_fail (12) == 12 (12) ** top === varnish v1 -expect sc_vcl_failure == 10 ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1 -wait ** l1 Waiting for logexp **** dT 18.926 ** top === server s1 { ** s1 Waiting for server (3/-1) ** s1 Starting server **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=61588 **** s1 macro def s1_sock=127.0.0.1:61588 * s1 Listen on 127.0.0.1:61588 ** top === varnish v1 -vcl+backend { **** dT 18.927 **** v1 CLI TX|vcl.inline vcl4 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "61588"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tsub vcl_backend_response { **** v1 CLI TX|\t\tdebug.fail(); **** v1 CLI TX|\t\tset bereq.http.not = "Should not happen"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 18.932 ** s1 Started on 127.0.0.1:61588 (1 iterations) **** dT 19.022 **** v1 vsl| 1026 SessClose c REM_CLOSE 0.015 **** dT 19.023 **** v1 vsl| 1026 End c **** dT 24.255 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl4 **** dT 24.282 **** v1 vsl| 0 CLI - Rd vcl.load vcl4 vcl_vcl4.1695125904.460107/vgc.so 1auto **** v1 vsl| 0 Debug - vcl4: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl4.1695125904.460107/vgc.so" as "vcl4" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695125909 1.0 **** dT 24.298 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl4' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1031 VCL_call "BACKEND_RESPONSE" **** dT 24.299 ** l1 === expect 0 1031 VCL_Error "Forced failure" ** l1 === expect 0 1031 VCL_return "fail" **** dT 24.300 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1031 VCL_call BACKEND_RESPONSE **** dT 24.301 ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 24.302 *** c1 connected fd 78 from 127.0.0.1 25510 to 127.0.0.1:61732 ** c1 === txreq -url /backend_response **** dT 24.303 **** c1 txreq|GET /backend_response HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 24.305 ** c1 === rxresp **** dT 24.306 *** s1 accepted fd 77 127.0.0.1 25511 ** s1 === rxreq **** dT 24.307 **** s1 rxhdr|GET /backend_response HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|User-Agent: c1\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r **** s1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1031\r **** s1 rxhdr|\r **** s1 rxhdrlen = 164 **** s1 http[ 0] |GET **** dT 24.308 **** s1 http[ 1] |/backend_response **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |User-Agent: c1 **** s1 http[ 5] |X-Forwarded-For: 127.0.0.1 **** s1 http[ 6] |Via: 1.1 v1 (Varnish/trunk) **** s1 http[ 7] |Accept-Encoding: gzip **** s1 http[ 8] |X-Varnish: 1031 **** s1 bodylen = 0 ** s1 === expect req.url == /backend_response **** s1 EXPECT req.url (/backend_response) == "/backend_response" match ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Tue, 19 Sep 2023 12:18:29 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r **** dT 24.312 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:29 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1030\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 278\r **** c1 rxhdr|Connection: keep-alive\r **** c1 rxhdr|\r **** c1 rxhdrlen = 208 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |Service Unavailable **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:29 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1030 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 278 **** c1 http[ 9] |Connection: keep-alive **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|Service Unavailable
**** c1 c-l|XID: 1030
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 278 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "Service Unavailable" **** c1 EXPECT resp.reason (Service Unavailable) == "Service Unavailable" match *** c1 closing fd 78 **** dT 24.314 ** c1 Ending *** s1 shutting fd 77 **** dT 24.315 ** s1 Ending **** l1 match| 1031 VCL_call b BACKEND_RESPONSE **** dT 24.316 *** l1 test | expect 0 1031 VCL_Error Forced failure **** l1 match| 1031 VCL_Error b Forced failure *** l1 test | expect 0 1031 VCL_return fail **** l1 match| 1031 VCL_return b fail **** l1 done | ** top === varnish v1 -expect vcl_fail == 13 **** dT 24.317 ** v1 as expected: vcl_fail (13) == 13 (13) ** top === varnish v1 -expect sc_vcl_failure == 10 ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1 -wait ** l1 Waiting for logexp ** top === varnish v1 -vcl+backend { **** v1 CLI TX|vcl.inline vcl5 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "61588"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tsub vcl_recv { **** v1 CLI TX|\t\tif (debug.fail2()) { **** v1 CLI TX|\t\t\treturn (hash); **** v1 CLI TX|\t\t} **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 24.384 **** v1 vsl| 0 CLI - Rd vcl.use vcl4 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 1029 Begin c sess 0 HTTP/1 **** v1 vsl| 1029 SessOpen c 127.0.0.1 25510 a0 127.0.0.1 61732 1695125909.834437 22 **** v1 vsl| 1029 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1029 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1029 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1029 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1029 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1029 Link c req 1030 rxreq **** v1 vsl| 1031 Begin b bereq 1030 fetch **** v1 vsl| 1031 VCL_use b vcl4 **** v1 vsl| 1031 Timestamp b Start: 1695125909.836668 0.000000 0.000000 **** v1 vsl| 1031 BereqMethod b GET **** v1 vsl| 1031 BereqURL b /backend_response **** v1 vsl| 1031 BereqProtocol b HTTP/1.1 **** v1 vsl| 1031 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1031 BereqHeader b User-Agent: c1 **** v1 vsl| 1031 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1031 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1031 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1031 BereqHeader b X-Varnish: 1031 **** v1 vsl| 1031 VCL_call b BACKEND_FETCH **** v1 vsl| 1031 VCL_return b fetch **** v1 vsl| 1031 Timestamp b Fetch: 1695125909.836892 0.000223 0.000223 **** v1 vsl| 1031 Timestamp b Connected: 1695125909.837571 0.000903 0.000679 **** v1 vsl| 1031 BackendOpen b 25 s1 127.0.0.1 61588 127.0.0.1 25511 connect **** v1 vsl| 1031 Timestamp b Bereq: 1695125909.837916 0.001247 0.000344 **** v1 vsl| 1031 BerespProtocol b HTTP/1.1 **** v1 vsl| 1031 BerespStatus b 200 **** v1 vsl| 1031 BerespReason b OK **** v1 vsl| 1031 BerespHeader b Date: Tue, 19 Sep 2023 12:18:29 GMT **** v1 vsl| 1031 BerespHeader b Server: s1 **** v1 vsl| 1031 BerespHeader b Content-Length: 0 **** v1 vsl| 1031 Timestamp b Beresp: 1695125909.841118 0.004449 0.003201 **** v1 vsl| 1031 TTL b RFC 120 10 0 1695125910 1695125910 1695125909 0 0 cacheable **** v1 vsl| 1031 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1031 VCL_Error b Forced failure **** v1 vsl| 1031 VCL_return b fail **** v1 vsl| 1031 BackendClose b 25 s1 close Backend/VCL requested close **** v1 vsl| 1031 BereqAcct b 164 0 164 87 0 87 **** v1 vsl| 1031 End b **** v1 vsl| 1030 Begin c req 1029 rxreq **** v1 vsl| 1030 Timestamp c Start: 1695125909.835797 0.000000 0.000000 **** v1 vsl| 1030 Timestamp c Req: 1695125909.835797 0.000000 0.000000 **** v1 vsl| 1030 VCL_use c vcl4 **** v1 vsl| 1030 ReqStart c 127.0.0.1 25510 a0 **** v1 vsl| 1030 ReqMethod c GET **** v1 vsl| 1030 ReqURL c /backend_response **** v1 vsl| 1030 ReqProtocol c HTTP/1.1 **** v1 vsl| 1030 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1030 ReqHeader c User-Agent: c1 **** v1 vsl| 1030 ReqHeader c X-Forwarded-For: 127.0.0.1 **** dT 24.385 **** v1 vsl| 1030 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1030 VCL_call c RECV **** v1 vsl| 1030 VCL_return c hash **** v1 vsl| 1030 VCL_call c HASH **** v1 vsl| 1030 VCL_return c lookup **** v1 vsl| 1030 VCL_call c MISS **** v1 vsl| 1030 VCL_return c fetch **** v1 vsl| 1030 Link c bereq 1031 fetch **** v1 vsl| 1030 Timestamp c Fetch: 1695125909.841958 0.006160 0.006160 **** v1 vsl| 1030 RespProtocol c HTTP/1.1 **** v1 vsl| 1030 RespStatus c 503 **** v1 vsl| 1030 RespReason c Service Unavailable **** v1 vsl| 1030 RespHeader c Date: Tue, 19 Sep 2023 12:18:29 GMT **** v1 vsl| 1030 RespHeader c Server: Varnish **** v1 vsl| 1030 RespHeader c X-Varnish: 1030 **** v1 vsl| 1030 VCL_call c SYNTH **** v1 vsl| 1030 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1030 RespHeader c Retry-After: 5 **** v1 vsl| 1030 VCL_return c deliver **** v1 vsl| 1030 Timestamp c Process: 1695125909.842357 0.006559 0.000398 **** v1 vsl| 1030 RespHeader c Content-Length: 278 **** v1 vsl| 1030 Storage c malloc Transient **** v1 vsl| 1030 Filters c **** v1 vsl| 1030 RespHeader c Connection: keep-alive **** v1 vsl| 1030 Timestamp c Resp: 1695125909.845663 0.009865 0.003305 **** v1 vsl| 1030 ReqAcct c 67 0 67 208 278 486 **** v1 vsl| 1030 End c **** v1 vsl| 1029 SessClose c REM_CLOSE 0.012 **** v1 vsl| 1029 End c **** dT 29.795 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl5 **** dT 29.837 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl5' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1033 VCL_call "RECV" ** l1 === expect 0 1033 VCL_Error "Forced failure" **** dT 29.838 ** l1 === expect 0 1033 VCL_return "fail" **** dT 29.839 ** top === client c1 { **** l1 begin| *** l1 test | expect * 1033 VCL_call RECV ** c1 Starting client ** c1 Waiting for client **** dT 29.840 ** c1 Started on 127.0.0.1:61732 (1 iterations) *** c1 Connect to 127.0.0.1:61732 **** dT 29.841 *** c1 connected fd 77 from 127.0.0.1 25512 to 127.0.0.1:61732 ** c1 === txreq **** dT 29.842 **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 29.844 ** c1 === rxresp **** dT 29.846 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 19 Sep 2023 12:18:35 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1033\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 19 Sep 2023 12:18:35 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1033 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1033
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 77 **** dT 29.847 ** c1 Ending ** top === varnish v1 -expect vcl_fail == 14 **** dT 29.848 ** v1 as expected: vcl_fail (14) == 14 (14) ** top === varnish v1 -expect sc_vcl_failure == 11 ** v1 as expected: sc_vcl_failure (11) == 11 (11) ** top === logexpect l1 -wait **** dT 29.849 ** l1 Waiting for logexp **** dT 29.850 **** l1 match| 1033 VCL_call c RECV *** l1 test | expect 0 1033 VCL_Error Forced failure **** l1 match| 1033 VCL_Error c Forced failure *** l1 test | expect 0 1033 VCL_return fail **** l1 match| 1033 VCL_return c fail **** l1 done | **** dT 29.851 ** top === varnish v1 -errvcl {Forced failure} { **** v1 CLI TX|vcl.inline vcl6 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tbackend proforma none; **** v1 CLI TX|\tsub vcl_init { **** v1 CLI TX|\t\tdebug.fail(); **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 29.876 **** v1 vsl| 0 CLI - Rd vcl.load vcl5 vcl_vcl5.1695125909.850856/vgc.so 1auto **** v1 vsl| 0 Debug - vcl5: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl5.1695125909.850856/vgc.so" as "vcl5" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695125915 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl5 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 1032 Begin c sess 0 HTTP/1 **** v1 vsl| 1032 SessOpen c 127.0.0.1 25512 a0 127.0.0.1 61732 1695125915.373525 24 **** v1 vsl| 1032 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1032 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:61732 **** v1 vsl| 1032 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1032 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:61732 **** v1 vsl| 1032 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:61732 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:61732 **** v1 vsl| 1032 Link c req 1033 rxreq **** v1 vsl| 1033 Begin c req 1032 rxreq **** v1 vsl| 1033 Timestamp c Start: 1695125915.374740 0.000000 0.000000 **** v1 vsl| 1033 Timestamp c Req: 1695125915.374740 0.000000 0.000000 **** v1 vsl| 1033 VCL_use c vcl5 **** v1 vsl| 1033 ReqStart c 127.0.0.1 25512 a0 **** v1 vsl| 1033 ReqMethod c GET **** v1 vsl| 1033 ReqURL c / **** v1 vsl| 1033 ReqProtocol c HTTP/1.1 **** v1 vsl| 1033 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1033 ReqHeader c User-Agent: c1 **** v1 vsl| 1033 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1033 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1033 VCL_call c RECV **** v1 vsl| 1033 VCL_Error c Forced failure **** v1 vsl| 1033 VCL_return c fail **** v1 vsl| 1033 RespProtocol c HTTP/1.1 **** v1 vsl| 1033 RespStatus c 503 **** v1 vsl| 1033 RespReason c VCL failed **** v1 vsl| 1033 RespHeader c Date: Tue, 19 Sep 2023 12:18:35 GMT **** v1 vsl| 1033 RespHeader c Server: Varnish **** v1 vsl| 1033 RespHeader c X-Varnish: 1033 **** v1 vsl| 1033 VCL_call c SYNTH **** v1 vsl| 1033 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1033 RespHeader c Retry-After: 5 **** v1 vsl| 1033 VCL_return c deliver **** v1 vsl| 1033 Timestamp c Process: 1695125915.375357 0.000617 0.000617 **** v1 vsl| 1033 RespHeader c Content-Length: 251 **** v1 vsl| 1033 Storage c malloc Transient **** v1 vsl| 1033 Filters c **** v1 vsl| 1033 RespHeader c Connection: close **** v1 vsl| 1033 Timestamp c Resp: 1695125915.376129 0.001389 0.000771 **** v1 vsl| 1033 ReqAcct c 51 0 51 194 251 445 **** v1 vsl| 1033 End c **** v1 vsl| 1032 SessClose c VCL_FAILURE 0.003 **** v1 vsl| 1032 End c **** dT 35.102 **** v1 vsl| 0 CLI - Rd vcl.load vcl6 vcl_vcl6.1695125915.384309/vgc.so 1auto **** dT 35.110 *** v1 CLI RX 300 **** v1 CLI RX|VCL "vcl6" Failed initialization **** v1 CLI RX|Message: **** v1 CLI RX|\tForced failure ** v1 VCL compilation failed (as expected) *** v1 Found expected string: ("Forced failure") ** top === varnish v1 -errvcl {thou shalt not fini} { **** v1 CLI TX|vcl.inline vcl7 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tbackend proforma none; **** v1 CLI TX|\tsub vcl_init { **** v1 CLI TX|\t\tdebug.fail_task_fini(); **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 35.205 **** v1 vsl| 0 CLI - Wr 300 58 VCL "vcl6" Failed initialization Message: Forced failure **** dT 35.206 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695125920 1.0 **** dT 40.388 *** v1 CLI RX 300 **** v1 CLI RX|VCL "vcl7" Failed initialization **** v1 CLI RX|Message: **** v1 CLI RX|\tthou shalt not fini ** v1 VCL compilation failed (as expected) *** v1 Found expected string: ("thou shalt not fini") ** top === varnish v1 -vcl { **** v1 CLI TX|vcl.inline vcl8 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tbackend proforma none; **** v1 CLI TX|\tsub vcl_fini { **** v1 CLI TX|\t\tdebug.fail(); **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 40.416 **** v1 vsl| 0 CLI - Rd vcl.load vcl7 vcl_vcl7.1695125920.643984/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 300 63 VCL "vcl7" Failed initialization Message: thou shalt not fini **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695125925 1.0 **** dT 45.641 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl8 **** dT 45.647 **** v1 vsl| 0 CLI - Rd vcl.load vcl8 vcl_vcl8.1695125925.922275/vgc.so 1auto **** v1 vsl| 0 Debug - vcl8: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl8.1695125925.922275/vgc.so" as "vcl8" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695125931 1.0 **** dT 45.687 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl8' now active ** top === varnish v1 -vcl+backend { **** v1 CLI TX|vcl.inline vcl9 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "61588"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 45.748 **** v1 vsl| 0 CLI - Rd vcl.use vcl8 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 50.912 *** v1 CLI RX 200 **** dT 50.913 **** v1 CLI TX|vcl.use vcl9 **** dT 50.955 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl9' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 0 CLI "^Rd vcl.state vcl8 0cold" ** l1 === expect 3 0 VCL_Error "^Forced failure" **** dT 50.956 ** l1 === expect 0 0 VCL_Error {^\QVRT_fail() from vcl_fini{} has no e... **** dT 50.957 ** top === varnish v1 -cliok "vcl.discard vcl8" **** v1 CLI TX|vcl.discard vcl8 **** dT 50.958 **** l1 begin| *** l1 test | expect * 0 CLI ^Rd vcl.state vcl8 0cold **** dT 50.979 **** v1 vsl| 0 CLI - Rd vcl.load vcl9 vcl_vcl9.1695125931.220518/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl9.1695125931.220518/vgc.so" as "vcl9" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695125936 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl9 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 51.002 **** l1 match| 0 CLI - Rd vcl.state vcl8 0cold *** l1 test | expect 3 0 VCL_Error ^Forced failure **** l1 match| 0 VCL_Error - Forced failure *** l1 test | expect 0 0 VCL_Error ^\\QVRT_fail() from vcl_fini{} has no effect\\E$ **** l1 match| 0 VCL_Error - VRT_fail() from vcl_fini{} has no effect **** l1 done | **** dT 51.004 *** v1 CLI RX 200 ** v1 CLI 200