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 8.199 ** top === varnish v1 -expect vcl_fail == 1 **** dT 8.210 **** 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 8.217 **** v1 vsl| 0 CLI - Rd debug.xid 999 **** dT 8.218 **** v1 vsl| 0 CLI - Wr 200 18 XID is 999 chunk 1 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 10255 **** v1 vsl| 1000 Begin c sess 0 HTTP/1 **** v1 vsl| 1000 SessOpen c 127.0.0.1 21788 a0 127.0.0.1 10255 1648609591.396090 22 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_SNDTIMEO non heredity for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_RCVTIMEO non heredity for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: Test confirmed TCP_NODELAY non heredity for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1000 Link c req 1001 rxreq **** v1 vsl| 1001 Begin c req 1000 rxreq **** v1 vsl| 1001 Timestamp c Start: 1648609591.397174 0.000000 0.000000 **** v1 vsl| 1001 Timestamp c Req: 1648609591.397174 0.000000 0.000000 **** v1 vsl| 1001 VCL_use c vcl1 **** v1 vsl| 1001 ReqStart c 127.0.0.1 21788 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 X-Forwarded-For: 127.0.0.1 **** 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: Wed, 30 Mar 2022 03:06:31 GMT **** v1 vsl| 1001 RespHeader c Server: Varnish **** v1 vsl| 1001 RespHeader c X-Varnish: 1001 **** dT 8.219 **** 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: 1648609591.400102 0.002928 0.002928 **** 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: 1648609591.413896 0.016722 0.013794 **** v1 vsl| 1001 ReqAcct c 35 0 35 194 251 445 **** v1 vsl| 1001 End c **** v1 vsl| 1000 SessClose c VCL_FAILURE 0.019 **** v1 vsl| 1000 End c **** dT 8.311 ** v1 as expected: vcl_fail (1) == 1 (1) ** top === varnish v1 -expect sc_vcl_failure == 1 ** v1 as expected: sc_vcl_failure (1) == 1 (1) ** top === logexpect l1003 -v v1 -g raw { **** dT 8.312 ** l1003 === expect * 1003 VCL_call "RECV" **** dT 8.313 ** l1003 === expect 0 1003 VCL_Error "Forced failure" ** l1003 === expect 0 1003 VCL_return "fail" ** l1003 === expect * 1003 VCL_call "SYNTH" **** dT 8.314 ** l1003 === expect 0 1003 VCL_return "restart" **** dT 8.315 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 8.325 **** l1003 begin| *** l1003 test | expect * 1003 VCL_call RECV **** dT 8.332 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 8.340 *** c1 connected fd 28 from 127.0.0.1 47801 to 127.0.0.1:10255 **** dT 8.341 ** 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|\r **** dT 8.361 ** c1 === rxresp **** dT 8.419 **** l1003 match| 1003 VCL_call c RECV *** l1003 test | expect 0 1003 VCL_Error Forced failure **** dT 8.420 **** l1003 match| 1003 VCL_Error c Forced failure *** l1003 test | expect 0 1003 VCL_return fail **** dT 8.421 **** l1003 match| 1003 VCL_return c fail *** l1003 test | expect * 1003 VCL_call SYNTH **** dT 8.422 **** v1 vsl| 1002 Begin c sess 0 HTTP/1 **** v1 vsl| 1002 SessOpen c 127.0.0.1 47801 a0 127.0.0.1 10255 1648609591.558908 23 **** v1 vsl| 1002 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** dT 8.423 **** v1 vsl| 1002 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1002 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** dT 8.424 **** v1 vsl| 1002 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1002 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** dT 8.425 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1002 Link c req 1003 rxreq **** dT 8.426 **** v1 vsl| 1003 Begin c req 1002 rxreq **** v1 vsl| 1003 Timestamp c Start: 1648609591.566935 0.000000 0.000000 **** v1 vsl| 1003 Timestamp c Req: 1648609591.566935 0.000000 0.000000 **** dT 8.427 **** v1 vsl| 1003 VCL_use c vcl1 **** v1 vsl| 1003 ReqStart c 127.0.0.1 47801 a0 **** v1 vsl| 1003 ReqMethod c GET **** v1 vsl| 1003 ReqURL c /hit **** dT 8.428 **** 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 X-Forwarded-For: 127.0.0.1 **** dT 8.429 **** v1 vsl| 1003 VCL_call c RECV **** v1 vsl| 1003 VCL_Error c Forced failure **** v1 vsl| 1003 VCL_return c fail **** dT 8.430 **** v1 vsl| 1003 RespProtocol c HTTP/1.1 **** dT 8.431 **** v1 vsl| 1003 RespStatus c 503 **** v1 vsl| 1003 RespReason c VCL failed **** v1 vsl| 1003 RespHeader c Date: Wed, 30 Mar 2022 03:06:31 GMT **** dT 8.432 **** v1 vsl| 1003 RespHeader c Server: Varnish **** v1 vsl| 1003 RespHeader c X-Varnish: 1003 **** v1 vsl| 1003 VCL_call c SYNTH **** dT 8.433 **** v1 vsl| 1003 VCL_return c restart **** v1 vsl| 1003 Timestamp c Process: 1648609591.601780 0.034844 0.034844 **** v1 vsl| 1003 Timestamp c Restart: 1648609591.602432 0.035497 0.000652 **** v1 vsl| 1003 Link c req 1004 restart **** dT 8.434 **** v1 vsl| 1003 End c **** dT 8.437 **** l1003 match| 1003 VCL_call c SYNTH **** dT 8.438 *** l1003 test | expect 0 1003 VCL_return restart **** dT 8.439 **** l1003 match| 1003 VCL_return c restart **** l1003 done | **** dT 8.464 *** s1 accepted fd 4 127.0.0.1 27335 **** dT 8.471 ** s1 === rxreq **** dT 8.518 **** s1 rxhdr|GET /hit HTTP/1.1\r **** s1 rxhdr|foo: restart\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1005\r **** s1 rxhdr|\r **** dT 8.519 **** s1 rxhdrlen = 92 **** s1 http[ 0] |GET **** dT 8.520 **** 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] |Accept-Encoding: gzip **** s1 http[ 6] |X-Varnish: 1005 **** dT 8.521 **** s1 bodylen = 0 ** s1 === expect req.url == /hit **** dT 8.522 **** s1 EXPECT req.url (/hit) == "/hit" match ** s1 === txresp **** dT 8.524 **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r **** dT 8.527 *** s1 shutting fd 4 **** dT 8.530 ** s1 Ending **** dT 8.744 **** v1 vsl| 1005 Begin b bereq 1004 fetch **** v1 vsl| 1005 VCL_use b vcl1 **** dT 8.745 **** v1 vsl| 1005 Timestamp b Start: 1648609591.648756 0.000000 0.000000 **** v1 vsl| 1005 BereqMethod b GET **** v1 vsl| 1005 BereqURL b /hit **** v1 vsl| 1005 BereqProtocol b HTTP/1.1 **** dT 8.746 **** v1 vsl| 1005 BereqHeader b foo: restart **** v1 vsl| 1005 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1005 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1005 BereqHeader b X-Varnish: 1005 **** dT 8.747 **** v1 vsl| 1005 VCL_call b BACKEND_FETCH **** v1 vsl| 1005 VCL_return b fetch **** v1 vsl| 1005 Timestamp b Fetch: 1648609591.649572 0.000816 0.000816 **** dT 8.748 **** v1 vsl| 1005 Timestamp b Connected: 1648609591.650501 0.001744 0.000928 **** v1 vsl| 1005 BackendOpen b 25 s1 127.0.0.1 34365 127.0.0.1 27335 connect **** dT 8.749 **** v1 vsl| 1005 Timestamp b Bereq: 1648609591.736703 0.087947 0.086202 **** v1 vsl| 1005 Timestamp b Beresp: 1648609591.737006 0.088249 0.000302 **** v1 vsl| 1005 BerespProtocol b HTTP/1.1 **** dT 8.750 **** v1 vsl| 1005 BerespStatus b 200 **** v1 vsl| 1005 BerespReason b OK **** dT 8.751 **** v1 vsl| 1005 BerespHeader b Content-Length: 0 **** v1 vsl| 1005 BerespHeader b Date: Wed, 30 Mar 2022 03:06:31 GMT **** v1 vsl| 1005 TTL b RFC 120 10 0 1648609592 1648609592 1648609591 0 0 cacheable **** dT 8.752 **** v1 vsl| 1005 VCL_call b BACKEND_RESPONSE **** dT 8.753 **** v1 vsl| 1005 VCL_return b deliver **** v1 vsl| 1005 Timestamp b Process: 1648609591.737535 0.088779 0.000529 **** v1 vsl| 1005 Filters b **** dT 8.754 **** v1 vsl| 1005 Storage b malloc s0 **** v1 vsl| 1005 Fetch_Body b 0 none - **** v1 vsl| 1005 BackendClose b 25 s1 recycle **** dT 8.755 **** v1 vsl| 1005 Timestamp b BerespBody: 1648609591.867549 0.218793 0.130014 **** v1 vsl| 1005 Length b 0 **** v1 vsl| 1005 BereqAcct b 92 0 92 38 0 38 **** dT 8.756 **** v1 vsl| 1005 End b **** v1 vsl| 1004 Begin c req 1003 restart **** v1 vsl| 1004 Timestamp c Start: 1648609591.602432 0.035497 0.000000 **** dT 8.757 **** v1 vsl| 1004 ReqStart c 127.0.0.1 47801 a0 **** v1 vsl| 1004 ReqMethod c GET **** v1 vsl| 1004 ReqURL c /hit **** dT 8.758 **** 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 **** dT 8.759 **** v1 vsl| 1004 VCL_call c RECV **** v1 vsl| 1004 VCL_return c hash **** v1 vsl| 1004 VCL_call c HASH **** dT 8.760 **** v1 vsl| 1004 VCL_return c lookup **** v1 vsl| 1004 VCL_call c MISS **** v1 vsl| 1004 VCL_return c fetch **** dT 8.761 **** v1 vsl| 1004 Link c bereq 1005 fetch **** v1 vsl| 1004 Timestamp c Fetch: 1648609591.873995 0.307060 0.271562 **** v1 vsl| 1004 RespProtocol c HTTP/1.1 **** dT 8.762 **** v1 vsl| 1004 RespStatus c 200 **** v1 vsl| 1004 RespReason c OK **** v1 vsl| 1004 RespHeader c Content-Length: 0 **** v1 vsl| 1004 RespHeader c Date: Wed, 30 Mar 2022 03:06:31 GMT **** dT 8.763 **** v1 vsl| 1004 RespHeader c X-Varnish: 1004 **** v1 vsl| 1004 RespHeader c Age: 0 **** v1 vsl| 1004 RespHeader c Via: 1.1 varnish (Varnish/7.1) **** dT 8.764 **** v1 vsl| 1004 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1004 VCL_call c DELIVER **** v1 vsl| 1004 VCL_return c deliver **** dT 8.765 **** v1 vsl| 1004 Timestamp c Process: 1648609591.878948 0.312013 0.004953 **** v1 vsl| 1004 Filters c **** v1 vsl| 1004 RespHeader c Connection: close **** v1 vsl| 1004 Timestamp c Resp: 1648609591.884176 0.317241 0.005228 **** v1 vsl| 1004 ReqAcct c 52 0 52 173 0 173 **** v1 vsl| 1004 End c **** v1 vsl| 1002 SessClose c VCL_FAILURE 0.331 **** v1 vsl| 1002 End c **** dT 8.766 **** c1 rxhdr|HTTP/1.1 200 OK\r **** c1 rxhdr|Content-Length: 0\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:31 GMT\r **** c1 rxhdr|X-Varnish: 1004\r **** c1 rxhdr|Age: 0\r **** c1 rxhdr|Via: 1.1 varnish (Varnish/7.1)\r **** c1 rxhdr|Accept-Ranges: bytes\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 173 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |200 **** c1 http[ 2] |OK **** c1 http[ 3] |Content-Length: 0 **** c1 http[ 4] |Date: Wed, 30 Mar 2022 03:06:31 GMT **** c1 http[ 5] |X-Varnish: 1004 **** c1 http[ 6] |Age: 0 **** c1 http[ 7] |Via: 1.1 varnish (Varnish/7.1) **** c1 http[ 8] |Accept-Ranges: bytes **** c1 http[ 9] |Connection: close **** c1 bodylen = 0 ** c1 === expect resp.status == 200 **** dT 8.767 **** 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 8.781 ** top === varnish v1 -expect vcl_fail == 2 ** v1 as expected: vcl_fail (2) == 2 (2) ** top === varnish v1 -expect sc_vcl_failure == 2 **** dT 8.782 ** v1 as expected: sc_vcl_failure (2) == 2 (2) ** top === logexpect l1007 -v v1 -g raw { **** dT 8.845 ** l1007 === expect * 1007 VCL_call "SYNTH" **** dT 8.846 ** l1007 === expect * 1007 VCL_Error "Forced failure" ** l1007 === expect 0 1007 VCL_return "fail" **** dT 8.847 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 8.870 **** l1007 begin| **** dT 8.871 *** l1007 test | expect * 1007 VCL_call SYNTH **** dT 8.876 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 8.890 *** c1 connected fd 32 from 127.0.0.1 28714 to 127.0.0.1:10255 **** dT 8.892 ** c1 === txreq -hdr "foo: synth" **** dT 8.894 **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: synth\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 8.969 **** v1 vsl| 1006 Begin c sess 0 HTTP/1 **** dT 8.970 **** v1 vsl| 1006 SessOpen c 127.0.0.1 28714 a0 127.0.0.1 10255 1648609592.143498 22 **** v1 vsl| 1006 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1006 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1006 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** dT 8.971 **** v1 vsl| 1006 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** dT 8.972 **** v1 vsl| 1006 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** dT 8.973 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1006 Link c req 1007 rxreq **** dT 8.989 ** 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 **** c1 Expecting close (fd = 32) **** c1 fd=32 EOF, as expected *** c1 closing fd 32 **** dT 8.990 ** c1 Ending **** dT 9.011 **** l1007 match| 1007 VCL_call c SYNTH *** l1007 test | expect * 1007 VCL_Error Forced failure **** dT 9.012 **** 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 | **** dT 9.017 ** top === varnish v1 -expect vcl_fail == 3 ** v1 as expected: vcl_fail (3) == 3 (3) ** top === varnish v1 -expect sc_vcl_failure == 3 **** dT 9.018 ** v1 as expected: sc_vcl_failure (3) == 3 (3) ** top === logexpect l1009 -v v1 -g raw { **** dT 9.019 ** l1009 === expect * 1009 VCL_call "HASH" **** dT 9.020 ** l1009 === expect 0 1009 VCL_Error "Forced failure" ** l1009 === expect 0 1009 VCL_return "fail" **** dT 9.021 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 9.023 **** l1009 begin| *** l1009 test | expect * 1009 VCL_call HASH **** dT 9.027 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 9.029 *** c1 connected fd 37 from 127.0.0.1 31422 to 127.0.0.1:10255 ** 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|\r **** dT 9.037 ** c1 === rxresp **** dT 9.038 **** 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 9.044 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:32 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 **** dT 9.045 **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Wed, 30 Mar 2022 03:06:32 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 9.046 ** c1 Ending **** dT 9.049 ** top === varnish v1 -expect vcl_fail == 4 **** dT 9.050 ** 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 9.051 ** l1012 === expect 0 1012 Begin {^bereq 1011 pipe} **** dT 9.052 ** 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} **** dT 9.053 ** l1012 === expect 0 = BereqHeader {^Host: } ** l1012 === expect 0 = BereqHeader {^X-Forwarded-For: } ** l1012 === expect 0 = BereqHeader {^X-Varnish: 1011} ** l1012 === expect 0 = BereqHeader {^Connection: close} ** l1012 === expect 0 = BereqAcct {^0 0 0 0 0 0} ** l1012 === expect 0 = End **** dT 9.054 ** top === logexpect l1011 -v v1 -g vxid -q "vxid == 1011" { **** dT 9.056 ** l1011 === expect 0 1011 Begin {^req 1010 rxreq} ** l1011 === expect 0 = Timestamp {^Start: } ** l1011 === expect 0 = Timestamp {^Req: } ** l1011 === expect 0 = VCL_use {^vcl1} **** dT 9.057 ** 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 {^X-Forwarded-For: } **** dT 9.058 ** 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} ** l1011 === expect 0 = VCL_Error {^Forced failure} **** dT 9.059 ** 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 9.060 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 9.063 **** l1012 begin| **** l1012 qry | vxid == 1012 *** l1012 test | expect 0 1012 Begin ^bereq 1011 pipe **** dT 9.065 **** l1011 begin| **** l1011 qry | vxid == 1011 *** l1011 test | expect 0 1011 Begin ^req 1010 rxreq **** dT 9.067 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 9.069 *** c1 connected fd 47 from 127.0.0.1 64675 to 127.0.0.1:10255 ** c1 === txreq -hdr "foo: pipe" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: pipe\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 9.076 **** v1 vsl| 1007 Begin c req 1006 rxreq **** v1 vsl| 1007 Timestamp c Start: 1648609592.162486 0.000000 0.000000 **** v1 vsl| 1007 Timestamp c Req: 1648609592.162486 0.000000 0.000000 **** v1 vsl| 1007 VCL_use c vcl1 **** v1 vsl| 1007 ReqStart c 127.0.0.1 28714 a0 **** v1 vsl| 1007 ReqMethod c GET **** v1 vsl| 1007 ReqURL c / **** v1 vsl| 1007 ReqProtocol c HTTP/1.1 **** dT 9.077 **** v1 vsl| 1007 ReqHeader c foo: synth **** v1 vsl| 1007 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1007 ReqHeader c X-Forwarded-For: 127.0.0.1 **** 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: Wed, 30 Mar 2022 03:06:32 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: 1648609592.183305 0.020818 0.020818 **** 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: 1648609592.186295 0.023808 0.002990 **** v1 vsl| 1007 ReqAcct c 47 0 47 38 0 38 **** v1 vsl| 1007 End c **** v1 vsl| 1006 SessClose c VCL_FAILURE 0.046 **** v1 vsl| 1006 End c **** v1 vsl| 1008 Begin c sess 0 HTTP/1 **** v1 vsl| 1008 SessOpen c 127.0.0.1 31422 a0 127.0.0.1 10255 1648609592.234228 23 **** v1 vsl| 1008 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1008 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1008 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1008 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1008 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1008 Link c req 1009 rxreq **** v1 vsl| 1009 Begin c req 1008 rxreq **** v1 vsl| 1009 Timestamp c Start: 1648609592.239234 0.000000 0.000000 **** v1 vsl| 1009 Timestamp c Req: 1648609592.239234 0.000000 0.000000 **** v1 vsl| 1009 VCL_use c vcl1 **** v1 vsl| 1009 ReqStart c 127.0.0.1 31422 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 X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1009 VCL_call c RECV **** v1 vsl| 1009 VCL_return c hash **** v1 vsl| 1009 VCL_call c HASH **** v1 vsl| 1009 VCL_Error c Forced failure **** v1 vsl| 1009 VCL_return c fail **** dT 9.078 **** 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: Wed, 30 Mar 2022 03:06:32 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: 1648609592.240835 0.001600 0.001600 **** 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: 1648609592.241675 0.002440 0.000840 **** v1 vsl| 1009 ReqAcct c 46 0 46 194 251 445 **** v1 vsl| 1009 End c **** v1 vsl| 1008 SessClose c VCL_FAILURE 0.008 **** v1 vsl| 1008 End c **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_LINGER for a0=127.0.0.1:10255 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPIDLE for a0=127.0.0.1:10255 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPCNT for a0=127.0.0.1:10255 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPINTVL for a0=127.0.0.1:10255 **** v1 vsl| 1010 Begin c sess 0 HTTP/1 **** v1 vsl| 1010 SessOpen c 127.0.0.1 64675 a0 127.0.0.1 10255 1648609592.274105 22 **** v1 vsl| 1010 Debug c sockopt: Not testing nonhereditary SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: Not testing nonhereditary SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: Not testing nonhereditary SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: Not testing nonhereditary TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1010 Link c req 1011 rxreq **** v1 vsl| 1012 Begin b bereq 1011 pipe **** v1 vsl| 1012 Timestamp b Start: 1648609592.278831 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 X-Forwarded-For: 127.0.0.1 **** 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 **** dT 9.079 **** v1 vsl| 1012 End b **** v1 vsl| 1011 Begin c req 1010 rxreq **** v1 vsl| 1011 Timestamp c Start: 1648609592.278250 0.000000 0.000000 **** v1 vsl| 1011 Timestamp c Req: 1648609592.278250 0.000000 0.000000 **** v1 vsl| 1011 VCL_use c vcl1 **** v1 vsl| 1011 ReqStart c 127.0.0.1 64675 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 X-Forwarded-For: 127.0.0.1 **** 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 **** 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: Wed, 30 Mar 2022 03:06:32 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: 1648609592.279662 0.001411 0.001411 **** 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: 1648609592.280444 0.002193 0.000782 **** v1 vsl| 1011 ReqAcct c 46 0 46 194 251 445 **** v1 vsl| 1011 End c **** v1 vsl| 1010 SessClose c VCL_FAILURE 0.007 **** v1 vsl| 1010 End c **** dT 9.081 **** l1012 match| 1012 Begin b bereq 1011 pipe *** l1012 test | expect 0 = Timestamp ^Start: **** l1012 match| 1012 Timestamp b Start: 1648609592.278831 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 ^X-Forwarded-For: **** l1012 match| 1012 BereqHeader b X-Forwarded-For: 127.0.0.1 *** 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 9.082 **** l1011 match| 1011 Begin c req 1010 rxreq *** l1011 test | expect 0 = Timestamp ^Start: **** dT 9.083 **** l1011 match| 1011 Timestamp c Start: 1648609592.278250 0.000000 0.000000 *** l1011 test | expect 0 = Timestamp ^Req: **** l1011 match| 1011 Timestamp c Req: 1648609592.278250 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 64675 a0 *** l1011 test | expect 0 = ReqMethod ^GET **** l1011 match| 1011 ReqMethod c GET *** 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 ^X-Forwarded-For: **** l1011 match| 1011 ReqHeader c X-Forwarded-For: 127.0.0.1 *** 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 9.085 ** c1 === rxresp **** dT 9.090 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:32 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 **** dT 9.091 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Wed, 30 Mar 2022 03:06:32 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 *** c1 closing fd 47 ** c1 Ending **** dT 9.094 ** top === varnish v1 -expect vcl_fail == 5 **** dT 9.095 ** 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 9.097 ** l1014 === expect * 1014 VCL_call "PASS" ** l1014 === expect 0 1014 VCL_Error "Forced failure" **** dT 9.098 ** l1014 === expect 0 1014 VCL_return "fail" **** dT 9.099 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 9.100 **** l1014 begin| *** l1014 test | expect * 1014 VCL_call PASS **** dT 9.102 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 9.103 *** c1 connected fd 52 from 127.0.0.1 65228 to 127.0.0.1:10255 **** dT 9.104 ** 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|\r **** dT 9.110 ** c1 === rxresp **** dT 9.115 **** 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 9.119 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:32 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: Wed, 30 Mar 2022 03:06:32 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 **** dT 9.120 ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 52 ** c1 Ending **** dT 9.123 ** top === varnish v1 -expect vcl_fail == 6 ** v1 as expected: vcl_fail (6) == 6 (6) ** top === varnish v1 -expect sc_vcl_failure == 6 **** dT 9.124 ** v1 as expected: sc_vcl_failure (6) == 6 (6) ** top === logexpect l1016 -v v1 -g raw { **** dT 9.125 ** l1016 === expect * 1016 VCL_call "PURGE" **** dT 9.126 ** l1016 === expect 0 1016 VCL_Error "Forced failure" ** l1016 === expect 0 1016 VCL_return "fail" **** dT 9.127 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 9.129 **** l1016 begin| *** l1016 test | expect * 1016 VCL_call PURGE **** dT 9.132 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 9.133 *** c1 connected fd 57 from 127.0.0.1 50671 to 127.0.0.1:10255 ** c1 === txreq -hdr "foo: purge" **** dT 9.134 **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: purge\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 9.138 ** c1 === rxresp **** dT 9.142 **** 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 9.144 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:32 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: Wed, 30 Mar 2022 03:06:32 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1016 **** dT 9.145 **** 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 ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 57 ** c1 Ending **** dT 9.148 ** top === varnish v1 -expect vcl_fail == 7 **** dT 9.149 ** v1 as expected: vcl_fail (7) == 7 (7) ** top === varnish v1 -expect sc_vcl_failure == 7 **** dT 9.151 ** v1 as expected: sc_vcl_failure (7) == 7 (7) ** top === logexpect l1018 -v v1 -g raw { **** dT 9.153 ** l1018 === expect * 1018 VCL_call "MISS" ** l1018 === expect 0 1018 VCL_Error "Forced failure" ** l1018 === expect 0 1018 VCL_return "fail" **** dT 9.154 ** top === client c1 { ** c1 Starting client **** dT 9.155 ** c1 Waiting for client **** dT 9.157 **** l1018 begin| *** l1018 test | expect * 1018 VCL_call MISS **** dT 9.159 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 9.161 *** c1 connected fd 62 from 127.0.0.1 15225 to 127.0.0.1:10255 ** c1 === txreq -url /miss -hdr "foo: miss" **** dT 9.162 **** c1 txreq|GET /miss HTTP/1.1\r **** c1 txreq|foo: miss\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 9.166 ** c1 === rxresp **** dT 9.171 **** 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 | **** dT 9.174 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:32 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: Wed, 30 Mar 2022 03:06:32 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1018 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** dT 9.175 **** 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 9.177 ** top === varnish v1 -expect vcl_fail == 8 **** dT 9.178 ** v1 as expected: vcl_fail (8) == 8 (8) ** top === varnish v1 -expect sc_vcl_failure == 8 ** v1 as expected: sc_vcl_failure (8) == 8 (8) ** top === logexpect l1020 -v v1 -g raw { **** dT 9.180 ** l1020 === expect * 1020 VCL_call "HIT" ** l1020 === expect 0 1020 VCL_Error "Forced failure" ** l1020 === expect 0 1020 VCL_return "fail" **** v1 vsl| 1013 Begin c sess 0 HTTP/1 **** v1 vsl| 1013 SessOpen c 127.0.0.1 65228 a0 127.0.0.1 10255 1648609592.308679 23 **** v1 vsl| 1013 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1013 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1013 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1013 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1013 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1013 Link c req 1014 rxreq **** dT 9.181 **** v1 vsl| 1014 Begin c req 1013 rxreq **** v1 vsl| 1014 Timestamp c Start: 1648609592.313335 0.000000 0.000000 **** v1 vsl| 1014 Timestamp c Req: 1648609592.313335 0.000000 0.000000 **** v1 vsl| 1014 VCL_use c vcl1 **** v1 vsl| 1014 ReqStart c 127.0.0.1 65228 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 X-Forwarded-For: 127.0.0.1 **** 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: Wed, 30 Mar 2022 03:06:32 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 **** v1 vsl| 1014 VCL_return c deliver **** v1 vsl| 1014 Timestamp c Process: 1648609592.314191 0.000856 0.000856 **** 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: 1648609592.314915 0.001580 0.000723 **** v1 vsl| 1014 ReqAcct c 46 0 46 194 251 445 **** v1 vsl| 1014 End c **** v1 vsl| 1013 SessClose c VCL_FAILURE 0.007 **** v1 vsl| 1013 End c **** v1 vsl| 1015 Begin c sess 0 HTTP/1 **** v1 vsl| 1015 SessOpen c 127.0.0.1 50671 a0 127.0.0.1 10255 1648609592.338517 22 **** v1 vsl| 1015 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1015 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1015 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1015 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1015 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1015 Link c req 1016 rxreq **** v1 vsl| 1016 Begin c req 1015 rxreq **** v1 vsl| 1016 Timestamp c Start: 1648609592.341288 0.000000 0.000000 **** v1 vsl| 1016 Timestamp c Req: 1648609592.341288 0.000000 0.000000 **** v1 vsl| 1016 VCL_use c vcl1 **** dT 9.182 **** v1 vsl| 1016 ReqStart c 127.0.0.1 50671 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 X-Forwarded-For: 127.0.0.1 **** 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: Wed, 30 Mar 2022 03:06:32 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: 1648609592.342548 0.001259 0.001259 **** 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: 1648609592.343302 0.002013 0.000753 **** v1 vsl| 1016 ReqAcct c 47 0 47 194 251 445 **** v1 vsl| 1016 End c **** v1 vsl| 1015 SessClose c VCL_FAILURE 0.005 **** v1 vsl| 1015 End c **** v1 vsl| 1017 Begin c sess 0 HTTP/1 **** v1 vsl| 1017 SessOpen c 127.0.0.1 15225 a0 127.0.0.1 10255 1648609592.366383 23 **** v1 vsl| 1017 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1017 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1017 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1017 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1017 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1017 Link c req 1018 rxreq **** v1 vsl| 1018 Begin c req 1017 rxreq **** v1 vsl| 1018 Timestamp c Start: 1648609592.369831 0.000000 0.000000 **** v1 vsl| 1018 Timestamp c Req: 1648609592.369831 0.000000 0.000000 **** v1 vsl| 1018 VCL_use c vcl1 **** v1 vsl| 1018 ReqStart c 127.0.0.1 15225 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 **** dT 9.183 **** v1 vsl| 1018 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1018 ReqHeader c X-Forwarded-For: 127.0.0.1 **** 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: Wed, 30 Mar 2022 03:06:32 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: 1648609592.370837 0.001005 0.001005 **** 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: 1648609592.371574 0.001743 0.000737 **** v1 vsl| 1018 ReqAcct c 50 0 50 194 251 445 **** v1 vsl| 1018 End c **** v1 vsl| 1017 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1017 End c **** dT 9.186 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 9.188 **** l1020 begin| *** l1020 test | expect * 1020 VCL_call HIT **** dT 9.190 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 9.191 *** c1 connected fd 67 from 127.0.0.1 51454 to 127.0.0.1:10255 **** dT 9.192 ** 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|\r **** dT 9.196 ** c1 === rxresp **** dT 9.198 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:32 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: Wed, 30 Mar 2022 03:06:32 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 **** dT 9.199 ** c1 Ending **** dT 9.201 **** 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 | **** dT 9.204 ** top === varnish v1 -expect vcl_fail == 9 **** dT 9.205 ** v1 as expected: vcl_fail (9) == 9 (9) ** top === varnish v1 -expect sc_vcl_failure == 9 **** dT 9.206 ** v1 as expected: sc_vcl_failure (9) == 9 (9) ** top === logexpect l1022 -v v1 -g raw { **** dT 9.207 ** l1022 === expect * 1022 VCL_call "DELIVER" **** dT 9.208 ** l1022 === expect 0 1022 VCL_Error "Forced failure" ** l1022 === expect 0 1022 VCL_return "fail" **** dT 9.209 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 9.214 **** l1022 begin| *** l1022 test | expect * 1022 VCL_call DELIVER **** dT 9.216 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 9.217 *** c1 connected fd 72 from 127.0.0.1 64629 to 127.0.0.1:10255 ** c1 === txreq -url /hit -hdr "foo: deliver" **** dT 9.218 **** c1 txreq|GET /hit HTTP/1.1\r **** c1 txreq|foo: deliver\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 9.222 ** c1 === rxresp **** dT 9.224 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:32 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 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Wed, 30 Mar 2022 03:06:32 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" **** dT 9.228 **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 72 ** c1 Ending **** dT 9.226 **** l1022 match| 1022 VCL_call c DELIVER **** dT 9.229 *** 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 9.231 ** top === varnish v1 -expect vcl_fail == 10 ** v1 as expected: vcl_fail (10) == 10 (10) ** top === varnish v1 -expect sc_vcl_failure == 10 **** dT 9.232 ** 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 **** dT 9.233 ** top === logexpect l1009 -wait ** l1009 Waiting for logexp ** top === logexpect l1012 -wait ** l1012 Waiting for logexp ** 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 **** dT 9.234 ** top === logexpect l1020 -wait ** l1020 Waiting for logexp ** top === logexpect l1022 -wait ** l1022 Waiting for logexp ** top === varnish v1 -vcl+backend { **** 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 = "34365"; } **** 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 9.284 **** v1 vsl| 1019 Begin c sess 0 HTTP/1 **** v1 vsl| 1019 SessOpen c 127.0.0.1 51454 a0 127.0.0.1 10255 1648609592.396687 22 **** v1 vsl| 1019 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1019 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1019 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1019 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1019 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** dT 9.285 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1019 Link c req 1020 rxreq **** v1 vsl| 1020 Begin c req 1019 rxreq **** v1 vsl| 1020 Timestamp c Start: 1648609592.399398 0.000000 0.000000 **** v1 vsl| 1020 Timestamp c Req: 1648609592.399398 0.000000 0.000000 **** v1 vsl| 1020 VCL_use c vcl1 **** v1 vsl| 1020 ReqStart c 127.0.0.1 51454 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 X-Forwarded-For: 127.0.0.1 **** 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.337608 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: Wed, 30 Mar 2022 03:06:32 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: 1648609592.400437 0.001039 0.001039 **** 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: 1648609592.401193 0.001795 0.000756 **** v1 vsl| 1020 ReqAcct c 48 0 48 194 251 445 **** v1 vsl| 1020 End c **** v1 vsl| 1019 SessClose c VCL_FAILURE 0.005 **** v1 vsl| 1019 End c **** v1 vsl| 1021 Begin c sess 0 HTTP/1 **** v1 vsl| 1021 SessOpen c 127.0.0.1 64629 a0 127.0.0.1 10255 1648609592.422463 23 **** v1 vsl| 1021 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1021 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1021 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1021 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1021 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1021 Link c req 1022 rxreq **** dT 9.286 **** v1 vsl| 1022 Begin c req 1021 rxreq **** v1 vsl| 1022 Timestamp c Start: 1648609592.425261 0.000000 0.000000 **** v1 vsl| 1022 Timestamp c Req: 1648609592.425261 0.000000 0.000000 **** v1 vsl| 1022 VCL_use c vcl1 **** v1 vsl| 1022 ReqStart c 127.0.0.1 64629 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 X-Forwarded-For: 127.0.0.1 **** 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.311745 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 Content-Length: 0 **** v1 vsl| 1022 RespHeader c Date: Wed, 30 Mar 2022 03:06:31 GMT **** v1 vsl| 1022 RespHeader c X-Varnish: 1022 1005 **** v1 vsl| 1022 RespHeader c Age: 0 **** v1 vsl| 1022 RespHeader c Via: 1.1 varnish (Varnish/7.1) **** 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: 1648609592.426141 0.000880 0.000880 **** 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: Wed, 30 Mar 2022 03:06:32 GMT **** v1 vsl| 1022 RespHeader c Server: Varnish **** dT 9.287 **** 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: 1648609592.426425 0.001164 0.000284 **** 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: 1648609592.427163 0.001902 0.000737 **** v1 vsl| 1022 ReqAcct c 52 0 52 194 251 445 **** v1 vsl| 1022 End c **** v1 vsl| 1021 SessClose c VCL_FAILURE 0.005 **** v1 vsl| 1021 End c **** dT 15.737 **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1648609592.440759/vgc.so 1auto **** dT 15.740 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl2 **** dT 15.786 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** top === logexpect l1 -v v1 -g raw { **** dT 15.788 ** l1 === expect * 1025 VCL_call "BACKEND_FETCH" ** l1 === expect 0 1025 VCL_Error "Forced failure" ** l1 === expect 0 1025 VCL_return "fail" **** dT 15.789 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1025 VCL_call BACKEND_FETCH **** dT 15.790 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 15.791 *** c1 connected fd 77 from 127.0.0.1 60205 to 127.0.0.1:10255 ** c1 === txreq -url /backend_fetch **** c1 txreq|GET /backend_fetch HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r ** c1 === rxresp **** dT 15.800 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:39 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: Wed, 30 Mar 2022 03:06:39 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" **** c1 EXPECT resp.reason (Service Unavailable) == "Service Unavailable" match *** c1 closing fd 77 **** dT 15.801 ** c1 Ending **** dT 15.802 **** 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 | ** top === varnish v1 -expect vcl_fail == 11 **** dT 15.803 ** v1 as expected: vcl_fail (11) == 11 (11) ** 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 15.804 ** 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=34365 **** s1 macro def s1_sock=127.0.0.1:34365 * s1 Listen on 127.0.0.1:34365 ** top === varnish v1 -vcl+backend { **** dT 15.805 **** 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 = "34365"; } **** 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 15.806 ** s1 Started on 127.0.0.1:34365 (1 iterations) **** dT 15.839 **** v1 vsl| 0 Debug - vcl2: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl2.1648609592.440759/vgc.so" as "vcl2" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1648609598 1.0 **** 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 60205 a0 127.0.0.1 10255 1648609598.997427 22 **** dT 15.840 **** v1 vsl| 1023 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1023 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1023 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1023 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1023 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** 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: 1648609599.001151 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 X-Forwarded-For: 127.0.0.1 **** 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: 1648609598.997853 0.000000 0.000000 **** v1 vsl| 1024 Timestamp c Req: 1648609598.997853 0.000000 0.000000 **** v1 vsl| 1024 VCL_use c vcl2 **** v1 vsl| 1024 ReqStart c 127.0.0.1 60205 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 X-Forwarded-For: 127.0.0.1 **** 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: 1648609599.002162 0.004308 0.004308 **** v1 vsl| 1024 RespProtocol c HTTP/1.1 **** v1 vsl| 1024 RespStatus c 503 **** v1 vsl| 1024 RespReason c Service Unavailable **** v1 vsl| 1024 RespHeader c Date: Wed, 30 Mar 2022 03:06:39 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: 1648609599.002748 0.004895 0.000586 **** dT 15.841 **** 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: 1648609599.011671 0.013818 0.008922 **** v1 vsl| 1024 ReqAcct c 48 0 48 208 278 486 **** v1 vsl| 1024 End c **** v1 vsl| 1023 SessClose c REM_CLOSE 0.015 **** v1 vsl| 1023 End c **** dT 20.529 *** v1 CLI RX 200 **** dT 20.530 **** v1 CLI TX|vcl.use vcl3 **** dT 20.551 **** v1 vsl| 0 CLI - Rd vcl.load vcl3 vcl_vcl3.1648609599.012870/vgc.so 1auto **** v1 vsl| 0 Debug - vcl3: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl3.1648609599.012870/vgc.so" as "vcl3" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1648609603 1.0 **** dT 20.574 *** 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 20.575 ** l1 === expect 0 1028 VCL_return "fail" **** dT 20.576 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1028 VCL_call BACKEND_ERROR ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 20.577 *** c1 connected fd 78 from 127.0.0.1 11459 to 127.0.0.1:10255 **** dT 20.578 ** c1 === txreq -url /backend_error **** c1 txreq|GET /backend_error HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r ** c1 === rxresp **** dT 20.581 *** s1 accepted fd 77 127.0.0.1 23464 **** dT 20.582 ** s1 === rxreq **** dT 20.583 **** s1 rxhdr|GET /backend_error HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1028\r **** s1 rxhdr|\r **** s1 rxhdrlen = 116 **** 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] |X-Forwarded-For: 127.0.0.1 **** s1 http[ 5] |Accept-Encoding: gzip **** s1 http[ 6] |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 20.585 ** s1 Ending **** dT 20.591 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:43 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: Wed, 30 Mar 2022 03:06:43 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 ** c1 === expect resp.reason == "Service Unavailable" **** c1 EXPECT resp.reason (Service Unavailable) == "Service Unavailable" match *** c1 closing fd 78 **** dT 20.592 ** c1 Ending **** dT 20.594 **** 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 20.595 ** 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 20.596 ** 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=34365 **** s1 macro def s1_sock=127.0.0.1:34365 * s1 Listen on 127.0.0.1:34365 ** top === varnish v1 -vcl+backend { **** dT 20.597 **** 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 = "34365"; } **** 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 ** s1 Started on 127.0.0.1:34365 (1 iterations) **** dT 20.652 **** 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 11459 a0 127.0.0.1 10255 1648609603.784337 23 **** v1 vsl| 1026 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1026 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1026 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1026 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1026 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** 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: 1648609603.785581 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 X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1028 BereqHeader b Accept-Encoding: gzip **** 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: 1648609603.785818 0.000237 0.000237 **** v1 vsl| 1028 Timestamp b Connected: 1648609603.786703 0.001122 0.000885 **** v1 vsl| 1028 BackendOpen b 25 s1 127.0.0.1 34365 127.0.0.1 23464 connect **** v1 vsl| 1028 Timestamp b Bereq: 1648609603.787100 0.001519 0.000396 **** 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: 1648609603.789914 0.004333 0.002813 **** v1 vsl| 1028 Timestamp b Error: 1648609603.789963 0.004381 0.000048 **** 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: Wed, 30 Mar 2022 03:06:43 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 116 0 116 0 0 0 **** dT 20.653 **** v1 vsl| 1028 End b **** v1 vsl| 1027 Begin c req 1026 rxreq **** v1 vsl| 1027 Timestamp c Start: 1648609603.784777 0.000000 0.000000 **** v1 vsl| 1027 Timestamp c Req: 1648609603.784777 0.000000 0.000000 **** v1 vsl| 1027 VCL_use c vcl3 **** v1 vsl| 1027 ReqStart c 127.0.0.1 11459 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 X-Forwarded-For: 127.0.0.1 **** 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: 1648609603.791453 0.006675 0.006675 **** 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: Wed, 30 Mar 2022 03:06:43 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: 1648609603.791851 0.007074 0.000398 **** 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: 1648609603.798168 0.013390 0.006316 **** v1 vsl| 1027 ReqAcct c 48 0 48 208 278 486 **** v1 vsl| 1027 End c **** v1 vsl| 1026 SessClose c REM_CLOSE 0.014 **** v1 vsl| 1026 End c **** dT 25.357 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl4 **** dT 25.403 *** 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" ** l1 === expect 0 1031 VCL_Error "Forced failure" **** dT 25.404 ** l1 === expect 0 1031 VCL_return "fail" **** dT 25.405 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1031 VCL_call BACKEND_RESPONSE **** dT 25.406 ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 25.407 *** c1 connected fd 78 from 127.0.0.1 58342 to 127.0.0.1:10255 ** c1 === txreq -url /backend_response **** c1 txreq|GET /backend_response HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r ** c1 === rxresp **** dT 25.411 *** s1 accepted fd 77 127.0.0.1 18578 ** s1 === rxreq **** dT 25.412 **** s1 rxhdr|GET /backend_response HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1031\r **** s1 rxhdr|\r **** s1 rxhdrlen = 119 **** s1 http[ 0] |GET **** s1 http[ 1] |/backend_response **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |X-Forwarded-For: 127.0.0.1 **** s1 http[ 5] |Accept-Encoding: gzip **** s1 http[ 6] |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|Content-Length: 0\r **** s1 txresp|\r **** dT 25.414 *** s1 shutting fd 77 ** s1 Ending **** dT 25.418 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:48 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: Wed, 30 Mar 2022 03:06:48 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1030 **** dT 25.419 **** 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 ** c1 Ending **** dT 25.421 **** l1 match| 1031 VCL_call b BACKEND_RESPONSE *** 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 | **** dT 25.422 ** top === varnish v1 -expect vcl_fail == 13 ** v1 as expected: vcl_fail (13) == 13 (13) ** top === varnish v1 -expect sc_vcl_failure == 10 **** dT 25.423 ** 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 = "34365"; } **** 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 25.444 **** v1 vsl| 0 CLI - Rd vcl.load vcl4 vcl_vcl4.1648609603.803762/vgc.so 1auto **** v1 vsl| 0 Debug - vcl4: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl4.1648609603.803762/vgc.so" as "vcl4" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1648609608 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl4 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 1029 Begin c sess 0 HTTP/1 **** dT 25.445 **** v1 vsl| 1029 SessOpen c 127.0.0.1 58342 a0 127.0.0.1 10255 1648609608.613439 22 **** v1 vsl| 1029 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1029 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1029 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1029 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1029 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** 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: 1648609608.614857 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 X-Forwarded-For: 127.0.0.1 **** 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: 1648609608.615135 0.000277 0.000277 **** v1 vsl| 1031 Timestamp b Connected: 1648609608.615805 0.000947 0.000669 **** v1 vsl| 1031 BackendOpen b 25 s1 127.0.0.1 34365 127.0.0.1 18578 connect **** v1 vsl| 1031 Timestamp b Bereq: 1648609608.616194 0.001336 0.000389 **** v1 vsl| 1031 Timestamp b Beresp: 1648609608.618748 0.003890 0.002553 **** 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 Content-Length: 0 **** v1 vsl| 1031 BerespHeader b Date: Wed, 30 Mar 2022 03:06:48 GMT **** v1 vsl| 1031 TTL b RFC 120 10 0 1648609609 1648609609 1648609608 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 119 0 119 38 0 38 **** v1 vsl| 1031 End b **** v1 vsl| 1030 Begin c req 1029 rxreq **** v1 vsl| 1030 Timestamp c Start: 1648609608.613909 0.000000 0.000000 **** v1 vsl| 1030 Timestamp c Req: 1648609608.613909 0.000000 0.000000 **** v1 vsl| 1030 VCL_use c vcl4 **** v1 vsl| 1030 ReqStart c 127.0.0.1 58342 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 X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1030 VCL_call c RECV **** v1 vsl| 1030 VCL_return c hash **** v1 vsl| 1030 VCL_call c HASH **** dT 25.446 **** 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: 1648609608.620756 0.006847 0.006847 **** 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: Wed, 30 Mar 2022 03:06:48 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: 1648609608.621410 0.007501 0.000653 **** 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: 1648609608.625663 0.011754 0.004253 **** v1 vsl| 1030 ReqAcct c 51 0 51 208 278 486 **** v1 vsl| 1030 End c **** v1 vsl| 1029 SessClose c REM_CLOSE 0.013 **** v1 vsl| 1029 End c **** dT 31.672 **** v1 vsl| 0 CLI - Rd vcl.load vcl5 vcl_vcl5.1648609608.630021/vgc.so 1auto **** v1 vsl| 0 Debug - vcl5: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl5.1648609608.630021/vgc.so" as "vcl5" **** dT 31.675 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl5 **** dT 31.719 *** 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" ** l1 === expect 0 1033 VCL_return "fail" **** dT 31.721 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1033 VCL_call RECV ** c1 Started on 127.0.0.1:10255 (1 iterations) *** c1 Connect to 127.0.0.1:10255 **** dT 31.722 *** c1 connected fd 77 from 127.0.0.1 28500 to 127.0.0.1:10255 ** c1 === txreq **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 31.723 ** c1 === rxresp **** dT 31.726 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 30 Mar 2022 03:06:54 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: Wed, 30 Mar 2022 03:06:54 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 **** dT 31.727 **** 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 ** c1 Ending **** dT 31.729 ** top === varnish v1 -expect vcl_fail == 14 **** dT 31.730 ** 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 ** l1 Waiting for logexp **** dT 31.733 **** 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 31.734 ** 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 31.775 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1648609614 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 28500 a0 127.0.0.1 10255 1648609614.928813 23 **** v1 vsl| 1032 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1032 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10255 **** v1 vsl| 1032 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1032 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10255 **** v1 vsl| 1032 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10255 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:10255 **** v1 vsl| 1032 Link c req 1033 rxreq **** v1 vsl| 1033 Begin c req 1032 rxreq **** v1 vsl| 1033 Timestamp c Start: 1648609614.929271 0.000000 0.000000 **** v1 vsl| 1033 Timestamp c Req: 1648609614.929271 0.000000 0.000000 **** v1 vsl| 1033 VCL_use c vcl5 **** v1 vsl| 1033 ReqStart c 127.0.0.1 28500 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 X-Forwarded-For: 127.0.0.1 **** 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: Wed, 30 Mar 2022 03:06:54 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: 1648609614.929827 0.000555 0.000555 **** v1 vsl| 1033 RespHeader c Content-Length: 251 **** dT 31.776 **** 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: 1648609614.933811 0.004539 0.003984 **** v1 vsl| 1033 ReqAcct c 35 0 35 194 251 445 **** v1 vsl| 1033 End c **** v1 vsl| 1032 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1032 End c **** dT 36.520 *** v1 CLI RX 300 **** v1 CLI RX|VCL "vcl6" Failed initialization **** v1 CLI RX|Message: **** v1 CLI RX|\tVFP already registered (per-vcl) **** v1 CLI RX|Forced failure ** v1 VCL compilation failed (as expected) **** dT 36.521 *** 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 36.577 **** v1 vsl| 0 CLI - Rd vcl.load vcl6 vcl_vcl6.1648609614.940729/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 300 91 VCL "vcl6" Failed initialization Message: VFP already registered (per-vcl) Forced failure **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1648609619 1.0 **** dT 42.086 *** v1 CLI RX 300 **** v1 CLI RX|VCL "vcl7" Failed initialization **** v1 CLI RX|Message: **** v1 CLI RX|\tVFP already registered (per-vcl) **** v1 CLI RX|thou shalt not fini **** dT 42.087 ** 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 42.127 **** v1 vsl| 0 CLI - Rd vcl.load vcl7 vcl_vcl7.1648609619.732451/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 300 96 VCL "vcl7" Failed initialization Message: VFP already registered (per-vcl) thou shalt not fini **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1648609625 1.0 **** dT 46.823 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl8 **** dT 46.833 **** v1 vsl| 0 CLI - Rd vcl.load vcl8 vcl_vcl8.1648609625.295419/vgc.so 1auto **** v1 vsl| 0 Debug - vcl8: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl8.1648609625.295419/vgc.so" as "vcl8" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1648609630 1.0 **** dT 46.867 *** 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 = "34365"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 46.934 **** v1 vsl| 0 CLI - Rd vcl.use vcl8 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 51.837 **** v1 vsl| 0 CLI - Rd vcl.load vcl9 vcl_vcl9.1648609630.073835/vgc.so 1auto **** dT 51.845 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl9 **** dT 51.888 *** 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 51.889 ** l1 === expect 0 0 VCL_Error {^\QVRT_fail() from vcl_fini{} has no e... **** dT 51.890 ** top === varnish v1 -cliok "vcl.discard vcl8" **** v1 CLI TX|vcl.discard vcl8 **** l1 begin| *** l1 test | expect * 0 CLI ^Rd vcl.state vcl8 0cold **** dT 51.936 **** l1 match| 0 CLI - Rd vcl.state vcl8 0cold *** l1 test | expect 3 0 VCL_Error ^Forced failure **** dT 51.939 **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl9.1648609630.073835/vgc.so" as "vcl9" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1648609635 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl9 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.state vcl8 0cold **** v1 vsl| 0 Debug - vcl8: VCL_EVENT_COLD **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.discard vcl8 **** dT 51.940 **** v1 vsl| 0 VCL_Error - Forced failure **** v1 vsl| 0 VCL_Error - VRT_fail() from vcl_fini{} has no effect **** v1 vsl| 0 CLI - Wr 200 0 **** dT 51.943 *** v1 CLI RX 200 ** v1 CLI 200