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 **** dT 11.090 ** c1 Ending **** dT 11.091 ** top === varnish v1 -expect vcl_fail == 1 **** dT 11.102 **** 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 11.153 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 42684 **** dT 11.154 **** v1 vsl| 1000 Begin c sess 0 HTTP/1 **** v1 vsl| 1000 SessOpen c 127.0.0.1 19403 a0 127.0.0.1 42684 1650423670.137077 22 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=127.0.0.1:42684 **** dT 11.155 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_SNDTIMEO non heredity for a0=127.0.0.1:42684 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_RCVTIMEO non heredity for a0=127.0.0.1:42684 **** v1 vsl| 1000 Debug c sockopt: Test confirmed TCP_NODELAY non heredity for a0=127.0.0.1:42684 **** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** dT 11.156 **** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1000 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1000 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1000 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1000 Link c req 1001 rxreq **** v1 vsl| 1001 Begin c req 1000 rxreq **** v1 vsl| 1001 Timestamp c Start: 1650423670.138163 0.000000 0.000000 **** v1 vsl| 1001 Timestamp c Req: 1650423670.138163 0.000000 0.000000 **** v1 vsl| 1001 VCL_use c vcl1 **** v1 vsl| 1001 ReqStart c 127.0.0.1 19403 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, 20 Apr 2022 03:01:10 GMT **** v1 vsl| 1001 RespHeader c Server: Varnish **** v1 vsl| 1001 RespHeader c X-Varnish: 1001 **** v1 vsl| 1001 VCL_call c SYNTH **** v1 vsl| 1001 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1001 RespHeader c Retry-After: 5 **** v1 vsl| 1001 VCL_return c deliver **** v1 vsl| 1001 Timestamp c Process: 1650423670.141072 0.002908 0.002908 **** 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: 1650423670.154678 0.016514 0.013605 **** v1 vsl| 1001 ReqAcct c 35 0 35 194 251 445 **** v1 vsl| 1001 End c **** v1 vsl| 1000 SessClose c VCL_FAILURE 0.018 **** v1 vsl| 1000 End c **** dT 11.202 ** 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 11.203 ** l1003 === expect * 1003 VCL_call "RECV" **** dT 11.204 ** l1003 === expect 0 1003 VCL_Error "Forced failure" ** l1003 === expect 0 1003 VCL_return "fail" ** l1003 === expect * 1003 VCL_call "SYNTH" ** l1003 === expect 0 1003 VCL_return "restart" **** dT 11.206 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1003 begin| *** l1003 test | expect * 1003 VCL_call RECV **** dT 11.207 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 11.208 *** c1 connected fd 28 from 127.0.0.1 47451 to 127.0.0.1:42684 ** 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 ** c1 === rxresp **** dT 11.213 *** s1 accepted fd 4 127.0.0.1 24491 **** dT 11.214 ** s1 === rxreq **** dT 11.215 **** 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 **** s1 rxhdrlen = 92 **** s1 http[ 0] |GET **** s1 http[ 1] |/hit **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |foo: restart **** s1 http[ 4] |Host: 127.0.0.1 **** s1 http[ 5] |Accept-Encoding: gzip **** s1 http[ 6] |X-Varnish: 1005 **** s1 bodylen = 0 ** s1 === expect req.url == /hit **** s1 EXPECT req.url (/hit) == "/hit" match ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r **** dT 11.217 *** s1 shutting fd 4 ** s1 Ending **** dT 11.219 **** l1003 match| 1003 VCL_call c RECV *** l1003 test | expect 0 1003 VCL_Error Forced failure **** l1003 match| 1003 VCL_Error c Forced failure *** l1003 test | expect 0 1003 VCL_return fail **** l1003 match| 1003 VCL_return c fail *** l1003 test | expect * 1003 VCL_call SYNTH **** l1003 match| 1003 VCL_call c SYNTH *** l1003 test | expect 0 1003 VCL_return restart **** l1003 match| 1003 VCL_return c restart **** l1003 done | **** dT 11.230 **** c1 rxhdr|HTTP/1.1 200 OK\r **** c1 rxhdr|Content-Length: 0\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:10 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, 20 Apr 2022 03:01:10 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 **** dT 11.231 ** c1 === expect resp.status == 200 **** c1 EXPECT resp.status (200) == "200" match ** c1 === expect resp.reason == "OK" **** c1 EXPECT resp.reason (OK) == "OK" match *** c1 closing fd 28 ** c1 Ending **** dT 11.232 ** top === varnish v1 -expect vcl_fail == 2 **** dT 11.257 **** v1 vsl| 1002 Begin c sess 0 HTTP/1 **** v1 vsl| 1002 SessOpen c 127.0.0.1 47451 a0 127.0.0.1 42684 1650423670.263827 23 **** v1 vsl| 1002 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1002 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1002 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1002 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1002 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1002 Link c req 1003 rxreq **** v1 vsl| 1003 Begin c req 1002 rxreq **** v1 vsl| 1003 Timestamp c Start: 1650423670.264384 0.000000 0.000000 **** v1 vsl| 1003 Timestamp c Req: 1650423670.264384 0.000000 0.000000 **** v1 vsl| 1003 VCL_use c vcl1 **** v1 vsl| 1003 ReqStart c 127.0.0.1 47451 a0 **** v1 vsl| 1003 ReqMethod c GET **** v1 vsl| 1003 ReqURL c /hit **** v1 vsl| 1003 ReqProtocol c HTTP/1.1 **** v1 vsl| 1003 ReqHeader c foo: restart **** v1 vsl| 1003 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1003 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1003 VCL_call c RECV **** v1 vsl| 1003 VCL_Error c Forced failure **** dT 11.258 **** v1 vsl| 1003 VCL_return c fail **** v1 vsl| 1003 RespProtocol c HTTP/1.1 **** v1 vsl| 1003 RespStatus c 503 **** v1 vsl| 1003 RespReason c VCL failed **** v1 vsl| 1003 RespHeader c Date: Wed, 20 Apr 2022 03:01:10 GMT **** v1 vsl| 1003 RespHeader c Server: Varnish **** v1 vsl| 1003 RespHeader c X-Varnish: 1003 **** v1 vsl| 1003 VCL_call c SYNTH **** v1 vsl| 1003 VCL_return c restart **** v1 vsl| 1003 Timestamp c Process: 1650423670.265207 0.000822 0.000822 **** v1 vsl| 1003 Timestamp c Restart: 1650423670.265252 0.000867 0.000044 **** v1 vsl| 1003 Link c req 1004 restart **** v1 vsl| 1003 End c **** v1 vsl| 1005 Begin b bereq 1004 fetch **** v1 vsl| 1005 VCL_use b vcl1 **** v1 vsl| 1005 Timestamp b Start: 1650423670.266182 0.000000 0.000000 **** v1 vsl| 1005 BereqMethod b GET **** v1 vsl| 1005 BereqURL b /hit **** v1 vsl| 1005 BereqProtocol b HTTP/1.1 **** v1 vsl| 1005 BereqHeader b foo: restart **** v1 vsl| 1005 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1005 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1005 BereqHeader b X-Varnish: 1005 **** v1 vsl| 1005 VCL_call b BACKEND_FETCH **** v1 vsl| 1005 VCL_return b fetch **** v1 vsl| 1005 Timestamp b Fetch: 1650423670.266428 0.000246 0.000246 **** v1 vsl| 1005 Timestamp b Connected: 1650423670.267247 0.001065 0.000818 **** v1 vsl| 1005 BackendOpen b 25 s1 127.0.0.1 20874 127.0.0.1 24491 connect **** v1 vsl| 1005 Timestamp b Bereq: 1650423670.267822 0.001640 0.000575 **** v1 vsl| 1005 Timestamp b Beresp: 1650423670.270553 0.004371 0.002730 **** v1 vsl| 1005 BerespProtocol b HTTP/1.1 **** v1 vsl| 1005 BerespStatus b 200 **** v1 vsl| 1005 BerespReason b OK **** v1 vsl| 1005 BerespHeader b Content-Length: 0 **** v1 vsl| 1005 BerespHeader b Date: Wed, 20 Apr 2022 03:01:10 GMT **** v1 vsl| 1005 TTL b RFC 120 10 0 1650423670 1650423670 1650423670 0 0 cacheable **** v1 vsl| 1005 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1005 VCL_return b deliver **** v1 vsl| 1005 Timestamp b Process: 1650423670.271076 0.004894 0.000523 **** v1 vsl| 1005 Filters b **** v1 vsl| 1005 Storage b malloc s0 **** v1 vsl| 1005 Fetch_Body b 0 none - **** v1 vsl| 1005 BackendClose b 25 s1 recycle **** v1 vsl| 1005 Timestamp b BerespBody: 1650423670.282509 0.016327 0.011433 **** v1 vsl| 1005 Length b 0 **** v1 vsl| 1005 BereqAcct b 92 0 92 38 0 38 **** v1 vsl| 1005 End b **** v1 vsl| 1004 Begin c req 1003 restart **** v1 vsl| 1004 Timestamp c Start: 1650423670.265252 0.000867 0.000000 **** v1 vsl| 1004 ReqStart c 127.0.0.1 47451 a0 **** v1 vsl| 1004 ReqMethod c GET **** v1 vsl| 1004 ReqURL c /hit **** dT 11.259 **** v1 vsl| 1004 ReqProtocol c HTTP/1.1 **** v1 vsl| 1004 ReqHeader c foo: restart **** v1 vsl| 1004 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1004 VCL_call c RECV **** v1 vsl| 1004 VCL_return c hash **** v1 vsl| 1004 VCL_call c HASH **** v1 vsl| 1004 VCL_return c lookup **** v1 vsl| 1004 VCL_call c MISS **** v1 vsl| 1004 VCL_return c fetch **** v1 vsl| 1004 Link c bereq 1005 fetch **** v1 vsl| 1004 Timestamp c Fetch: 1650423670.282935 0.018550 0.017682 **** v1 vsl| 1004 RespProtocol c HTTP/1.1 **** 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, 20 Apr 2022 03:01:10 GMT **** 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) **** v1 vsl| 1004 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1004 VCL_call c DELIVER **** v1 vsl| 1004 VCL_return c deliver **** v1 vsl| 1004 Timestamp c Process: 1650423670.283328 0.018943 0.000393 **** v1 vsl| 1004 Filters c **** v1 vsl| 1004 RespHeader c Connection: close **** v1 vsl| 1004 Timestamp c Resp: 1650423670.287567 0.023182 0.004238 **** v1 vsl| 1004 ReqAcct c 52 0 52 173 0 173 **** v1 vsl| 1004 End c **** v1 vsl| 1002 SessClose c VCL_FAILURE 0.025 **** v1 vsl| 1002 End c **** dT 11.334 ** v1 as expected: vcl_fail (2) == 2 (2) **** dT 11.335 ** top === varnish v1 -expect sc_vcl_failure == 2 ** v1 as expected: sc_vcl_failure (2) == 2 (2) ** top === logexpect l1007 -v v1 -g raw { **** dT 11.336 ** l1007 === expect * 1007 VCL_call "SYNTH" **** dT 11.337 ** l1007 === expect * 1007 VCL_Error "Forced failure" ** l1007 === expect 0 1007 VCL_return "fail" **** dT 11.338 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1007 begin| *** l1007 test | expect * 1007 VCL_call SYNTH **** dT 11.339 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 11.340 *** c1 connected fd 32 from 127.0.0.1 56088 to 127.0.0.1:42684 ** c1 === txreq -hdr "foo: synth" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: synth\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r ** c1 === rxresp **** dT 11.342 **** 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) **** dT 11.343 **** c1 fd=32 EOF, as expected *** c1 closing fd 32 ** c1 Ending **** dT 11.344 ** top === varnish v1 -expect vcl_fail == 3 **** dT 11.350 **** l1007 match| 1007 VCL_call c SYNTH *** l1007 test | expect * 1007 VCL_Error Forced failure **** l1007 match| 1007 VCL_Error c Forced failure *** l1007 test | expect 0 1007 VCL_return fail **** l1007 match| 1007 VCL_return c fail **** l1007 done | **** dT 11.360 **** v1 vsl| 1006 Begin c sess 0 HTTP/1 **** v1 vsl| 1006 SessOpen c 127.0.0.1 56088 a0 127.0.0.1 42684 1650423670.395682 22 **** v1 vsl| 1006 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1006 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1006 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1006 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1006 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1006 Link c req 1007 rxreq **** v1 vsl| 1007 Begin c req 1006 rxreq **** v1 vsl| 1007 Timestamp c Start: 1650423670.396127 0.000000 0.000000 **** v1 vsl| 1007 Timestamp c Req: 1650423670.396127 0.000000 0.000000 **** v1 vsl| 1007 VCL_use c vcl1 **** v1 vsl| 1007 ReqStart c 127.0.0.1 56088 a0 **** v1 vsl| 1007 ReqMethod c GET **** v1 vsl| 1007 ReqURL c / **** v1 vsl| 1007 ReqProtocol c HTTP/1.1 **** v1 vsl| 1007 ReqHeader c foo: synth **** v1 vsl| 1007 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1007 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1007 VCL_call c RECV **** dT 11.361 **** 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, 20 Apr 2022 03:01:10 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: 1650423670.396704 0.000576 0.000576 **** 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: 1650423670.397703 0.001575 0.000999 **** v1 vsl| 1007 ReqAcct c 47 0 47 38 0 38 **** v1 vsl| 1007 End c **** v1 vsl| 1006 SessClose c VCL_FAILURE 0.004 **** v1 vsl| 1006 End c **** dT 11.446 ** v1 as expected: vcl_fail (3) == 3 (3) **** dT 11.447 ** top === varnish v1 -expect sc_vcl_failure == 3 ** v1 as expected: sc_vcl_failure (3) == 3 (3) ** top === logexpect l1009 -v v1 -g raw { **** dT 11.448 ** l1009 === expect * 1009 VCL_call "HASH" **** dT 11.449 ** l1009 === expect 0 1009 VCL_Error "Forced failure" ** l1009 === expect 0 1009 VCL_return "fail" **** dT 11.450 ** top === client c1 { ** c1 Starting client **** dT 11.451 ** c1 Waiting for client **** l1009 begin| *** l1009 test | expect * 1009 VCL_call HASH ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 11.452 *** c1 connected fd 37 from 127.0.0.1 44217 to 127.0.0.1:42684 ** 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 ** c1 === rxresp **** dT 11.457 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:10 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1009\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Wed, 20 Apr 2022 03:01:10 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 11.458 ** c1 Ending ** top === varnish v1 -expect vcl_fail == 4 **** dT 11.461 **** l1009 match| 1009 VCL_call c HASH **** dT 11.462 *** 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 | **** v1 vsl| 1008 Begin c sess 0 HTTP/1 **** v1 vsl| 1008 SessOpen c 127.0.0.1 44217 a0 127.0.0.1 42684 1650423670.507975 23 **** v1 vsl| 1008 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1008 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1008 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1008 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1008 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1008 Link c req 1009 rxreq **** v1 vsl| 1009 Begin c req 1008 rxreq **** dT 11.463 **** v1 vsl| 1009 Timestamp c Start: 1650423670.508427 0.000000 0.000000 **** v1 vsl| 1009 Timestamp c Req: 1650423670.508427 0.000000 0.000000 **** v1 vsl| 1009 VCL_use c vcl1 **** v1 vsl| 1009 ReqStart c 127.0.0.1 44217 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 **** 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, 20 Apr 2022 03:01:10 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: 1650423670.509153 0.000725 0.000725 **** 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: 1650423670.513868 0.005440 0.004714 **** v1 vsl| 1009 ReqAcct c 46 0 46 194 251 445 **** v1 vsl| 1009 End c **** v1 vsl| 1008 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1008 End c **** dT 11.560 ** 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 11.562 ** l1012 === expect 0 1012 Begin {^bereq 1011 pipe} ** l1012 === expect 0 = Timestamp {^Start:} ** l1012 === expect 0 = BereqMethod {^GET} **** dT 11.563 ** l1012 === expect 0 = BereqURL {^/} ** l1012 === expect 0 = BereqProtocol {^HTTP/1.1} ** l1012 === expect 0 = BereqHeader {^foo: pipe} ** 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} **** dT 11.564 ** l1012 === expect 0 = BereqAcct {^0 0 0 0 0 0} ** l1012 === expect 0 = End **** dT 11.565 **** l1012 begin| **** l1012 qry | vxid == 1012 *** l1012 test | expect 0 1012 Begin ^bereq 1011 pipe ** top === logexpect l1011 -v v1 -g vxid -q "vxid == 1011" { **** dT 11.567 ** l1011 === expect 0 1011 Begin {^req 1010 rxreq} ** l1011 === expect 0 = Timestamp {^Start: } ** l1011 === expect 0 = Timestamp {^Req: } ** l1011 === expect 0 = VCL_use {^vcl1} ** l1011 === expect 0 = ReqStart **** dT 11.568 ** 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: } ** l1011 === expect 0 = VCL_call {^RECV} **** dT 11.569 ** 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} ** l1011 === expect 0 = VCL_return {^fail} **** dT 11.570 ** l1011 === expect 0 = RespProtocol {^HTTP/1.1} ** l1011 === expect 0 = RespStatus {^503} ** l1011 === expect 0 = RespReason {^VCL failed} **** dT 11.571 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1011 begin| **** l1011 qry | vxid == 1011 *** l1011 test | expect 0 1011 Begin ^req 1010 rxreq **** dT 11.572 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 11.573 *** c1 connected fd 47 from 127.0.0.1 33633 to 127.0.0.1:42684 ** 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 11.577 ** c1 === rxresp **** dT 11.579 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:10 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1011\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Wed, 20 Apr 2022 03:01:10 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 **** dT 11.580 ** c1 Ending **** dT 11.581 **** l1012 match| 1012 Begin b bereq 1011 pipe *** l1012 test | expect 0 = Timestamp ^Start: **** l1012 match| 1012 Timestamp b Start: 1650423670.629994 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 **** dT 11.582 **** 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 | ** top === varnish v1 -expect vcl_fail == 5 **** dT 11.583 ** 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 11.584 ** l1014 === expect * 1014 VCL_call "PASS" **** dT 11.585 ** l1014 === expect 0 1014 VCL_Error "Forced failure" ** l1014 === expect 0 1014 VCL_return "fail" **** dT 11.586 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 11.587 **** l1011 match| 1011 Begin c req 1010 rxreq *** l1011 test | expect 0 = Timestamp ^Start: **** l1011 match| 1011 Timestamp c Start: 1650423670.629493 0.000000 0.000000 *** l1011 test | expect 0 = Timestamp ^Req: **** l1011 match| 1011 Timestamp c Req: 1650423670.629493 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 33633 a0 *** l1011 test | expect 0 = ReqMethod ^GET **** l1011 match| 1011 ReqMethod c GET **** dT 11.588 *** 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 11.602 **** l1014 begin| *** l1014 test | expect * 1014 VCL_call PASS **** dT 11.604 ** c1 Started on 127.0.0.1:42684 (1 iterations) **** dT 11.605 *** c1 Connect to 127.0.0.1:42684 **** dT 11.606 *** c1 connected fd 52 from 127.0.0.1 49514 to 127.0.0.1:42684 ** c1 === txreq -hdr "foo: pass" **** dT 11.607 **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: pass\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 11.621 ** c1 === rxresp **** dT 11.623 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:10 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, 20 Apr 2022 03:01:10 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1014 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1014
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match **** dT 11.624 *** c1 closing fd 52 ** c1 Ending **** dT 11.636 **** 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 11.637 ** top === varnish v1 -expect vcl_fail == 6 ** v1 as expected: vcl_fail (6) == 6 (6) ** top === varnish v1 -expect sc_vcl_failure == 6 **** dT 11.638 ** v1 as expected: sc_vcl_failure (6) == 6 (6) ** top === logexpect l1016 -v v1 -g raw { **** dT 11.639 ** l1016 === expect * 1016 VCL_call "PURGE" **** dT 11.640 ** l1016 === expect 0 1016 VCL_Error "Forced failure" ** l1016 === expect 0 1016 VCL_return "fail" **** dT 11.641 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 11.650 **** l1016 begin| *** l1016 test | expect * 1016 VCL_call PURGE **** dT 11.653 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 11.655 *** c1 connected fd 57 from 127.0.0.1 21623 to 127.0.0.1:42684 ** c1 === txreq -hdr "foo: purge" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: purge\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 11.667 **** v1 vsl| 1010 Begin c sess 0 HTTP/1 **** v1 vsl| 1010 SessOpen c 127.0.0.1 33633 a0 127.0.0.1 42684 1650423670.628825 22 **** v1 vsl| 1010 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1010 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1010 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1010 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1010 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1010 Link c req 1011 rxreq **** v1 vsl| 1012 Begin b bereq 1011 pipe **** v1 vsl| 1012 Timestamp b Start: 1650423670.629994 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 **** v1 vsl| 1012 End b **** v1 vsl| 1011 Begin c req 1010 rxreq **** v1 vsl| 1011 Timestamp c Start: 1650423670.629493 0.000000 0.000000 **** v1 vsl| 1011 Timestamp c Req: 1650423670.629493 0.000000 0.000000 **** dT 11.668 **** v1 vsl| 1011 VCL_use c vcl1 **** v1 vsl| 1011 ReqStart c 127.0.0.1 33633 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, 20 Apr 2022 03:01:10 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: 1650423670.630472 0.000978 0.000978 **** 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: 1650423670.631268 0.001774 0.000795 **** v1 vsl| 1011 ReqAcct c 46 0 46 194 251 445 **** v1 vsl| 1011 End c **** v1 vsl| 1010 SessClose c VCL_FAILURE 0.003 **** v1 vsl| 1010 End c **** v1 vsl| 1013 Begin c sess 0 HTTP/1 **** v1 vsl| 1013 SessOpen c 127.0.0.1 49514 a0 127.0.0.1 42684 1650423670.660693 23 **** v1 vsl| 1013 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1013 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1013 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1013 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1013 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1013 Link c req 1014 rxreq **** v1 vsl| 1014 Begin c req 1013 rxreq **** v1 vsl| 1014 Timestamp c Start: 1650423670.672773 0.000000 0.000000 **** v1 vsl| 1014 Timestamp c Req: 1650423670.672773 0.000000 0.000000 **** v1 vsl| 1014 VCL_use c vcl1 **** v1 vsl| 1014 ReqStart c 127.0.0.1 49514 a0 **** dT 11.669 **** 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, 20 Apr 2022 03:01:10 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: 1650423670.674708 0.001934 0.001934 **** 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: 1650423670.675483 0.002709 0.000774 **** v1 vsl| 1014 ReqAcct c 46 0 46 194 251 445 **** v1 vsl| 1014 End c **** v1 vsl| 1013 SessClose c VCL_FAILURE 0.015 **** v1 vsl| 1013 End c **** v1 vsl| 1015 Begin c sess 0 HTTP/1 **** v1 vsl| 1015 SessOpen c 127.0.0.1 21623 a0 127.0.0.1 42684 1650423670.709089 22 **** v1 vsl| 1015 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1015 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1015 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1015 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1015 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1015 Link c req 1016 rxreq **** dT 11.694 **** 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 11.696 ** c1 === rxresp **** dT 11.698 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:10 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, 20 Apr 2022 03:01:10 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1016 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** dT 11.699 **** 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 11.701 ** top === varnish v1 -expect vcl_fail == 7 **** dT 11.702 ** v1 as expected: vcl_fail (7) == 7 (7) ** top === varnish v1 -expect sc_vcl_failure == 7 ** v1 as expected: sc_vcl_failure (7) == 7 (7) ** top === logexpect l1018 -v v1 -g raw { **** dT 11.703 ** l1018 === expect * 1018 VCL_call "MISS" **** dT 11.704 ** l1018 === expect 0 1018 VCL_Error "Forced failure" ** l1018 === expect 0 1018 VCL_return "fail" **** dT 11.705 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 11.706 **** l1018 begin| **** dT 11.707 *** l1018 test | expect * 1018 VCL_call MISS **** dT 11.709 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 11.711 *** c1 connected fd 62 from 127.0.0.1 25163 to 127.0.0.1:42684 ** c1 === txreq -url /miss -hdr "foo: miss" **** c1 txreq|GET /miss HTTP/1.1\r **** c1 txreq|foo: miss\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 11.715 ** c1 === rxresp **** dT 11.717 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:10 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, 20 Apr 2022 03:01:10 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1018 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1018
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 62 **** dT 11.718 ** c1 Ending **** dT 11.721 **** 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 11.722 ** top === varnish v1 -expect vcl_fail == 8 **** dT 11.724 ** v1 as expected: vcl_fail (8) == 8 (8) ** top === varnish v1 -expect sc_vcl_failure == 8 **** dT 11.725 ** v1 as expected: sc_vcl_failure (8) == 8 (8) ** top === logexpect l1020 -v v1 -g raw { **** dT 11.726 ** l1020 === expect * 1020 VCL_call "HIT" ** l1020 === expect 0 1020 VCL_Error "Forced failure" **** dT 11.727 ** l1020 === expect 0 1020 VCL_return "fail" **** dT 11.728 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 11.730 **** l1020 begin| *** l1020 test | expect * 1020 VCL_call HIT **** dT 11.733 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 11.735 *** c1 connected fd 67 from 127.0.0.1 64655 to 127.0.0.1:42684 ** 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 11.740 ** c1 === rxresp **** dT 11.744 **** 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 11.747 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:10 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, 20 Apr 2022 03:01:10 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 11.748 ** c1 Ending **** dT 11.752 ** top === varnish v1 -expect vcl_fail == 9 ** v1 as expected: vcl_fail (9) == 9 (9) ** top === varnish v1 -expect sc_vcl_failure == 9 **** dT 11.753 ** v1 as expected: sc_vcl_failure (9) == 9 (9) ** top === logexpect l1022 -v v1 -g raw { **** dT 11.754 ** l1022 === expect * 1022 VCL_call "DELIVER" **** dT 11.755 ** l1022 === expect 0 1022 VCL_Error "Forced failure" ** l1022 === expect 0 1022 VCL_return "fail" **** dT 11.756 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 11.758 **** l1022 begin| *** l1022 test | expect * 1022 VCL_call DELIVER **** dT 11.762 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 11.764 *** c1 connected fd 72 from 127.0.0.1 64485 to 127.0.0.1:42684 ** c1 === txreq -url /hit -hdr "foo: deliver" **** c1 txreq|GET /hit HTTP/1.1\r **** c1 txreq|foo: deliver\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 11.768 ** c1 === rxresp **** dT 11.770 **** v1 vsl| 1016 Begin c req 1015 rxreq **** v1 vsl| 1016 Timestamp c Start: 1650423670.720723 0.000000 0.000000 **** v1 vsl| 1016 Timestamp c Req: 1650423670.720723 0.000000 0.000000 **** v1 vsl| 1016 VCL_use c vcl1 **** v1 vsl| 1016 ReqStart c 127.0.0.1 21623 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, 20 Apr 2022 03:01:10 GMT **** dT 11.771 **** 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: 1650423670.725639 0.004915 0.004915 **** 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: 1650423670.726395 0.005672 0.000756 **** v1 vsl| 1016 ReqAcct c 47 0 47 194 251 445 **** v1 vsl| 1016 End c **** v1 vsl| 1015 SessClose c VCL_FAILURE 0.018 **** v1 vsl| 1015 End c **** v1 vsl| 1017 Begin c sess 0 HTTP/1 **** v1 vsl| 1017 SessOpen c 127.0.0.1 25163 a0 127.0.0.1 42684 1650423670.765089 23 **** v1 vsl| 1017 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1017 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1017 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1017 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1017 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1017 Link c req 1018 rxreq **** v1 vsl| 1018 Begin c req 1017 rxreq **** v1 vsl| 1018 Timestamp c Start: 1650423670.767921 0.000000 0.000000 **** v1 vsl| 1018 Timestamp c Req: 1650423670.767921 0.000000 0.000000 **** v1 vsl| 1018 VCL_use c vcl1 **** v1 vsl| 1018 ReqStart c 127.0.0.1 25163 a0 **** v1 vsl| 1018 ReqMethod c GET **** v1 vsl| 1018 ReqURL c /miss **** v1 vsl| 1018 ReqProtocol c HTTP/1.1 **** v1 vsl| 1018 ReqHeader c foo: miss **** v1 vsl| 1018 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1018 ReqHeader c 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, 20 Apr 2022 03:01:10 GMT **** v1 vsl| 1018 RespHeader c Server: Varnish **** v1 vsl| 1018 RespHeader c X-Varnish: 1018 **** v1 vsl| 1018 VCL_call c SYNTH **** dT 11.772 **** 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: 1650423670.768909 0.000988 0.000988 **** 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: 1650423670.769655 0.001734 0.000745 **** v1 vsl| 1018 ReqAcct c 50 0 50 194 251 445 **** v1 vsl| 1018 End c **** v1 vsl| 1017 SessClose c VCL_FAILURE 0.005 **** v1 vsl| 1017 End c **** v1 vsl| 1019 Begin c sess 0 HTTP/1 **** v1 vsl| 1019 SessOpen c 127.0.0.1 64655 a0 127.0.0.1 42684 1650423670.789102 22 **** v1 vsl| 1019 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1019 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1019 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1019 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1019 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1019 Link c req 1020 rxreq **** v1 vsl| 1020 Begin c req 1019 rxreq **** v1 vsl| 1020 Timestamp c Start: 1650423670.792510 0.000000 0.000000 **** v1 vsl| 1020 Timestamp c Req: 1650423670.792510 0.000000 0.000000 **** v1 vsl| 1020 VCL_use c vcl1 **** v1 vsl| 1020 ReqStart c 127.0.0.1 64655 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.478043 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, 20 Apr 2022 03:01:10 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 **** dT 11.773 **** v1 vsl| 1020 VCL_return c deliver **** v1 vsl| 1020 Timestamp c Process: 1650423670.793538 0.001028 0.001028 **** 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: 1650423670.794270 0.001760 0.000731 **** v1 vsl| 1020 ReqAcct c 48 0 48 194 251 445 **** v1 vsl| 1020 End c **** v1 vsl| 1019 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1019 End c **** v1 vsl| 1021 Begin c sess 0 HTTP/1 **** v1 vsl| 1021 SessOpen c 127.0.0.1 64485 a0 127.0.0.1 42684 1650423670.818082 23 **** v1 vsl| 1021 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1021 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1021 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1021 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1021 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1021 Link c req 1022 rxreq **** v1 vsl| 1022 Begin c req 1021 rxreq **** v1 vsl| 1022 Timestamp c Start: 1650423670.820973 0.000000 0.000000 **** v1 vsl| 1022 Timestamp c Req: 1650423670.820973 0.000000 0.000000 **** v1 vsl| 1022 VCL_use c vcl1 **** v1 vsl| 1022 ReqStart c 127.0.0.1 64485 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.449579 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, 20 Apr 2022 03:01:10 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: 1650423670.821811 0.000837 0.000837 **** v1 vsl| 1022 RespProtocol c HTTP/1.1 **** dT 11.774 **** v1 vsl| 1022 RespStatus c 503 **** v1 vsl| 1022 RespReason c VCL failed **** v1 vsl| 1022 RespHeader c Date: Wed, 20 Apr 2022 03:01:10 GMT **** v1 vsl| 1022 RespHeader c Server: Varnish **** v1 vsl| 1022 RespHeader c X-Varnish: 1022 **** v1 vsl| 1022 VCL_call c SYNTH **** v1 vsl| 1022 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1022 RespHeader c Retry-After: 5 **** v1 vsl| 1022 VCL_return c deliver **** v1 vsl| 1022 Timestamp c Process: 1650423670.822126 0.001152 0.000314 **** 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: 1650423670.822832 0.001858 0.000705 **** 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 11.775 **** l1022 match| 1022 VCL_call c DELIVER *** l1022 test | expect 0 1022 VCL_Error Forced failure **** l1022 match| 1022 VCL_Error c Forced failure *** l1022 test | expect 0 1022 VCL_return fail **** l1022 match| 1022 VCL_return c fail **** l1022 done | **** dT 11.782 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:10 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, 20 Apr 2022 03:01:10 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1022 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1022
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 72 **** dT 11.783 ** c1 Ending **** dT 11.785 ** top === varnish v1 -expect vcl_fail == 10 ** v1 as expected: vcl_fail (10) == 10 (10) ** top === varnish v1 -expect sc_vcl_failure == 10 **** dT 11.786 ** 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 11.787 ** 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 11.788 ** 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 = "20874"; } **** 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 11.978 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_LINGER for a0=127.0.0.1:42684 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPIDLE for a0=127.0.0.1:42684 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPCNT for a0=127.0.0.1:42684 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPINTVL for a0=127.0.0.1:42684 **** dT 17.226 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl2 **** dT 17.270 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** top === logexpect l1 -v v1 -g raw { **** dT 17.271 ** l1 === expect * 1025 VCL_call "BACKEND_FETCH" **** dT 17.272 ** l1 === expect 0 1025 VCL_Error "Forced failure" ** l1 === expect 0 1025 VCL_return "fail" **** dT 17.273 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 17.275 **** l1 begin| *** l1 test | expect * 1025 VCL_call BACKEND_FETCH **** dT 17.279 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 17.281 *** c1 connected fd 77 from 127.0.0.1 14745 to 127.0.0.1:42684 ** 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 **** dT 17.286 ** c1 === rxresp **** dT 17.288 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:16 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, 20 Apr 2022 03:01:16 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 **** dT 17.289 **** 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 17.290 ** c1 Ending **** dT 17.292 **** 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 17.293 ** v1 as expected: vcl_fail (11) == 11 (11) ** top === varnish v1 -expect sc_vcl_failure == 10 **** dT 17.296 ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1 -wait ** l1 Waiting for logexp ** 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=20874 **** s1 macro def s1_sock=127.0.0.1:20874 **** dT 17.297 * s1 Listen on 127.0.0.1:20874 ** top === varnish v1 -vcl+backend { **** 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 = "20874"; } **** 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 17.298 **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1650423670.843994/vgc.so 1auto **** v1 vsl| 0 Debug - vcl2: VCL_EVENT_WARM **** dT 17.299 **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl2.1650423670.843994/vgc.so" as "vcl2" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1650423676 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 14745 a0 127.0.0.1 42684 1650423676.335497 22 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** 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: 1650423676.339245 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: 1650423676.338258 0.000000 0.000000 **** v1 vsl| 1024 Timestamp c Req: 1650423676.338258 0.000000 0.000000 **** v1 vsl| 1024 VCL_use c vcl2 **** v1 vsl| 1024 ReqStart c 127.0.0.1 14745 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 **** dT 17.300 **** v1 vsl| 1024 VCL_return c fetch **** v1 vsl| 1024 Link c bereq 1025 fetch **** v1 vsl| 1024 Timestamp c Fetch: 1650423676.339694 0.001435 0.001435 **** 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, 20 Apr 2022 03:01:16 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: 1650423676.340244 0.001985 0.000549 **** 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: 1650423676.341256 0.002997 0.001012 **** v1 vsl| 1024 ReqAcct c 48 0 48 208 278 486 **** v1 vsl| 1024 End c **** v1 vsl| 1023 SessClose c REM_CLOSE 0.009 **** v1 vsl| 1023 End c **** dT 17.302 ** s1 Started on 127.0.0.1:20874 (1 iterations) **** dT 22.112 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl3 **** dT 22.157 *** 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" **** dT 22.158 ** l1 === expect 0 1028 VCL_Error "Forced failure" ** l1 === expect 0 1028 VCL_return "fail" **** dT 22.159 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 22.161 **** l1 begin| *** l1 test | expect * 1028 VCL_call BACKEND_ERROR **** dT 22.165 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 22.167 *** c1 connected fd 78 from 127.0.0.1 42566 to 127.0.0.1:42684 ** 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 **** dT 22.171 ** c1 === rxresp **** dT 22.172 *** s1 accepted fd 77 127.0.0.1 48940 ** s1 === rxreq **** dT 22.175 **** 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 22.180 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:21 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, 20 Apr 2022 03:01:21 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1027 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** dT 22.181 **** 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 22.182 ** c1 Ending **** dT 22.183 ** s1 Ending **** dT 22.184 ** top === varnish v1 -expect vcl_fail == 12 **** dT 22.187 ** 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) **** dT 22.188 ** top === logexpect l1 -wait ** l1 Waiting for logexp **** 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 | **** dT 22.194 **** v1 vsl| 0 CLI - Rd vcl.load vcl3 vcl_vcl3.1650423676.352823/vgc.so 1auto **** v1 vsl| 0 Debug - vcl3: VCL_EVENT_WARM **** dT 22.195 **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl3.1650423676.352823/vgc.so" as "vcl3" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1650423681 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl3 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 1026 Begin c sess 0 HTTP/1 **** v1 vsl| 1026 SessOpen c 127.0.0.1 42566 a0 127.0.0.1 42684 1650423681.221282 23 **** v1 vsl| 1026 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1026 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1026 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1026 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1026 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** 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: 1650423681.224999 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: 1650423681.225277 0.000277 0.000277 **** v1 vsl| 1028 Timestamp b Connected: 1650423681.225952 0.000952 0.000674 **** v1 vsl| 1028 BackendOpen b 25 s1 127.0.0.1 20874 127.0.0.1 48940 connect **** dT 22.196 **** v1 vsl| 1028 Timestamp b Bereq: 1650423681.226342 0.001342 0.000389 **** 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: 1650423681.231246 0.006247 0.004904 **** v1 vsl| 1028 Timestamp b Error: 1650423681.231297 0.006298 0.000051 **** 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, 20 Apr 2022 03:01:21 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 **** v1 vsl| 1028 End b **** v1 vsl| 1027 Begin c req 1026 rxreq **** v1 vsl| 1027 Timestamp c Start: 1650423681.224126 0.000000 0.000000 **** v1 vsl| 1027 Timestamp c Req: 1650423681.224126 0.000000 0.000000 **** v1 vsl| 1027 VCL_use c vcl3 **** v1 vsl| 1027 ReqStart c 127.0.0.1 42566 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: 1650423681.231864 0.007738 0.007738 **** 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, 20 Apr 2022 03:01:21 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: 1650423681.232345 0.008219 0.000480 **** 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: 1650423681.233202 0.009076 0.000857 **** v1 vsl| 1027 ReqAcct c 48 0 48 208 278 486 **** v1 vsl| 1027 End c **** v1 vsl| 1026 SessClose c REM_CLOSE 0.015 **** v1 vsl| 1026 End c **** dT 22.197 ** top === server s1 { ** s1 Waiting for server (3/-1) ** s1 Starting server **** dT 22.198 **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=20874 **** s1 macro def s1_sock=127.0.0.1:20874 * s1 Listen on 127.0.0.1:20874 ** top === varnish v1 -vcl+backend { **** 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 = "20874"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tsub vcl_backend_response { **** v1 CLI TX|\t\tdebug.fail(); **** v1 CLI TX|\t\tset bereq.http.not = "Should not happen"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 22.210 ** s1 Started on 127.0.0.1:20874 (1 iterations) **** dT 27.589 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl4 **** dT 27.604 **** v1 vsl| 0 CLI - Rd vcl.load vcl4 vcl_vcl4.1650423681.253974/vgc.so 1auto **** v1 vsl| 0 Debug - vcl4: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl4.1650423681.253974/vgc.so" as "vcl4" **** v1 vsl| 0 CLI - Rd ping **** dT 27.605 **** v1 vsl| 0 CLI - Wr 200 19 PONG 1650423686 1.0 **** dT 27.637 *** 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 27.638 ** l1 === expect 0 1031 VCL_return "fail" **** dT 27.639 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 27.641 **** l1 begin| *** l1 test | expect * 1031 VCL_call BACKEND_RESPONSE **** dT 27.645 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 27.647 *** c1 connected fd 78 from 127.0.0.1 60049 to 127.0.0.1:42684 ** 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 **** dT 27.652 ** c1 === rxresp **** dT 27.654 *** s1 accepted fd 77 127.0.0.1 50680 **** dT 27.655 ** s1 === rxreq **** dT 27.656 **** 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 27.658 *** s1 shutting fd 77 ** s1 Ending **** dT 27.662 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:26 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, 20 Apr 2022 03:01:26 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1030 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 278 **** c1 http[ 9] |Connection: keep-alive **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|Service Unavailable
**** c1 c-l|XID: 1030
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 278 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "Service Unavailable" **** c1 EXPECT resp.reason (Service Unavailable) == "Service Unavailable" match *** c1 closing fd 78 **** dT 27.664 ** c1 Ending **** dT 27.665 **** 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 27.667 ** top === varnish v1 -expect vcl_fail == 13 **** dT 27.668 ** v1 as expected: vcl_fail (13) == 13 (13) ** top === varnish v1 -expect sc_vcl_failure == 10 ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1 -wait ** l1 Waiting for logexp ** top === varnish v1 -vcl+backend { **** v1 CLI TX|vcl.inline vcl5 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "20874"; } **** 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 27.706 **** v1 vsl| 0 CLI - Rd vcl.use vcl4 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 1029 Begin c sess 0 HTTP/1 **** v1 vsl| 1029 SessOpen c 127.0.0.1 60049 a0 127.0.0.1 42684 1650423686.701529 22 **** v1 vsl| 1029 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1029 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1029 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1029 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1029 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** 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: 1650423686.705739 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 **** dT 27.707 **** 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: 1650423686.705975 0.000236 0.000236 **** v1 vsl| 1031 Timestamp b Connected: 1650423686.706694 0.000954 0.000718 **** v1 vsl| 1031 BackendOpen b 25 s1 127.0.0.1 20874 127.0.0.1 50680 connect **** v1 vsl| 1031 Timestamp b Bereq: 1650423686.707118 0.001379 0.000424 **** v1 vsl| 1031 Timestamp b Beresp: 1650423686.711875 0.006136 0.004756 **** 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, 20 Apr 2022 03:01:26 GMT **** v1 vsl| 1031 TTL b RFC 120 10 0 1650423687 1650423687 1650423686 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: 1650423686.704837 0.000000 0.000000 **** v1 vsl| 1030 Timestamp c Req: 1650423686.704837 0.000000 0.000000 **** v1 vsl| 1030 VCL_use c vcl4 **** v1 vsl| 1030 ReqStart c 127.0.0.1 60049 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 **** 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: 1650423686.713878 0.009041 0.009041 **** 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, 20 Apr 2022 03:01:26 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: 1650423686.714432 0.009595 0.000553 **** 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 **** dT 27.708 **** v1 vsl| 1030 Timestamp c Resp: 1650423686.717966 0.013129 0.003534 **** v1 vsl| 1030 ReqAcct c 51 0 51 208 278 486 **** v1 vsl| 1030 End c **** v1 vsl| 1029 SessClose c REM_CLOSE 0.017 **** v1 vsl| 1029 End c **** dT 32.345 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl5 **** dT 32.387 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl5' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1033 VCL_call "RECV" **** dT 32.389 **** v1 vsl| 0 CLI - Rd vcl.load vcl5 vcl_vcl5.1650423686.724319/vgc.so 1auto **** v1 vsl| 0 Debug - vcl5: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl5.1650423686.724319/vgc.so" as "vcl5" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1650423691 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl5 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 32.391 ** l1 === expect 0 1033 VCL_Error "Forced failure" ** l1 === expect 0 1033 VCL_return "fail" **** dT 32.392 ** top === client c1 { **** dT 32.393 ** c1 Starting client ** c1 Waiting for client **** dT 32.394 **** l1 begin| *** l1 test | expect * 1033 VCL_call RECV **** dT 32.397 ** c1 Started on 127.0.0.1:42684 (1 iterations) *** c1 Connect to 127.0.0.1:42684 **** dT 32.399 *** c1 connected fd 77 from 127.0.0.1 52693 to 127.0.0.1:42684 ** c1 === txreq **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|\r **** dT 32.403 ** c1 === rxresp **** dT 32.405 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Wed, 20 Apr 2022 03:01:31 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, 20 Apr 2022 03:01:31 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 32.407 **** 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 32.409 **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1033
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 77 **** dT 32.410 ** c1 Ending **** dT 32.411 ** top === varnish v1 -expect vcl_fail == 14 **** dT 32.412 ** v1 as expected: vcl_fail (14) == 14 (14) ** top === varnish v1 -expect sc_vcl_failure == 11 **** dT 32.413 ** v1 as expected: sc_vcl_failure (11) == 11 (11) ** top === logexpect l1 -wait ** l1 Waiting for logexp **** dT 32.416 ** 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 32.491 **** v1 vsl| 1032 Begin c sess 0 HTTP/1 **** v1 vsl| 1032 SessOpen c 127.0.0.1 52693 a0 127.0.0.1 42684 1650423691.453405 23 **** v1 vsl| 1032 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1032 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42684 **** v1 vsl| 1032 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1032 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42684 **** v1 vsl| 1032 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42684 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42684 **** v1 vsl| 1032 Link c req 1033 rxreq **** v1 vsl| 1033 Begin c req 1032 rxreq **** v1 vsl| 1033 Timestamp c Start: 1650423691.455920 0.000000 0.000000 **** v1 vsl| 1033 Timestamp c Req: 1650423691.455920 0.000000 0.000000 **** v1 vsl| 1033 VCL_use c vcl5 **** v1 vsl| 1033 ReqStart c 127.0.0.1 52693 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 **** dT 32.492 **** v1 vsl| 1033 RespReason c VCL failed **** v1 vsl| 1033 RespHeader c Date: Wed, 20 Apr 2022 03:01:31 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: 1650423691.456580 0.000660 0.000660 **** v1 vsl| 1033 RespHeader c Content-Length: 251 **** v1 vsl| 1033 Storage c malloc Transient **** v1 vsl| 1033 Filters c **** v1 vsl| 1033 RespHeader c Connection: close **** v1 vsl| 1033 Timestamp c Resp: 1650423691.457329 0.001409 0.000748 **** v1 vsl| 1033 ReqAcct c 35 0 35 194 251 445 **** v1 vsl| 1033 End c **** v1 vsl| 1032 SessClose c VCL_FAILURE 0.004 **** v1 vsl| 1032 End c **** dT 37.428 *** 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) *** v1 Found expected string: ("Forced failure") ** top === varnish v1 -errvcl {thou shalt not fini} { **** dT 37.433 **** 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 37.487 **** v1 vsl| 0 CLI - Rd vcl.load vcl6 vcl_vcl6.1650423691.471684/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 1650423696 1.0 **** dT 42.791 **** v1 vsl| 0 CLI - Rd vcl.load vcl7 vcl_vcl7.1650423696.490091/vgc.so 1auto **** dT 42.801 *** 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 ** 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.892 **** 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 1650423701 1.0 **** dT 47.683 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl8 **** dT 47.692 **** v1 vsl| 0 CLI - Rd vcl.load vcl8 vcl_vcl8.1650423701.859318/vgc.so 1auto **** v1 vsl| 0 Debug - vcl8: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl8.1650423701.859318/vgc.so" as "vcl8" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1650423706 1.0 **** dT 47.726 *** 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 = "20874"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 47.795 **** v1 vsl| 0 CLI - Rd vcl.use vcl8 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 53.026 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl9 **** dT 53.072 *** 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" **** dT 53.073 ** l1 === expect 3 0 VCL_Error "^Forced failure" ** l1 === expect 0 0 VCL_Error {^\QVRT_fail() from vcl_fini{} has no e... **** dT 53.074 ** top === varnish v1 -cliok "vcl.discard vcl8" **** dT 53.075 **** v1 CLI TX|vcl.discard vcl8 **** l1 begin| *** l1 test | expect * 0 CLI ^Rd vcl.state vcl8 0cold **** dT 53.102 **** v1 vsl| 0 CLI - Rd vcl.load vcl9 vcl_vcl9.1650423706.782164/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl9.1650423706.782164/vgc.so" as "vcl9" **** dT 53.103 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1650423712 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl9 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 53.118 **** l1 match| 0 CLI - Rd vcl.state vcl8 0cold *** l1 test | expect 3 0 VCL_Error ^Forced failure **** dT 53.119 **** l1 match| 0 VCL_Error - Forced failure *** l1 test | expect 0 0 VCL_Error ^\\QVRT_fail() from vcl_fini{} has no effect\\E$ **** l1 match| 0 VCL_Error - VRT_fail() from vcl_fini{} has no effect **** l1 done | **** dT 53.124 *** v1 CLI RX 200 **** dT 53.125 ** v1 CLI 200