**** dT 0.000 * top TEST ../../../../bin/vinyltest/tests/r03940.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/root/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest **** 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:40405 **** top extmacro def listen_addr=127.0.0.1:0 **** top extmacro def bad_ip=192.0.2.255 **** dT 0.001 **** top extmacro def topbuild=/root/VT/vinyl-cache/vinyl-cache-trunk/_build/sub **** top extmacro def topsrc=/root/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/../.. **** top macro def testdir=/root/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/../../../../bin/vinyltest/tests **** top macro def tmpdir=/root/VT/_vtest_tmp/vtc.56748.5d8efa11 **** top macro def vtcid=vtc.56748.5d8efa11 ** top === vtest "test startup_timeout vs. stevedore init / open" * top VTEST test startup_timeout vs. stevedore init / open ** top === vinyl v1 -arg "-sdebug=debug,dinit=5s -pstartup_timeout=3s -... **** dT 0.010 ** v1 Launch *** v1 CMD: cd ${pwd} && exec vinyld -d -n /root/VT/_vtest_tmp/vtc.56748.5d8efa11/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 43927' -P /root/VT/_vtest_tmp/vtc.56748.5d8efa11/v1/vinyld.pid -p vmod_path=/root/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/vmod/.libs: -sdebug=debug,dinit=5s -pstartup_timeout=3s -pcli_timeout=2s -p feature=+no_coredump *** v1 CMD: cd /root/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest && exec vinyld -d -n /root/VT/_vtest_tmp/vtc.56748.5d8efa11/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 43927' -P /root/VT/_vtest_tmp/vtc.56748.5d8efa11/v1/vinyld.pid -p vmod_path=/root/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/vmod/.libs: -sdebug=debug,dinit=5s -pstartup_timeout=3s -pcli_timeout=2s -p feature=+no_coredump **** dT 0.011 *** v1 PID: 56764 **** v1 macro def v1_pid=56764 **** v1 macro def v1_name=/root/VT/_vtest_tmp/vtc.56748.5d8efa11/v1 **** dT 0.035 *** v1 debug|Warning: mlock() of VSM failed: Operation not permitted (1) *** v1 debug|Info: max locked memory (soft): unlimited *** v1 debug|Info: max locked memory (hard): unlimited **** dT 0.045 *** v1 debug|Debug: Version: vinyl-cache-trunk revision bc336ca02f345c1ee3a80f39b5d7d1dfbbcf2bc5 *** v1 debug|Debug: Platform: FreeBSD,15.1-RELEASE-p1,amd64,-junix,-sdebug,-sdefault,-ssynth,-hcritbit *** v1 debug|200 325 *** v1 debug|----------------------------- *** v1 debug|Vinyl Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|FreeBSD,15.1-RELEASE-p1,amd64,-junix,-sdebug,-sdefault,-ssynth,-hcritbit *** v1 debug|vinyl-cache-trunk revision bc336ca02f345c1ee3a80f39b5d7d1dfbbcf2bc5 *** 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.143 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 4 **** dT 0.144 *** v1 CLI RX 107 **** v1 CLI RX|dthuthsagzidqrcqhdnnyjqewvtfgfmn **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** v1 CLI TX|auth 7259a9f38a17439f65f439b62efb9748c40a66ca4c7cd0a5d9cd855d12e50a9c **** dT 0.146 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Vinyl Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|FreeBSD,15.1-RELEASE-p1,amd64,-junix,-sdebug,-sdefault,-ssynth,-hcritbit **** v1 CLI RX|vinyl-cache-trunk revision bc336ca02f345c1ee3a80f39b5d7d1dfbbcf2bc5 **** 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.147 **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend none none; **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.247 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.348 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.448 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.548 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.648 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.749 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.849 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.949 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.050 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.150 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.250 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.255 *** v1 CLI RX 200 **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 **** dT 1.313 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active **** dT 1.314 ** top === vinyl v1 -cliexpect \ **** v1 CLI TX|start **** dT 1.350 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.365 *** v1 debug|Debug: Child (56843) Started **** dT 1.451 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.551 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.652 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.752 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.852 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 1.952 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.053 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.153 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.253 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.354 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.454 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.554 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.655 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.755 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.855 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.956 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.056 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.156 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.257 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.357 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.457 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.557 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.658 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.758 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.858 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.959 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.059 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.159 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.260 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.360 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.412 *** v1 debug|Error: Child failed on launch within startup_timeout=3.00s *** v1 debug|Error: Child (56843) said Child starts *** v1 debug|Error: Child (56843) said -sdebug init delay 5.000000s *** v1 debug|Error: Child (56843) said -sdebug open delay in init 0.000000s **** dT 4.460 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.560 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.660 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.761 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.861 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.961 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.061 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.162 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.262 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.362 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.463 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.563 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.663 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.763 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.864 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 5.964 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.064 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.165 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.265 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.365 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 6.439 *** v1 debug|Error: Child (56843) not dying (waitpid = 0), killing *** v1 debug|Child (56843) died signal=6 **** dT 6.440 *** v1 debug|Error: Child (56843) Panic at: Tue, 14 Jul 2026 03:58:41 GMT *** v1 debug|Wrong turn at ../../../../bin/vinyld/cache/cache_main.c:388: *** v1 debug|It's time for the big quit *** v1 debug|version = vinyl-cache-trunk revision bc336ca02f345c1ee3a80f39b5d7d1dfbbcf2bc5, vrt api = 23.0 *** v1 debug|ident = FreeBSD,15.1-RELEASE-p1,amd64,-junix,-sdebug,-sdefault,-ssynth,-hcritbit,kqueue *** v1 debug|now = 1117803.121851 (mono), 1784001521.842548 (real) *** v1 debug|Backtrace: *** v1 debug| ip=0x3c3f5a sp=0x820e43f90 *** v1 debug| ip=0x2f4256 sp=0x820e43fb0 *** v1 debug| ip=0x2f3fb5 sp=0x820e43fd0 *** v1 debug| ip=0x3c3107 sp=0x820e440d0 *** v1 debug| ip=0x2edaec sp=0x820e44110 *** v1 debug| ip=0x82453844c sp=0x820e44130 *** v1 debug| ip=0x824537a5b sp=0x820e44180 *** v1 debug| ip=0x820f992d3 sp=0x820e441f0 *** v1 debug| ip=0x827f6616a sp=0x820e447a8 <__sys_nanosleep+0xa> *** v1 debug| ip=0x82453a3cc sp=0x820e447b0 *** v1 debug| ip=0x3db50c sp=0x820e447e0 *** v1 debug| ip=0x2f712a sp=0x820e44820 *** v1 debug| ip=0x2ed4b8 sp=0x820e44840 *** v1 debug| ip=0x360101 sp=0x820e44940 *** v1 debug| ip=0x360f27 sp=0x *** v1 debug|820e449b0 *** v1 debug| ip=0x3c79f5 sp=0x820e449e0 *** v1 debug| ip=0x3c7502 sp=0x820e44a20 *** v1 debug| ip=0x3c65a4 sp=0x820e44a70 *** v1 debug| ip=0x3c6129 sp=0x820e44ae0 *** v1 debug| ip=0x361ea6 sp=0x820e44f40 *** v1 debug| ip=0x3c98b1 sp=0x820e44f60 *** v1 debug| ip=0x3c9419 sp=0x820e44fb0 *** v1 debug| ip=0x366fb8 sp=0x820e44fe0 *** v1 debug| ip=0x824f0423f sp=0x820e45190 <__libc_start1+0x12f> *** v1 debug| ip=0x2a4aa4 sp=0x820e451e0 <_start+0x24> *** v1 debug|argv = { *** v1 debug| [0] = \"vinyld\", *** v1 debug| [1] = \"-d\", *** v1 debug| [2] = \"-n\", *** v1 debug| [3] = \"/root/VT/_vtest_tmp/vtc.56748.5d8efa11/v1\", *** v1 debug| [4] = \"-i\", *** v1 debug| [5] = \"v1\", *** v1 debug| [6] = \"-l\", *** v1 debug| [7] = \"2m\", *** v1 debug| [8] = \"-p\", *** v1 debug| [9] = \"auto_restart=off\", *** v1 debug| [10] = \"-p\", *** v1 debug| [11] = \"syslog_cli_traffic=off\", *** v1 debug| [12] = \"-p\", *** v1 debug| [13] = \"thread_pool_min=10\", *** v1 debug| [14] = \"-p\", *** v1 debug| [15] = \"debug=+vtc_mode\", *** v1 debug| [16] = \"-p\", *** v1 debug| [17] = \"vsl_mask=+Debug,+H2RxHdr,+H2RxBody\", *** v1 debug| [18] = \"-p\", *** v1 debug| [19] = \"h2_initial_window_size=1m\", *** v1 debug| [20] = \" *** v1 debug|-p\", *** v1 debug| [21] = \"h2_rx_window_low_water=64k\", *** v1 debug| [22] = \"-a\", *** v1 debug| [23] = \"127.0.0.1:0\", *** v1 debug| [24] = \"-M\", *** v1 debug| [25] = \"127.0.0.1 43927\", *** v1 debug| [26] = \"-P\", *** v1 debug| [27] = \"/root/VT/_vtest_tmp/vtc.56748.5d8efa11/v1/vinyld.pid\", *** v1 debug| [28] = \"-p\", *** v1 debug| [29] = \"vmod_path=/root/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/vmod/.libs:\", *** v1 debug| [30] = \"-sdebug=debug,dinit=5s\", *** v1 debug| [31] = \"-pstartup_timeout=3s\", *** v1 debug| [32] = \"-pcli_timeout=2s\", *** v1 debug| [33] = \"-p\", *** v1 debug| [34] = \"feature=+no_coredump\", *** v1 debug|} *** v1 debug|pthread.self = 0x2ef43c84e010 *** v1 debug|pthread.name = (cache-main) *** v1 debug|thr.req = NULL *** v1 debug|thr.busyobj = NULL *** v1 debug|thr.worker = NULL *** v1 debug|vmods = { *** v1 debug|}, *** v1 debug|pools = { *** v1 debug| pool = 0x2ef43de01000 { *** v1 debug| nidle = 9, *** v1 debug| nthr = 10, *** v1 debug| lqueue = 0 *** v1 debug| }, *** v1 debug| pool = 0x2ef43de01100 { *** v1 debug| nidle = 9, *** v1 debug| nthr = 10, *** v1 debug| lqueue = 0 *** v1 debug| }, *** v1 debug|}, *** v1 debug| *** v1 debug| *** v1 debug|Debug: Child cleanup complete *** v1 CLI RX 400 **** v1 CLI RX|Child failed on launch within startup_timeout=3.00s ** v1 CLI 400 ** top === shell {vinyladm -n ${v1_name} panic.clear || true } **** top shell_cmd|set -e ;exec 2>&1 ; vinyladm -n /root/VT/_vtest_tmp/vtc.56748.5d8efa11/v1 panic.clear || true **** dT 6.473 **** top shell_out| **** top shell_status = 0x0000 ** top === vinyl v1 -wait ** v1 Wait **** v1 CLI TX|backend.list **** dT 6.513 *** v1 CLI RX 101 **** v1 CLI RX|Unknown request in manager process (child not running). **** v1 CLI RX|Type 'help' for more info. ** v1 Stop **** v1 CLI TX|stop **** dT 6.553 *** v1 CLI RX 300 **** v1 CLI RX|Child in state stopped *** v1 wait-stopped **** v1 CLI TX|status **** dT 6.594 *** v1 CLI RX 200 **** v1 CLI RX|Child in state stopped **** v1 CLI TX|panic.show **** dT 6.634 *** v1 CLI RX 300 **** v1 CLI RX|Child has not panicked or panic has been cleared *** v1 debug|Info: manager stopping child *** v1 debug|Info: manager dies **** dT 6.636 **** v1 STDOUT EOF **** dT 6.667 ** v1 WAIT4 pid=56764 status=0x4000 (user 1.018485 sys 0.152371) ** top === process p1 { vinyld \ **** dT 6.679 **** p1 CMD: vinyld \ -sdebug=debug,dinit=5s \ -pstartup_timeout=3s -pcli_timeout=2s \ -n /root/VT/_vtest_tmp/vtc.56748.5d8efa11/p1 -a :0 -b none 2>&1 **** dT 6.680 *** p1 PID: 56943 **** p1 macro def p1_pid=56943 **** p1 macro def p1_dir=/root/VT/_vtest_tmp/vtc.56748.5d8efa11/p1 **** p1 macro def p1_out=/root/VT/_vtest_tmp/vtc.56748.5d8efa11/p1/term **** p1 macro def p1_err=/root/VT/_vtest_tmp/vtc.56748.5d8efa11/p1/stderr **** dT 6.684 **** p1 stderr read 0 **** dT 13.008 **** p1 stdout read 0 ** p1 WAIT4 pid=56943 status=0x0200 (user 0.000000 sys 0.010799) **** p1 macro undef p1_pid **** p1 stdout 2109 bytes, stderr 0 bytes ** top === shell {grep -q "Child failed on launch within startup_timeou... **** top shell_cmd|set -e ;exec 2>&1 ; grep -q "Child failed on launch within startup_timeout=3.00s" /root/VT/_vtest_tmp/vtc.56748.5d8efa11/p1/term **** dT 13.014 **** top shell_status = 0x0001 ---- top shell_exit not as expected: got 0x0001 wanted 0x0000 * top RESETTING after ../../../../bin/vinyltest/tests/r03940.vtc **** dT 13.015 * top TEST ../../../../bin/vinyltest/tests/r03940.vtc FAILED