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 7.405 ** c1 Ending ** top === varnish v1 -expect vcl_fail == 1 **** dT 7.416 **** l1001 match| 1001 VCL_call c RECV *** l1001 test | expect 0 1001 VCL_Error Forced failure **** l1001 match| 1001 VCL_Error c Forced failure *** l1001 test | expect 0 1001 VCL_return fail **** l1001 match| 1001 VCL_return c fail **** l1001 done | **** dT 7.418 ** 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 7.420 ** l1003 === expect * 1003 VCL_call "RECV" ** l1003 === expect 0 1003 VCL_Error "Forced failure" ** l1003 === expect 0 1003 VCL_return "fail" **** dT 7.421 ** l1003 === expect * 1003 VCL_call "SYNTH" ** l1003 === expect 0 1003 VCL_return "restart" **** dT 7.422 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1003 begin| *** l1003 test | expect * 1003 VCL_call RECV **** dT 7.423 ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 7.424 *** c1 connected fd 28 from 127.0.0.1 12164 to 127.0.0.1:45506 ** c1 === txreq -url /hit -hdr "foo: restart" **** dT 7.425 **** c1 txreq|GET /hit HTTP/1.1\r **** c1 txreq|foo: restart\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.428 ** c1 === rxresp **** dT 7.430 *** s1 accepted fd 4 127.0.0.1 25787 ** s1 === rxreq **** dT 7.432 **** s1 rxhdr|GET /hit HTTP/1.1\r **** s1 rxhdr|foo: restart\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|User-Agent: c1\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1005\r **** s1 rxhdr|\r **** s1 rxhdrlen = 108 **** s1 http[ 0] |GET **** s1 http[ 1] |/hit **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |foo: restart **** s1 http[ 4] |Host: 127.0.0.1 **** s1 http[ 5] |User-Agent: c1 **** s1 http[ 6] |Accept-Encoding: gzip **** s1 http[ 7] |X-Varnish: 1005 **** s1 bodylen = 0 ** s1 === expect req.url == /hit **** s1 EXPECT req.url (/hit) == "/hit" match ** s1 === txresp **** dT 7.433 **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Tue, 09 Apr 2024 17:50:24 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r **** dT 7.434 *** s1 shutting fd 4 ** s1 Ending **** dT 7.436 **** 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 **** dT 7.437 **** l1003 match| 1003 VCL_call c SYNTH *** l1003 test | expect 0 1003 VCL_return restart **** l1003 match| 1003 VCL_return c restart **** l1003 done | **** dT 7.451 **** c1 rxhdr|HTTP/1.1 200 OK\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:24 GMT\r **** c1 rxhdr|Server: s1\r **** c1 rxhdr|Content-Length: 0\r **** c1 rxhdr|X-Varnish: 1004\r **** c1 rxhdr|Age: 0\r **** c1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r **** c1 rxhdr|Accept-Ranges: bytes\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 182 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |200 **** c1 http[ 2] |OK **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:24 GMT **** c1 http[ 4] |Server: s1 **** c1 http[ 5] |Content-Length: 0 **** c1 http[ 6] |X-Varnish: 1004 **** c1 http[ 7] |Age: 0 **** c1 http[ 8] |Via: 1.1 v1 (Varnish/trunk) **** c1 http[ 9] |Accept-Ranges: bytes **** c1 http[10] |Connection: close **** dT 7.453 **** c1 bodylen = 0 ** c1 === expect resp.status == 200 **** c1 EXPECT resp.status (200) == "200" match ** c1 === expect resp.reason == "OK" **** c1 EXPECT resp.reason (OK) == "OK" match *** c1 closing fd 28 ** c1 Ending **** dT 7.454 ** top === varnish v1 -expect vcl_fail == 2 ** v1 as expected: vcl_fail (2) == 2 (2) **** dT 7.455 ** 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 7.456 ** l1007 === expect * 1007 VCL_call "SYNTH" **** dT 7.457 ** l1007 === expect * 1007 VCL_Error "Forced failure" ** l1007 === expect 0 1007 VCL_return "fail" **** dT 7.458 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1007 begin| *** l1007 test | expect * 1007 VCL_call SYNTH **** dT 7.459 ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 7.460 *** c1 connected fd 32 from 127.0.0.1 29209 to 127.0.0.1:45506 ** c1 === txreq -hdr "foo: synth" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: synth\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.462 ** c1 === rxresp **** dT 7.463 **** 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 **** dT 7.464 ** c1 === expect_close **** c1 Expecting close (fd = 32) **** c1 fd=32 EOF, as expected *** c1 closing fd 32 ** c1 Ending **** dT 7.465 ** top === varnish v1 -expect vcl_fail == 3 ** v1 as expected: vcl_fail (3) == 3 (3) ** top === varnish v1 -expect sc_vcl_failure == 3 **** dT 7.466 ** v1 as expected: sc_vcl_failure (3) == 3 (3) ** top === logexpect l1009 -v v1 -g raw { **** v1 vsl| 0 CLI - Rd debug.listen_address **** dT 7.467 **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 45506 **** v1 vsl| 1000 Begin c sess 0 HTTP/1 **** v1 vsl| 1000 SessOpen c 127.0.0.1 35444 a0 127.0.0.1 45506 1712685024.726479 20 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_SNDTIMEO non heredity for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_RCVTIMEO non heredity for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: Test confirmed TCP_NODELAY non heredity for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1000 Link c req 1001 rxreq **** v1 vsl| 1001 Begin c req 1000 rxreq **** v1 vsl| 1001 Timestamp c Start: 1712685024.727509 0.000000 0.000000 **** v1 vsl| 1001 Timestamp c Req: 1712685024.727509 0.000000 0.000000 **** v1 vsl| 1001 VCL_use c vcl1 **** v1 vsl| 1001 ReqStart c 127.0.0.1 35444 a0 **** v1 vsl| 1001 ReqMethod c GET **** v1 vsl| 1001 ReqURL c / **** v1 vsl| 1001 ReqProtocol c HTTP/1.1 **** v1 vsl| 1001 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1001 ReqHeader c User-Agent: c1 **** v1 vsl| 1001 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1001 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1001 VCL_call c RECV **** v1 vsl| 1001 VCL_Error c Forced failure **** v1 vsl| 1001 VCL_return c fail **** v1 vsl| 1001 RespProtocol c HTTP/1.1 **** v1 vsl| 1001 RespStatus c 503 **** v1 vsl| 1001 RespReason c VCL failed **** v1 vsl| 1001 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 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: 1712685024.730244 0.002735 0.002735 **** 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: 1712685024.738034 0.010524 0.007789 **** v1 vsl| 1001 ReqAcct c 51 0 51 194 251 445 **** v1 vsl| 1001 End c **** v1 vsl| 1000 SessClose c VCL_FAILURE 0.013 **** v1 vsl| 1000 End c **** v1 vsl| 1002 Begin c sess 0 HTTP/1 **** v1 vsl| 1002 SessOpen c 127.0.0.1 12164 a0 127.0.0.1 45506 1712685024.754496 21 **** v1 vsl| 1002 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1002 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1002 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1002 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1002 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** dT 7.468 **** v1 vsl| 1002 Link c req 1003 rxreq **** v1 vsl| 1003 Begin c req 1002 rxreq **** v1 vsl| 1003 Timestamp c Start: 1712685024.755270 0.000000 0.000000 **** v1 vsl| 1003 Timestamp c Req: 1712685024.755270 0.000000 0.000000 **** v1 vsl| 1003 VCL_use c vcl1 **** v1 vsl| 1003 ReqStart c 127.0.0.1 12164 a0 **** v1 vsl| 1003 ReqMethod c GET **** v1 vsl| 1003 ReqURL c /hit **** v1 vsl| 1003 ReqProtocol c HTTP/1.1 **** v1 vsl| 1003 ReqHeader c foo: restart **** v1 vsl| 1003 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1003 ReqHeader c User-Agent: c1 **** v1 vsl| 1003 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1003 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1003 VCL_call c RECV **** v1 vsl| 1003 VCL_Error c Forced failure **** v1 vsl| 1003 VCL_return c fail **** v1 vsl| 1003 RespProtocol c HTTP/1.1 **** v1 vsl| 1003 RespStatus c 503 **** v1 vsl| 1003 RespReason c VCL failed **** v1 vsl| 1003 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 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: 1712685024.756076 0.000805 0.000805 **** v1 vsl| 1003 Timestamp c Restart: 1712685024.756119 0.000849 0.000043 **** v1 vsl| 1003 Link c req 1004 restart **** v1 vsl| 1003 End c **** v1 vsl| 1004 Begin c req 1003 restart **** v1 vsl| 1004 Timestamp c Start: 1712685024.756119 0.000849 0.000000 **** v1 vsl| 1004 ReqStart c 127.0.0.1 12164 a0 **** v1 vsl| 1004 ReqMethod c GET **** v1 vsl| 1004 ReqURL c /hit **** v1 vsl| 1004 ReqProtocol c HTTP/1.1 **** v1 vsl| 1004 ReqHeader c foo: restart **** v1 vsl| 1004 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1004 ReqHeader c User-Agent: c1 **** v1 vsl| 1004 VCL_call c RECV **** v1 vsl| 1004 VCL_return c hash **** v1 vsl| 1004 VCL_call c HASH **** v1 vsl| 1004 VCL_return c lookup **** v1 vsl| 1004 VCL_call c MISS **** v1 vsl| 1004 VCL_return c fetch **** v1 vsl| 1004 Link c bereq 1005 fetch **** v1 vsl| 1004 Timestamp c Fetch: 1712685024.778373 0.023102 0.022253 **** 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 Date: Tue, 09 Apr 2024 17:50:24 GMT **** v1 vsl| 1004 RespHeader c Server: s1 **** v1 vsl| 1004 RespHeader c Content-Length: 0 **** v1 vsl| 1004 RespHeader c X-Varnish: 1004 **** v1 vsl| 1004 RespHeader c Age: 0 **** v1 vsl| 1004 RespHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1004 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1004 VCL_call c DELIVER **** v1 vsl| 1004 VCL_return c deliver **** v1 vsl| 1004 Timestamp c Process: 1712685024.778716 0.023446 0.000343 **** v1 vsl| 1004 Filters c **** v1 vsl| 1004 RespHeader c Connection: close **** v1 vsl| 1004 Timestamp c Resp: 1712685024.781104 0.025833 0.002387 **** v1 vsl| 1004 ReqAcct c 68 0 68 182 0 182 **** dT 7.469 **** v1 vsl| 1004 End c **** v1 vsl| 1002 SessClose c VCL_FAILURE 0.027 **** v1 vsl| 1002 End c **** v1 vsl| 1005 Begin b bereq 1004 fetch **** v1 vsl| 1005 VCL_use b vcl1 **** v1 vsl| 1005 Timestamp b Start: 1712685024.757448 0.000000 0.000000 **** v1 vsl| 1005 BereqMethod b GET **** v1 vsl| 1005 BereqURL b /hit **** v1 vsl| 1005 BereqProtocol b HTTP/1.1 **** v1 vsl| 1005 BereqHeader b foo: restart **** v1 vsl| 1005 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1005 BereqHeader b User-Agent: c1 **** v1 vsl| 1005 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1005 BereqHeader b X-Varnish: 1005 **** v1 vsl| 1005 VCL_call b BACKEND_FETCH **** v1 vsl| 1005 VCL_return b fetch **** v1 vsl| 1005 Timestamp b Fetch: 1712685024.757655 0.000207 0.000207 **** v1 vsl| 1005 Timestamp b Connected: 1712685024.758565 0.001116 0.000909 **** v1 vsl| 1005 BackendOpen b 20 s1 127.0.0.1 49855 127.0.0.1 25787 connect **** v1 vsl| 1005 Timestamp b Bereq: 1712685024.764155 0.006706 0.005589 **** v1 vsl| 1005 BerespProtocol b HTTP/1.1 **** v1 vsl| 1005 BerespStatus b 200 **** v1 vsl| 1005 BerespReason b OK **** v1 vsl| 1005 BerespHeader b Date: Tue, 09 Apr 2024 17:50:24 GMT **** v1 vsl| 1005 BerespHeader b Server: s1 **** v1 vsl| 1005 BerespHeader b Content-Length: 0 **** v1 vsl| 1005 Timestamp b Beresp: 1712685024.764460 0.007011 0.000304 **** v1 vsl| 1005 TTL b RFC 120 10 0 1712685025 1712685025 1712685024 0 0 cacheable **** v1 vsl| 1005 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1005 VCL_return b deliver **** v1 vsl| 1005 Timestamp b Process: 1712685024.764954 0.007506 0.000494 **** 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 20 s1 recycle **** v1 vsl| 1005 Timestamp b BerespBody: 1712685024.781960 0.024511 0.017005 **** v1 vsl| 1005 Length b 0 **** v1 vsl| 1005 BereqAcct b 108 0 108 87 0 87 **** v1 vsl| 1005 End b **** v1 vsl| 1006 Begin c sess 0 HTTP/1 **** v1 vsl| 1006 SessOpen c 127.0.0.1 29209 a0 127.0.0.1 45506 1712685024.790099 22 **** v1 vsl| 1006 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1006 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1006 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1006 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1006 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1006 Link c req 1007 rxreq **** v1 vsl| 1007 Begin c req 1006 rxreq **** v1 vsl| 1007 Timestamp c Start: 1712685024.790734 0.000000 0.000000 **** v1 vsl| 1007 Timestamp c Req: 1712685024.790734 0.000000 0.000000 **** v1 vsl| 1007 VCL_use c vcl1 **** v1 vsl| 1007 ReqStart c 127.0.0.1 29209 a0 **** v1 vsl| 1007 ReqMethod c GET **** v1 vsl| 1007 ReqURL c / **** v1 vsl| 1007 ReqProtocol c HTTP/1.1 **** v1 vsl| 1007 ReqHeader c foo: synth **** v1 vsl| 1007 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1007 ReqHeader c User-Agent: c1 **** v1 vsl| 1007 ReqHeader c X-Forwarded-For: 127.0.0.1 **** dT 7.470 **** v1 vsl| 1007 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1007 VCL_call c RECV **** v1 vsl| 1007 VCL_return c synth **** v1 vsl| 1007 VCL_call c HASH **** v1 vsl| 1007 VCL_return c lookup **** v1 vsl| 1007 RespProtocol c HTTP/1.1 **** v1 vsl| 1007 RespStatus c 748 **** v1 vsl| 1007 RespReason c Unknown HTTP Status **** v1 vsl| 1007 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 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: 1712685024.791391 0.000657 0.000657 **** 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: 1712685024.792091 0.001356 0.000699 **** v1 vsl| 1007 ReqAcct c 63 0 63 38 0 38 **** v1 vsl| 1007 End c **** v1 vsl| 1006 SessClose c VCL_FAILURE 0.002 **** v1 vsl| 1006 End c **** l1007 match| 1007 VCL_call c SYNTH *** l1007 test | expect * 1007 VCL_Error Forced failure **** l1007 match| 1007 VCL_Error c Forced failure **** dT 7.471 *** l1007 test | expect 0 1007 VCL_return fail **** l1007 match| 1007 VCL_return c fail **** l1007 done | **** dT 7.472 ** l1009 === expect * 1009 VCL_call "HASH" ** l1009 === expect 0 1009 VCL_Error "Forced failure" ** l1009 === expect 0 1009 VCL_return "fail" **** dT 7.474 **** l1009 begin| *** l1009 test | expect * 1009 VCL_call HASH ** top === client c1 { ** c1 Starting client ** c1 Waiting for client ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 7.475 *** c1 connected fd 37 from 127.0.0.1 33380 to 127.0.0.1:45506 **** dT 7.476 ** c1 === txreq -hdr "foo: hash" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: hash\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.479 ** c1 === rxresp **** dT 7.481 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:24 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1009\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:24 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 **** dT 7.482 **** 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 ** c1 Ending **** dT 7.483 ** top === varnish v1 -expect vcl_fail == 4 ** v1 as expected: vcl_fail (4) == 4 (4) ** top === varnish v1 -expect sc_vcl_failure == 4 **** dT 7.484 ** v1 as expected: sc_vcl_failure (4) == 4 (4) ** top === logexpect l1012 -v v1 -g vxid -q "vxid == 1012" { **** dT 7.485 ** l1012 === expect 0 1012 Begin {^bereq 1011 pipe} **** dT 7.486 ** l1012 === expect 0 = Timestamp {^Start:} ** l1012 === expect 0 = BereqMethod {^GET} ** l1012 === expect 0 = BereqURL {^/} ** l1012 === expect 0 = BereqProtocol {^HTTP/1.1} ** l1012 === expect 0 = BereqHeader {^foo: pipe} ** l1012 === expect 0 = BereqHeader {^Host: } ** l1012 === expect 0 = BereqHeader {^User-Agent: c1} **** dT 7.487 ** l1012 === expect 0 = BereqHeader {^X-Forwarded-For: } ** l1012 === expect 0 = BereqHeader {^Via: } ** l1012 === expect 0 = BereqHeader {^X-Varnish: 1011} ** l1012 === expect 0 = BereqHeader {^Connection: close} ** l1012 === expect 0 = BereqAcct {^0 0 0 0 0 0} ** l1012 === expect 0 = End **** dT 7.489 ** top === logexpect l1011 -v v1 -g vxid -q "vxid == 1011" { **** dT 7.490 ** l1011 === expect 0 1011 Begin {^req 1010 rxreq} ** l1011 === expect 0 = Timestamp {^Start: } ** l1011 === expect 0 = Timestamp {^Req: } **** dT 7.491 ** l1011 === expect 0 = VCL_use {^vcl1} ** l1011 === expect 0 = ReqStart ** l1011 === expect 0 = ReqMethod {^GET} ** l1011 === expect 0 = ReqURL {^/} ** l1011 === expect 0 = ReqProtocol {^HTTP/1.1} ** l1011 === expect 0 = ReqHeader {^foo: pipe} ** l1011 === expect 0 = ReqHeader {^Host: } ** l1011 === expect 0 = reqHeader {^User-Agent: c1} **** dT 7.492 ** l1011 === expect 0 = ReqHeader {^X-Forwarded-For: } ** l1011 === expect 0 = ReqHeader {^Via: } ** l1011 === expect 0 = VCL_call {^RECV} ** l1011 === expect 0 = VCL_return {^pipe} ** l1011 === expect 0 = VCL_call {^HASH} ** l1011 === expect 0 = VCL_return {^lookup} ** l1011 === expect 0 = Link {^bereq 1012 pipe} **** dT 7.493 ** l1011 === expect 0 = VCL_call {^PIPE} ** l1011 === expect 0 = VCL_Error {^Forced failure} ** l1011 === expect 0 = VCL_return {^fail} ** l1011 === expect 0 = RespProtocol {^HTTP/1.1} ** l1011 === expect 0 = RespStatus {^503} ** l1011 === expect 0 = RespReason {^VCL failed} **** dT 7.494 ** top === client c1 { ** c1 Starting client **** dT 7.495 ** c1 Waiting for client **** l1009 match| 1009 VCL_call c HASH *** l1009 test | expect 0 1009 VCL_Error Forced failure **** l1009 match| 1009 VCL_Error c Forced failure *** l1009 test | expect 0 1009 VCL_return fail **** l1009 match| 1009 VCL_return c fail **** l1009 done | **** dT 7.496 **** l1012 begin| **** l1012 qry | vxid == 1012 *** l1012 test | expect 0 1012 Begin ^bereq 1011 pipe **** l1011 begin| **** l1011 qry | vxid == 1011 *** l1011 test | expect 0 1011 Begin ^req 1010 rxreq ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 7.497 *** c1 connected fd 47 from 127.0.0.1 34002 to 127.0.0.1:45506 ** c1 === txreq -hdr "foo: pipe" **** dT 7.498 **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: pipe\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.500 ** c1 === rxresp **** dT 7.502 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:24 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1011\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:24 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 7.503 ** c1 Ending **** dT 7.504 ** top === varnish v1 -expect vcl_fail == 5 **** dT 7.505 ** v1 as expected: vcl_fail (5) == 5 (5) ** top === varnish v1 -expect sc_vcl_failure == 5 ** v1 as expected: sc_vcl_failure (5) == 5 (5) ** top === logexpect l1014 -v v1 -g raw { **** dT 7.508 **** l1011 match| 1011 Begin c req 1010 rxreq *** l1011 test | expect 0 = Timestamp ^Start: **** l1011 match| 1011 Timestamp c Start: 1712685024.828192 0.000000 0.000000 *** l1011 test | expect 0 = Timestamp ^Req: **** l1011 match| 1011 Timestamp c Req: 1712685024.828192 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 34002 a0 *** l1011 test | expect 0 = ReqMethod ^GET **** l1011 match| 1011 ReqMethod c GET *** l1011 test | expect 0 = ReqURL ^/ **** l1011 match| 1011 ReqURL c / *** l1011 test | expect 0 = ReqProtocol ^HTTP/1.1 **** l1011 match| 1011 ReqProtocol c HTTP/1.1 *** l1011 test | expect 0 = ReqHeader ^foo: pipe **** l1011 match| 1011 ReqHeader c foo: pipe *** l1011 test | expect 0 = ReqHeader ^Host: **** l1011 match| 1011 ReqHeader c Host: 127.0.0.1 *** l1011 test | expect 0 = reqHeader ^User-Agent: c1 **** l1011 match| 1011 ReqHeader c User-Agent: c1 *** l1011 test | expect 0 = ReqHeader ^X-Forwarded-For: **** l1011 match| 1011 ReqHeader c X-Forwarded-For: 127.0.0.1 *** l1011 test | expect 0 = ReqHeader ^Via: **** l1011 match| 1011 ReqHeader c Via: 1.1 v1 (Varnish/trunk) *** l1011 test | expect 0 = VCL_call ^RECV **** l1011 match| 1011 VCL_call c RECV *** l1011 test | expect 0 = VCL_return ^pipe **** l1011 match| 1011 VCL_return c pipe *** l1011 test | expect 0 = VCL_call ^HASH **** l1011 match| 1011 VCL_call c HASH *** l1011 test | expect 0 = VCL_return ^lookup **** l1011 match| 1011 VCL_return c lookup *** l1011 test | expect 0 = Link ^bereq 1012 pipe **** l1011 match| 1011 Link c bereq 1012 pipe *** l1011 test | expect 0 = VCL_call ^PIPE **** l1011 match| 1011 VCL_call c PIPE *** l1011 test | expect 0 = VCL_Error ^Forced failure **** l1011 match| 1011 VCL_Error c Forced failure *** l1011 test | expect 0 = VCL_return ^fail **** l1011 match| 1011 VCL_return c fail *** l1011 test | expect 0 = RespProtocol ^HTTP/1.1 **** l1011 match| 1011 RespProtocol c HTTP/1.1 *** l1011 test | expect 0 = RespStatus ^503 **** dT 7.509 **** l1011 match| 1011 RespStatus c 503 *** l1011 test | expect 0 = RespReason ^VCL failed **** l1011 match| 1011 RespReason c VCL failed **** l1011 done | **** dT 7.510 **** l1012 match| 1012 Begin b bereq 1011 pipe *** l1012 test | expect 0 = Timestamp ^Start: **** l1012 match| 1012 Timestamp b Start: 1712685024.828713 0.000000 0.000000 *** l1012 test | expect 0 = BereqMethod ^GET **** l1012 match| 1012 BereqMethod b GET *** l1012 test | expect 0 = BereqURL ^/ **** l1012 match| 1012 BereqURL b / *** l1012 test | expect 0 = BereqProtocol ^HTTP/1.1 **** l1012 match| 1012 BereqProtocol b HTTP/1.1 *** l1012 test | expect 0 = BereqHeader ^foo: pipe **** l1012 match| 1012 BereqHeader b foo: pipe *** l1012 test | expect 0 = BereqHeader ^Host: **** l1012 match| 1012 BereqHeader b Host: 127.0.0.1 *** l1012 test | expect 0 = BereqHeader ^User-Agent: c1 **** l1012 match| 1012 BereqHeader b User-Agent: c1 *** l1012 test | expect 0 = BereqHeader ^X-Forwarded-For: **** l1012 match| 1012 BereqHeader b X-Forwarded-For: 127.0.0.1 *** l1012 test | expect 0 = BereqHeader ^Via: **** l1012 match| 1012 BereqHeader b Via: 1.1 v1 (Varnish/trunk) *** l1012 test | expect 0 = BereqHeader ^X-Varnish: 1011 **** l1012 match| 1012 BereqHeader b X-Varnish: 1011 *** l1012 test | expect 0 = BereqHeader ^Connection: close **** l1012 match| 1012 BereqHeader b Connection: close *** l1012 test | expect 0 = BereqAcct ^0 0 0 0 0 0 **** l1012 match| 1012 BereqAcct b 0 0 0 0 0 0 *** l1012 test | expect 0 = End **** l1012 match| 1012 End b **** l1012 done | **** dT 7.511 ** l1014 === expect * 1014 VCL_call "PASS" ** l1014 === expect 0 1014 VCL_Error "Forced failure" ** l1014 === expect 0 1014 VCL_return "fail" **** dT 7.512 ** top === client c1 { **** dT 7.513 ** c1 Starting client ** c1 Waiting for client **** l1014 begin| *** l1014 test | expect * 1014 VCL_call PASS ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 7.514 *** c1 connected fd 52 from 127.0.0.1 60514 to 127.0.0.1:45506 ** c1 === txreq -hdr "foo: pass" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: pass\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.517 ** c1 === rxresp **** dT 7.518 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:24 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 **** dT 7.519 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:24 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1014 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1014
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 52 ** c1 Ending **** dT 7.521 ** top === varnish v1 -expect vcl_fail == 6 ** v1 as expected: vcl_fail (6) == 6 (6) ** top === varnish v1 -expect sc_vcl_failure == 6 **** dT 7.522 ** v1 as expected: sc_vcl_failure (6) == 6 (6) ** top === logexpect l1016 -v v1 -g raw { **** dT 7.523 ** l1016 === expect * 1016 VCL_call "PURGE" **** dT 7.524 **** 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 | ** l1016 === expect 0 1016 VCL_Error "Forced failure" **** dT 7.525 ** l1016 === expect 0 1016 VCL_return "fail" **** dT 7.526 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1016 begin| *** l1016 test | expect * 1016 VCL_call PURGE ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 7.527 *** c1 connected fd 57 from 127.0.0.1 52238 to 127.0.0.1:45506 **** dT 7.528 ** c1 === txreq -hdr "foo: purge" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: purge\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.531 ** c1 === rxresp **** dT 7.532 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:24 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1016\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:24 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 7.533 **** 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 7.535 ** top === varnish v1 -expect vcl_fail == 7 ** v1 as expected: vcl_fail (7) == 7 (7) ** top === varnish v1 -expect sc_vcl_failure == 7 ** v1 as expected: sc_vcl_failure (7) == 7 (7) ** top === logexpect l1018 -v v1 -g raw { **** dT 7.537 ** l1018 === expect * 1018 VCL_call "MISS" ** l1018 === expect 0 1018 VCL_Error "Forced failure" ** l1018 === expect 0 1018 VCL_return "fail" **** dT 7.538 ** top === client c1 { ** c1 Starting client **** dT 7.539 ** c1 Waiting for client **** l1016 match| 1016 VCL_call c PURGE *** l1016 test | expect 0 1016 VCL_Error Forced failure **** l1016 match| 1016 VCL_Error c Forced failure *** l1016 test | expect 0 1016 VCL_return fail **** l1016 match| 1016 VCL_return c fail **** l1016 done | **** dT 7.540 **** l1018 begin| *** l1018 test | expect * 1018 VCL_call MISS ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 7.541 *** c1 connected fd 62 from 127.0.0.1 20075 to 127.0.0.1:45506 **** dT 7.542 ** c1 === txreq -url /miss -hdr "foo: miss" **** c1 txreq|GET /miss HTTP/1.1\r **** c1 txreq|foo: miss\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.544 ** c1 === rxresp **** dT 7.546 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:24 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1018\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:24 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 **** dT 7.547 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 62 ** c1 Ending **** dT 7.548 ** top === varnish v1 -expect vcl_fail == 8 **** dT 7.549 ** v1 as expected: vcl_fail (8) == 8 (8) ** top === varnish v1 -expect sc_vcl_failure == 8 ** v1 as expected: sc_vcl_failure (8) == 8 (8) ** top === logexpect l1020 -v v1 -g raw { **** dT 7.551 ** l1020 === expect * 1020 VCL_call "HIT" ** l1020 === expect 0 1020 VCL_Error "Forced failure" **** dT 7.552 ** l1020 === expect 0 1020 VCL_return "fail" **** dT 7.553 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 7.554 **** l1018 match| 1018 VCL_call c MISS *** l1018 test | expect 0 1018 VCL_Error Forced failure **** l1018 match| 1018 VCL_Error c Forced failure *** l1018 test | expect 0 1018 VCL_return fail **** l1018 match| 1018 VCL_return c fail **** l1018 done | **** l1020 begin| *** l1020 test | expect * 1020 VCL_call HIT **** dT 7.555 ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 7.556 *** c1 connected fd 67 from 127.0.0.1 43726 to 127.0.0.1:45506 ** c1 === txreq -url /hit -hdr "foo: hit" **** c1 txreq|GET /hit HTTP/1.1\r **** c1 txreq|foo: hit\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.559 ** c1 === rxresp **** dT 7.560 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:24 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1020\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:24 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 **** dT 7.561 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1020
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 67 ** c1 Ending **** dT 7.563 ** top === varnish v1 -expect vcl_fail == 9 ** v1 as expected: vcl_fail (9) == 9 (9) ** top === varnish v1 -expect sc_vcl_failure == 9 ** v1 as expected: sc_vcl_failure (9) == 9 (9) ** top === logexpect l1022 -v v1 -g raw { **** dT 7.565 **** 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 7.566 ** l1022 === expect * 1022 VCL_call "DELIVER" ** l1022 === expect 0 1022 VCL_Error "Forced failure" ** l1022 === expect 0 1022 VCL_return "fail" **** dT 7.568 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1022 begin| *** l1022 test | expect * 1022 VCL_call DELIVER ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 7.569 *** c1 connected fd 72 from 127.0.0.1 27279 to 127.0.0.1:45506 **** dT 7.570 ** c1 === txreq -url /hit -hdr "foo: deliver" **** c1 txreq|GET /hit HTTP/1.1\r **** c1 txreq|foo: deliver\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** v1 vsl| 1008 Begin c sess 0 HTTP/1 **** dT 7.571 **** v1 vsl| 1008 SessOpen c 127.0.0.1 33380 a0 127.0.0.1 45506 1712685024.805643 23 **** v1 vsl| 1008 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1008 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1008 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1008 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1008 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1008 Link c req 1009 rxreq **** v1 vsl| 1009 Begin c req 1008 rxreq **** v1 vsl| 1009 Timestamp c Start: 1712685024.806311 0.000000 0.000000 **** v1 vsl| 1009 Timestamp c Req: 1712685024.806311 0.000000 0.000000 **** v1 vsl| 1009 VCL_use c vcl1 **** v1 vsl| 1009 ReqStart c 127.0.0.1 33380 a0 **** v1 vsl| 1009 ReqMethod c GET **** v1 vsl| 1009 ReqURL c / **** v1 vsl| 1009 ReqProtocol c HTTP/1.1 **** v1 vsl| 1009 ReqHeader c foo: hash **** v1 vsl| 1009 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1009 ReqHeader c User-Agent: c1 **** v1 vsl| 1009 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1009 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1009 VCL_call c RECV **** v1 vsl| 1009 VCL_return c hash **** v1 vsl| 1009 VCL_call c HASH **** v1 vsl| 1009 VCL_Error c Forced failure **** v1 vsl| 1009 VCL_return c fail **** v1 vsl| 1009 RespProtocol c HTTP/1.1 **** v1 vsl| 1009 RespStatus c 503 **** v1 vsl| 1009 RespReason c VCL failed **** v1 vsl| 1009 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 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: 1712685024.807373 0.001062 0.001062 **** 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: 1712685024.809449 0.003138 0.002075 **** v1 vsl| 1009 ReqAcct c 62 0 62 194 251 445 **** v1 vsl| 1009 End c **** v1 vsl| 1008 SessClose c VCL_FAILURE 0.004 **** v1 vsl| 1008 End c **** v1 vsl| 1010 Begin c sess 0 HTTP/1 **** v1 vsl| 1010 SessOpen c 127.0.0.1 34002 a0 127.0.0.1 45506 1712685024.827518 20 **** v1 vsl| 1010 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1010 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1010 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1010 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1010 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1010 Link c req 1011 rxreq **** v1 vsl| 1012 Begin b bereq 1011 pipe **** v1 vsl| 1012 Timestamp b Start: 1712685024.828713 0.000000 0.000000 **** v1 vsl| 1012 BereqMethod b GET **** dT 7.572 **** v1 vsl| 1012 BereqURL b / **** v1 vsl| 1012 BereqProtocol b HTTP/1.1 **** v1 vsl| 1012 BereqHeader b foo: pipe **** v1 vsl| 1012 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1012 BereqHeader b User-Agent: c1 **** v1 vsl| 1012 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1012 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1012 BereqHeader b X-Varnish: 1011 **** v1 vsl| 1012 BereqHeader b Connection: close **** v1 vsl| 1012 BereqAcct b 0 0 0 0 0 0 **** v1 vsl| 1012 End b **** v1 vsl| 1011 Begin c req 1010 rxreq **** v1 vsl| 1011 Timestamp c Start: 1712685024.828192 0.000000 0.000000 **** v1 vsl| 1011 Timestamp c Req: 1712685024.828192 0.000000 0.000000 **** v1 vsl| 1011 VCL_use c vcl1 **** v1 vsl| 1011 ReqStart c 127.0.0.1 34002 a0 **** v1 vsl| 1011 ReqMethod c GET **** v1 vsl| 1011 ReqURL c / **** v1 vsl| 1011 ReqProtocol c HTTP/1.1 **** v1 vsl| 1011 ReqHeader c foo: pipe **** v1 vsl| 1011 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1011 ReqHeader c User-Agent: c1 **** v1 vsl| 1011 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1011 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1011 VCL_call c RECV **** v1 vsl| 1011 VCL_return c pipe **** v1 vsl| 1011 VCL_call c HASH **** v1 vsl| 1011 VCL_return c lookup **** v1 vsl| 1011 Link c bereq 1012 pipe **** v1 vsl| 1011 VCL_call c PIPE **** v1 vsl| 1011 VCL_Error c Forced failure **** v1 vsl| 1011 VCL_return c fail **** v1 vsl| 1011 RespProtocol c HTTP/1.1 **** v1 vsl| 1011 RespStatus c 503 **** v1 vsl| 1011 RespReason c VCL failed **** v1 vsl| 1011 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 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: 1712685024.829165 0.000972 0.000972 **** 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: 1712685024.832910 0.004717 0.003745 **** v1 vsl| 1011 ReqAcct c 62 0 62 194 251 445 **** v1 vsl| 1011 End c **** v1 vsl| 1010 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1010 End c **** v1 vsl| 1013 Begin c sess 0 HTTP/1 **** v1 vsl| 1013 SessOpen c 127.0.0.1 60514 a0 127.0.0.1 45506 1712685024.844296 21 **** v1 vsl| 1013 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1013 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1013 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1013 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1013 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1013 Link c req 1014 rxreq **** dT 7.573 **** v1 vsl| 1014 Begin c req 1013 rxreq **** v1 vsl| 1014 Timestamp c Start: 1712685024.844937 0.000000 0.000000 **** v1 vsl| 1014 Timestamp c Req: 1712685024.844937 0.000000 0.000000 **** v1 vsl| 1014 VCL_use c vcl1 **** v1 vsl| 1014 ReqStart c 127.0.0.1 60514 a0 **** v1 vsl| 1014 ReqMethod c GET **** v1 vsl| 1014 ReqURL c / **** v1 vsl| 1014 ReqProtocol c HTTP/1.1 **** v1 vsl| 1014 ReqHeader c foo: pass **** v1 vsl| 1014 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1014 ReqHeader c User-Agent: c1 **** v1 vsl| 1014 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1014 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1014 VCL_call c RECV **** v1 vsl| 1014 VCL_return c pass **** v1 vsl| 1014 VCL_call c HASH **** v1 vsl| 1014 VCL_return c lookup **** v1 vsl| 1014 VCL_call c PASS **** v1 vsl| 1014 VCL_Error c Forced failure **** v1 vsl| 1014 VCL_return c fail **** v1 vsl| 1014 RespProtocol c HTTP/1.1 **** v1 vsl| 1014 RespStatus c 503 **** v1 vsl| 1014 RespReason c VCL failed **** v1 vsl| 1014 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 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: 1712685024.845697 0.000759 0.000759 **** 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: 1712685024.849427 0.004489 0.003729 **** v1 vsl| 1014 ReqAcct c 62 0 62 194 251 445 **** v1 vsl| 1014 End c **** v1 vsl| 1013 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1013 End c **** v1 vsl| 1015 Begin c sess 0 HTTP/1 **** v1 vsl| 1015 SessOpen c 127.0.0.1 52238 a0 127.0.0.1 45506 1712685024.857923 20 **** v1 vsl| 1015 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1015 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1015 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1015 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1015 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1015 Link c req 1016 rxreq **** v1 vsl| 1016 Begin c req 1015 rxreq **** v1 vsl| 1016 Timestamp c Start: 1712685024.858605 0.000000 0.000000 **** v1 vsl| 1016 Timestamp c Req: 1712685024.858605 0.000000 0.000000 **** v1 vsl| 1016 VCL_use c vcl1 **** v1 vsl| 1016 ReqStart c 127.0.0.1 52238 a0 **** v1 vsl| 1016 ReqMethod c GET **** v1 vsl| 1016 ReqURL c / **** dT 7.574 **** v1 vsl| 1016 ReqProtocol c HTTP/1.1 **** v1 vsl| 1016 ReqHeader c foo: purge **** v1 vsl| 1016 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1016 ReqHeader c User-Agent: c1 **** v1 vsl| 1016 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1016 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1016 VCL_call c RECV **** v1 vsl| 1016 VCL_return c purge **** v1 vsl| 1016 VCL_call c HASH **** v1 vsl| 1016 VCL_return c lookup **** v1 vsl| 1016 VCL_call c PURGE **** v1 vsl| 1016 VCL_Error c Forced failure **** v1 vsl| 1016 VCL_return c fail **** v1 vsl| 1016 RespProtocol c HTTP/1.1 **** v1 vsl| 1016 RespStatus c 503 **** v1 vsl| 1016 RespReason c VCL failed **** v1 vsl| 1016 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 GMT **** v1 vsl| 1016 RespHeader c Server: Varnish **** v1 vsl| 1016 RespHeader c X-Varnish: 1016 **** v1 vsl| 1016 VCL_call c SYNTH **** v1 vsl| 1016 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1016 RespHeader c Retry-After: 5 **** v1 vsl| 1016 VCL_return c deliver **** v1 vsl| 1016 Timestamp c Process: 1712685024.859544 0.000939 0.000939 **** 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: 1712685024.863277 0.004672 0.003732 **** v1 vsl| 1016 ReqAcct c 63 0 63 194 251 445 **** v1 vsl| 1016 End c **** v1 vsl| 1015 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1015 End c **** v1 vsl| 1017 Begin c sess 0 HTTP/1 **** v1 vsl| 1017 SessOpen c 127.0.0.1 20075 a0 127.0.0.1 45506 1712685024.871715 21 **** v1 vsl| 1017 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1017 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1017 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1017 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1017 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1017 Link c req 1018 rxreq **** v1 vsl| 1018 Begin c req 1017 rxreq **** v1 vsl| 1018 Timestamp c Start: 1712685024.872414 0.000000 0.000000 **** v1 vsl| 1018 Timestamp c Req: 1712685024.872414 0.000000 0.000000 **** v1 vsl| 1018 VCL_use c vcl1 **** v1 vsl| 1018 ReqStart c 127.0.0.1 20075 a0 **** v1 vsl| 1018 ReqMethod c GET **** v1 vsl| 1018 ReqURL c /miss **** v1 vsl| 1018 ReqProtocol c HTTP/1.1 **** v1 vsl| 1018 ReqHeader c foo: miss **** v1 vsl| 1018 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1018 ReqHeader c User-Agent: c1 **** v1 vsl| 1018 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1018 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1018 VCL_call c RECV **** v1 vsl| 1018 VCL_return c hash **** v1 vsl| 1018 VCL_call c HASH **** v1 vsl| 1018 VCL_return c lookup **** v1 vsl| 1018 VCL_call c MISS **** dT 7.575 **** v1 vsl| 1018 VCL_Error c Forced failure **** v1 vsl| 1018 VCL_return c fail **** v1 vsl| 1018 RespProtocol c HTTP/1.1 **** v1 vsl| 1018 RespStatus c 503 **** v1 vsl| 1018 RespReason c VCL failed **** v1 vsl| 1018 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 GMT **** v1 vsl| 1018 RespHeader c Server: Varnish **** v1 vsl| 1018 RespHeader c X-Varnish: 1018 **** v1 vsl| 1018 VCL_call c SYNTH **** v1 vsl| 1018 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1018 RespHeader c Retry-After: 5 **** v1 vsl| 1018 VCL_return c deliver **** v1 vsl| 1018 Timestamp c Process: 1712685024.873350 0.000936 0.000936 **** 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: 1712685024.877097 0.004683 0.003746 **** v1 vsl| 1018 ReqAcct c 66 0 66 194 251 445 **** v1 vsl| 1018 End c **** v1 vsl| 1017 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1017 End c **** v1 vsl| 1019 Begin c sess 0 HTTP/1 **** v1 vsl| 1019 SessOpen c 127.0.0.1 43726 a0 127.0.0.1 45506 1712685024.885900 20 **** v1 vsl| 1019 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1019 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1019 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1019 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1019 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1019 Link c req 1020 rxreq **** v1 vsl| 1020 Begin c req 1019 rxreq **** v1 vsl| 1020 Timestamp c Start: 1712685024.886576 0.000000 0.000000 **** v1 vsl| 1020 Timestamp c Req: 1712685024.886576 0.000000 0.000000 **** v1 vsl| 1020 VCL_use c vcl1 **** v1 vsl| 1020 ReqStart c 127.0.0.1 43726 a0 **** v1 vsl| 1020 ReqMethod c GET **** v1 vsl| 1020 ReqURL c /hit **** v1 vsl| 1020 ReqProtocol c HTTP/1.1 **** v1 vsl| 1020 ReqHeader c foo: hit **** v1 vsl| 1020 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1020 ReqHeader c User-Agent: c1 **** v1 vsl| 1020 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1020 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1020 VCL_call c RECV **** v1 vsl| 1020 VCL_return c hash **** v1 vsl| 1020 VCL_call c HASH **** v1 vsl| 1020 VCL_return c lookup **** v1 vsl| 1020 Hit c 1005 119.877884 10.000000 0.000000 **** v1 vsl| 1020 VCL_call c HIT **** v1 vsl| 1020 VCL_Error c Forced failure **** v1 vsl| 1020 VCL_return c fail **** v1 vsl| 1020 RespProtocol c HTTP/1.1 **** v1 vsl| 1020 RespStatus c 503 **** v1 vsl| 1020 RespReason c VCL failed **** v1 vsl| 1020 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 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 7.576 **** v1 vsl| 1020 VCL_return c deliver **** v1 vsl| 1020 Timestamp c Process: 1712685024.887530 0.000954 0.000954 **** 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: 1712685024.891279 0.004702 0.003748 **** v1 vsl| 1020 ReqAcct c 64 0 64 194 251 445 **** v1 vsl| 1020 End c **** v1 vsl| 1019 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1019 End c **** v1 vsl| 1021 Begin c sess 0 HTTP/1 **** v1 vsl| 1021 SessOpen c 127.0.0.1 27279 a0 127.0.0.1 45506 1712685024.899740 21 **** v1 vsl| 1021 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1021 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1021 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1021 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1021 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 ** c1 === rxresp **** dT 7.580 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:24 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: Tue, 09 Apr 2024 17:50:24 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 **** dT 7.581 **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1022
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 72 ** c1 Ending **** dT 7.583 **** 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 | ** top === varnish v1 -expect vcl_fail == 10 **** dT 7.584 ** v1 as expected: vcl_fail (10) == 10 (10) ** top === varnish v1 -expect sc_vcl_failure == 10 ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1001 -wait ** l1001 Waiting for logexp **** dT 7.585 ** top === logexpect l1003 -wait ** l1003 Waiting for logexp ** top === logexpect l1007 -wait ** l1007 Waiting for logexp ** top === logexpect l1009 -wait ** l1009 Waiting for logexp ** top === logexpect l1012 -wait ** l1012 Waiting for logexp ** top === logexpect l1011 -wait ** l1011 Waiting for logexp ** top === logexpect l1014 -wait ** l1014 Waiting for logexp **** dT 7.586 ** top === logexpect l1016 -wait ** l1016 Waiting for logexp ** top === logexpect l1018 -wait ** l1018 Waiting for logexp ** top === logexpect l1020 -wait ** l1020 Waiting for logexp ** top === logexpect l1022 -wait ** l1022 Waiting for logexp ** top === varnish v1 -vcl+backend { **** 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 = "49855"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tsub vcl_backend_fetch { **** v1 CLI TX|\t\tdebug.fail(); **** v1 CLI TX|\t\tset bereq.http.not = "Should not happen"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 7.677 **** v1 vsl| 1021 Link c req 1022 rxreq **** v1 vsl| 1022 Begin c req 1021 rxreq **** v1 vsl| 1022 Timestamp c Start: 1712685024.906280 0.000000 0.000000 **** v1 vsl| 1022 Timestamp c Req: 1712685024.906280 0.000000 0.000000 **** v1 vsl| 1022 VCL_use c vcl1 **** v1 vsl| 1022 ReqStart c 127.0.0.1 27279 a0 **** v1 vsl| 1022 ReqMethod c GET **** v1 vsl| 1022 ReqURL c /hit **** v1 vsl| 1022 ReqProtocol c HTTP/1.1 **** v1 vsl| 1022 ReqHeader c foo: deliver **** v1 vsl| 1022 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1022 ReqHeader c User-Agent: c1 **** v1 vsl| 1022 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1022 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1022 VCL_call c RECV **** v1 vsl| 1022 VCL_return c hash **** v1 vsl| 1022 VCL_call c HASH **** v1 vsl| 1022 VCL_return c lookup **** v1 vsl| 1022 Hit c 1005 119.858179 10.000000 0.000000 **** v1 vsl| 1022 VCL_call c HIT **** v1 vsl| 1022 VCL_return c deliver **** v1 vsl| 1022 RespProtocol c HTTP/1.1 **** v1 vsl| 1022 RespStatus c 200 **** v1 vsl| 1022 RespReason c OK **** v1 vsl| 1022 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 GMT **** v1 vsl| 1022 RespHeader c Server: s1 **** v1 vsl| 1022 RespHeader c Content-Length: 0 **** v1 vsl| 1022 RespHeader c X-Varnish: 1022 1005 **** v1 vsl| 1022 RespHeader c Age: 0 **** v1 vsl| 1022 RespHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1022 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1022 VCL_call c DELIVER **** v1 vsl| 1022 VCL_Error c Forced failure **** v1 vsl| 1022 VCL_return c fail **** v1 vsl| 1022 RespProtocol c HTTP/1.1 **** v1 vsl| 1022 RespStatus c 503 **** v1 vsl| 1022 RespReason c VCL failed **** v1 vsl| 1022 RespHeader c Date: Tue, 09 Apr 2024 17:50:24 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: 1712685024.907375 0.001094 0.001094 **** 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: 1712685024.911216 0.004935 0.003840 **** v1 vsl| 1022 ReqAcct c 68 0 68 194 251 445 **** v1 vsl| 1022 End c **** dT 7.678 **** v1 vsl| 1021 SessClose c VCL_FAILURE 0.012 **** v1 vsl| 1021 End c **** dT 8.287 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_LINGER for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPIDLE for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPCNT for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPINTVL for a0=127.0.0.1:45506 **** dT 9.306 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_LINGER for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPIDLE for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPCNT for a0=127.0.0.1:45506 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPINTVL for a0=127.0.0.1:45506 **** dT 12.792 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl2 **** dT 12.835 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** top === logexpect l1 -v v1 -g raw { **** dT 12.836 ** l1 === expect * 1025 VCL_call "BACKEND_FETCH" **** dT 12.837 ** l1 === expect 0 1025 VCL_Error "Forced failure" ** l1 === expect 0 1025 VCL_return "fail" **** dT 12.838 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1025 VCL_call BACKEND_FETCH **** dT 12.839 ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 12.840 *** c1 connected fd 77 from 127.0.0.1 17554 to 127.0.0.1:45506 ** c1 === txreq -url /backend_fetch **** c1 txreq|GET /backend_fetch HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 12.842 ** c1 === rxresp **** dT 12.846 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:30 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1024\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 278\r **** c1 rxhdr|Connection: keep-alive\r **** c1 rxhdr|\r **** c1 rxhdrlen = 208 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |Service Unavailable **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:30 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1024 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 278 **** c1 http[ 9] |Connection: keep-alive **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|Service Unavailable
**** c1 c-l|XID: 1024
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 278 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "Service Unavailable" **** c1 EXPECT resp.reason (Service Unavailable) == "Service Unavailable" match *** c1 closing fd 77 **** dT 12.848 ** c1 Ending ** top === varnish v1 -expect vcl_fail == 11 **** dT 12.849 ** v1 as expected: vcl_fail (11) == 11 (11) ** top === varnish v1 -expect sc_vcl_failure == 10 **** dT 12.850 **** l1 match| 1025 VCL_call b BACKEND_FETCH *** l1 test | expect 0 1025 VCL_Error Forced failure **** l1 match| 1025 VCL_Error b Forced failure *** l1 test | expect 0 1025 VCL_return fail **** l1 match| 1025 VCL_return b fail **** l1 done | ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1 -wait ** l1 Waiting for logexp **** dT 12.851 ** 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=49855 **** s1 macro def s1_sock=127.0.0.1:49855 * s1 Listen on 127.0.0.1:49855 **** dT 12.852 ** 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 = "49855"; } **** 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 12.857 ** s1 Started on 127.0.0.1:49855 (1 iterations) **** dT 12.876 **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1712685024.916899/vgc.so 1auto **** dT 12.877 **** v1 vsl| 0 Debug - vcl2: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl2.1712685024.916899/vgc.so" as "vcl2" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1712685030 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 17554 a0 127.0.0.1 45506 1712685030.170153 20 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** 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: 1712685030.171862 0.000000 0.000000 **** v1 vsl| 1025 BereqMethod b GET **** v1 vsl| 1025 BereqURL b /backend_fetch **** v1 vsl| 1025 BereqProtocol b HTTP/1.1 **** v1 vsl| 1025 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1025 BereqHeader b User-Agent: c1 **** v1 vsl| 1025 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1025 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1025 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1025 BereqHeader b X-Varnish: 1025 **** v1 vsl| 1025 VCL_call b BACKEND_FETCH **** v1 vsl| 1025 VCL_Error b Forced failure **** v1 vsl| 1025 VCL_return b fail **** v1 vsl| 1025 BereqAcct b 0 0 0 0 0 0 **** v1 vsl| 1025 End b **** v1 vsl| 1024 Begin c req 1023 rxreq **** v1 vsl| 1024 Timestamp c Start: 1712685030.170858 0.000000 0.000000 **** v1 vsl| 1024 Timestamp c Req: 1712685030.170858 0.000000 0.000000 **** v1 vsl| 1024 VCL_use c vcl2 **** v1 vsl| 1024 ReqStart c 127.0.0.1 17554 a0 **** v1 vsl| 1024 ReqMethod c GET **** v1 vsl| 1024 ReqURL c /backend_fetch **** v1 vsl| 1024 ReqProtocol c HTTP/1.1 **** v1 vsl| 1024 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1024 ReqHeader c User-Agent: c1 **** v1 vsl| 1024 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1024 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1024 VCL_call c RECV **** v1 vsl| 1024 VCL_return c hash **** v1 vsl| 1024 VCL_call c HASH **** v1 vsl| 1024 VCL_return c lookup **** v1 vsl| 1024 VCL_call c MISS **** v1 vsl| 1024 VCL_return c fetch **** v1 vsl| 1024 Link c bereq 1025 fetch **** v1 vsl| 1024 Timestamp c Fetch: 1712685030.172334 0.001476 0.001476 **** v1 vsl| 1024 RespProtocol c HTTP/1.1 **** v1 vsl| 1024 RespStatus c 503 **** dT 12.878 **** v1 vsl| 1024 RespReason c Service Unavailable **** v1 vsl| 1024 RespHeader c Date: Tue, 09 Apr 2024 17:50:30 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: 1712685030.172905 0.002047 0.000571 **** 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: 1712685030.176436 0.005577 0.003530 **** v1 vsl| 1024 ReqAcct c 64 0 64 208 278 486 **** v1 vsl| 1024 End c **** v1 vsl| 1023 SessClose c REM_CLOSE 0.007 **** v1 vsl| 1023 End c **** dT 18.136 **** v1 vsl| 0 CLI - Rd vcl.load vcl3 vcl_vcl3.1712685030.182086/vgc.so 1auto **** dT 18.140 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl3 **** dT 18.183 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl3' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1028 VCL_call "BACKEND_ERROR" ** l1 === expect 0 1028 VCL_Error "Forced failure" **** dT 18.184 ** l1 === expect 0 1028 VCL_return "fail" **** dT 18.185 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1028 VCL_call BACKEND_ERROR **** dT 18.186 ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 18.187 *** c1 connected fd 78 from 127.0.0.1 39749 to 127.0.0.1:45506 **** dT 18.188 ** c1 === txreq -url /backend_error **** c1 txreq|GET /backend_error HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 18.191 ** c1 === rxresp *** s1 accepted fd 77 127.0.0.1 17736 ** s1 === rxreq **** dT 18.193 **** s1 rxhdr|GET /backend_error HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|User-Agent: c1\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r **** s1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1028\r **** s1 rxhdr|\r **** s1 rxhdrlen = 161 **** s1 http[ 0] |GET **** s1 http[ 1] |/backend_error **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |User-Agent: c1 **** s1 http[ 5] |X-Forwarded-For: 127.0.0.1 **** s1 http[ 6] |Via: 1.1 v1 (Varnish/trunk) **** s1 http[ 7] |Accept-Encoding: gzip **** s1 http[ 8] |X-Varnish: 1028 **** s1 bodylen = 0 ** s1 === expect req.url == /backend_error **** s1 EXPECT req.url (/backend_error) == "/backend_error" match *** s1 shutting fd 77 **** dT 18.198 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:35 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 **** dT 18.199 **** c1 http[ 2] |Service Unavailable **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:35 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1027 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 278 **** c1 http[ 9] |Connection: keep-alive **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|Service Unavailable
**** c1 c-l|XID: 1027
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 278 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "Service Unavailable" **** c1 EXPECT resp.reason (Service Unavailable) == "Service Unavailable" match *** c1 closing fd 78 **** dT 18.200 ** c1 Ending **** dT 18.201 ** s1 Ending **** dT 18.202 **** l1 match| 1028 VCL_call b BACKEND_ERROR *** l1 test | expect 0 1028 VCL_Error Forced failure **** l1 match| 1028 VCL_Error b Forced failure *** l1 test | expect 0 1028 VCL_return fail **** l1 match| 1028 VCL_return b fail **** l1 done | ** top === varnish v1 -expect vcl_fail == 12 **** dT 18.203 ** v1 as expected: vcl_fail (12) == 12 (12) ** top === varnish v1 -expect sc_vcl_failure == 10 ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1 -wait ** l1 Waiting for logexp ** top === server s1 { ** s1 Waiting for server (3/-1) ** s1 Starting server **** dT 18.204 **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=49855 **** s1 macro def s1_sock=127.0.0.1:49855 * s1 Listen on 127.0.0.1:49855 ** 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 = "49855"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tsub vcl_backend_response { **** v1 CLI TX|\t\tdebug.fail(); **** v1 CLI TX|\t\tset bereq.http.not = "Should not happen"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 18.210 ** s1 Started on 127.0.0.1:49855 (1 iterations) **** dT 18.238 **** v1 vsl| 0 Debug - vcl3: VCL_EVENT_WARM **** dT 18.239 **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl3.1712685030.182086/vgc.so" as "vcl3" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1712685035 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 39749 a0 127.0.0.1 45506 1712685035.516460 21 **** v1 vsl| 1026 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1026 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1026 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1026 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1026 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** 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: 1712685035.518858 0.000000 0.000000 **** v1 vsl| 1028 BereqMethod b GET **** v1 vsl| 1028 BereqURL b /backend_error **** v1 vsl| 1028 BereqProtocol b HTTP/1.1 **** v1 vsl| 1028 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1028 BereqHeader b User-Agent: c1 **** v1 vsl| 1028 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1028 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1028 BereqHeader b Accept-Encoding: gzip **** 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: 1712685035.519118 0.000260 0.000260 **** v1 vsl| 1028 Timestamp b Connected: 1712685035.519915 0.001056 0.000796 **** v1 vsl| 1028 BackendOpen b 23 s1 127.0.0.1 49855 127.0.0.1 17736 connect **** v1 vsl| 1028 Timestamp b Bereq: 1712685035.520321 0.001462 0.000406 **** v1 vsl| 1028 FetchError b HTC eof (Unexpected end of input) **** v1 vsl| 1028 BackendClose b 23 s1 close RX_BAD **** v1 vsl| 1028 Timestamp b Beresp: 1712685035.523634 0.004775 0.003312 **** v1 vsl| 1028 Timestamp b Error: 1712685035.523679 0.004820 0.000045 **** v1 vsl| 1028 BerespProtocol b HTTP/1.1 **** v1 vsl| 1028 BerespStatus b 503 **** v1 vsl| 1028 BerespReason b Backend fetch failed **** v1 vsl| 1028 BerespHeader b Date: Tue, 09 Apr 2024 17:50:35 GMT **** v1 vsl| 1028 BerespHeader b Server: Varnish **** v1 vsl| 1028 VCL_call b BACKEND_ERROR **** v1 vsl| 1028 VCL_Error b Forced failure **** v1 vsl| 1028 VCL_return b fail **** v1 vsl| 1028 BereqAcct b 161 0 161 0 0 0 **** v1 vsl| 1028 End b **** v1 vsl| 1027 Begin c req 1026 rxreq **** v1 vsl| 1027 Timestamp c Start: 1712685035.517969 0.000000 0.000000 **** v1 vsl| 1027 Timestamp c Req: 1712685035.517969 0.000000 0.000000 **** v1 vsl| 1027 VCL_use c vcl3 **** v1 vsl| 1027 ReqStart c 127.0.0.1 39749 a0 **** v1 vsl| 1027 ReqMethod c GET **** v1 vsl| 1027 ReqURL c /backend_error **** v1 vsl| 1027 ReqProtocol c HTTP/1.1 **** v1 vsl| 1027 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1027 ReqHeader c User-Agent: c1 **** v1 vsl| 1027 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1027 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** dT 18.240 **** 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: 1712685035.524384 0.006415 0.006415 **** v1 vsl| 1027 RespProtocol c HTTP/1.1 **** v1 vsl| 1027 RespStatus c 503 **** v1 vsl| 1027 RespReason c Service Unavailable **** v1 vsl| 1027 RespHeader c Date: Tue, 09 Apr 2024 17:50:35 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: 1712685035.524752 0.006783 0.000368 **** 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: 1712685035.526152 0.008183 0.001399 **** v1 vsl| 1027 ReqAcct c 64 0 64 208 278 486 **** v1 vsl| 1027 End c **** v1 vsl| 1026 SessClose c REM_CLOSE 0.013 **** v1 vsl| 1026 End c **** dT 23.401 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl4 **** dT 23.444 *** 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 23.445 ** l1 === expect 0 1031 VCL_return "fail" **** dT 23.446 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1031 VCL_call BACKEND_RESPONSE **** dT 23.447 ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 23.448 *** c1 connected fd 78 from 127.0.0.1 12096 to 127.0.0.1:45506 **** dT 23.449 ** c1 === txreq -url /backend_response **** c1 txreq|GET /backend_response HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 23.451 ** c1 === rxresp **** dT 23.452 *** s1 accepted fd 77 127.0.0.1 63449 ** s1 === rxreq **** dT 23.454 **** s1 rxhdr|GET /backend_response HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|User-Agent: c1\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r **** s1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1031\r **** s1 rxhdr|\r **** s1 rxhdrlen = 164 **** s1 http[ 0] |GET **** s1 http[ 1] |/backend_response **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |User-Agent: c1 **** s1 http[ 5] |X-Forwarded-For: 127.0.0.1 **** s1 http[ 6] |Via: 1.1 v1 (Varnish/trunk) **** s1 http[ 7] |Accept-Encoding: gzip **** s1 http[ 8] |X-Varnish: 1031 **** s1 bodylen = 0 ** s1 === expect req.url == /backend_response **** s1 EXPECT req.url (/backend_response) == "/backend_response" match ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Tue, 09 Apr 2024 17:50:40 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r **** dT 23.459 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:40 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1030\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 278\r **** c1 rxhdr|Connection: keep-alive\r **** c1 rxhdr|\r **** c1 rxhdrlen = 208 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |Service Unavailable **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:40 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 23.461 ** c1 Ending *** s1 shutting fd 77 **** dT 23.462 ** s1 Ending **** l1 match| 1031 VCL_call b BACKEND_RESPONSE **** dT 23.463 *** l1 test | expect 0 1031 VCL_Error Forced failure **** l1 match| 1031 VCL_Error b Forced failure *** l1 test | expect 0 1031 VCL_return fail **** l1 match| 1031 VCL_return b fail **** l1 done | ** top === varnish v1 -expect vcl_fail == 13 **** dT 23.464 ** 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 = "49855"; } **** 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 23.469 **** v1 vsl| 0 CLI - Rd vcl.load vcl4 vcl_vcl4.1712685035.534609/vgc.so 1auto **** v1 vsl| 0 Debug - vcl4: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl4.1712685035.534609/vgc.so" as "vcl4" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1712685040 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl4 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 1029 Begin c sess 0 HTTP/1 **** v1 vsl| 1029 SessOpen c 127.0.0.1 12096 a0 127.0.0.1 45506 1712685040.777231 20 **** v1 vsl| 1029 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1029 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1029 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1029 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1029 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** 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: 1712685040.779611 0.000000 0.000000 **** v1 vsl| 1031 BereqMethod b GET **** v1 vsl| 1031 BereqURL b /backend_response **** v1 vsl| 1031 BereqProtocol b HTTP/1.1 **** v1 vsl| 1031 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1031 BereqHeader b User-Agent: c1 **** v1 vsl| 1031 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1031 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1031 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1031 BereqHeader b X-Varnish: 1031 **** v1 vsl| 1031 VCL_call b BACKEND_FETCH **** v1 vsl| 1031 VCL_return b fetch **** v1 vsl| 1031 Timestamp b Fetch: 1712685040.779845 0.000233 0.000233 **** v1 vsl| 1031 Timestamp b Connected: 1712685040.780532 0.000921 0.000687 **** v1 vsl| 1031 BackendOpen b 23 s1 127.0.0.1 49855 127.0.0.1 63449 connect **** v1 vsl| 1031 Timestamp b Bereq: 1712685040.780892 0.001280 0.000359 **** v1 vsl| 1031 BerespProtocol b HTTP/1.1 **** v1 vsl| 1031 BerespStatus b 200 **** v1 vsl| 1031 BerespReason b OK **** v1 vsl| 1031 BerespHeader b Date: Tue, 09 Apr 2024 17:50:40 GMT **** v1 vsl| 1031 BerespHeader b Server: s1 **** v1 vsl| 1031 BerespHeader b Content-Length: 0 **** v1 vsl| 1031 Timestamp b Beresp: 1712685040.784395 0.004784 0.003503 **** dT 23.470 **** v1 vsl| 1031 TTL b RFC 120 10 0 1712685041 1712685041 1712685040 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 23 s1 close RESP_CLOSE **** v1 vsl| 1031 BereqAcct b 164 0 164 87 0 87 **** v1 vsl| 1031 End b **** v1 vsl| 1030 Begin c req 1029 rxreq **** v1 vsl| 1030 Timestamp c Start: 1712685040.778731 0.000000 0.000000 **** v1 vsl| 1030 Timestamp c Req: 1712685040.778731 0.000000 0.000000 **** v1 vsl| 1030 VCL_use c vcl4 **** v1 vsl| 1030 ReqStart c 127.0.0.1 12096 a0 **** v1 vsl| 1030 ReqMethod c GET **** v1 vsl| 1030 ReqURL c /backend_response **** v1 vsl| 1030 ReqProtocol c HTTP/1.1 **** v1 vsl| 1030 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1030 ReqHeader c User-Agent: c1 **** v1 vsl| 1030 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1030 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1030 VCL_call c RECV **** v1 vsl| 1030 VCL_return c hash **** v1 vsl| 1030 VCL_call c HASH **** v1 vsl| 1030 VCL_return c lookup **** v1 vsl| 1030 VCL_call c MISS **** v1 vsl| 1030 VCL_return c fetch **** v1 vsl| 1030 Link c bereq 1031 fetch **** v1 vsl| 1030 Timestamp c Fetch: 1712685040.785243 0.006511 0.006511 **** v1 vsl| 1030 RespProtocol c HTTP/1.1 **** v1 vsl| 1030 RespStatus c 503 **** v1 vsl| 1030 RespReason c Service Unavailable **** v1 vsl| 1030 RespHeader c Date: Tue, 09 Apr 2024 17:50:40 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: 1712685040.785625 0.006893 0.000381 **** v1 vsl| 1030 RespHeader c Content-Length: 278 **** v1 vsl| 1030 Storage c malloc Transient **** v1 vsl| 1030 Filters c **** v1 vsl| 1030 RespHeader c Connection: keep-alive **** v1 vsl| 1030 Timestamp c Resp: 1712685040.789274 0.010542 0.003649 **** v1 vsl| 1030 ReqAcct c 67 0 67 208 278 486 **** v1 vsl| 1030 End c **** v1 vsl| 1029 SessClose c REM_CLOSE 0.013 **** v1 vsl| 1029 End c **** dT 28.706 *** v1 CLI RX 200 **** dT 28.707 **** v1 CLI TX|vcl.use vcl5 **** dT 28.750 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl5' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1033 VCL_call "RECV" ** l1 === expect 0 1033 VCL_Error "Forced failure" **** dT 28.751 ** l1 === expect 0 1033 VCL_return "fail" **** dT 28.752 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1033 VCL_call RECV **** dT 28.753 ** c1 Started on 127.0.0.1:45506 (1 iterations) *** c1 Connect to 127.0.0.1:45506 **** dT 28.754 *** c1 connected fd 77 from 127.0.0.1 52119 to 127.0.0.1:45506 ** c1 === txreq **** dT 28.755 **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 28.757 ** c1 === rxresp **** dT 28.759 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Tue, 09 Apr 2024 17:50:46 GMT\r **** c1 rxhdr|Server: Varnish\r **** c1 rxhdr|X-Varnish: 1033\r **** c1 rxhdr|Content-Type: text/html; charset=utf-8\r **** c1 rxhdr|Retry-After: 5\r **** c1 rxhdr|Content-Length: 251\r **** c1 rxhdr|Connection: close\r **** c1 rxhdr|\r **** c1 rxhdrlen = 194 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Tue, 09 Apr 2024 17:50:46 GMT **** c1 http[ 4] |Server: Varnish **** c1 http[ 5] |X-Varnish: 1033 **** c1 http[ 6] |Content-Type: text/html; charset=utf-8 **** c1 http[ 7] |Retry-After: 5 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1033
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 77 ** c1 Ending **** dT 28.760 ** top === varnish v1 -expect vcl_fail == 14 **** dT 28.761 ** v1 as expected: vcl_fail (14) == 14 (14) ** top === varnish v1 -expect sc_vcl_failure == 11 ** v1 as expected: sc_vcl_failure (11) == 11 (11) ** top === logexpect l1 -wait ** l1 Waiting for logexp **** dT 28.764 **** 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 | ** 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 28.770 **** v1 vsl| 0 CLI - Rd vcl.load vcl5 vcl_vcl5.1712685040.794732/vgc.so 1auto **** v1 vsl| 0 Debug - vcl5: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl5.1712685040.794732/vgc.so" as "vcl5" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1712685046 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl5 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 1032 Begin c sess 0 HTTP/1 **** v1 vsl| 1032 SessOpen c 127.0.0.1 52119 a0 127.0.0.1 45506 1712685046.083304 21 **** v1 vsl| 1032 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1032 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45506 **** v1 vsl| 1032 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1032 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45506 **** v1 vsl| 1032 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45506 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45506 **** v1 vsl| 1032 Link c req 1033 rxreq **** v1 vsl| 1033 Begin c req 1032 rxreq **** v1 vsl| 1033 Timestamp c Start: 1712685046.084437 0.000000 0.000000 **** v1 vsl| 1033 Timestamp c Req: 1712685046.084437 0.000000 0.000000 **** v1 vsl| 1033 VCL_use c vcl5 **** v1 vsl| 1033 ReqStart c 127.0.0.1 52119 a0 **** v1 vsl| 1033 ReqMethod c GET **** v1 vsl| 1033 ReqURL c / **** v1 vsl| 1033 ReqProtocol c HTTP/1.1 **** v1 vsl| 1033 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1033 ReqHeader c User-Agent: c1 **** v1 vsl| 1033 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1033 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1033 VCL_call c RECV **** v1 vsl| 1033 VCL_Error c Forced failure **** v1 vsl| 1033 VCL_return c fail **** v1 vsl| 1033 RespProtocol c HTTP/1.1 **** v1 vsl| 1033 RespStatus c 503 **** v1 vsl| 1033 RespReason c VCL failed **** v1 vsl| 1033 RespHeader c Date: Tue, 09 Apr 2024 17:50:46 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: 1712685046.085089 0.000652 0.000652 **** 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: 1712685046.085795 0.001357 0.000705 **** v1 vsl| 1033 ReqAcct c 51 0 51 194 251 445 **** v1 vsl| 1033 End c **** v1 vsl| 1032 SessClose c VCL_FAILURE 0.003 **** v1 vsl| 1032 End c **** dT 33.898 *** v1 CLI RX 300 **** v1 CLI RX|VCL "vcl6" Failed initialization **** v1 CLI RX|Message: **** v1 CLI RX|\tForced failure ** v1 VCL compilation failed (as expected) *** v1 Found expected string: ("Forced failure") ** top === varnish v1 -errvcl {thou shalt not fini} { **** v1 CLI TX|vcl.inline vcl7 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tbackend proforma none; **** v1 CLI TX|\tsub vcl_init { **** v1 CLI TX|\t\tdebug.fail_task_fini(); **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 33.965 **** v1 vsl| 0 CLI - Rd vcl.load vcl6 vcl_vcl6.1712685046.094558/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 300 58 VCL "vcl6" Failed initialization Message: Forced failure **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1712685051 1.0 **** dT 39.212 *** v1 CLI RX 300 **** v1 CLI RX|VCL "vcl7" Failed initialization **** v1 CLI RX|Message: **** v1 CLI RX|\tthou shalt not fini ** v1 VCL compilation failed (as expected) *** v1 Found expected string: ("thou shalt not fini") ** top === varnish v1 -vcl { **** v1 CLI TX|vcl.inline vcl8 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tbackend proforma none; **** v1 CLI TX|\tsub vcl_fini { **** v1 CLI TX|\t\tdebug.fail(); **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 39.275 **** v1 vsl| 0 CLI - Rd vcl.load vcl7 vcl_vcl7.1712685051.228213/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 300 63 VCL "vcl7" Failed initialization Message: thou shalt not fini **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1712685056 1.0 **** dT 44.356 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl8 **** dT 44.380 **** v1 vsl| 0 CLI - Rd vcl.load vcl8 vcl_vcl8.1712685056.542677/vgc.so 1auto **** v1 vsl| 0 Debug - vcl8: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl8.1712685056.542677/vgc.so" as "vcl8" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1712685061 1.0 **** dT 44.399 *** 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 = "49855"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 44.482 **** v1 vsl| 0 CLI - Rd vcl.use vcl8 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 49.399 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl9 **** dT 49.443 *** 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 49.444 ** l1 === expect 3 0 VCL_Error "^Forced failure" ** l1 === expect 0 0 VCL_Error {^\QVRT_fail() from vcl_fini{} has no e... **** dT 49.445 ** top === varnish v1 -cliok "vcl.discard vcl8" **** v1 CLI TX|vcl.discard vcl8 **** dT 49.446 **** l1 begin| *** l1 test | expect * 0 CLI ^Rd vcl.state vcl8 0cold **** dT 49.488 **** v1 vsl| 0 CLI - Rd vcl.load vcl9 vcl_vcl9.1712685061.729406/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl9.1712685061.729406/vgc.so" as "vcl9" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1712685066 1.0 **** dT 49.489 **** v1 vsl| 0 CLI - Rd vcl.use vcl9 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 49.492 *** v1 CLI RX 200 ** v1 CLI 200