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.313 ** c1 Ending **** dT 7.314 ** top === varnish v1 -expect vcl_fail == 1 **** dT 7.325 **** 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 | ** v1 as expected: vcl_fail (1) == 1 (1) ** top === varnish v1 -expect sc_vcl_failure == 1 **** dT 7.326 ** v1 as expected: sc_vcl_failure (1) == 1 (1) ** top === logexpect l1003 -v v1 -g raw { **** dT 7.327 ** l1003 === expect * 1003 VCL_call "RECV" **** dT 7.328 ** l1003 === expect 0 1003 VCL_Error "Forced failure" ** l1003 === expect 0 1003 VCL_return "fail" ** l1003 === expect * 1003 VCL_call "SYNTH" **** dT 7.329 ** l1003 === expect 0 1003 VCL_return "restart" **** dT 7.330 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1003 begin| *** l1003 test | expect * 1003 VCL_call RECV **** dT 7.331 ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 7.332 *** c1 connected fd 28 from 127.0.0.1 54607 to 127.0.0.1:57566 ** c1 === txreq -url /hit -hdr "foo: restart" **** c1 txreq|GET /hit HTTP/1.1\r **** c1 txreq|foo: restart\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.335 ** c1 === rxresp **** dT 7.337 *** s1 accepted fd 4 127.0.0.1 35672 **** dT 7.338 ** s1 === rxreq **** dT 7.339 **** 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 **** dT 7.340 **** 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.341 **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 22 Apr 2024 13:27:24 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r *** s1 shutting fd 4 ** s1 Ending **** dT 7.344 **** l1003 match| 1003 VCL_call c RECV *** l1003 test | expect 0 1003 VCL_Error Forced failure **** l1003 match| 1003 VCL_Error c Forced failure *** l1003 test | expect 0 1003 VCL_return fail **** l1003 match| 1003 VCL_return c fail *** l1003 test | expect * 1003 VCL_call SYNTH **** l1003 match| 1003 VCL_call c SYNTH *** l1003 test | expect 0 1003 VCL_return restart **** l1003 match| 1003 VCL_return c restart **** l1003 done | **** dT 7.354 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 57566 **** v1 vsl| 1000 Begin c sess 0 HTTP/1 **** v1 vsl| 1000 SessOpen c 127.0.0.1 51357 a0 127.0.0.1 57566 1713792444.612860 17 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_SNDTIMEO non heredity for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_RCVTIMEO non heredity for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: Test confirmed TCP_NODELAY non heredity for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1000 Link c req 1001 rxreq **** v1 vsl| 1001 Begin c req 1000 rxreq **** dT 7.355 **** v1 vsl| 1001 Timestamp c Start: 1713792444.613611 0.000000 0.000000 **** v1 vsl| 1001 Timestamp c Req: 1713792444.613611 0.000000 0.000000 **** v1 vsl| 1001 VCL_use c vcl1 **** v1 vsl| 1001 ReqStart c 127.0.0.1 51357 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: Mon, 22 Apr 2024 13:27: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: 1713792444.615974 0.002363 0.002363 **** 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: 1713792444.622960 0.009349 0.006986 **** v1 vsl| 1001 ReqAcct c 51 0 51 194 251 445 **** v1 vsl| 1001 End c **** v1 vsl| 1000 SessClose c VCL_FAILURE 0.011 **** v1 vsl| 1000 End c **** v1 vsl| 1002 Begin c sess 0 HTTP/1 **** v1 vsl| 1002 SessOpen c 127.0.0.1 54607 a0 127.0.0.1 57566 1713792444.639833 21 **** v1 vsl| 1002 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1002 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1002 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1002 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1002 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1002 Link c req 1003 rxreq **** v1 vsl| 1003 Begin c req 1002 rxreq **** v1 vsl| 1003 Timestamp c Start: 1713792444.640519 0.000000 0.000000 **** v1 vsl| 1003 Timestamp c Req: 1713792444.640519 0.000000 0.000000 **** v1 vsl| 1003 VCL_use c vcl1 **** v1 vsl| 1003 ReqStart c 127.0.0.1 54607 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 **** dT 7.356 **** v1 vsl| 1003 RespStatus c 503 **** v1 vsl| 1003 RespReason c VCL failed **** v1 vsl| 1003 RespHeader c Date: Mon, 22 Apr 2024 13:27: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: 1713792444.641341 0.000822 0.000822 **** v1 vsl| 1003 Timestamp c Restart: 1713792444.641384 0.000865 0.000042 **** v1 vsl| 1003 Link c req 1004 restart **** v1 vsl| 1003 End c **** dT 7.359 **** c1 rxhdr|HTTP/1.1 200 OK\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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 **** 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 **** dT 7.360 ** c1 Ending **** dT 7.361 ** top === varnish v1 -expect vcl_fail == 2 **** dT 7.362 ** v1 as expected: vcl_fail (2) == 2 (2) ** 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.364 ** l1007 === expect * 1007 VCL_call "SYNTH" ** l1007 === expect * 1007 VCL_Error "Forced failure" ** l1007 === expect 0 1007 VCL_return "fail" **** dT 7.365 ** top === client c1 { ** c1 Starting client **** dT 7.366 ** c1 Waiting for client **** l1007 begin| *** l1007 test | expect * 1007 VCL_call SYNTH **** dT 7.367 ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 7.368 *** c1 connected fd 32 from 127.0.0.1 32549 to 127.0.0.1:57566 ** c1 === txreq -hdr "foo: synth" **** dT 7.369 **** 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.371 ** c1 === rxresp **** c1 rxhdr|HTTP/1.1 500 Internal Server Error\r **** c1 rxhdr|\r **** c1 rxhdrlen = 38 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |500 **** dT 7.372 **** c1 http[ 2] |Internal Server Error **** c1 bodylen = 0 ** c1 === expect resp.status == 500 **** c1 EXPECT resp.status (500) == "500" match ** c1 === expect_close **** c1 Expecting close (fd = 32) **** c1 fd=32 EOF, as expected *** c1 closing fd 32 ** c1 Ending **** dT 7.373 ** top === varnish v1 -expect vcl_fail == 3 **** dT 7.374 ** v1 as expected: vcl_fail (3) == 3 (3) ** top === varnish v1 -expect sc_vcl_failure == 3 ** v1 as expected: sc_vcl_failure (3) == 3 (3) ** top === logexpect l1009 -v v1 -g raw { **** dT 7.376 ** l1009 === expect * 1009 VCL_call "HASH" ** l1009 === expect 0 1009 VCL_Error "Forced failure" ** l1009 === expect 0 1009 VCL_return "fail" **** dT 7.378 **** l1009 begin| *** l1009 test | expect * 1009 VCL_call HASH ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 7.379 ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 7.380 *** c1 connected fd 37 from 127.0.0.1 37414 to 127.0.0.1:57566 ** 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 **** l1007 match| 1007 VCL_call c SYNTH *** l1007 test | expect * 1007 VCL_Error Forced failure **** l1007 match| 1007 VCL_Error c Forced failure *** l1007 test | expect 0 1007 VCL_return fail **** l1007 match| 1007 VCL_return c fail **** l1007 done | **** dT 7.383 ** c1 === rxresp **** dT 7.385 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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.386 **** 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.388 ** 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.389 **** 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 | ** v1 as expected: sc_vcl_failure (4) == 4 (4) **** dT 7.390 ** top === logexpect l1012 -v v1 -g vxid -q "vxid == 1012" { **** dT 7.391 ** l1012 === expect 0 1012 Begin {^bereq 1011 pipe} ** l1012 === expect 0 = Timestamp {^Start:} ** l1012 === expect 0 = BereqMethod {^GET} **** dT 7.392 ** 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} ** l1012 === expect 0 = BereqHeader {^X-Forwarded-For: } ** l1012 === expect 0 = BereqHeader {^Via: } **** dT 7.393 ** 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.394 ** top === logexpect l1011 -v v1 -g vxid -q "vxid == 1011" { **** dT 7.395 ** l1011 === expect 0 1011 Begin {^req 1010 rxreq} **** dT 7.396 ** l1011 === expect 0 = Timestamp {^Start: } ** l1011 === expect 0 = Timestamp {^Req: } ** l1011 === expect 0 = VCL_use {^vcl1} ** l1011 === expect 0 = ReqStart ** l1011 === expect 0 = ReqMethod {^GET} **** dT 7.397 ** 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} ** l1011 === expect 0 = ReqHeader {^X-Forwarded-For: } ** l1011 === expect 0 = ReqHeader {^Via: } ** l1011 === expect 0 = VCL_call {^RECV} **** dT 7.398 ** l1011 === expect 0 = VCL_return {^pipe} ** l1011 === expect 0 = VCL_call {^HASH} ** l1011 === expect 0 = VCL_return {^lookup} ** l1011 === expect 0 = Link {^bereq 1012 pipe} ** l1011 === expect 0 = VCL_call {^PIPE} ** l1011 === expect 0 = VCL_Error {^Forced failure} ** l1011 === expect 0 = VCL_return {^fail} **** dT 7.399 ** l1011 === expect 0 = RespProtocol {^HTTP/1.1} ** l1011 === expect 0 = RespStatus {^503} ** l1011 === expect 0 = RespReason {^VCL failed} **** dT 7.400 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1012 begin| **** l1012 qry | vxid == 1012 *** l1012 test | expect 0 1012 Begin ^bereq 1011 pipe **** dT 7.401 **** l1011 begin| **** l1011 qry | vxid == 1011 *** l1011 test | expect 0 1011 Begin ^req 1010 rxreq ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 7.402 *** c1 connected fd 47 from 127.0.0.1 18030 to 127.0.0.1:57566 ** c1 === txreq -hdr "foo: pipe" **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|foo: pipe\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.405 ** c1 === rxresp **** dT 7.407 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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.408 ** c1 Ending **** dT 7.409 ** top === varnish v1 -expect vcl_fail == 5 **** dT 7.410 ** 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.412 **** l1011 match| 1011 Begin c req 1010 rxreq *** l1011 test | expect 0 = Timestamp ^Start: **** l1011 match| 1011 Timestamp c Start: 1713792444.710604 0.000000 0.000000 *** l1011 test | expect 0 = Timestamp ^Req: **** l1011 match| 1011 Timestamp c Req: 1713792444.710604 0.000000 0.000000 *** l1011 test | expect 0 = VCL_use ^vcl1 **** dT 7.413 **** l1011 match| 1011 VCL_use c vcl1 *** l1011 test | expect 0 = ReqStart **** l1011 match| 1011 ReqStart c 127.0.0.1 18030 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 **** l1011 match| 1011 RespStatus c 503 *** l1011 test | expect 0 = RespReason ^VCL failed **** l1011 match| 1011 RespReason c VCL failed **** l1011 done | **** dT 7.415 ** l1014 === expect * 1014 VCL_call "PASS" ** l1014 === expect 0 1014 VCL_Error "Forced failure" ** l1014 === expect 0 1014 VCL_return "fail" **** dT 7.416 ** top === client c1 { **** dT 7.417 ** c1 Starting client ** c1 Waiting for client **** l1012 match| 1012 Begin b bereq 1011 pipe *** l1012 test | expect 0 = Timestamp ^Start: **** l1012 match| 1012 Timestamp b Start: 1713792444.711158 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 **** dT 7.418 *** 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 | **** l1014 begin| *** l1014 test | expect * 1014 VCL_call PASS ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 7.419 *** c1 connected fd 52 from 127.0.0.1 30916 to 127.0.0.1:57566 **** dT 7.420 ** 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.422 ** c1 === rxresp **** dT 7.424 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |503 **** c1 http[ 2] |VCL failed **** c1 http[ 3] |Date: Mon, 22 Apr 2024 13:27: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 **** dT 7.425 **** 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.426 ** top === varnish v1 -expect vcl_fail == 6 **** dT 7.427 ** v1 as expected: vcl_fail (6) == 6 (6) ** top === varnish v1 -expect sc_vcl_failure == 6 ** v1 as expected: sc_vcl_failure (6) == 6 (6) ** top === logexpect l1016 -v v1 -g raw { **** dT 7.429 **** l1014 match| 1014 VCL_call c PASS *** l1014 test | expect 0 1014 VCL_Error Forced failure **** l1014 match| 1014 VCL_Error c Forced failure *** l1014 test | expect 0 1014 VCL_return fail **** l1014 match| 1014 VCL_return c fail **** l1014 done | **** dT 7.430 ** l1016 === expect * 1016 VCL_call "PURGE" ** l1016 === expect 0 1016 VCL_Error "Forced failure" ** l1016 === expect 0 1016 VCL_return "fail" **** dT 7.431 ** top === client c1 { **** dT 7.432 ** c1 Starting client ** c1 Waiting for client **** l1016 begin| *** l1016 test | expect * 1016 VCL_call PURGE ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 7.433 *** c1 connected fd 57 from 127.0.0.1 62030 to 127.0.0.1:57566 ** 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.436 ** c1 === rxresp **** dT 7.438 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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 **** 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 **** dT 7.439 ** c1 Ending **** dT 7.440 ** top === varnish v1 -expect vcl_fail == 7 ** v1 as expected: vcl_fail (7) == 7 (7) ** top === varnish v1 -expect sc_vcl_failure == 7 **** dT 7.441 ** v1 as expected: sc_vcl_failure (7) == 7 (7) ** top === logexpect l1018 -v v1 -g raw { **** dT 7.442 ** l1018 === expect * 1018 VCL_call "MISS" ** l1018 === expect 0 1018 VCL_Error "Forced failure" **** dT 7.443 **** 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.444 ** l1018 === expect 0 1018 VCL_return "fail" **** dT 7.445 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1018 begin| *** l1018 test | expect * 1018 VCL_call MISS **** dT 7.446 ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 7.447 *** c1 connected fd 62 from 127.0.0.1 37666 to 127.0.0.1:57566 ** 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.450 ** c1 === rxresp **** dT 7.453 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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 **** 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.454 ** top === varnish v1 -expect vcl_fail == 8 **** dT 7.455 ** 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.456 **** l1018 match| 1018 VCL_call c MISS *** l1018 test | expect 0 1018 VCL_Error Forced failure **** l1018 match| 1018 VCL_Error c Forced failure *** l1018 test | expect 0 1018 VCL_return fail **** l1018 match| 1018 VCL_return c fail **** l1018 done | **** dT 7.457 **** v1 vsl| 1004 Begin c req 1003 restart **** v1 vsl| 1004 Timestamp c Start: 1713792444.641384 0.000865 0.000000 **** v1 vsl| 1004 ReqStart c 127.0.0.1 54607 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: 1713792444.663751 0.023231 0.022366 **** 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: Mon, 22 Apr 2024 13:27: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: 1713792444.664091 0.023572 0.000340 **** v1 vsl| 1004 Filters c **** v1 vsl| 1004 RespHeader c Connection: close **** v1 vsl| 1004 Timestamp c Resp: 1713792444.667555 0.027035 0.003463 **** v1 vsl| 1004 ReqAcct c 68 0 68 182 0 182 **** v1 vsl| 1004 End c **** v1 vsl| 1002 SessClose c VCL_FAILURE 0.028 **** v1 vsl| 1002 End c **** v1 vsl| 1005 Begin b bereq 1004 fetch **** v1 vsl| 1005 VCL_use b vcl1 **** v1 vsl| 1005 Timestamp b Start: 1713792444.642523 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: 1713792444.642948 0.000425 0.000425 **** v1 vsl| 1005 Timestamp b Connected: 1713792444.643834 0.001311 0.000885 **** dT 7.458 **** v1 vsl| 1005 BackendOpen b 17 s1 127.0.0.1 26984 127.0.0.1 35672 connect **** v1 vsl| 1005 Timestamp b Bereq: 1713792444.649210 0.006686 0.005375 **** 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: Mon, 22 Apr 2024 13:27:24 GMT **** v1 vsl| 1005 BerespHeader b Server: s1 **** v1 vsl| 1005 BerespHeader b Content-Length: 0 **** v1 vsl| 1005 Timestamp b Beresp: 1713792444.649516 0.006992 0.000306 **** v1 vsl| 1005 TTL b RFC 120 10 0 1713792445 1713792445 1713792444 0 0 cacheable **** v1 vsl| 1005 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1005 VCL_return b deliver **** v1 vsl| 1005 Timestamp b Process: 1713792444.650035 0.007512 0.000519 **** 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 17 s1 recycle **** v1 vsl| 1005 Timestamp b BerespBody: 1713792444.672991 0.030468 0.022955 **** 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 32549 a0 127.0.0.1 57566 1713792444.676128 22 **** v1 vsl| 1006 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1006 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1006 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1006 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1006 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1006 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1006 Link c req 1007 rxreq **** v1 vsl| 1007 Begin c req 1006 rxreq **** v1 vsl| 1007 Timestamp c Start: 1713792444.677173 0.000000 0.000000 **** v1 vsl| 1007 Timestamp c Req: 1713792444.677173 0.000000 0.000000 **** v1 vsl| 1007 VCL_use c vcl1 **** v1 vsl| 1007 ReqStart c 127.0.0.1 32549 a0 **** v1 vsl| 1007 ReqMethod c GET **** v1 vsl| 1007 ReqURL c / **** v1 vsl| 1007 ReqProtocol c HTTP/1.1 **** v1 vsl| 1007 ReqHeader c foo: synth **** v1 vsl| 1007 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1007 ReqHeader c User-Agent: c1 **** v1 vsl| 1007 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1007 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1007 VCL_call c RECV **** v1 vsl| 1007 VCL_return c synth **** v1 vsl| 1007 VCL_call c HASH **** v1 vsl| 1007 VCL_return c lookup **** v1 vsl| 1007 RespProtocol c HTTP/1.1 **** v1 vsl| 1007 RespStatus c 748 **** v1 vsl| 1007 RespReason c Unknown HTTP Status **** v1 vsl| 1007 RespHeader c Date: Mon, 22 Apr 2024 13:27: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: 1713792444.677845 0.000671 0.000671 **** 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: 1713792444.678885 0.001711 0.001040 **** dT 7.459 **** v1 vsl| 1007 ReqAcct c 63 0 63 38 0 38 **** v1 vsl| 1007 End c **** v1 vsl| 1006 SessClose c VCL_FAILURE 0.004 **** v1 vsl| 1006 End c **** v1 vsl| 1008 Begin c sess 0 HTTP/1 **** v1 vsl| 1008 SessOpen c 127.0.0.1 37414 a0 127.0.0.1 57566 1713792444.687924 23 **** v1 vsl| 1008 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1008 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1008 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1008 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1008 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1008 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1008 Link c req 1009 rxreq **** v1 vsl| 1009 Begin c req 1008 rxreq **** v1 vsl| 1009 Timestamp c Start: 1713792444.688747 0.000000 0.000000 **** v1 vsl| 1009 Timestamp c Req: 1713792444.688747 0.000000 0.000000 **** v1 vsl| 1009 VCL_use c vcl1 **** v1 vsl| 1009 ReqStart c 127.0.0.1 37414 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: Mon, 22 Apr 2024 13:27: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: 1713792444.689837 0.001090 0.001090 **** 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: 1713792444.693806 0.005059 0.003969 **** v1 vsl| 1009 ReqAcct c 62 0 62 194 251 445 **** v1 vsl| 1009 End c **** v1 vsl| 1008 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1008 End c **** v1 vsl| 1010 Begin c sess 0 HTTP/1 **** v1 vsl| 1010 SessOpen c 127.0.0.1 18030 a0 127.0.0.1 57566 1713792444.709949 17 **** v1 vsl| 1010 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1010 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1010 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1010 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1010 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** dT 7.460 **** v1 vsl| 1010 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1010 Link c req 1011 rxreq **** v1 vsl| 1012 Begin b bereq 1011 pipe **** v1 vsl| 1012 Timestamp b Start: 1713792444.711158 0.000000 0.000000 **** v1 vsl| 1012 BereqMethod b GET **** v1 vsl| 1012 BereqURL b / **** v1 vsl| 1012 BereqProtocol b HTTP/1.1 **** v1 vsl| 1012 BereqHeader b foo: pipe **** v1 vsl| 1012 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1012 BereqHeader b User-Agent: c1 **** v1 vsl| 1012 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1012 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1012 BereqHeader b X-Varnish: 1011 **** v1 vsl| 1012 BereqHeader b Connection: close **** v1 vsl| 1012 BereqAcct b 0 0 0 0 0 0 **** v1 vsl| 1012 End b **** v1 vsl| 1011 Begin c req 1010 rxreq **** v1 vsl| 1011 Timestamp c Start: 1713792444.710604 0.000000 0.000000 **** v1 vsl| 1011 Timestamp c Req: 1713792444.710604 0.000000 0.000000 **** v1 vsl| 1011 VCL_use c vcl1 **** v1 vsl| 1011 ReqStart c 127.0.0.1 18030 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: Mon, 22 Apr 2024 13:27: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: 1713792444.711584 0.000980 0.000980 **** 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: 1713792444.715349 0.004745 0.003765 **** 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 30916 a0 127.0.0.1 57566 1713792444.727448 21 **** v1 vsl| 1013 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1013 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1013 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1013 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** dT 7.461 **** v1 vsl| 1013 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1013 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1013 Link c req 1014 rxreq **** v1 vsl| 1014 Begin c req 1013 rxreq **** v1 vsl| 1014 Timestamp c Start: 1713792444.728137 0.000000 0.000000 **** v1 vsl| 1014 Timestamp c Req: 1713792444.728137 0.000000 0.000000 **** v1 vsl| 1014 VCL_use c vcl1 **** v1 vsl| 1014 ReqStart c 127.0.0.1 30916 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: Mon, 22 Apr 2024 13:27: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: 1713792444.728895 0.000757 0.000757 **** 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: 1713792444.732589 0.004451 0.003693 **** 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 62030 a0 127.0.0.1 57566 1713792444.740864 17 **** v1 vsl| 1015 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1015 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1015 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1015 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1015 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1015 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1015 Link c req 1016 rxreq **** v1 vsl| 1016 Begin c req 1015 rxreq **** v1 vsl| 1016 Timestamp c Start: 1713792444.741506 0.000000 0.000000 **** v1 vsl| 1016 Timestamp c Req: 1713792444.741506 0.000000 0.000000 **** v1 vsl| 1016 VCL_use c vcl1 **** v1 vsl| 1016 ReqStart c 127.0.0.1 62030 a0 **** v1 vsl| 1016 ReqMethod c GET **** v1 vsl| 1016 ReqURL c / **** dT 7.462 **** 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: Mon, 22 Apr 2024 13:27: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: 1713792444.742468 0.000962 0.000962 **** 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: 1713792444.746178 0.004672 0.003709 **** 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 37666 a0 127.0.0.1 57566 1713792444.754814 21 **** v1 vsl| 1017 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1017 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1017 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1017 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1017 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1017 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1017 Link c req 1018 rxreq **** v1 vsl| 1018 Begin c req 1017 rxreq **** v1 vsl| 1018 Timestamp c Start: 1713792444.755466 0.000000 0.000000 **** v1 vsl| 1018 Timestamp c Req: 1713792444.755466 0.000000 0.000000 **** v1 vsl| 1018 VCL_use c vcl1 **** v1 vsl| 1018 ReqStart c 127.0.0.1 37666 a0 **** v1 vsl| 1018 ReqMethod c GET **** v1 vsl| 1018 ReqURL c /miss **** v1 vsl| 1018 ReqProtocol c HTTP/1.1 **** v1 vsl| 1018 ReqHeader c foo: miss **** v1 vsl| 1018 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1018 ReqHeader c User-Agent: c1 **** v1 vsl| 1018 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1018 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1018 VCL_call c RECV **** v1 vsl| 1018 VCL_return c hash **** v1 vsl| 1018 VCL_call c HASH **** v1 vsl| 1018 VCL_return c lookup **** v1 vsl| 1018 VCL_call c MISS **** v1 vsl| 1018 VCL_Error c Forced failure **** v1 vsl| 1018 VCL_return c fail **** dT 7.463 **** 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: Mon, 22 Apr 2024 13:27: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: 1713792444.756392 0.000926 0.000926 **** 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: 1713792444.758062 0.002596 0.001670 **** v1 vsl| 1018 ReqAcct c 66 0 66 194 251 445 **** v1 vsl| 1018 End c **** v1 vsl| 1017 SessClose c VCL_FAILURE 0.004 **** v1 vsl| 1017 End c **** dT 7.464 ** l1020 === expect * 1020 VCL_call "HIT" ** l1020 === expect 0 1020 VCL_Error "Forced failure" ** l1020 === expect 0 1020 VCL_return "fail" **** dT 7.466 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1020 begin| *** l1020 test | expect * 1020 VCL_call HIT ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 7.467 *** c1 connected fd 67 from 127.0.0.1 62408 to 127.0.0.1:57566 **** dT 7.468 ** 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.471 ** c1 === rxresp **** dT 7.472 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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 **** c1 http[ 9] |Connection: close **** dT 7.473 **** 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.474 ** top === varnish v1 -expect vcl_fail == 9 **** dT 7.475 ** 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.477 **** 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.478 ** l1022 === expect * 1022 VCL_call "DELIVER" ** l1022 === expect 0 1022 VCL_Error "Forced failure" ** l1022 === expect 0 1022 VCL_return "fail" **** dT 7.479 ** top === client c1 { **** dT 7.480 ** c1 Starting client ** c1 Waiting for client **** l1022 begin| *** l1022 test | expect * 1022 VCL_call DELIVER ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 7.481 *** c1 connected fd 72 from 127.0.0.1 47009 to 127.0.0.1:57566 ** c1 === txreq -url /hit -hdr "foo: deliver" **** dT 7.482 **** c1 txreq|GET /hit HTTP/1.1\r **** c1 txreq|foo: deliver\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r **** dT 7.485 ** c1 === rxresp **** dT 7.486 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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 **** dT 7.487 **** c1 http[ 8] |Content-Length: 251 **** c1 http[ 9] |Connection: close **** c1 c-l| **** c1 c-l| **** c1 c-l| **** c1 c-l|VCL failed
**** c1 c-l|XID: 1022
**** c1 c-l|Varnish cache server
**** c1 c-l| **** c1 c-l| **** c1 bodylen = 251 ** c1 === expect resp.status == 503 **** c1 EXPECT resp.status (503) == "503" match ** c1 === expect resp.reason == "VCL failed" **** c1 EXPECT resp.reason (VCL failed) == "VCL failed" match *** c1 closing fd 72 ** c1 Ending **** dT 7.489 ** top === varnish v1 -expect vcl_fail == 10 ** v1 as expected: vcl_fail (10) == 10 (10) ** top === varnish v1 -expect sc_vcl_failure == 10 **** dT 7.490 ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1001 -wait ** l1001 Waiting for logexp ** top === logexpect l1003 -wait ** l1003 Waiting for logexp ** top === logexpect l1007 -wait ** l1007 Waiting for logexp **** dT 7.491 **** 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 === logexpect l1009 -wait ** l1009 Waiting for logexp ** top === logexpect l1012 -wait ** l1012 Waiting for logexp **** dT 7.492 ** top === logexpect l1011 -wait ** l1011 Waiting for logexp ** top === logexpect l1014 -wait ** l1014 Waiting for logexp ** top === logexpect l1016 -wait ** l1016 Waiting for logexp ** top === logexpect l1018 -wait ** l1018 Waiting for logexp ** top === logexpect l1020 -wait ** l1020 Waiting for logexp ** top === logexpect l1022 -wait ** l1022 Waiting for logexp **** dT 7.493 ** 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 = "26984"; } **** 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.564 **** v1 vsl| 1019 Begin c sess 0 HTTP/1 **** v1 vsl| 1019 SessOpen c 127.0.0.1 62408 a0 127.0.0.1 57566 1713792444.775402 17 **** v1 vsl| 1019 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1019 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1019 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1019 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1019 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1019 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1019 Link c req 1020 rxreq **** v1 vsl| 1020 Begin c req 1019 rxreq **** v1 vsl| 1020 Timestamp c Start: 1713792444.776074 0.000000 0.000000 **** v1 vsl| 1020 Timestamp c Req: 1713792444.776074 0.000000 0.000000 **** v1 vsl| 1020 VCL_use c vcl1 **** v1 vsl| 1020 ReqStart c 127.0.0.1 62408 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.873442 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: Mon, 22 Apr 2024 13:27: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 **** v1 vsl| 1020 VCL_return c deliver **** v1 vsl| 1020 Timestamp c Process: 1713792444.777025 0.000951 0.000951 **** 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: 1713792444.780760 0.004685 0.003734 **** v1 vsl| 1020 ReqAcct c 64 0 64 194 251 445 **** v1 vsl| 1020 End c **** dT 7.565 **** 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 47009 a0 127.0.0.1 57566 1713792444.789095 21 **** v1 vsl| 1021 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1021 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1021 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1021 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1021 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1021 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1021 Link c req 1022 rxreq **** v1 vsl| 1022 Begin c req 1021 rxreq **** v1 vsl| 1022 Timestamp c Start: 1713792444.789786 0.000000 0.000000 **** v1 vsl| 1022 Timestamp c Req: 1713792444.789786 0.000000 0.000000 **** v1 vsl| 1022 VCL_use c vcl1 **** v1 vsl| 1022 ReqStart c 127.0.0.1 47009 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.859730 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: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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: 1713792444.790865 0.001078 0.001078 **** 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: 1713792444.794892 0.005106 0.004027 **** v1 vsl| 1022 ReqAcct c 68 0 68 194 251 445 **** dT 7.566 **** v1 vsl| 1022 End c **** v1 vsl| 1021 SessClose c VCL_FAILURE 0.006 **** v1 vsl| 1021 End c **** dT 8.187 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_LINGER for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPIDLE for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPCNT for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPINTVL for a0=127.0.0.1:57566 **** dT 9.203 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_LINGER for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPIDLE for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPCNT for a0=127.0.0.1:57566 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPINTVL for a0=127.0.0.1:57566 **** dT 12.868 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl2 **** dT 12.911 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** top === logexpect l1 -v v1 -g raw { **** dT 12.912 ** l1 === expect * 1025 VCL_call "BACKEND_FETCH" **** dT 12.913 ** l1 === expect 0 1025 VCL_Error "Forced failure" ** l1 === expect 0 1025 VCL_return "fail" **** dT 12.914 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1025 VCL_call BACKEND_FETCH **** dT 12.915 ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 12.916 *** c1 connected fd 77 from 127.0.0.1 47010 to 127.0.0.1:57566 ** 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.918 ** c1 === rxresp **** dT 12.922 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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 **** dT 12.923 **** 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.924 ** c1 Ending **** dT 12.925 ** top === varnish v1 -expect vcl_fail == 11 ** v1 as expected: vcl_fail (11) == 11 (11) ** top === varnish v1 -expect sc_vcl_failure == 10 **** dT 12.926 ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1 -wait ** l1 Waiting for logexp **** 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 | **** dT 12.927 ** top === server s1 { ** s1 Waiting for server (3/-1) ** s1 Starting server **** dT 12.928 **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=26984 **** s1 macro def s1_sock=127.0.0.1:26984 * s1 Listen on 127.0.0.1:26984 ** 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 = "26984"; } **** 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.933 ** s1 Started on 127.0.0.1:26984 (1 iterations) **** dT 12.953 **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1713792444.800722/vgc.so 1auto **** v1 vsl| 0 Debug - vcl2: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl2.1713792444.800722/vgc.so" as "vcl2" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1713792450 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 47010 a0 127.0.0.1 57566 1713792450.223835 17 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: Not testing nonhereditary TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1023 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** 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: 1713792450.225639 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: 1713792450.224582 0.000000 0.000000 **** v1 vsl| 1024 Timestamp c Req: 1713792450.224582 0.000000 0.000000 **** v1 vsl| 1024 VCL_use c vcl2 **** v1 vsl| 1024 ReqStart c 127.0.0.1 47010 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) **** dT 12.954 **** 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: 1713792450.226149 0.001567 0.001567 **** v1 vsl| 1024 RespProtocol c HTTP/1.1 **** v1 vsl| 1024 RespStatus c 503 **** v1 vsl| 1024 RespReason c Service Unavailable **** v1 vsl| 1024 RespHeader c Date: Mon, 22 Apr 2024 13:27: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: 1713792450.226722 0.002140 0.000572 **** 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: 1713792450.230287 0.005705 0.003564 **** 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.225 **** v1 vsl| 0 CLI - Rd vcl.load vcl3 vcl_vcl3.1713792450.235904/vgc.so 1auto **** dT 18.230 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl3 **** dT 18.273 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl3' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1028 VCL_call "BACKEND_ERROR" **** dT 18.274 ** l1 === expect 0 1028 VCL_Error "Forced failure" ** l1 === expect 0 1028 VCL_return "fail" **** dT 18.275 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1028 VCL_call BACKEND_ERROR **** dT 18.276 ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 18.278 *** c1 connected fd 78 from 127.0.0.1 47011 to 127.0.0.1:57566 ** 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.281 ** c1 === rxresp *** s1 accepted fd 77 127.0.0.1 47012 **** dT 18.282 ** s1 === rxreq **** dT 18.283 **** 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 **** dT 18.284 **** s1 EXPECT req.url (/backend_error) == "/backend_error" match *** s1 shutting fd 77 **** dT 18.289 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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 **** c1 http[ 2] |Service Unavailable **** c1 http[ 3] |Date: Mon, 22 Apr 2024 13:27: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.290 ** c1 Ending **** dT 18.291 ** s1 Ending **** dT 18.292 **** 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.293 ** v1 as expected: vcl_fail (12) == 12 (12) ** top === varnish v1 -expect sc_vcl_failure == 10 ** v1 as expected: sc_vcl_failure (10) == 10 (10) ** top === logexpect l1 -wait ** l1 Waiting for logexp **** dT 18.294 ** 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=26984 **** s1 macro def s1_sock=127.0.0.1:26984 * s1 Listen on 127.0.0.1:26984 ** 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 = "26984"; } **** 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.302 ** s1 Started on 127.0.0.1:26984 (1 iterations) **** dT 18.327 **** v1 vsl| 0 Debug - vcl3: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl3.1713792450.235904/vgc.so" as "vcl3" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1713792455 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 47011 a0 127.0.0.1 57566 1713792455.584162 22 **** v1 vsl| 1026 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1026 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1026 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1026 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1026 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1026 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** 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: 1713792455.586592 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: 1713792455.586858 0.000266 0.000266 **** v1 vsl| 1028 Timestamp b Connected: 1713792455.587648 0.001056 0.000789 **** v1 vsl| 1028 BackendOpen b 23 s1 127.0.0.1 26984 127.0.0.1 47012 connect **** v1 vsl| 1028 Timestamp b Bereq: 1713792455.588050 0.001457 0.000401 **** 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: 1713792455.591377 0.004785 0.003327 **** v1 vsl| 1028 Timestamp b Error: 1713792455.591425 0.004833 0.000047 **** 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: Mon, 22 Apr 2024 13:27: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: 1713792455.585739 0.000000 0.000000 **** v1 vsl| 1027 Timestamp c Req: 1713792455.585739 0.000000 0.000000 **** dT 18.328 **** v1 vsl| 1027 VCL_use c vcl3 **** v1 vsl| 1027 ReqStart c 127.0.0.1 47011 a0 **** v1 vsl| 1027 ReqMethod c GET **** v1 vsl| 1027 ReqURL c /backend_error **** v1 vsl| 1027 ReqProtocol c HTTP/1.1 **** v1 vsl| 1027 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1027 ReqHeader c User-Agent: c1 **** v1 vsl| 1027 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1027 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1027 VCL_call c RECV **** v1 vsl| 1027 VCL_return c hash **** v1 vsl| 1027 VCL_call c HASH **** v1 vsl| 1027 VCL_return c lookup **** v1 vsl| 1027 VCL_call c MISS **** v1 vsl| 1027 VCL_return c fetch **** v1 vsl| 1027 Link c bereq 1028 fetch **** v1 vsl| 1027 Timestamp c Fetch: 1713792455.592151 0.006412 0.006412 **** 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: Mon, 22 Apr 2024 13:27: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: 1713792455.592517 0.006778 0.000365 **** 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: 1713792455.593881 0.008141 0.001363 **** 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.502 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl4 **** dT 23.545 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl4' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1031 VCL_call "BACKEND_RESPONSE" **** dT 23.546 ** l1 === expect 0 1031 VCL_Error "Forced failure" ** l1 === expect 0 1031 VCL_return "fail" **** dT 23.547 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1031 VCL_call BACKEND_RESPONSE **** dT 23.548 ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 23.549 *** c1 connected fd 78 from 127.0.0.1 47013 to 127.0.0.1:57566 **** dT 23.550 ** 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.553 ** c1 === rxresp *** s1 accepted fd 77 127.0.0.1 47014 ** s1 === rxreq **** dT 23.555 **** 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 **** dT 23.556 **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 22 Apr 2024 13:27:40 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r **** dT 23.560 **** c1 rxhdr|HTTP/1.1 503 Service Unavailable\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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.562 ** c1 Ending **** dT 23.563 *** s1 shutting fd 77 ** s1 Ending **** dT 23.564 **** l1 match| 1031 VCL_call b BACKEND_RESPONSE *** l1 test | expect 0 1031 VCL_Error Forced failure **** l1 match| 1031 VCL_Error b Forced failure *** l1 test | expect 0 1031 VCL_return fail **** l1 match| 1031 VCL_return b fail **** l1 done | ** top === varnish v1 -expect vcl_fail == 13 **** dT 23.565 ** 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 { **** dT 23.566 **** 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 = "26984"; } **** 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.570 **** v1 vsl| 0 CLI - Rd vcl.load vcl4 vcl_vcl4.1713792455.602351/vgc.so 1auto **** v1 vsl| 0 Debug - vcl4: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl4.1713792455.602351/vgc.so" as "vcl4" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1713792460 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 47013 a0 127.0.0.1 57566 1713792460.855985 17 **** v1 vsl| 1029 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1029 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1029 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1029 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1029 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1029 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** 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: 1713792460.858356 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 **** dT 23.571 **** v1 vsl| 1031 VCL_call b BACKEND_FETCH **** v1 vsl| 1031 VCL_return b fetch **** v1 vsl| 1031 Timestamp b Fetch: 1713792460.858590 0.000233 0.000233 **** v1 vsl| 1031 Timestamp b Connected: 1713792460.859277 0.000921 0.000687 **** v1 vsl| 1031 BackendOpen b 23 s1 127.0.0.1 26984 127.0.0.1 47014 connect **** v1 vsl| 1031 Timestamp b Bereq: 1713792460.859635 0.001278 0.000357 **** 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: Mon, 22 Apr 2024 13:27:40 GMT **** v1 vsl| 1031 BerespHeader b Server: s1 **** v1 vsl| 1031 BerespHeader b Content-Length: 0 **** v1 vsl| 1031 Timestamp b Beresp: 1713792460.863157 0.004800 0.003522 **** v1 vsl| 1031 TTL b RFC 120 10 0 1713792461 1713792461 1713792460 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: 1713792460.857479 0.000000 0.000000 **** v1 vsl| 1030 Timestamp c Req: 1713792460.857479 0.000000 0.000000 **** v1 vsl| 1030 VCL_use c vcl4 **** v1 vsl| 1030 ReqStart c 127.0.0.1 47013 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: 1713792460.863995 0.006516 0.006516 **** 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: Mon, 22 Apr 2024 13:27: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: 1713792460.864369 0.006890 0.000373 **** 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: 1713792460.867965 0.010485 0.003595 **** 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.822 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl5 **** dT 28.865 **** v1 vsl| 0 CLI - Rd vcl.load vcl5 vcl_vcl5.1713792460.873456/vgc.so 1auto **** v1 vsl| 0 Debug - vcl5: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl5.1713792460.873456/vgc.so" as "vcl5" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1713792466 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl5 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 28.866 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl5' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1033 VCL_call "RECV" ** l1 === expect 0 1033 VCL_Error "Forced failure" ** l1 === expect 0 1033 VCL_return "fail" **** dT 28.867 ** top === client c1 { **** dT 28.868 ** c1 Starting client ** c1 Waiting for client **** l1 begin| *** l1 test | expect * 1033 VCL_call RECV ** c1 Started on 127.0.0.1:57566 (1 iterations) *** c1 Connect to 127.0.0.1:57566 **** dT 28.870 *** c1 connected fd 77 from 127.0.0.1 47015 to 127.0.0.1:57566 ** c1 === txreq **** 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.872 ** c1 === rxresp **** dT 28.874 **** c1 rxhdr|HTTP/1.1 503 VCL failed\r **** c1 rxhdr|Date: Mon, 22 Apr 2024 13:27: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: Mon, 22 Apr 2024 13:27: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 **** dT 28.875 ** 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.876 ** top === varnish v1 -expect vcl_fail == 14 **** dT 28.877 ** 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.879 **** l1 match| 1033 VCL_call c RECV *** l1 test | expect 0 1033 VCL_Error Forced failure **** l1 match| 1033 VCL_Error c Forced failure *** l1 test | expect 0 1033 VCL_return fail **** l1 match| 1033 VCL_return c fail **** l1 done | **** dT 28.880 ** 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.966 **** v1 vsl| 1032 Begin c sess 0 HTTP/1 **** v1 vsl| 1032 SessOpen c 127.0.0.1 47015 a0 127.0.0.1 57566 1713792466.176419 22 **** v1 vsl| 1032 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1032 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:57566 **** v1 vsl| 1032 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1032 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:57566 **** v1 vsl| 1032 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:57566 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1032 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:57566 **** v1 vsl| 1032 Link c req 1033 rxreq **** v1 vsl| 1033 Begin c req 1032 rxreq **** v1 vsl| 1033 Timestamp c Start: 1713792466.177572 0.000000 0.000000 **** v1 vsl| 1033 Timestamp c Req: 1713792466.177572 0.000000 0.000000 **** v1 vsl| 1033 VCL_use c vcl5 **** v1 vsl| 1033 ReqStart c 127.0.0.1 47015 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: Mon, 22 Apr 2024 13:27: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: 1713792466.178205 0.000632 0.000632 **** 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: 1713792466.178931 0.001358 0.000726 **** 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 34.017 *** 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} { **** dT 34.018 **** 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 34.060 **** v1 vsl| 0 CLI - Rd vcl.load vcl6 vcl_vcl6.1713792466.187679/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 1713792471 1.0 **** dT 39.192 *** v1 CLI RX 300 **** dT 39.193 **** 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.199 **** v1 vsl| 0 CLI - Rd vcl.load vcl7 vcl_vcl7.1713792471.325447/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 1713792476 1.0 **** dT 44.420 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl8 **** dT 44.463 *** 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 = "26984"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 44.502 **** v1 vsl| 0 CLI - Rd vcl.load vcl8 vcl_vcl8.1713792476.501071/vgc.so 1auto **** v1 vsl| 0 Debug - vcl8: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl8.1713792476.501071/vgc.so" as "vcl8" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1713792481 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl8 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 49.445 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl9 **** dT 49.486 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl9' now active ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 0 CLI "^Rd vcl.state vcl8 0cold" ** l1 === expect 3 0 VCL_Error "^Forced failure" **** dT 49.487 ** l1 === expect 0 0 VCL_Error {^\QVRT_fail() from vcl_fini{} has no e... **** dT 49.488 ** top === varnish v1 -cliok "vcl.discard vcl8" **** v1 CLI TX|vcl.discard vcl8 **** l1 begin| *** l1 test | expect * 0 CLI ^Rd vcl.state vcl8 0cold **** dT 49.510 **** v1 vsl| 0 CLI - Rd vcl.load vcl9 vcl_vcl9.1713792481.770952/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl9.1713792481.770952/vgc.so" as "vcl9" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1713792486 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl9 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 49.532 **** l1 match| 0 CLI - Rd vcl.state vcl8 0cold *** l1 test | expect 3 0 VCL_Error ^Forced failure **** dT 49.535 *** v1 CLI RX 200 ** v1 CLI 200