**** 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=/sysroot/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:39637 **** 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=/sysroot/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests **** top macro def tmpdir=/tmp/vtest.clang/_vtest_tmp/vtc.21880.6f946ce8 **** top macro def vtcid=vtc.21880.6f946ce8 ** 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=42151 **** s1 macro def s1_sock=127.0.0.1:42151 * s1 Listen on 127.0.0.1:42151 ** top === varnish v1 -arg "-p vcl_cooldown=1" \ **** dT 0.003 ** s1 Started on 127.0.0.1:42151 (20 iterations) **** dT 0.029 ** v1 Launch *** v1 CMD: cd ${pwd} && exec varnishd -d -n /tmp/vtest.clang/_vtest_tmp/vtc.21880.6f946ce8/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 40329' -P /tmp/vtest.clang/_vtest_tmp/vtc.21880.6f946ce8/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 /sysroot/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /tmp/vtest.clang/_vtest_tmp/vtc.21880.6f946ce8/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 40329' -P /tmp/vtest.clang/_vtest_tmp/vtc.21880.6f946ce8/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: 21936 **** v1 macro def v1_pid=21936 **** v1 macro def v1_name=/tmp/vtest.clang/_vtest_tmp/vtc.21880.6f946ce8/v1 **** dT 0.119 *** v1 debug|Debug: Version: varnish-trunk revision d19ee66d49787248367b7751beb35bb96adaf9ab *** v1 debug|Debug: Platform: Linux,5.3.11-100.fc29.x86_64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit *** v1 debug|200 323 *** v1 debug|----------------------------- *** v1 debug|Varnish Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|Linux,5.3.11-100.fc29.x86_64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit *** v1 debug|varnish-trunk revision d19ee66d49787248367b7751beb35bb96adaf9ab *** 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.215 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 7 *** v1 CLI RX 107 **** v1 CLI RX|agkbkqlsbrarbgntmgmunuixtbamgusv **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** dT 0.216 **** v1 CLI TX|auth 67d0ea5085ecbf2654cee0b5b18859bc646431327f81e9fd1f75917eca4e3f55 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Varnish Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Linux,5.3.11-100.fc29.x86_64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|varnish-trunk revision d19ee66d49787248367b7751beb35bb96adaf9ab **** 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 = "42151"; **** v1 CLI TX|\t\t.probe = { .interval = 1s; } **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.324 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.428 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.528 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.629 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.731 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.833 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.934 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.035 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.136 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.137 *** v1 CLI RX 200 **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 **** dT 1.138 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 1.146 *** v1 debug|Debug: Child (22146) Started **** dT 1.202 *** v1 debug|Child launched OK **** dT 1.206 *** s1 accepted fd 5 127.0.0.1 39672 ** 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, 18 Sep 2023 15:43:08 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 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address **** dT 1.209 *** v1 debug|Info: Child (22146) said Child starts *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 43351 **** v1 CLI TX|debug.xid 1000 **** dT 1.212 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address **** dT 1.215 *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 43351 ** v1 Listen on 127.0.0.1 43351 **** v1 macro def v1_addr=127.0.0.1 **** v1 macro def v1_port=43351 **** v1 macro def v1_sock=127.0.0.1:43351 **** v1 macro def v1_a0_addr=127.0.0.1 **** v1 macro def v1_a0_port=43351 **** v1 macro def v1_a0_sock=127.0.0.1:43351 **** dT 1.237 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1695051787.548317/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.1695051787.548317/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:43351 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:43351 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:43351 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:43351 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:43351 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:43351 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:43351 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:43351 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 43351 **** 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 43351 **** dT 1.315 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 **** dT 1.317 ** v1 as expected: VBE.vcl1.default.happy (3) >= 0 (0) ** top === varnish v1 -expect !VBE.vcl2.default.happy **** dT 1.408 *** s1 shutting fd 5 **** dT 1.448 **** v1 vsl| 0 Backend_health - default Went healthy 4---X-RH 3 3 8 0.206934 0.068978 "HTTP/1.1 200 OK" **** dT 2.413 *** s1 accepted fd 5 127.0.0.1 39682 ** 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, 18 Sep 2023 15:43: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.614 *** s1 shutting fd 5 **** dT 2.668 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 4 3 8 0.203127 0.102515 "HTTP/1.1 200 OK" **** dT 3.616 *** s1 accepted fd 5 127.0.0.1 39692 ** s1 === rxreq **** dT 3.617 **** 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, 18 Sep 2023 15:43: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.817 *** s1 shutting fd 5 **** dT 3.890 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 5 3 8 0.201426 0.127243 "HTTP/1.1 200 OK" **** dT 4.296 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051791 1.0 **** dT 4.820 *** s1 accepted fd 5 127.0.0.1 39714 ** 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, 18 Sep 2023 15:43: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.021 *** s1 shutting fd 5 **** dT 5.102 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 6 3 8 0.203071 0.146200 "HTTP/1.1 200 OK" **** dT 6.023 *** s1 accepted fd 5 127.0.0.1 39738 ** 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, 18 Sep 2023 15:43: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.224 *** s1 shutting fd 5 **** dT 6.236 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 7 3 8 0.202162 0.160190 "HTTP/1.1 200 OK" **** dT 6.428 ** v1 not found (as expected): VBE.vcl2.default.happy ** top === varnish v1 -cliok "backend.list -p *.*" **** v1 CLI TX|backend.list -p *.* **** dT 6.433 *** v1 CLI RX 200 **** v1 CLI RX|Backend name Admin Probe Health Last change **** v1 CLI RX|vcl1.default probe 7/8 healthy Mon, 18 Sep 2023 15:43:08 GMT **** v1 CLI RX| Current states good: 7 threshold: 3 window: 8 **** v1 CLI RX| Average response time of good probes: 0.160190 **** 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.dir_warmcold healthy 0/0 healthy Mon, 18 Sep 2023 15:43:08 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 = "42151"; **** v1 CLI TX|\t\t.probe = { .interval = 1s; } **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 6.437 **** v1 vsl| 0 CLI - Rd backend.list -p *.* **** v1 vsl| 0 CLI - Wr 200 685 Backend name Admin Probe Health Last change vcl1.default probe 7/8 healthy Mon, 18 Sep 2023 15:43:08 GMT Current states good: 7 threshold: 3 window: 8 Average response time of good probes: 0.160190 Oldes **** dT 7.129 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl2 *** s1 accepted fd 5 127.0.0.1 39760 ** 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 **** dT 7.130 **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 18 Sep 2023 15:43: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) *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** top === delay .4 *** top delaying 0.4 second(s) **** dT 7.151 **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1695051793.762998/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.1695051793.762998/vgc.so" as "vcl2" **** v1 vsl| 0 CLI - Rd vcl.use vcl2 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 7.251 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051794 1.0 **** dT 7.335 *** s1 shutting fd 5 *** s1 accepted fd 5 127.0.0.1 39762 **** dT 7.336 ** 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, 18 Sep 2023 15:43: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.351 **** v1 vsl| 0 Backend_health - default Went healthy 4---X-RH 3 3 8 0.206846 0.068949 "HTTP/1.1 200 OK" **** dT 7.538 ** 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 **** dT 7.539 ** 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" ** l1 === expect * 0 Debug "vcl1: VCL_EVENT_WARM" ** top === varnish v1 -cliok "vcl.state vcl1 cold" **** v1 CLI TX|vcl.state vcl1 cold *** s1 shutting fd 5 **** dT 7.543 **** l1 begin| *** l1 test | expect * 0 Debug vcl1: VCL_EVENT_COLD **** dT 7.558 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 8 3 8 0.316197 0.199192 "HTTP/1.1 200 OK" **** dT 7.598 **** l1 match| 0 Debug - vcl1: VCL_EVENT_COLD *** l1 test | expect * 0 Debug vcl1: VCL_EVENT_WARM **** dT 7.600 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliexpect "available *cold *cold *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list **** dT 7.612 *** 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 7.662 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 0cold **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_COLD **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 78 available cold cold 0 vcl1 active auto warm 0 vcl2 **** dT 8.013 ** top === varnish v1 -expect !VBE.vcl1.default.happy **** dT 8.337 *** s1 accepted fd 5 127.0.0.1 39774 ** 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, 18 Sep 2023 15:43:15 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 8.539 *** s1 shutting fd 5 **** dT 8.574 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 4 3 8 0.202252 0.102274 "HTTP/1.1 200 OK" **** dT 9.543 *** s1 accepted fd 5 127.0.0.1 39778 ** 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, 18 Sep 2023 15:43: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.743 *** s1 shutting fd 5 **** dT 9.793 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 5 3 8 0.201786 0.127152 "HTTP/1.1 200 OK" **** dT 10.311 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051797 1.0 **** dT 10.747 *** s1 accepted fd 5 127.0.0.1 39782 ** 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, 18 Sep 2023 15:43: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 10.947 *** s1 shutting fd 5 **** dT 11.019 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 6 3 8 0.200807 0.145566 "HTTP/1.1 200 OK" **** dT 11.951 *** s1 accepted fd 5 127.0.0.1 39790 ** 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, 18 Sep 2023 15:43: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.153 *** s1 shutting fd 5 **** dT 12.242 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 7 3 8 0.203124 0.159955 "HTTP/1.1 200 OK" **** dT 13.120 ** v1 not found (as expected): VBE.vcl1.default.happy ** top === varnish v1 -clierr 300 "vcl.use vcl1" **** v1 CLI TX|vcl.use vcl1 **** dT 13.121 *** 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 13.154 *** s1 accepted fd 5 127.0.0.1 39798 ** s1 === rxreq **** dT 13.155 **** 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, 18 Sep 2023 15:43: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.162 **** 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 **** l1 match| 0 Debug - vcl1: VCL_EVENT_WARM **** l1 done | **** dT 13.163 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.use vcl1" **** v1 CLI TX|vcl.use vcl1 *** 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 13.164 *** v1 CLI RX 200 **** dT 13.165 **** 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 13.265 **** v1 vsl| 0 CLI - Rd vcl.use vcl1 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 78 active warm warm 0 vcl1 available auto warm 0 vcl2 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051800 1.0 **** dT 13.362 *** s1 shutting fd 5 *** s1 accepted fd 5 127.0.0.1 39800 ** 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, 18 Sep 2023 15:43: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.365 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 8 3 8 0.208193 0.172015 "HTTP/1.1 200 OK" **** dT 13.564 *** s1 shutting fd 5 **** dT 13.565 ** 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 **** dT 13.566 ** 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.567 **** v1 vsl| 0 Backend_health - default Went healthy 4---X-RH 3 3 8 0.402543 0.134181 "HTTP/1.1 200 OK" **** dT 14.364 *** s1 accepted fd 5 127.0.0.1 39810 ** 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, 18 Sep 2023 15:43: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 14.484 **** 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 14.566 *** s1 shutting fd 5 **** dT 14.568 *** s1 accepted fd 5 127.0.0.1 39812 ** 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, 18 Sep 2023 15:43: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 14.584 **** v1 vsl| 0 Backend_health - default Still sick ------RH 2 3 8 0.202628 0.067543 "" **** dT 14.770 *** s1 shutting fd 5 **** dT 14.790 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 4 3 8 0.208014 0.152639 "HTTP/1.1 200 OK" **** dT 15.779 *** s1 accepted fd 5 127.0.0.1 39824 ** 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, 18 Sep 2023 15:43: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 15.980 *** s1 shutting fd 5 **** dT 16.022 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 5 3 8 0.202999 0.165229 "HTTP/1.1 200 OK" **** dT 16.223 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051803 1.0 **** dT 16.983 *** s1 accepted fd 5 127.0.0.1 39838 ** s1 === rxreq **** dT 16.984 **** 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, 18 Sep 2023 15:43: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.185 *** s1 shutting fd 5 **** dT 17.237 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 6 3 8 0.202113 0.174450 "HTTP/1.1 200 OK" **** dT 17.569 ** top === varnish v1 -cliexpect "active *warm *warm *[0-9]+ *vcl1\\s+a... **** v1 CLI TX|vcl.list **** dT 17.570 *** 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.654 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 78 active warm warm 0 vcl1 available auto cold 0 vcl2 **** dT 18.192 *** s1 accepted fd 5 127.0.0.1 39858 ** 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, 18 Sep 2023 15:43: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.396 *** s1 shutting fd 5 **** dT 18.474 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 7 3 8 0.209826 0.183294 "HTTP/1.1 200 OK" **** dT 19.293 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051806 1.0 **** dT 19.400 *** s1 accepted fd 5 127.0.0.1 39876 ** 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, 18 Sep 2023 15:43:26 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 19.610 *** s1 shutting fd 5 **** dT 19.710 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 8 3 8 0.210090 0.189993 "HTTP/1.1 200 OK" **** dT 20.612 *** s1 accepted fd 5 127.0.0.1 39888 ** 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 **** dT 20.613 **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 18 Sep 2023 15:43: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.814 *** s1 shutting fd 5 ** s1 Ending **** dT 20.839 **** v1 vsl| 0 Backend_health - default Still healthy 4---X-RH 8 3 8 0.202250 0.193057 "HTTP/1.1 200 OK" **** dT 22.255 **** v1 vsl| 0 CLI - Rd ping **** dT 22.256 **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051809 1.0 **** dT 22.694 ** v1 not found (as expected): VBE.vcl2.default.happy ** top === varnish v1 -cliok "vcl.use vcl2" **** v1 CLI TX|vcl.use vcl2 **** dT 22.695 *** 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.736 *** 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.762 **** 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 78 available warm warm 0 vcl1 active auto warm 0 vcl2 **** dT 23.875 **** v1 vsl| 0 Backend_health - default Still healthy 4---Xr-- 7 3 8 0.000000 0.193057 "Poll error 110 (Connection timed out)" **** dT 24.784 **** v1 vsl| 0 Backend_health - default Still sick 4---Xr-- 2 3 8 0.000000 0.000000 "Poll error 110 (Connection timed out)" **** dT 25.289 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051812 1.0 **** dT 26.737 ** top === varnish v1 -cliexpect "available *warm *warm *[0-9]+ *vcl1\\... **** dT 26.738 **** v1 CLI TX|vcl.list *** 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 (1022) >= 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 *** 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 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliexpect "available *auto *warm *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list **** dT 26.739 *** 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.802 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 78 available warm warm 0 vcl1 active auto warm 0 vcl2 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 1auto **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 78 available auto warm 0 vcl1 active auto warm 0 vcl2 **** dT 26.903 **** v1 vsl| 0 Backend_health - default Still healthy 4---Xr-- 6 3 8 0.000000 0.193057 "Poll error 110 (Connection timed out)" **** dT 27.141 ** 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.720 **** v1 vsl| 0 Backend_health - default Still sick 4---Xr-- 2 3 8 0.000000 0.000000 "Poll error 110 (Connection timed out)" **** dT 28.027 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 0auto **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_COLD **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 0 **** dT 28.235 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051815 1.0 **** dT 29.861 **** 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.770 **** v1 vsl| 0 Backend_health - default Still sick 4---Xr-- 2 3 8 0.000000 0.000000 "Poll error 110 (Connection timed out)" **** dT 31.150 ** top === varnish v1 -cliexpect "available *auto *cold *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list *** 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.188 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 78 available auto cold 0 vcl1 active auto warm 0 vcl2 **** dT 31.289 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051818 1.0 **** dT 33.824 **** v1 vsl| 0 Backend_health - default Still sick 4---Xr-- 2 3 8 0.000000 0.000000 "Poll error 110 (Connection timed out)" **** dT 34.230 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1695051821 1.0 **** dT 36.235 ** 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.276 *** 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.277 *** 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\\... **** v1 CLI TX|vcl.list *** 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 *** v1 debug|Debug: Stopping Child **** dT 36.350 **** 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. **** dT 36.351 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 78 available auto cold 0 vcl1 active auto warm 0 vcl2 **** v1 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 36.378 *** 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 CLI RX 200 **** 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 *** v1 debug|Info: Child (22146) said Child dies *** v1 debug|Info: Child (22146) ended *** v1 debug|Debug: Child cleanup complete **** dT 36.394 *** v1 debug|Debug: Child (26559) Started **** dT 36.432 *** v1 debug|Child launched OK **** dT 36.434 *** v1 debug|Error: Child (26559) 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 (26559) said Child starts # top TEST ../../../../bin/varnishtest/tests/v00003.vtc TIMED OUT (kill -9) # top TEST ../../../../bin/varnishtest/tests/v00003.vtc FAILED (60.076) signal=9 FAIL tests/v00003.vtc (exit status: 2)