**** dT 0.000 * top TEST ../../../../bin/varnishtest/tests/v00003.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest **** top extmacro def date(...) **** top extmacro def string(...) **** top extmacro def localhost=127.0.0.1 **** top extmacro def bad_backend=127.0.0.1:38157 **** top extmacro def listen_addr=127.0.0.1:0 **** top extmacro def bad_ip=192.0.2.255 **** top extmacro def topbuild=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub **** top extmacro def topsrc=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/../.. **** top macro def testdir=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests **** top macro def tmpdir=/tmp/vtest.clang/_vtest_tmp/vtc.5328.4e7f3736 **** top macro def vtcid=vtc.5328.4e7f3736 ** top === varnishtest "vcl.state coverage tests" * top VTEST vcl.state coverage tests ** top === server s1 -repeat 20 { ** s1 Starting server **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=44829 **** s1 macro def s1_sock=127.0.0.1:44829 * s1 Listen on 127.0.0.1:44829 ** top === varnish v1 -arg "-p vcl_cooldown=1" \ ** s1 Started on 127.0.0.1:44829 (20 iterations) **** dT 0.003 ** v1 Launch *** v1 CMD: cd ${pwd} && exec varnishd -d -n /tmp/vtest.clang/_vtest_tmp/vtc.5328.4e7f3736/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 33541' -P /tmp/vtest.clang/_vtest_tmp/vtc.5328.4e7f3736/v1/varnishd.pid -p vmod_path=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -p vcl_cooldown=1 -p thread_pool_min=5 -p thread_pool_max=5 *** v1 CMD: cd /tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /tmp/vtest.clang/_vtest_tmp/vtc.5328.4e7f3736/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 33541' -P /tmp/vtest.clang/_vtest_tmp/vtc.5328.4e7f3736/v1/varnishd.pid -p vmod_path=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -p vcl_cooldown=1 -p thread_pool_min=5 -p thread_pool_max=5 *** v1 PID: 5347 **** v1 macro def v1_pid=5347 **** v1 macro def v1_name=/tmp/vtest.clang/_vtest_tmp/vtc.5328.4e7f3736/v1 **** dT 0.016 *** v1 debug|Debug: Version: varnish-trunk revision 7e9b65c62cc14ca13576de8bee530e748bcf7836 *** v1 debug|Debug: Platform: Linux,4.19.0-17-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit *** v1 debug|200 316 *** v1 debug|----------------------------- *** v1 debug|Varnish Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|Linux,4.19.0-17-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit *** v1 debug|varnish-trunk revision 7e9b65c62cc14ca13576de8bee530e748bcf7836 *** v1 debug| *** v1 debug|Type 'help' for command list. *** v1 debug|Type 'quit' to close CLI session. *** v1 debug|Type 'start' to launch worker process. *** v1 debug| **** dT 0.115 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 7 *** v1 CLI RX 107 **** v1 CLI RX|azukjuxeqwbhshwbcpoietncvamxfgmu **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** v1 CLI TX|auth 357aa3ea8d461c50c9debdc8f09769874a4d73bd14271b7dbc91f3bdcc50a6cd **** dT 0.116 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Varnish Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Linux,4.19.0-17-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|varnish-trunk revision 7e9b65c62cc14ca13576de8bee530e748bcf7836 **** v1 CLI RX| **** v1 CLI RX|Type 'help' for command list. **** v1 CLI RX|Type 'quit' to close CLI session. **** v1 CLI RX|Type 'start' to launch worker process. **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tbackend default { **** v1 CLI TX|\t\t.host = "127.0.0.1"; **** v1 CLI TX|\t\t.port = "44829"; **** v1 CLI TX|\t\t.probe = { .interval = 1s; } **** v1 CLI TX|\t} **** v1 CLI TX|\tbackend noprobe { **** v1 CLI TX|\t\t.host = "127.0.0.1"; **** v1 CLI TX|\t\t.port = "44829"; **** v1 CLI TX|\t} **** v1 CLI TX|\tsub vcl_backend_fetch { **** v1 CLI TX|\t\tset bereq.backend = noprobe; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.222 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.325 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.429 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.530 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.569 *** v1 CLI RX 200 **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 0.616 *** v1 debug|Debug: Child (5367) Started **** dT 0.643 *** v1 debug|Child launched OK **** dT 0.644 *** s1 accepted fd 5 127.0.0.1 60186 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:07 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) *** v1 CLI RX 200 *** v1 wait-running **** v1 CLI TX|status *** v1 debug|Info: Child (5367) said Child starts **** dT 0.689 *** v1 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address **** dT 0.734 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1762776667.297219/vgc.so 1auto **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_WARM **** v1 vsl| 0 Backend_health - default Still sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1762776667.297219/vgc.so" as "vcl1" **** v1 vsl| 0 CLI - Rd vcl.use "vcl1" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd start **** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:36905 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:36905 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:36905 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:36905 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:36905 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:36905 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:36905 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:36905 **** v1 vsl| 0 CLI - Wr 200 0 *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 36905 **** v1 CLI TX|debug.xid 1000 **** dT 0.777 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address **** dT 0.821 *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 36905 ** v1 Listen on 127.0.0.1 36905 **** v1 macro def v1_addr=127.0.0.1 **** v1 macro def v1_port=36905 **** v1 macro def v1_sock=127.0.0.1:36905 **** v1 macro def v1_a0_addr=127.0.0.1 **** v1 macro def v1_a0_port=36905 **** v1 macro def v1_a0_sock=127.0.0.1:36905 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 **** dT 0.823 ** v1 as expected: VBE.vcl1.default.happy (3) >= 0 (0) ** top === varnish v1 -expect VBE.vcl1.noprobe.happy > 9223372036854775... ** v1 as expected: VBE.vcl1.noprobe.happy (18446744073709551615) > 9223372036854775808 (9223372036854775808) ** top === varnish v1 -expect !VBE.vcl2.default.happy **** dT 0.836 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 36905 **** v1 vsl| 0 CLI - Rd debug.xid 1000 **** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 36905 **** dT 0.844 *** s1 shutting fd 5 (server run) **** dT 0.942 **** v1 vsl| 0 Backend_health - default Went healthy 4---X-RH 3 3 8 0.200703 0.066901 "HTTP/1.1 200 OK" **** dT 1.845 *** s1 accepted fd 5 127.0.0.1 60198 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:09 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 2.045 *** s1 shutting fd 5 (server run) **** dT 2.067 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 4 3 8 0.200648 0.100338 "HTTP/1.1 200 OK" **** dT 3.054 *** s1 accepted fd 5 127.0.0.1 60206 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:10 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 3.258 *** s1 shutting fd 5 (server run) **** dT 3.288 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 5 3 8 0.204225 0.126309 "HTTP/1.1 200 OK" **** dT 3.689 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776670 1.0 **** dT 4.259 *** s1 accepted fd 5 127.0.0.1 60214 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:11 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 4.461 *** s1 shutting fd 5 (server run) **** dT 4.500 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 6 3 8 0.202491 0.145355 "HTTP/1.1 200 OK" **** dT 5.463 *** s1 accepted fd 5 127.0.0.1 60234 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:12 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 5.663 *** s1 shutting fd 5 (server run) **** dT 5.728 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 7 3 8 0.201026 0.159273 "HTTP/1.1 200 OK" **** dT 5.929 ** v1 not found (as expected): VBE.vcl2.default.happy ** top === varnish v1 -cliok "backend.list -p *.*" **** v1 CLI TX|backend.list -p *.* **** dT 5.973 *** v1 CLI RX 200 **** v1 CLI RX|Backend name Admin Probe Health Last change **** v1 CLI RX|vcl1.default probe 7/8 healthy Mon, 10 Nov 2025 12:11:07 GMT **** v1 CLI RX| Current states good: 7 threshold: 3 window: 8 **** v1 CLI RX| Average response time of good probes: 0.159273 **** v1 CLI RX| Oldest ================================================== Newest **** v1 CLI RX| -----------------------------------------------------------44444 Good IPv4 **** v1 CLI RX| -----------------------------------------------------------XXXXX Good Xmit **** v1 CLI RX| -----------------------------------------------------------RRRRR Good Recv **** v1 CLI RX| ---------------------------------------------------------HHHHHHH Happy **** v1 CLI RX| **** v1 CLI RX|vcl1.noprobe healthy 0/0 healthy Mon, 10 Nov 2025 12:11:07 GMT **** v1 CLI RX|vcl1.dir_warmcold healthy 0/0 healthy Mon, 10 Nov 2025 12:11:07 GMT ** v1 CLI 200 ** top === varnish v1 -vcl { **** v1 CLI TX|vcl.inline vcl2 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\tbackend default { **** v1 CLI TX|\t\t.host = "127.0.0.1"; **** v1 CLI TX|\t\t.port = "44829"; **** v1 CLI TX|\t\t.probe = { .interval = 1s; } **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 6.029 **** v1 vsl| 0 CLI - Rd backend.list -p *.* **** v1 vsl| 0 CLI - Wr 200 766 Backend name Admin Probe Health Last change vcl1.default probe 7/8 healthy Mon, 10 Nov 2025 12:11:07 GMT Current states good: 7 threshold: 3 window: 8 Average response time of good probes: 0.159273 Old **** dT 6.423 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl2 *** s1 accepted fd 5 127.0.0.1 60244 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:13 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** top === delay .4 *** top delaying 0.4 second(s) **** dT 6.434 **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1762776673.154727/vgc.so 1auto **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 Backend_health - default Still sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl2.1762776673.154727/vgc.so" as "vcl2" **** v1 vsl| 0 CLI - Rd vcl.use vcl2 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 6.623 *** s1 shutting fd 5 (server run) **** dT 6.635 **** v1 vsl| 0 Backend_health - default Went healthy 4---X-RH 3 3 8 0.200576 0.066859 "HTTP/1.1 200 OK" **** dT 6.663 *** s1 accepted fd 5 127.0.0.1 60250 **** dT 6.664 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:13 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 6.735 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776673 1.0 **** dT 6.824 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 ** v1 as expected: VBE.vcl1.default.happy (127) >= 0 (0) ** top === varnish v1 -expect VBE.vcl2.default.happy >= 0 ** v1 as expected: VBE.vcl2.default.happy (7) >= 0 (0) ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 0 Debug "vcl1: VCL_EVENT_COLD" **** dT 6.825 ** l1 === expect * 0 Debug "vcl1: VCL_EVENT_WARM" ** top === varnish v1 -cliok "vcl.state vcl1 cold" **** v1 CLI TX|vcl.state vcl1 cold **** l1 begin| *** l1 test | expect * 0 Debug vcl1: VCL_EVENT_COLD **** dT 6.864 *** s1 shutting fd 5 (server run) **** dT 6.867 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliexpect "available *cold *cold *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list **** dT 6.869 **** l1 match| 0 Debug - vcl1: VCL_EVENT_COLD *** l1 test | expect * 0 Debug vcl1: VCL_EVENT_WARM **** dT 6.920 *** v1 CLI RX 200 **** v1 CLI RX|available cold cold 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === delay .4 *** top delaying 0.4 second(s) **** dT 6.935 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 8 3 8 0.200634 0.169613 "HTTP/1.1 200 OK" **** v1 vsl| 0 CLI - Rd vcl.state vcl1 0cold **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_COLD **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available cold cold 0 vcl1 active auto warm 0 vcl2 **** dT 7.321 ** top === varnish v1 -expect !VBE.vcl1.default.happy **** dT 7.623 *** s1 accepted fd 5 127.0.0.1 60268 ** s1 === rxreq **** dT 7.624 **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:14 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 7.824 *** s1 shutting fd 5 (server run) **** dT 7.850 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 4 3 8 0.200651 0.100307 "HTTP/1.1 200 OK" **** dT 8.828 *** s1 accepted fd 5 127.0.0.1 60280 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:16 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 9.029 *** s1 shutting fd 5 (server run) **** dT 9.053 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 5 3 8 0.201987 0.125727 "HTTP/1.1 200 OK" **** dT 9.673 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776676 1.0 **** dT 10.030 *** s1 accepted fd 5 127.0.0.1 60298 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:17 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 10.230 *** s1 shutting fd 5 (server run) **** dT 10.274 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 6 3 8 0.200628 0.144452 "HTTP/1.1 200 OK" **** dT 11.231 *** s1 accepted fd 5 127.0.0.1 60302 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:18 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 11.431 *** s1 shutting fd 5 (server run) **** dT 11.488 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 7 3 8 0.200534 0.158473 "HTTP/1.1 200 OK" **** dT 12.413 ** v1 not found (as expected): VBE.vcl1.default.happy ** top === varnish v1 -clierr 300 "vcl.use vcl1" **** v1 CLI TX|vcl.use vcl1 **** dT 12.433 *** s1 accepted fd 5 127.0.0.1 60310 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:19 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 12.468 *** v1 CLI RX 300 **** v1 CLI RX|VCL 'vcl1' is cold - set to auto or warm first ** v1 CLI 300 ** top === varnish v1 -cliok "vcl.state vcl1 warm" **** v1 CLI TX|vcl.state vcl1 warm **** dT 12.523 **** l1 match| 0 Debug - vcl1: VCL_EVENT_WARM **** l1 done | *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.use vcl1" **** v1 CLI TX|vcl.use vcl1 **** dT 12.535 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 1warm **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_WARM **** v1 vsl| 0 Backend_health - default Still sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 0 **** dT 12.585 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 CLI 200 ** top === varnish v1 -cliexpect "active *warm *warm *[0-9]+ *vcl1\\s+a... **** v1 CLI TX|vcl.list **** dT 12.641 *** s1 shutting fd 5 (server run) *** s1 accepted fd 5 127.0.0.1 60312 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:19 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** v1 vsl| 0 CLI - Rd vcl.use vcl1 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 12.645 *** v1 CLI RX 200 **** v1 CLI RX|active warm warm 0 vcl1 **** v1 CLI RX|available auto warm 0 vcl2 ** v1 CLI 200 ** top === delay .4 *** top delaying 0.4 second(s) **** dT 12.746 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 active warm warm 0 vcl1 available auto warm 0 vcl2 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 8 3 8 0.208235 0.170913 "HTTP/1.1 200 OK" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776679 1.0 **** dT 12.854 *** s1 shutting fd 5 (server run) **** dT 12.954 **** v1 vsl| 0 Backend_health - default Went healthy 4---X-RH 3 3 8 0.329541 0.109847 "HTTP/1.1 200 OK" **** dT 13.049 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 ** v1 as expected: VBE.vcl1.default.happy (7) >= 0 (0) ** top === varnish v1 -expect VBE.vcl2.default.happy >= 0 ** v1 as expected: VBE.vcl2.default.happy (255) >= 0 (0) ** top === logexpect l1 -wait ** l1 Waiting for logexp ** top === delay 4 *** top delaying 4 second(s) **** dT 13.653 *** s1 accepted fd 5 127.0.0.1 60316 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:20 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 13.789 **** v1 vsl| 0 CLI - Rd vcl.state vcl2 0auto **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 0 **** dT 13.853 *** s1 shutting fd 5 (server run) **** dT 13.865 *** s1 accepted fd 5 127.0.0.1 60320 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:21 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 13.891 **** v1 vsl| 0 Backend_health - default Still sick ------RH 2 3 8 0.204348 0.068116 "" **** dT 14.069 *** s1 shutting fd 5 (server run) **** dT 14.112 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 4 3 8 0.206348 0.133972 "HTTP/1.1 200 OK" **** dT 15.069 *** s1 accepted fd 5 127.0.0.1 60322 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:22 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 15.278 *** s1 shutting fd 5 (server run) **** dT 15.355 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 5 3 8 0.209347 0.152816 "HTTP/1.1 200 OK" **** dT 15.665 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776682 1.0 **** dT 16.285 *** s1 accepted fd 5 127.0.0.1 60334 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:23 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 16.487 *** s1 shutting fd 5 (server run) **** dT 16.591 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 6 3 8 0.209713 0.167040 "HTTP/1.1 200 OK" **** dT 17.049 ** top === varnish v1 -cliexpect "active *warm *warm *[0-9]+ *vcl1\\s+a... **** dT 17.050 **** v1 CLI TX|vcl.list **** dT 17.103 *** v1 CLI RX 200 **** v1 CLI RX|active warm warm 0 vcl1 **** v1 CLI RX|available auto cold 0 vcl2 ** v1 CLI 200 ** top === varnish v1 -expect !VBE.vcl2.default.happy **** dT 17.113 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 active warm warm 0 vcl1 available auto cold 0 vcl2 **** dT 17.492 *** s1 accepted fd 5 127.0.0.1 60340 ** s1 === rxreq **** dT 17.493 **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:24 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 17.701 *** s1 shutting fd 5 (server run) **** dT 17.727 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 7 3 8 0.209328 0.177612 "HTTP/1.1 200 OK" **** dT 18.706 *** s1 accepted fd 5 127.0.0.1 60350 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:25 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 18.760 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776685 1.0 **** dT 18.916 *** s1 shutting fd 5 (server run) **** dT 18.961 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 8 3 8 0.218107 0.187736 "HTTP/1.1 200 OK" **** dT 19.931 *** s1 accepted fd 5 127.0.0.1 60364 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 54 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 10 Nov 2025 12:11:27 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 20.133 *** s1 shutting fd 5 (server run) ** s1 Ending **** dT 20.191 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 8 3 8 0.202332 0.191385 "HTTP/1.1 200 OK" **** dT 21.725 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776688 1.0 **** dT 22.241 ** v1 not found (as expected): VBE.vcl2.default.happy ** top === varnish v1 -cliok "vcl.use vcl2" **** v1 CLI TX|vcl.use vcl2 **** dT 22.286 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** v1 CLI 200 ** top === varnish v1 -cliexpect "available *warm *warm *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list **** dT 22.335 *** v1 CLI RX 200 **** v1 CLI RX|available warm warm 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === delay 4 *** top delaying 4 second(s) **** dT 22.341 **** v1 vsl| 0 CLI - Rd vcl.state vcl2 1auto **** v1 vsl| 0 Backend_health - default Still sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.use vcl2 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available warm warm 0 vcl1 active auto warm 0 vcl2 **** dT 23.249 **** v1 vsl| 0 Backend_health - default Still healthy 4---Xr-- 7 3 8 0.000000 0.191385 "Poll error 110 (Connection timed out)" **** dT 24.296 **** v1 vsl| 0 Backend_health - default Still sick 4---Xr-- 2 3 8 0.000000 0.000000 "Poll error 110 (Connection timed out)" **** dT 24.704 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776691 1.0 **** dT 26.242 **** v1 vsl| 0 Backend_health - default Still healthy 4---Xr-- 6 3 8 0.000000 0.191385 "Poll error 110 (Connection timed out)" **** dT 26.337 ** top === varnish v1 -cliexpect "available *warm *warm *[0-9]+ *vcl1\\... **** dT 26.338 **** v1 CLI TX|vcl.list **** dT 26.413 *** v1 CLI RX 200 **** v1 CLI RX|available warm warm 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 ** v1 as expected: VBE.vcl1.default.happy (2044) >= 0 (0) ** top === varnish v1 -expect VBE.vcl2.default.happy >= 0 ** v1 as expected: VBE.vcl2.default.happy (6) >= 0 (0) ** top === varnish v1 -clierr 300 "vcl.state vcl2 cold" **** v1 CLI TX|vcl.state vcl2 cold **** dT 26.450 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available warm warm 0 vcl1 active auto warm 0 vcl2 **** dT 26.462 *** v1 CLI RX 300 **** v1 CLI RX|Cannot set the active VCL cold. ** v1 CLI 300 ** top === varnish v1 -cliok "vcl.state vcl1 auto" **** v1 CLI TX|vcl.state vcl1 auto **** dT 26.517 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliexpect "available *auto *warm *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list **** dT 26.554 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 1auto **** v1 vsl| 0 CLI - Wr 200 0 **** dT 26.561 *** v1 CLI RX 200 **** v1 CLI RX|available auto warm 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === delay .4 *** top delaying 0.4 second(s) **** dT 26.654 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available auto warm 0 vcl1 active auto warm 0 vcl2 **** dT 26.966 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 ** v1 as expected: VBE.vcl1.default.happy (2044) >= 0 (0) ** top === delay 4 *** top delaying 4 second(s) **** dT 27.395 **** v1 vsl| 0 Backend_health - default Still sick 4---Xr-- 2 3 8 0.000000 0.000000 "Poll error 110 (Connection timed out)" **** dT 27.701 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776694 1.0 **** dT 27.808 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 0auto **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_COLD **** v1 vsl| 0 CLI - Wr 200 0 **** dT 29.244 **** v1 vsl| 0 Backend_health - default Still sick -----r-H 2 3 8 0.000000 0.000000 "Poll error 110 (Connection timed out)" **** dT 30.401 **** v1 vsl| 0 Backend_health - default Still sick 4---Xr-- 2 3 8 0.000000 0.000000 "Poll error 110 (Connection timed out)" **** dT 30.709 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776697 1.0 **** dT 30.969 ** top === varnish v1 -cliexpect "available *auto *cold *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list **** dT 31.014 *** v1 CLI RX 200 **** v1 CLI RX|available auto cold 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === varnish v1 -expect !VBE.vcl1.default.happy **** dT 31.020 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available auto cold 0 vcl1 active auto warm 0 vcl2 **** dT 33.420 **** v1 vsl| 0 Backend_health - default Still sick 4---Xr-- 2 3 8 0.000000 0.000000 "Poll error 110 (Connection timed out)" **** dT 33.726 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1762776700 1.0 **** dT 36.142 ** v1 not found (as expected): VBE.vcl1.default.happy ** top === varnish v1 -cliok "param.set max_esi_depth 42" **** v1 CLI TX|param.set max_esi_depth 42 **** dT 36.192 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -clierr 300 "vcl.state vcl1 warm" **** v1 CLI TX|vcl.state vcl1 warm **** dT 36.237 *** v1 CLI RX 300 **** v1 CLI RX|Failed **** v1 CLI RX|Message: **** v1 CLI RX|\tmax_esi_depth is not the answer. ** v1 CLI 300 ** top === varnish v1 -cliexpect "available *auto *cold *[0-9]+ *vcl1\\... **** dT 36.238 **** v1 CLI TX|vcl.list **** dT 36.282 *** v1 CLI RX 200 **** v1 CLI RX|available auto cold 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === varnish v1 -cliok stop **** v1 CLI TX|stop **** dT 36.292 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 1warm **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 300 71 Failed Message: max_esi_depth is not the answer. **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available auto cold 0 vcl1 active auto warm 0 vcl2 **** dT 36.329 *** v1 debug|Debug: Stopping Child **** dT 36.393 **** v1 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 36.436 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.state vcl1 warm" **** v1 CLI TX|vcl.state vcl1 warm *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.list" **** v1 CLI TX|vcl.list *** v1 debug|Info: Child (5367) said Child dies *** v1 debug|Info: Child (5367) ended *** v1 debug|Debug: Child cleanup complete **** dT 36.479 *** v1 CLI RX 200 **** dT 36.480 **** v1 CLI RX|available warm warm - vcl1 **** v1 CLI RX|active auto warm - vcl2 ** v1 CLI 200 ** top === varnish v1 -clierr 300 start **** v1 CLI TX|start **** dT 36.553 *** v1 debug|Debug: Child (9543) Started **** dT 36.582 *** v1 debug|Child launched OK **** dT 36.586 *** v1 debug|Error: Child (9543) Pushing vcls failed: *** v1 debug|VCL "vcl1" Failed warmup *** v1 debug|Message: *** v1 debug|\tmax_esi_depth is not the answer. *** v1 debug|Debug: Stopping Child *** v1 debug|Info: Child (9543) said Child starts # top TEST ../../../../bin/varnishtest/tests/v00003.vtc TIMED OUT (kill -9) # top TEST ../../../../bin/varnishtest/tests/v00003.vtc FAILED (60.101) signal=9 FAIL tests/v00003.vtc (exit status: 2)