**** dT 0.001 * top TEST ../../../../bin/varnishtest/tests/p00008.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:54387 **** 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.87003.4811724f **** top macro def vtcid=vtc.87003.4811724f **** dT 0.004 ** top === varnishtest "Ban list sync across silos" * top VTEST Ban list sync across silos ** top === feature persistent_storage ** top === shell "rm -f ${tmpdir}/_.per[12]" **** top shell_cmd|set -e ;exec 2>&1 ; rm -f /root/VT/_vtest_tmp/vtc.87003.4811724f/_.per[12] **** dT 0.029 **** top shell_status = 0x0000 ** top === server s1 { ** s1 Starting server **** dT 0.030 **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=54415 **** s1 macro def s1_sock=127.0.0.1:54415 * s1 Listen on 127.0.0.1:54415 ** top === varnish v1 \ **** dT 0.032 ** s1 Started on 127.0.0.1:54415 (1 iterations) **** dT 0.065 ** v1 Launch **** dT 0.066 *** v1 CMD: cd ${pwd} && exec varnishd -d -n /root/VT/_vtest_tmp/vtc.87003.4811724f/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 25930' -P /root/VT/_vtest_tmp/vtc.87003.4811724f/v1/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -pfeature=+wait_silo -pban_lurker_sleep=0 -sper1=deprecated_persistent,/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per1,5m -sper2=deprecated_persistent,/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per2,5m *** v1 CMD: cd /root/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /root/VT/_vtest_tmp/vtc.87003.4811724f/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 25930' -P /root/VT/_vtest_tmp/vtc.87003.4811724f/v1/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -pfeature=+wait_silo -pban_lurker_sleep=0 -sper1=deprecated_persistent,/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per1,5m -sper2=deprecated_persistent,/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per2,5m **** dT 0.069 *** v1 PID: 87020 **** v1 macro def v1_pid=87020 **** dT 0.070 **** v1 macro def v1_name=/root/VT/_vtest_tmp/vtc.87003.4811724f/v1 **** dT 0.211 *** v1 debug|Debug: Version: varnish-trunk revision 097bc420dfb4fc3e0675ba15a5efc2e17bf4ff7a *** v1 debug|Debug: Platform: FreeBSD,13.5-RELEASE,arm,-jnone,-sdeprecated_persistent,-sdeprecated_persistent,-sdefault,-hcritbit *** v1 debug|200 350 *** v1 debug|----------------------------- *** v1 debug|Varnish Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|FreeBSD,13.5-RELEASE,arm,-jnone,-sdeprecated_persistent,-sdeprecated_persistent,-sdefault,-hcritbit *** v1 debug|varnish-trunk revision 097bc420dfb4fc3e0675ba15a5efc2e17bf4ff7a *** 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.295 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 6 **** dT 0.297 *** v1 CLI RX 107 **** v1 CLI RX|nfxtowqzkicvfrnqgjctaylnopypgqal **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** dT 0.300 **** v1 CLI TX|auth 79cacb8675c3bebf40738d5b64d0c38b2c6d6545f9778105a2266410ed2e969d **** dT 0.303 *** v1 CLI RX 200 **** dT 0.304 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Varnish Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|FreeBSD,13.5-RELEASE,arm,-jnone,-sdeprecated_persistent,-sdeprecated_persistent,-sdefault,-hcritbit **** v1 CLI RX|varnish-trunk revision 097bc420dfb4fc3e0675ba15a5efc2e17bf4ff7a **** 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.305 **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.0; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "54415"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|\t\tsub vcl_backend_response { **** v1 CLI TX|\t\t\tset beresp.storage = storage.per1; **** v1 CLI TX|\t\t\tif (bereq.url ~ "silo2") { **** v1 CLI TX|\t\t\t\tset beresp.storage = storage.per2; **** v1 CLI TX|\t\t\t} **** v1 CLI TX|\t\t} **** v1 CLI TX|\t **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.408 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.509 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.611 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.713 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.815 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.917 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.019 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.120 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.229 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.330 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.432 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.534 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.635 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.737 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.839 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.940 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.042 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.144 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.245 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.346 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.448 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.550 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.651 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.753 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.855 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.957 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.059 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.161 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.263 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.365 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.467 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.569 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.671 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.773 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.875 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.976 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.077 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.179 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.281 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.383 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.485 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.587 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.689 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.791 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.893 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.994 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.097 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.123 *** v1 CLI RX 200 **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 **** dT 5.166 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 5.204 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.252 *** v1 debug|Debug: Child (87029) Started **** dT 5.307 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.411 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.761 *** v1 debug|Child launched OK **** dT 5.782 *** v1 CLI RX 200 *** v1 wait-running **** v1 CLI TX|status *** v1 debug|Info: Child (87029) said Child starts **** dT 5.783 *** v1 debug|Info: Child (87029) said sizeof(struct smp_ident) = 112 = 0x70 *** v1 debug|Info: Child (87029) said sizeof(struct smp_sign) = 32 = 0x20 *** v1 debug|Info: Child (87029) said sizeof(struct smp_segptr) = 32 = 0x20 *** v1 debug|Info: Child (87029) said sizeof(struct smp_object) = 72 = 0x48 *** v1 debug|Info: Child (87029) said CHK(0x2073d770 SILO 0x20a00000 ) = 1 **** dT 5.784 *** v1 debug|Info: Child (87029) said Warning SILO (/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per1) not reloaded (reason=1) *** v1 debug|Info: Child (87029) said min_nseg = 10, max_segl = 104441 *** v1 debug|Info: Child (87029) said max_nseg = 6553, min_segl = 159 *** v1 debug|Info: Child (87029) said aim_nseg = 255, aim_segl = 4095 *** v1 debug|Info: Child (87029) said free_reserve = 40950 *** v1 debug|Info: Child (87029) said sizeof(struct smp_ident) = 112 = 0x70 *** v1 debug|Info: Child (87029) said sizeof(struct smp_sign) = 32 = 0x20 *** v1 debug|Info: Child (87029) said sizeof(struct smp_segptr) = 32 = 0x20 *** v1 debug|Info: Child (87029) said sizeof(struct smp_object) = 72 = 0x48 *** v1 debug|Info: Child (87029) said CHK(0x2073daf0 SILO 0x20f00000 ) = 1 *** v1 debug|Info: Child (87029) said Warning SILO (/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per2) not reloaded (reason=1) **** dT 5.785 *** v1 debug|Info: Child (87029) said min_nseg = 10, max_segl = 104441 *** v1 debug|Info: Child (87029) said max_nseg = 6553, min_segl = 159 *** v1 debug|Info: Child (87029) said aim_nseg = 255, aim_segl = 4095 *** v1 debug|Info: Child (87029) said free_reserve = 40950 *** v1 debug|Info: Child (87029) said Wrapped silo *** v1 debug|Info: Child (87029) said Wrapped silo *** v1 debug|Info: Child (87029) said Silo completely loaded *** v1 debug|Info: Child (87029) said Silo completely loaded **** dT 5.825 *** v1 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1742124594.091926/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1742124594.091926/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:48449 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:48449 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:48449 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:48449 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:48449 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:48449 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:48449 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:48449 **** v1 vsl| 0 Error - Kernel filtering: sock=3, errno=2 No such file or directory **** v1 vsl| 0 CLI - Wr 200 0 **** dT 5.869 *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 48449 **** v1 CLI TX|debug.xid 1000 **** dT 5.912 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address **** dT 5.933 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 48449 **** v1 vsl| 0 CLI - Rd debug.xid 1000 **** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** dT 5.955 *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 48449 ** v1 Listen on 127.0.0.1 48449 **** v1 macro def v1_addr=127.0.0.1 **** v1 macro def v1_port=48449 **** v1 macro def v1_sock=127.0.0.1:48449 **** v1 macro def v1_a0_addr=127.0.0.1 **** dT 5.956 **** v1 macro def v1_a0_port=48449 **** v1 macro def v1_a0_sock=127.0.0.1:48449 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 5.957 ** c1 Started on 127.0.0.1:48449 (1 iterations) *** c1 Connect to 127.0.0.1:48449 **** dT 5.958 *** c1 connected fd 16 from 127.0.0.1 61796 to 127.0.0.1:48449 **** dT 5.959 ** c1 === txreq -url "/silo1" **** c1 txreq|GET /silo1 HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === rxresp **** dT 5.964 *** s1 accepted fd 4 127.0.0.1 60113 ** s1 === rxreq **** dT 5.966 **** s1 rxhdr|GET /silo1 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: 1002\r **** s1 rxhdr|\r **** s1 rxhdrlen = 153 **** s1 http[ 0] |GET **** s1 http[ 1] |/silo1 **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |User-Agent: c1 **** dT 5.967 **** 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: 1002 **** s1 bodylen = 0 ** s1 === expect req.url == "/silo1" **** s1 EXPECT req.url (/silo1) == "/silo1" match ** s1 === txresp -hdr "X-Foo: foo" **** dT 5.968 **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|X-Foo: foo\r **** s1 txresp|Date: Sun, 16 Mar 2025 11:29:59 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === rxreq **** dT 5.983 **** c1 rxhdr|HTTP/1.1 200 OK\r **** c1 rxhdr|X-Foo: foo\r **** c1 rxhdr|Date: Sun, 16 Mar 2025 11:29:59 GMT\r **** c1 rxhdr|Server: s1\r **** c1 rxhdr|Content-Length: 0\r **** c1 rxhdr|X-Varnish: 1001\r **** c1 rxhdr|Age: 0\r **** c1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r **** c1 rxhdr|Accept-Ranges: bytes\r **** c1 rxhdr|Connection: keep-alive\r **** c1 rxhdr|\r **** c1 rxhdrlen = 199 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |200 **** c1 http[ 2] |OK **** c1 http[ 3] |X-Foo: foo **** c1 http[ 4] |Date: Sun, 16 Mar 2025 11:29:59 GMT **** c1 http[ 5] |Server: s1 **** c1 http[ 6] |Content-Length: 0 **** c1 http[ 7] |X-Varnish: 1001 **** c1 http[ 8] |Age: 0 **** dT 5.984 **** c1 http[ 9] |Via: 1.1 v1 (Varnish/trunk) **** c1 http[10] |Accept-Ranges: bytes **** c1 http[11] |Connection: keep-alive **** c1 bodylen = 0 ** c1 === expect resp.status == 200 **** c1 EXPECT resp.status (200) == "200" match ** c1 === expect resp.http.x-foo == "foo" **** c1 EXPECT resp.http.x-foo (foo) == "foo" match ** c1 === txreq -url "/silo2" **** c1 txreq|GET /silo2 HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === rxresp **** dT 5.988 **** s1 rxhdr|GET /silo2 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: 1004\r **** s1 rxhdr|\r **** s1 rxhdrlen = 153 **** s1 http[ 0] |GET **** s1 http[ 1] |/silo2 **** 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: 1004 **** s1 bodylen = 0 ** s1 === expect req.url == "/silo2" **** s1 EXPECT req.url (/silo2) == "/silo2" match ** s1 === txresp -hdr "X-Foo: foo" **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|X-Foo: foo\r **** s1 txresp|Date: Sun, 16 Mar 2025 11:29:59 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r **** dT 5.989 *** s1 shutting fd 4 ** s1 Ending **** dT 6.004 **** c1 rxhdr|HTTP/1.1 200 OK\r **** c1 rxhdr|X-Foo: foo\r **** c1 rxhdr|Date: Sun, 16 Mar 2025 11:29:59 GMT\r **** c1 rxhdr|Server: s1\r **** c1 rxhdr|Content-Length: 0\r **** c1 rxhdr|X-Varnish: 1003\r **** c1 rxhdr|Age: 0\r **** c1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r **** c1 rxhdr|Accept-Ranges: bytes\r **** c1 rxhdr|Connection: keep-alive\r **** c1 rxhdr|\r **** dT 6.005 **** c1 rxhdrlen = 199 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |200 **** c1 http[ 2] |OK **** c1 http[ 3] |X-Foo: foo **** c1 http[ 4] |Date: Sun, 16 Mar 2025 11:29:59 GMT **** c1 http[ 5] |Server: s1 **** c1 http[ 6] |Content-Length: 0 **** c1 http[ 7] |X-Varnish: 1003 **** c1 http[ 8] |Age: 0 **** c1 http[ 9] |Via: 1.1 v1 (Varnish/trunk) **** c1 http[10] |Accept-Ranges: bytes **** c1 http[11] |Connection: keep-alive **** c1 bodylen = 0 ** c1 === expect resp.status == 200 **** c1 EXPECT resp.status (200) == "200" match ** c1 === expect resp.http.x-foo == "foo" **** c1 EXPECT resp.http.x-foo (foo) == "foo" match *** c1 closing fd 16 ** c1 Ending **** dT 6.006 ** top === varnish v1 -stop ** v1 Stop **** v1 CLI TX|stop **** dT 6.040 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 48449 **** v1 vsl| 1000 Begin c sess 0 HTTP/1 **** v1 vsl| 1000 SessOpen c 127.0.0.1 61796 a0 127.0.0.1 48449 1742124599.706089 22 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=127.0.0.1:48449 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_SNDTIMEO non heredity for a0=127.0.0.1:48449 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_RCVTIMEO non heredity for a0=127.0.0.1:48449 **** v1 vsl| 1000 Debug c sockopt: Test confirmed TCP_NODELAY non heredity for a0=127.0.0.1:48449 **** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:48449 **** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:48449 **** dT 6.041 **** v1 vsl| 1000 Debug c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:48449 **** v1 vsl| 1000 Debug c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:48449 **** v1 vsl| 1000 Debug c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:48449 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:48449 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:48449 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:48449 **** v1 vsl| 1000 Link c req 1001 rxreq **** v1 vsl| 1001 Begin c req 1000 rxreq **** v1 vsl| 1001 Timestamp c Start: 1742124599.706915 0.000000 0.000000 **** v1 vsl| 1001 Timestamp c Req: 1742124599.706915 0.000000 0.000000 **** v1 vsl| 1001 VCL_use c vcl1 **** v1 vsl| 1001 ReqStart c 127.0.0.1 61796 a0 **** v1 vsl| 1001 ReqMethod c GET **** v1 vsl| 1001 ReqURL c /silo1 **** 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_return c hash **** v1 vsl| 1001 VCL_call c HASH **** v1 vsl| 1001 VCL_return c lookup **** v1 vsl| 1001 VCL_call c MISS **** v1 vsl| 1001 VCL_return c fetch **** v1 vsl| 1001 Link c bereq 1002 fetch **** v1 vsl| 1001 Timestamp c Fetch: 1742124599.726941 0.020026 0.020026 **** v1 vsl| 1001 RespProtocol c HTTP/1.1 **** v1 vsl| 1001 RespStatus c 200 **** v1 vsl| 1001 RespReason c OK **** v1 vsl| 1001 RespHeader c X-Foo: foo **** v1 vsl| 1001 RespHeader c Date: Sun, 16 Mar 2025 11:29:59 GMT **** v1 vsl| 1001 RespHeader c Server: s1 **** v1 vsl| 1001 RespHeader c Content-Length: 0 **** v1 vsl| 1001 RespHeader c X-Varnish: 1001 **** v1 vsl| 1001 RespHeader c Age: 0 **** v1 vsl| 1001 RespHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1001 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1001 VCL_call c DELIVER **** v1 vsl| 1001 VCL_return c deliver **** v1 vsl| 1001 Timestamp c Process: 1742124599.727233 0.020318 0.000292 **** v1 vsl| 1001 Filters c **** v1 vsl| 1001 RespHeader c Connection: keep-alive **** v1 vsl| 1001 Timestamp c Resp: 1742124599.730419 0.023504 0.003185 **** v1 vsl| 1001 ReqAcct c 56 0 56 199 0 199 **** v1 vsl| 1001 End c **** v1 vsl| 1000 Link c req 1003 rxreq **** v1 vsl| 1002 Begin b bereq 1001 fetch **** v1 vsl| 1002 VCL_use b vcl1 **** v1 vsl| 1002 Timestamp b Start: 1742124599.708283 0.000000 0.000000 **** v1 vsl| 1002 BereqMethod b GET **** v1 vsl| 1002 BereqURL b /silo1 **** v1 vsl| 1002 BereqProtocol b HTTP/1.1 **** v1 vsl| 1002 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1002 BereqHeader b User-Agent: c1 **** v1 vsl| 1002 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1002 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1002 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1002 BereqHeader b X-Varnish: 1002 **** v1 vsl| 1002 VCL_call b BACKEND_FETCH **** v1 vsl| 1002 VCL_return b fetch **** dT 6.042 **** v1 vsl| 1002 Timestamp b Fetch: 1742124599.708492 0.000209 0.000209 **** v1 vsl| 1002 Timestamp b Connected: 1742124599.709384 0.001101 0.000891 **** v1 vsl| 1002 BackendOpen b 25 s1 127.0.0.1 54415 127.0.0.1 60113 connect **** v1 vsl| 1002 Timestamp b Bereq: 1742124599.714458 0.006175 0.005074 **** v1 vsl| 1002 BerespProtocol b HTTP/1.1 **** v1 vsl| 1002 BerespStatus b 200 **** v1 vsl| 1002 BerespReason b OK **** v1 vsl| 1002 BerespHeader b X-Foo: foo **** v1 vsl| 1002 BerespHeader b Date: Sun, 16 Mar 2025 11:29:59 GMT **** v1 vsl| 1002 BerespHeader b Server: s1 **** v1 vsl| 1002 BerespHeader b Content-Length: 0 **** v1 vsl| 1002 Timestamp b Beresp: 1742124599.714733 0.006450 0.000275 **** v1 vsl| 1002 TTL b RFC 120 10 0 1742124600 1742124600 1742124599 0 0 cacheable **** v1 vsl| 1002 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1002 VCL_return b deliver **** v1 vsl| 1002 Debug b Missing content-range header or unknown range unit **** v1 vsl| 1002 Timestamp b Process: 1742124599.715259 0.006976 0.000526 **** v1 vsl| 1002 Filters b **** v1 vsl| 1002 Storage b deprecated_persistent per1 **** v1 vsl| 1002 Fetch_Body b 0 none - **** v1 vsl| 1002 BackendClose b 25 s1 recycle **** v1 vsl| 1002 Timestamp b BerespBody: 1742124599.732106 0.023823 0.016846 **** v1 vsl| 1002 Length b 0 **** v1 vsl| 1002 BereqAcct b 153 0 153 99 0 99 **** v1 vsl| 1002 End b **** v1 vsl| 1003 Begin c req 1000 rxreq **** v1 vsl| 1003 Timestamp c Start: 1742124599.730659 0.000000 0.000000 **** v1 vsl| 1003 Timestamp c Req: 1742124599.730659 0.000000 0.000000 **** v1 vsl| 1003 VCL_use c vcl1 **** v1 vsl| 1003 ReqStart c 127.0.0.1 61796 a0 **** v1 vsl| 1003 ReqMethod c GET **** v1 vsl| 1003 ReqURL c /silo2 **** v1 vsl| 1003 ReqProtocol c HTTP/1.1 **** 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_return c hash **** v1 vsl| 1003 VCL_call c HASH **** v1 vsl| 1003 VCL_return c lookup **** v1 vsl| 1003 VCL_call c MISS **** v1 vsl| 1003 VCL_return c fetch **** v1 vsl| 1003 Link c bereq 1004 fetch **** v1 vsl| 1003 Timestamp c Fetch: 1742124599.748363 0.017704 0.017704 **** v1 vsl| 1003 RespProtocol c HTTP/1.1 **** v1 vsl| 1003 RespStatus c 200 **** v1 vsl| 1003 RespReason c OK **** v1 vsl| 1003 RespHeader c X-Foo: foo **** v1 vsl| 1003 RespHeader c Date: Sun, 16 Mar 2025 11:29:59 GMT **** v1 vsl| 1003 RespHeader c Server: s1 **** v1 vsl| 1003 RespHeader c Content-Length: 0 **** v1 vsl| 1003 RespHeader c X-Varnish: 1003 **** v1 vsl| 1003 RespHeader c Age: 0 **** v1 vsl| 1003 RespHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1003 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1003 VCL_call c DELIVER **** v1 vsl| 1003 VCL_return c deliver **** v1 vsl| 1003 Timestamp c Process: 1742124599.748641 0.017982 0.000277 **** v1 vsl| 1003 Filters c **** v1 vsl| 1003 RespHeader c Connection: keep-alive **** v1 vsl| 1003 Timestamp c Resp: 1742124599.752393 0.021734 0.003751 **** dT 6.043 **** v1 vsl| 1003 ReqAcct c 56 0 56 199 0 199 **** v1 vsl| 1003 End c **** v1 vsl| 1000 SessClose c REM_CLOSE 0.047 **** v1 vsl| 1000 End c **** v1 vsl| 1004 Begin b bereq 1003 fetch **** v1 vsl| 1004 VCL_use b vcl1 **** v1 vsl| 1004 Timestamp b Start: 1742124599.731497 0.000000 0.000000 **** v1 vsl| 1004 BereqMethod b GET **** v1 vsl| 1004 BereqURL b /silo2 **** v1 vsl| 1004 BereqProtocol b HTTP/1.1 **** v1 vsl| 1004 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1004 BereqHeader b User-Agent: c1 **** v1 vsl| 1004 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1004 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1004 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1004 BereqHeader b X-Varnish: 1004 **** v1 vsl| 1004 VCL_call b BACKEND_FETCH **** v1 vsl| 1004 VCL_return b fetch **** v1 vsl| 1004 Timestamp b Fetch: 1742124599.731686 0.000189 0.000189 **** v1 vsl| 1004 Timestamp b Connected: 1742124599.731791 0.000293 0.000104 **** v1 vsl| 1004 BackendOpen b 25 s1 127.0.0.1 54415 127.0.0.1 60113 reuse **** v1 vsl| 1004 Timestamp b Bereq: 1742124599.735846 0.004349 0.004055 **** v1 vsl| 1004 BerespProtocol b HTTP/1.1 **** v1 vsl| 1004 BerespStatus b 200 **** v1 vsl| 1004 BerespReason b OK **** v1 vsl| 1004 BerespHeader b X-Foo: foo **** v1 vsl| 1004 BerespHeader b Date: Sun, 16 Mar 2025 11:29:59 GMT **** v1 vsl| 1004 BerespHeader b Server: s1 **** v1 vsl| 1004 BerespHeader b Content-Length: 0 **** v1 vsl| 1004 Timestamp b Beresp: 1742124599.736405 0.004908 0.000559 **** v1 vsl| 1004 TTL b RFC 120 10 0 1742124600 1742124600 1742124599 0 0 cacheable **** v1 vsl| 1004 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1004 VCL_return b deliver **** v1 vsl| 1004 Debug b Missing content-range header or unknown range unit **** v1 vsl| 1004 Timestamp b Process: 1742124599.736986 0.005489 0.000580 **** v1 vsl| 1004 Filters b **** v1 vsl| 1004 Storage b deprecated_persistent per2 **** v1 vsl| 1004 Fetch_Body b 0 none - **** v1 vsl| 1004 BackendClose b 25 s1 recycle **** v1 vsl| 1004 Timestamp b BerespBody: 1742124599.753356 0.021859 0.016370 **** v1 vsl| 1004 Length b 0 **** v1 vsl| 1004 BereqAcct b 153 0 153 99 0 99 **** v1 vsl| 1004 End b **** dT 6.049 *** v1 debug|Debug: Stopping Child **** dT 6.150 **** v1 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 6.933 *** v1 debug|Info: Child (87029) said Child dies *** v1 debug|Info: Child (87029) ended **** dT 6.935 *** v1 debug|Debug: Child cleanup complete **** dT 6.936 *** v1 CLI RX 200 *** v1 wait-stopped **** v1 CLI TX|status **** dT 6.978 *** v1 CLI RX 200 **** v1 CLI RX|Child in state stopped ** top === server s1 -wait ** s1 Waiting for server (3/-1) ** top === varnish v2 \ **** dT 7.012 ** v2 Launch *** v2 CMD: cd ${pwd} && exec varnishd -d -n /root/VT/_vtest_tmp/vtc.87003.4811724f/v2 -i v2 -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 24586' -P /root/VT/_vtest_tmp/vtc.87003.4811724f/v2/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -pfeature=+wait_silo -pban_lurker_sleep=0 -sdeprecated_persistent,/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per1,5m **** dT 7.013 *** v2 CMD: cd /root/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /root/VT/_vtest_tmp/vtc.87003.4811724f/v2 -i v2 -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 24586' -P /root/VT/_vtest_tmp/vtc.87003.4811724f/v2/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -pfeature=+wait_silo -pban_lurker_sleep=0 -sdeprecated_persistent,/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per1,5m **** dT 7.016 *** v2 PID: 87034 **** v2 macro def v2_pid=87034 **** dT 7.017 **** v2 macro def v2_name=/root/VT/_vtest_tmp/vtc.87003.4811724f/v2 **** dT 7.263 *** v2 debug|Debug: Version: varnish-trunk revision 097bc420dfb4fc3e0675ba15a5efc2e17bf4ff7a *** v2 debug|Debug: Platform: FreeBSD,13.5-RELEASE,arm,-jnone,-sdeprecated_persistent,-sdefault,-hcritbit *** v2 debug|200 326 *** v2 debug|----------------------------- *** v2 debug|Varnish Cache CLI 1.0 *** v2 debug|----------------------------- *** v2 debug|FreeBSD,13.5-RELEASE,arm,-jnone,-sdeprecated_persistent,-sdefault,-hcritbit *** v2 debug|varnish-trunk revision 097bc420dfb4fc3e0675ba15a5efc2e17bf4ff7a *** v2 debug| *** v2 debug|Type 'help' for command list. *** v2 debug|Type 'quit' to close CLI session. *** v2 debug|Type 'start' to launch worker process. *** v2 debug| **** dT 7.342 **** v2 CLIPOLL 1 0x1 0x0 0x0 *** v2 CLI connection fd = 16 **** dT 7.344 *** v2 CLI RX 107 **** v2 CLI RX|ctkghxowfnsrzogjnwlsxlfpbzrvtjzl **** v2 CLI RX| **** v2 CLI RX|Authentication required. **** dT 7.346 **** v2 CLI TX|auth b3a3f0315b759020d472de07b8a490be0e9fed44ae321334ce2aa20389d49439 **** dT 7.350 *** v2 CLI RX 200 **** v2 CLI RX|----------------------------- **** v2 CLI RX|Varnish Cache CLI 1.0 **** v2 CLI RX|----------------------------- **** v2 CLI RX|FreeBSD,13.5-RELEASE,arm,-jnone,-sdeprecated_persistent,-sdefault,-hcritbit **** v2 CLI RX|varnish-trunk revision 097bc420dfb4fc3e0675ba15a5efc2e17bf4ff7a **** v2 CLI RX| **** v2 CLI RX|Type 'help' for command list. **** v2 CLI RX|Type 'quit' to close CLI session. **** v2 CLI RX|Type 'start' to launch worker process. **** dT 7.351 **** v2 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v2 CLI TX|vcl 4.1; **** v2 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "54415"; } **** v2 CLI TX| **** v2 CLI TX| **** v2 CLI TX|%XJEIFLH|)Xspa8P **** dT 7.454 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 7.556 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 7.658 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 7.760 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 7.862 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 7.963 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 8.065 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 8.167 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 8.269 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 8.371 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 8.472 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 8.574 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 8.675 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 8.777 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 8.879 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 8.981 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 9.083 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 9.185 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 9.287 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 9.391 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 9.493 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 9.595 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 9.697 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 9.799 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 9.901 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 10.003 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 10.105 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 10.207 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 10.308 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 10.410 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 10.513 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 10.615 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 10.718 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 10.820 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 10.922 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 11.024 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 11.126 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 11.228 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 11.331 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 11.433 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 11.536 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 11.638 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 11.740 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 11.843 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 11.962 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 12.065 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 12.124 *** v2 CLI RX 200 **** v2 CLI RX|VCL compiled. **** v2 CLI TX|vcl.use vcl1 **** dT 12.167 *** v2 CLI RX 200 **** v2 CLI RX|VCL 'vcl1' now active ** v2 Start **** v2 CLI TX|start **** dT 12.168 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 12.252 *** v2 debug|Debug: Child (87043) Started **** dT 12.271 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 12.375 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 12.680 *** v2 debug|Child launched OK **** dT 12.683 **** v2 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1742124601.137839/vgc.so 1auto **** dT 12.702 *** v2 CLI RX 200 *** v2 wait-running **** v2 CLI TX|status **** dT 12.703 *** v2 debug|Info: Child (87043) said Child starts **** dT 12.704 *** v2 debug|Info: Child (87043) said sizeof(struct smp_ident) = 112 = 0x70 *** v2 debug|Info: Child (87043) said sizeof(struct smp_sign) = 32 = 0x20 *** v2 debug|Info: Child (87043) said sizeof(struct smp_segptr) = 32 = 0x20 *** v2 debug|Info: Child (87043) said sizeof(struct smp_object) = 72 = 0x48 *** v2 debug|Info: Child (87043) said min_nseg = 10, max_segl = 104441 *** v2 debug|Info: Child (87043) said max_nseg = 6553, min_segl = 159 *** v2 debug|Info: Child (87043) said aim_nseg = 255, aim_segl = 4095 *** v2 debug|Info: Child (87043) said free_reserve = 40950 *** v2 debug|Info: Child (87043) said Dropped 0 segments to make free_reserve *** v2 debug|Info: Child (87043) said Silo completely loaded **** dT 12.745 *** v2 CLI RX 200 **** v2 CLI RX|Child in state running **** v2 CLI TX|debug.listen_address **** dT 12.789 **** v2 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1742124601.137839/vgc.so" as "vcl1" **** v2 vsl| 0 CLI - Rd vcl.use "vcl1" **** v2 vsl| 0 CLI - Wr 200 0 **** v2 vsl| 0 CLI - Rd start **** v2 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:45408 **** v2 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45408 **** v2 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45408 **** v2 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45408 **** v2 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45408 **** v2 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:45408 **** dT 12.790 **** v2 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:45408 **** v2 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:45408 **** v2 vsl| 0 Error - Kernel filtering: sock=3, errno=2 No such file or directory **** v2 vsl| 0 CLI - Wr 200 0 **** v2 vsl| 0 CLI - Rd debug.listen_address **** v2 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 45408 **** dT 12.791 *** v2 CLI RX 200 **** v2 CLI RX|a0 127.0.0.1 45408 **** v2 CLI TX|debug.xid 1000 **** dT 12.834 *** v2 CLI RX 200 **** dT 12.835 **** v2 CLI RX|XID is 1000 chunk 1 **** v2 CLI TX|debug.listen_address **** dT 12.878 *** v2 CLI RX 200 **** v2 CLI RX|a0 127.0.0.1 45408 ** v2 Listen on 127.0.0.1 45408 **** v2 macro def v2_addr=127.0.0.1 **** v2 macro def v2_port=45408 **** v2 macro def v2_sock=127.0.0.1:45408 **** v2 macro def v2_a0_addr=127.0.0.1 **** v2 macro def v2_a0_port=45408 **** v2 macro def v2_a0_sock=127.0.0.1:45408 **** dT 12.879 ** top === varnish v2 -cliok "ban obj.http.x-foo == foo" **** v2 CLI TX|ban obj.http.x-foo == foo **** dT 12.897 **** v2 vsl| 0 CLI - Rd debug.xid 1000 **** v2 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** v2 vsl| 0 CLI - Rd debug.listen_address **** v2 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 45408 **** dT 12.923 *** v2 CLI RX 200 ** v2 CLI 200 ** top === varnish v2 -cliok "ban.list" **** v2 CLI TX|ban.list **** dT 12.967 *** v2 CLI RX 200 **** v2 CLI RX|Present bans: **** v2 CLI RX|1742124606.667988 0 - obj.http.x-foo == foo **** v2 CLI RX|1742124606.347290 0 C **** v2 CLI RX|1742124599.408352 1 C ** v2 CLI 200 ** top === varnish v2 -stop ** v2 Stop **** v2 CLI TX|stop **** dT 13.005 **** v2 vsl| 0 CLI - Rd ban obj.http.x-foo == foo **** v2 vsl| 0 CLI - Wr 200 0 **** v2 vsl| 0 CLI - Rd ban.list **** v2 vsl| 0 CLI - Wr 200 119 Present bans: 1742124606.667988 0 - obj.http.x-foo == foo 1742124606.347290 0 C 1742124599.408352 1 C **** dT 13.010 *** v2 debug|Debug: Stopping Child **** dT 13.109 **** v2 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 13.864 *** v2 debug|Info: Child (87043) said Child dies **** dT 13.871 *** v2 debug|Info: Child (87043) ended **** dT 13.873 *** v2 debug|Debug: Child cleanup complete **** dT 13.874 *** v2 CLI RX 200 *** v2 wait-stopped **** v2 CLI TX|status **** dT 13.917 *** v2 CLI RX 200 **** v2 CLI RX|Child in state stopped ** top === varnish v3 \ **** dT 13.951 ** v3 Launch *** v3 CMD: cd ${pwd} && exec varnishd -d -n /root/VT/_vtest_tmp/vtc.87003.4811724f/v3 -i v3 -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 29055' -P /root/VT/_vtest_tmp/vtc.87003.4811724f/v3/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -pfeature=+wait_silo -pban_lurker_sleep=0 -sdeprecated_persistent,/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per1,5m -sdeprecated_persistent,/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per2,5m *** v3 CMD: cd /root/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /root/VT/_vtest_tmp/vtc.87003.4811724f/v3 -i v3 -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 29055' -P /root/VT/_vtest_tmp/vtc.87003.4811724f/v3/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -pfeature=+wait_silo -pban_lurker_sleep=0 -sdeprecated_persistent,/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per1,5m -sdeprecated_persistent,/root/VT/_vtest_tmp/vtc.87003.4811724f/_.per2,5m **** dT 14.012 *** v3 PID: 87046 **** dT 14.018 **** v3 macro def v3_pid=87046 **** dT 14.020 **** v3 macro def v3_name=/root/VT/_vtest_tmp/vtc.87003.4811724f/v3 **** dT 14.208 *** v3 debug|Debug: Version: varnish-trunk revision 097bc420dfb4fc3e0675ba15a5efc2e17bf4ff7a *** v3 debug|Debug: Platform: FreeBSD,13.5-RELEASE,arm,-jnone,-sdeprecated_persistent,-sdeprecated_persistent,-sdefault,-hcritbit *** v3 debug|200 350 *** v3 debug|----------------------------- *** v3 debug|Varnish Cache CLI 1.0 *** v3 debug|----------------------------- *** v3 debug|FreeBSD,13.5-RELEASE,arm,-jnone,-sdeprecated_persistent,-sdeprecated_persistent,-sdefault,-hcritbit *** v3 debug|varnish-trunk revision 097bc420dfb4fc3e0675ba15a5efc2e17bf4ff7a *** v3 debug| *** v3 debug|Type 'help' for command list. *** v3 debug|Type 'quit' to close CLI session. *** v3 debug|Type 'start' to launch worker process. *** v3 debug| **** dT 14.290 **** v3 CLIPOLL 1 0x1 0x0 0x0 *** v3 CLI connection fd = 27 **** dT 14.292 *** v3 CLI RX 107 **** v3 CLI RX|fcdsybjodnyhwuyvmdrbcwzrmaviofar **** v3 CLI RX| **** v3 CLI RX|Authentication required. **** dT 14.295 **** v3 CLI TX|auth 7f53abb70dfa97e2cb8475d1299fe909e572c7a4cea7720752304150ac5014d2 **** dT 14.298 *** v3 CLI RX 200 **** v3 CLI RX|----------------------------- **** v3 CLI RX|Varnish Cache CLI 1.0 **** v3 CLI RX|----------------------------- **** v3 CLI RX|FreeBSD,13.5-RELEASE,arm,-jnone,-sdeprecated_persistent,-sdeprecated_persistent,-sdefault,-hcritbit **** v3 CLI RX|varnish-trunk revision 097bc420dfb4fc3e0675ba15a5efc2e17bf4ff7a **** v3 CLI RX| **** v3 CLI RX|Type 'help' for command list. **** v3 CLI RX|Type 'quit' to close CLI session. **** v3 CLI RX|Type 'start' to launch worker process. **** dT 14.299 **** v3 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v3 CLI TX|vcl 4.1; **** v3 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "54415"; } **** v3 CLI TX| **** v3 CLI TX| **** v3 CLI TX|%XJEIFLH|)Xspa8P **** dT 14.402 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 14.504 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 14.606 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 14.708 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 14.810 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 14.912 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 15.014 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 15.116 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 15.218 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 15.320 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 15.422 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 15.523 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 15.625 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 15.727 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 15.829 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 15.931 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 16.032 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 16.134 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 16.236 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 16.338 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 16.440 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 16.542 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 16.644 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 16.746 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 16.848 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 16.951 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 17.054 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 17.157 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 17.260 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 17.363 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 17.466 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 17.569 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 17.671 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 17.773 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 17.876 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 17.978 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 18.080 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 18.183 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 18.285 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 18.387 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 18.489 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 18.591 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 18.693 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 18.795 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 18.898 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 19.001 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 19.105 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 19.116 *** v3 CLI RX 200 **** v3 CLI RX|VCL compiled. **** v3 CLI TX|vcl.use vcl1 **** dT 19.157 *** v3 CLI RX 200 **** v3 CLI RX|VCL 'vcl1' now active ** v3 Start **** v3 CLI TX|start **** dT 19.208 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 19.243 *** v3 debug|Debug: Child (87055) Started **** dT 19.312 *** v3 vsl|No VSL chunk found (child not started ?) **** dT 19.687 *** v3 debug|Child launched OK **** dT 19.708 *** v3 CLI RX 200 *** v3 wait-running **** v3 CLI TX|status **** dT 19.709 *** v3 debug|Info: Child (87055) said Child starts **** dT 19.710 *** v3 debug|Info: Child (87055) said sizeof(struct smp_ident) = 112 = 0x70 *** v3 debug|Info: Child (87055) said sizeof(struct smp_sign) = 32 = 0x20 *** v3 debug|Info: Child (87055) said sizeof(struct smp_segptr) = 32 = 0x20 *** v3 debug|Info: Child (87055) said sizeof(struct smp_object) = 72 = 0x48 *** v3 debug|Info: Child (87055) said min_nseg = 10, max_segl = 104441 *** v3 debug|Info: Child (87055) said max_nseg = 6553, min_segl = 159 *** v3 debug|Info: Child (87055) said aim_nseg = 255, aim_segl = 4095 *** v3 debug|Info: Child (87055) said free_reserve = 40950 *** v3 debug|Info: Child (87055) said sizeof(struct smp_ident) = 112 = 0x70 *** v3 debug|Info: Child (87055) said sizeof(struct smp_sign) = 32 = 0x20 *** v3 debug|Info: Child (87055) said sizeof(struct smp_segptr) = 32 = 0x20 **** dT 19.711 *** v3 debug|Info: Child (87055) said sizeof(struct smp_object) = 72 = 0x48 *** v3 debug|Info: Child (87055) said min_nseg = 10, max_segl = 104441 *** v3 debug|Info: Child (87055) said max_nseg = 6553, min_segl = 159 *** v3 debug|Info: Child (87055) said aim_nseg = 255, aim_segl = 4095 *** v3 debug|Info: Child (87055) said free_reserve = 40950 *** v3 debug|Info: Child (87055) said Dropped 0 segments to make free_reserve *** v3 debug|Info: Child (87055) said Dropped 0 segments to make free_reserve *** v3 debug|Info: Child (87055) said Silo completely loaded *** v3 debug|Info: Child (87055) said Silo completely loaded **** dT 19.724 **** v3 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1742124608.085801/vgc.so 1auto **** v3 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1742124608.085801/vgc.so" as "vcl1" **** v3 vsl| 0 CLI - Rd vcl.use "vcl1" **** v3 vsl| 0 CLI - Wr 200 0 **** v3 vsl| 0 CLI - Rd start **** v3 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:10262 **** v3 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:10262 **** v3 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:10262 **** v3 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:10262 **** v3 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:10262 **** v3 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:10262 **** v3 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:10262 **** v3 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:10262 **** v3 vsl| 0 Error - Kernel filtering: sock=3, errno=2 No such file or directory **** v3 vsl| 0 CLI - Wr 200 0 **** dT 19.751 *** v3 CLI RX 200 **** v3 CLI RX|Child in state running **** v3 CLI TX|debug.listen_address **** dT 19.794 *** v3 CLI RX 200 **** dT 19.795 **** v3 CLI RX|a0 127.0.0.1 10262 **** v3 CLI TX|debug.xid 1000 **** dT 19.830 **** v3 vsl| 0 CLI - Rd debug.listen_address **** v3 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 10262 **** dT 19.838 *** v3 CLI RX 200 **** dT 19.839 **** v3 CLI RX|XID is 1000 chunk 1 **** v3 CLI TX|debug.listen_address **** dT 19.882 *** v3 CLI RX 200 **** dT 19.883 **** v3 CLI RX|a0 127.0.0.1 10262 ** v3 Listen on 127.0.0.1 10262 **** v3 macro def v3_addr=127.0.0.1 **** v3 macro def v3_port=10262 **** v3 macro def v3_sock=127.0.0.1:10262 **** v3 macro def v3_a0_addr=127.0.0.1 **** v3 macro def v3_a0_port=10262 **** v3 macro def v3_a0_sock=127.0.0.1:10262 ** top === varnish v3 -cliok "ban.list" **** v3 CLI TX|ban.list **** dT 19.926 *** v3 CLI RX 200 **** v3 CLI RX|Present bans: **** v3 CLI RX|1742124613.335381 0 C **** v3 CLI RX|1742124606.667988 0 - obj.http.x-foo == foo **** v3 CLI RX|1742124606.347290 0 C **** v3 CLI RX|1742124599.408352 2 C ** v3 CLI 200 ** top === varnish v3 -stop ** v3 Stop **** v3 CLI TX|stop **** dT 19.938 **** v3 vsl| 0 CLI - Rd debug.xid 1000 **** v3 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** v3 vsl| 0 CLI - Rd debug.listen_address **** v3 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 10262 **** v3 vsl| 0 CLI - Rd ban.list **** v3 vsl| 0 CLI - Wr 200 147 Present bans: 1742124613.335381 0 C 1742124606.667988 0 - obj.http.x-foo == foo 1742124606.347290 0 C 1742124599.408352 2 C **** dT 19.969 *** v3 debug|Debug: Stopping Child **** dT 20.046 **** v3 vsl| 0 CLI - EOF on CLI connection, worker stops # top TEST ../../../../bin/varnishtest/tests/p00008.vtc TIMED OUT (kill -9) # top TEST ../../../../bin/varnishtest/tests/p00008.vtc FAILED (60.030) signal=9 FAIL tests/p00008.vtc (exit status: 2)