**** dT 0.001 * top TEST ../../../../bin/varnishtest/tests/r03038.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/root/VT/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:17648 **** top extmacro def listen_addr=127.0.0.1:0 **** top extmacro def bad_ip=192.0.2.255 **** top extmacro def topbuild=/root/VT/varnish-cache/varnish-trunk/_build/sub **** top extmacro def topsrc=/root/VT/varnish-cache/varnish-trunk/_build/sub/../.. **** dT 0.002 **** top macro def testdir=/root/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests **** top macro def tmpdir=/root/VT/_vtest_tmp/vtc.88459.129ce2fe **** top macro def vtcid=vtc.88459.129ce2fe **** dT 0.004 ** top === varnishtest "vcl.list and cli_limit" * top VTEST vcl.list and cli_limit ** top === server s1 { ** s1 Starting server **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=55719 **** s1 macro def s1_sock=127.0.0.1:55719 * s1 Listen on 127.0.0.1:55719 **** dT 0.005 ** top === varnish v1 -vcl+backend { } -start **** dT 0.006 ** s1 Started on 127.0.0.1:55719 (1 iterations) **** dT 0.042 ** v1 Launch *** v1 CMD: cd ${pwd} && exec varnishd -d -n /root/VT/_vtest_tmp/vtc.88459.129ce2fe/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 32722' -P /root/VT/_vtest_tmp/vtc.88459.129ce2fe/v1/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs *** v1 CMD: cd /root/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /root/VT/_vtest_tmp/vtc.88459.129ce2fe/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 32722' -P /root/VT/_vtest_tmp/vtc.88459.129ce2fe/v1/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs **** dT 0.045 *** v1 PID: 88475 **** dT 0.046 **** v1 macro def v1_pid=88475 **** v1 macro def v1_name=/root/VT/_vtest_tmp/vtc.88459.129ce2fe/v1 **** dT 0.426 *** v1 debug|Debug: Version: varnish-trunk revision d2540ce118d15362c0f3945ca0512eb87ba88f70 **** dT 0.427 *** v1 debug|Debug: Platform: FreeBSD,13.5-RELEASE,arm,-jnone,-sdefault,-sdefault,-hcritbit *** v1 debug|200 312 *** v1 debug|----------------------------- *** v1 debug|Varnish Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|FreeBSD,13.5-RELEASE,arm,-jnone,-sdefault,-sdefault,-hcritbit *** v1 debug|varnish-trunk revision d2540ce118d15362c0f3945ca0512eb87ba88f70 *** 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.447 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 6 **** dT 0.449 *** v1 CLI RX 107 **** v1 CLI RX|ieypqsdbvseijqmgjzsjfvzcgxajxufv **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** dT 0.452 **** v1 CLI TX|auth 59544a66105b840ec86f7e9071bf9e4f12fcb4b5986da1afa82fe67bd6b53613 **** dT 0.455 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Varnish Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|FreeBSD,13.5-RELEASE,arm,-jnone,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|varnish-trunk revision d2540ce118d15362c0f3945ca0512eb87ba88f70 **** 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. **** dT 0.457 **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "55719"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.560 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.675 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.792 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.893 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.994 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.096 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.197 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.299 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.401 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.503 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.605 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.713 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.814 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.916 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.018 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.119 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.221 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.325 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.425 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.527 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.629 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.731 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.833 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.934 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.036 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.137 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.239 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.341 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.443 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.545 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.647 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.749 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.851 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.953 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.055 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.157 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.259 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.361 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.463 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.565 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.666 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.770 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.872 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.974 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.076 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.187 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.288 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.392 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.494 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.598 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.699 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.804 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.910 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.011 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.113 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.214 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.316 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.418 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.520 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.622 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.724 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.825 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.927 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 7.029 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 7.153 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 7.256 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 7.357 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 7.428 *** v1 CLI RX 200 **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 **** dT 7.464 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 7.473 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 7.566 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 7.582 *** v1 debug|Debug: Child (88488) Started **** dT 7.673 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 8.330 *** v1 debug|Child launched OK **** dT 8.376 *** v1 CLI RX 200 *** v1 wait-running **** v1 CLI TX|status **** dT 8.377 *** v1 debug|Info: Child (88488) said Child starts **** dT 8.417 *** v1 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address **** dT 8.431 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1750061354.120500/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1750061354.120500/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:43224 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:43224 **** v1 vsl| 0 Error - Kernel filtering: sock=3, errno=2 No such file or directory **** v1 vsl| 0 CLI - Wr 200 0 **** dT 8.466 *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 43224 **** v1 CLI TX|debug.xid 1000 **** dT 8.511 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address **** dT 8.537 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 43224 **** v1 vsl| 0 CLI - Rd debug.xid 1000 **** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** dT 8.564 *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 43224 ** v1 Listen on 127.0.0.1 43224 **** v1 macro def v1_addr=127.0.0.1 **** v1 macro def v1_port=43224 **** v1 macro def v1_sock=127.0.0.1:43224 **** v1 macro def v1_a0_addr=127.0.0.1 **** v1 macro def v1_a0_port=43224 **** v1 macro def v1_a0_sock=127.0.0.1:43224 ** 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 = "55719"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 8.639 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 43224 **** dT 9.452 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_LINGER for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified SO_KEEPALIVE for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_NODELAY for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPIDLE for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPCNT for a0=127.0.0.1:43224 **** v1 vsl| 0 Debug - sockopt: Not setting unmodified TCP_KEEPINTVL for a0=127.0.0.1:43224 **** dT 18.178 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl2 **** dT 18.215 **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1750061362.190350/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl2.1750061362.190350/vgc.so" as "vcl2" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1750061371 1.0 **** dT 18.225 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** 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 = "55719"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 18.317 **** v1 vsl| 0 CLI - Rd vcl.use vcl2 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 28.148 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl3 **** dT 28.212 **** v1 vsl| 0 CLI - Rd vcl.load vcl3 vcl_vcl3.1750061371.851528/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl3.1750061371.851528/vgc.so" as "vcl3" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1750061381 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl3 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 28.214 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl3' now active ** 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 = "55719"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 37.569 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl4 **** dT 37.616 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl4' now active ** top === varnish v1 -vcl+backend { } **** v1 CLI TX|vcl.inline vcl5 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "55719"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 37.617 **** v1 vsl| 0 CLI - Rd vcl.load vcl4 vcl_vcl4.1750061381.840252/vgc.so 1auto **** dT 37.618 **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl4.1750061381.840252/vgc.so" as "vcl4" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1750061391 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl4 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 45.598 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl5 **** dT 45.627 **** v1 vsl| 0 CLI - Rd vcl.load vcl5 vcl_vcl5.1750061391.242530/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl5.1750061391.242530/vgc.so" as "vcl5" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1750061399 1.0 **** dT 45.642 *** v1 CLI RX 200 **** dT 45.643 **** v1 CLI RX|VCL 'vcl5' now active ** top === varnish v1 -vcl+backend { } **** v1 CLI TX|vcl.inline vcl6 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "55719"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 45.729 **** v1 vsl| 0 CLI - Rd vcl.use vcl5 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 54.734 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl6 **** dT 54.781 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl6' now active ** top === varnish v1 -vcl+backend { } **** v1 CLI TX|vcl.inline vcl7 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "55719"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 54.800 **** v1 vsl| 0 CLI - Rd vcl.load vcl6 vcl_vcl6.1750061399.269115/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl6.1750061399.269115/vgc.so" as "vcl6" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1750061408 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl6 **** v1 vsl| 0 CLI - Wr 200 0 # top TEST ../../../../bin/varnishtest/tests/r03038.vtc TIMED OUT (kill -9) # top TEST ../../../../bin/varnishtest/tests/r03038.vtc FAILED (60.041) signal=9 FAIL tests/r03038.vtc (exit status: 2)