**** dT 0.000 * top TEST ../../../../bin/varnishtest/tests/r02722.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:13465 **** 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/../.. **** 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.22422.2489fb16 **** top macro def vtcid=vtc.22422.2489fb16 ** top === varnishtest "TCP vs UDS sockopt inheritance" * top VTEST TCP vs UDS sockopt inheritance ** top === feature cmd {test $(uname) != SunOS} **** dT 0.002 ** top === server s0 { **** s0 macro def s0_addr=127.0.0.1 **** s0 macro def s0_port=22418 **** s0 macro def s0_sock=127.0.0.1:22418 ** s0 Starting dispatch server ** top === varnish v1 -arg {-a TCP=:0 -a "UDS=${tmpdir}/v1.sock"} ** s0 Dispatch started on 127.0.0.1:22418 **** dT 0.005 ** top === varnish v1 -cliok "param.set debug +flush_head" ** v1 Launch *** v1 CMD: cd ${pwd} && exec varnishd -d -n /root/VT/_vtest_tmp/vtc.22422.2489fb16/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 -M '127.0.0.1 56365' -P /root/VT/_vtest_tmp/vtc.22422.2489fb16/v1/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -a TCP=:0 -a "UDS=/root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock" *** v1 CMD: cd /root/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /root/VT/_vtest_tmp/vtc.22422.2489fb16/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 -M '127.0.0.1 56365' -P /root/VT/_vtest_tmp/vtc.22422.2489fb16/v1/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -a TCP=:0 -a "UDS=/root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock" **** dT 0.006 *** v1 PID: 22440 **** v1 macro def v1_pid=22440 **** v1 macro def v1_name=/root/VT/_vtest_tmp/vtc.22422.2489fb16/v1 **** dT 0.021 *** v1 debug|Debug: Version: varnish-trunk revision f37cebe89eadb4bdb00b8825a6677044ddca7c9e *** v1 debug|Debug: Platform: FreeBSD,14.2-RELEASE-p1,i386,-junix,-sdefault,-sdefault,-hcritbit *** v1 debug|200 316 *** v1 debug|----------------------------- *** v1 debug|Varnish Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|FreeBSD,14.2-RELEASE-p1,i386,-junix,-sdefault,-sdefault,-hcritbit *** v1 debug|varnish-trunk revision f37cebe89eadb4bdb00b8825a6677044ddca7c9e *** 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.123 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 6 **** dT 0.124 *** v1 CLI RX 107 **** v1 CLI RX|wjzqwoojplkzlswvedemwcnuzbdhfkev **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** v1 CLI TX|auth af0805409043851af12396821d5f4617845dd229a2e4452d356c1cf5740098ca **** dT 0.125 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Varnish Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|FreeBSD,14.2-RELEASE-p1,i386,-junix,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|varnish-trunk revision f37cebe89eadb4bdb00b8825a6677044ddca7c9e **** 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|param.set debug +flush_head **** dT 0.235 *** v1 CLI RX 200 ** v1 CLI 200 **** dT 0.236 ** top === varnish v1 -cliok "param.set timeout_idle 1" **** v1 CLI TX|param.set timeout_idle 1 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.269 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -vcl+backend { } -start **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s0 { .host = "127.0.0.1"; .port = "22418"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.338 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.440 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.542 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.645 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.747 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.858 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.948 *** v1 CLI RX 200 **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 **** dT 0.964 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.006 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 1.049 *** v1 debug|Debug: Child (22460) Started **** dT 1.097 *** v1 debug|Child launched OK **** dT 1.104 *** v1 CLI RX 200 *** v1 wait-running **** v1 CLI TX|status *** v1 debug|Info: Child (22460) said Child starts **** dT 1.158 *** v1 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address **** dT 1.178 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1742830299.000861/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1742830299.000861/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 TCP=[::]:37515 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for TCP=[::]:37515 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for TCP=[::]:37515 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for TCP=[::]:37515 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for TCP=[::]:37515 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for TCP=[::]:37515 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for TCP=[::]:37515 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for TCP=[::]:37515 **** v1 vsl| 0 Error - Kernel filtering: sock=3, errno=2 No such file or directory **** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for TCP=0.0.0.0:12602 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for TCP=0.0.0.0:12602 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for TCP=0.0.0.0:12602 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for TCP=0.0.0.0:12602 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for TCP=0.0.0.0:12602 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for TCP=0.0.0.0:12602 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for TCP=0.0.0.0:12602 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for TCP=0.0.0.0:12602 **** v1 vsl| 0 Error - Kernel filtering: sock=4, errno=2 No such file or directory **** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for UDS=/root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for UDS=/root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for UDS=/root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for UDS=/root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock **** v1 vsl| 0 Error - Kernel filtering: sock=5, errno=2 No such file or directory **** v1 vsl| 0 CLI - Wr 200 0 **** dT 1.193 *** v1 CLI RX 200 **** v1 CLI RX|TCP :: 37515 **** v1 CLI RX|TCP 0.0.0.0 12602 **** v1 CLI RX|UDS /root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock - **** v1 CLI TX|debug.xid 1000 **** dT 1.234 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address **** dT 1.279 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 84 TCP :: 37515 TCP 0.0.0.0 12602 UDS /root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock - **** 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 84 TCP :: 37515 TCP 0.0.0.0 12602 UDS /root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock - *** v1 CLI RX 200 **** v1 CLI RX|TCP :: 37515 **** v1 CLI RX|TCP 0.0.0.0 12602 **** v1 CLI RX|UDS /root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock - ** v1 Listen on :: 37515 **** v1 macro def v1_addr=:: **** v1 macro def v1_port=37515 **** v1 macro def v1_sock=[::]:37515 **** v1 macro def v1_TCP_addr=:: **** v1 macro def v1_TCP_port=37515 **** v1 macro def v1_TCP_sock=[::]:37515 **** v1 macro def v1_UDS_addr=0.0.0.0 **** v1 macro def v1_UDS_port=0 **** v1 macro def v1_UDS_sock=/root/VT/_vtest_tmp/vtc.22422.2489fb16/v1.sock ** top === client c1 { ** top === client c1 -run ** c1 Starting client ** c1 Waiting for client **** dT 1.280 ** c1 Started on [::]:37515 (1 iterations) *** c1 Connect to [::]:37515 *** c1 connected fd 16 from ::1 22884 to [::]:37515 ** c1 === txreq -req POST -hdr "Content-Length: 100" **** c1 txreq|POST / HTTP/1.1\r **** c1 txreq|Content-Length: 100\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === send some **** c1 send|some ** c1 === rxresp **** dT 1.281 **** c1 rxhdr|107 59 **** c1 rxhdr|cdhfzjcdzgfazkrhgfitaogjhwxykfig **** c1 rxhdr| **** c1 rxhdrlen = 47 **** c1 http[ 0] |107 **** c1 http[ 1] |59 **** c1 http[ 3] |cdhfzjcdzgfazkrhgfitaogjhwxykfig **** c1 bodylen = 0 ** c1 === expect resp.status == 503 ---- c1 EXPECT resp.status (59) == "503" failed * top RESETTING after ../../../../bin/varnishtest/tests/r02722.vtc **** dT 1.282 ** s0 Waiting for server (3/-1) ** v1 Wait **** v1 CLI TX|panic.show **** dT 1.324 *** v1 CLI RX 300 **** v1 CLI RX|Child has not panicked or panic has been cleared *** v1 debug|Info: manager stopping child *** v1 debug|Debug: Stopping Child **** dT 1.387 **** v1 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 1.433 *** v1 debug|Info: Child (22460) said Child dies **** dT 1.434 *** v1 debug|Info: Child (22460) ended **** dT 1.442 *** v1 debug|Debug: Child cleanup complete *** v1 debug|Info: manager dies **** dT 1.454 **** v1 STDOUT EOF **** dT 1.489 ** v1 WAIT4 pid=22440 status=0x0000 (user 0.356736 sys 0.037950) * top TEST ../../../../bin/varnishtest/tests/r02722.vtc FAILED # top TEST ../../../../bin/varnishtest/tests/r02722.vtc FAILED (1.490) exit=2 FAIL tests/r02722.vtc (exit status: 2)