**** dT 0.000
* top TEST ../../../../bin/vinyltest/tests/b00074.vtc starting
**** top extmacro def pkg_version=trunk
**** top extmacro def pkg_branch=trunk
**** top extmacro def pwd=/Users/mcarine/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:55058
**** top extmacro def listen_addr=127.0.0.1:0
**** top extmacro def bad_ip=192.0.2.255
**** top extmacro def topbuild=/Users/mcarine/VT/vinyl-cache/vinyl-cache-trunk/_build/sub
**** top extmacro def topsrc=/Users/mcarine/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/../..
**** top macro def testdir=/Users/mcarine/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/../../../../bin/vinyltest/tests
**** top macro def tmpdir=/var/folders/j5/7zzsd8nj1pdc64vg52sfknx40000gn/T//_vtest_tmp/vtc.29531.37d12af4
**** top macro def vtcid=vtc.29531.37d12af4
** top === vtest "Test logexpect fail command"
* top VTEST Test logexpect fail command
** top === vinyl v1 -vcl {
**** dT 0.007
** v1 Launch
*** v1 CMD: cd ${pwd} && exec vinyld -d -n /var/folders/j5/7zzsd8nj1pdc64vg52sfknx40000gn/T//_vtest_tmp/vtc.29531.37d12af4/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 55059' -P /var/folders/j5/7zzsd8nj1pdc64vg52sfknx40000gn/T//_vtest_tmp/vtc.29531.37d12af4/v1/vinyld.pid -p vmod_path=/Users/mcarine/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/vmod/.libs:
**** dT 0.008
*** v1 CMD: cd /Users/mcarine/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest && exec vinyld -d -n /var/folders/j5/7zzsd8nj1pdc64vg52sfknx40000gn/T//_vtest_tmp/vtc.29531.37d12af4/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 55059' -P /var/folders/j5/7zzsd8nj1pdc64vg52sfknx40000gn/T//_vtest_tmp/vtc.29531.37d12af4/v1/vinyld.pid -p vmod_path=/Users/mcarine/VT/vinyl-cache/vinyl-cache-trunk/_build/sub/vmod/.libs:
*** v1 PID: 29549
**** v1 macro def v1_pid=29549
**** v1 macro def v1_name=/var/folders/j5/7zzsd8nj1pdc64vg52sfknx40000gn/T//_vtest_tmp/vtc.29531.37d12af4/v1
**** dT 0.029
*** v1 debug|Debug: Version: vinyl-cache-trunk revision 038401c68bfafffff399f364d7845115d7753e0a
*** v1 debug|Debug: Platform: Darwin,24.5.0,arm64,-jnone,-sdefault,-sdefault,-ssynth,-hcritbit
*** v1 debug|200 317
*** v1 debug|-----------------------------
*** v1 debug|Vinyl Cache CLI 1.0
*** v1 debug|-----------------------------
*** v1 debug|Darwin,24.5.0,arm64,-jnone,-sdefault,-sdefault,-ssynth,-hcritbit
*** v1 debug|vinyl-cache-trunk revision 038401c68bfafffff399f364d7845115d7753e0a
*** 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.127
**** v1 CLIPOLL 1 0x1 0x0 0x0
*** v1 CLI connection fd = 5
*** v1 CLI RX 107
**** v1 CLI RX|iqyfqcvelpivshvnsuqendtfnshigirn
**** v1 CLI RX|
**** v1 CLI RX|Authentication required.
**** dT 0.128
**** v1 CLI TX|auth b7edea775437f2a5e460418743cac54450aa27af88b2fe8cd362d331be1f4cff
*** v1 CLI RX 200
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Vinyl Cache CLI 1.0
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Darwin,24.5.0,arm64,-jnone,-sdefault,-sdefault,-ssynth,-hcritbit
**** v1 CLI RX|vinyl-cache-trunk revision 038401c68bfafffff399f364d7845115d7753e0a
**** 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 std;
**** v1 CLI TX|
**** v1 CLI TX|\tbackend proforma None;
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_init {
**** v1 CLI TX|\t\tstd.log("i0");
**** v1 CLI TX|\t\tstd.log("i1");
**** v1 CLI TX|\t\tstd.log("i2");
**** v1 CLI TX|\t\tstd.log("i3");
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_recv {
**** v1 CLI TX|\t\tstd.log("r0");
**** v1 CLI TX|\t\tstd.log("r1");
**** v1 CLI TX|\t\tstd.log("r2");
**** v1 CLI TX|\t\tstd.log("r3");
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|%XJEIFLH|)Xspa8P
**** dT 0.238
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.340
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.414
*** v1 CLI RX 200
**** v1 CLI RX|VCL compiled.
**** v1 CLI TX|vcl.use vcl1
*** v1 CLI RX 200
**** v1 CLI RX|VCL 'vcl1' now active
** v1 Start
**** v1 CLI TX|start
**** dT 0.419
*** v1 debug|Debug: Child (29559) Started
**** dT 0.452
*** v1 debug|Child launched OK
**** dT 0.556
*** v1 debug|Info: Child (29559) said Child starts
*** v1 CLI RX 200
*** v1 wait-running
**** v1 CLI TX|status
**** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1781218444.659540/vgc.so 1auto
**** v1 vsl| 0 VCL_Log - i0
**** v1 vsl| 0 VCL_Log - i1
**** v1 vsl| 0 VCL_Log - i2
**** v1 vsl| 0 VCL_Log - i3
**** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1781218444.659540/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:55061
**** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:55061
**** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:55061
**** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:55061
**** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:55061
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPALIVE for a0=127.0.0.1:55061
**** v1 vsl| 0 CLI - Wr 200 0
*** v1 CLI RX 200
**** v1 CLI RX|Child in state running
**** v1 CLI TX|debug.listen_address
**** dT 0.557
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 55061
**** v1 CLI TX|debug.xid 1000
*** v1 CLI RX 200
**** v1 CLI RX|XID is 1000 chunk 1
**** v1 CLI TX|debug.listen_address
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 55061
** v1 Listen on 127.0.0.1 55061
**** v1 macro def v1_addr=127.0.0.1
**** v1 macro def v1_port=55061
**** v1 macro def v1_sock=127.0.0.1:55061
**** v1 macro def v1_a0_addr=127.0.0.1
**** v1 macro def v1_a0_port=55061
**** v1 macro def v1_a0_sock=127.0.0.1:55061
** top === logexpect l1 -v v1 -g vxid -q "vxid == 1001" {
** l1 === fail add * Error "out of workspace"
** l1 === fail add * VCL_Error "Workspace overflow"
** l1 === expect * 1001 End
** l1 === fail clear
**** dT 0.558
** top === logexpect l2 -v v1 -err -g vxid -q "vxid == 1001" {
**** l1 begin|
**** l1 qry | vxid == 1001
*** l1 cond | fail add * Error out of workspace
*** l1 cond | fail add * VCL_Error Workspace overflow
*** l1 test | expect * 1001 End
** l2 === fail add * VCL_Log ^r2
** top === logexpect l3 -v v1 -g vxid -q "vxid == 1001" {
**** l2 begin|
**** l2 qry | vxid == 1001
*** l2 cond | fail add * VCL_Log ^r2
** l3 === fail add * VCL_Log ^r2
** l3 === expect * 1001 VCL_Log ^r0
** l3 === expect 0 = VCL_Log ^r1
** l3 === fail clear
** l3 === expect 1 = VCL_Log ^r3
** top === client c1 {
**** l3 begin|
**** l3 qry | vxid == 1001
*** l3 cond | fail add * VCL_Log ^r2
*** l3 test | expect * 1001 VCL_Log ^r0
** c1 Starting client
** c1 Waiting for client
** c1 Started on 127.0.0.1:55061 (1 iterations)
*** c1 Connect to 127.0.0.1:55061
**** dT 0.559
*** c1 connected fd 30 from 127.0.0.1 55065 to 127.0.0.1:55061
** c1 === txreq
**** c1 txreq|GET / HTTP/1.1\r
**** c1 txreq|Host: 127.0.0.1\r
**** c1 txreq|User-Agent: c1\r
**** c1 txreq|\r
** c1 === rxresp
**** dT 0.560
**** c1 rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c1 rxhdr|Date: Thu, 11 Jun 2026 22:54:05 GMT\r
**** c1 rxhdr|Server: Vinyl-Cache\r
**** c1 rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1 rxhdr|Retry-After: 5\r
**** c1 rxhdr|X-Vinyl: 1001\r
**** c1 rxhdr|Age: 0\r
**** c1 rxhdr|Via: 1.1 v1 (Vinyl-Cache/trunk)\r
**** c1 rxhdr|Content-Length: 279\r
**** c1 rxhdr|Connection: keep-alive\r
**** c1 rxhdr|\r
**** c1 rxhdrlen = 252
**** c1 http[ 0] |HTTP/1.1
**** c1 http[ 1] |503
**** c1 http[ 2] |Backend fetch failed
**** c1 http[ 3] |Date: Thu, 11 Jun 2026 22:54:05 GMT
**** c1 http[ 4] |Server: Vinyl-Cache
**** c1 http[ 5] |Content-Type: text/html; charset=utf-8
**** c1 http[ 6] |Retry-After: 5
**** c1 http[ 7] |X-Vinyl: 1001
**** c1 http[ 8] |Age: 0
**** c1 http[ 9] |Via: 1.1 v1 (Vinyl-Cache/trunk)
**** c1 http[10] |Content-Length: 279
**** c1 http[11] |Connection: keep-alive
**** c1 c-l|
**** c1 c-l|
**** c1 c-l|
**** c1 c-l| 503 Backend fetch failed
**** c1 c-l|
**** c1 c-l|
**** c1 c-l| Error 503 Backend fetch failed
**** c1 c-l| Backend fetch failed
**** c1 c-l| Guru Meditation:
**** c1 c-l| XID: 1002
**** c1 c-l|
**** c1 c-l| Vinyl Cache server
**** c1 c-l|
**** c1 c-l|
**** c1 bodylen = 279
*** c1 closing fd 30
** c1 Ending
** top === logexpect l4 -v v1 -d 1 -g raw {
** l4 === fail add * VCL_Log ^i2
**** dT 0.561
** l4 === expect * 0 VCL_Log ^i0
** l4 === expect 0 = VCL_Log ^i1
** l4 === fail clear
** l4 === expect 1 = VCL_Log ^i3
** l4 === fail add * Error "out of workspace"
** l4 === fail add * VCL_Error "Workspace overflow"
** l4 === expect * 1000 End
** l4 === fail clear
** top === logexpect l1 -wait
** l1 Waiting for logexp
**** l4 begin|
*** l4 cond | fail add * VCL_Log ^i2
*** l4 test | expect * 0 VCL_Log ^i0
**** l4 match| 0 VCL_Log - i0
*** l4 test | expect 0 = VCL_Log ^i1
**** l4 match| 0 VCL_Log - i1
*** l4 cond | fail clear
*** l4 test | expect 1 = VCL_Log ^i3
**** l4 match| 0 VCL_Log - i3
*** l4 cond | fail add * Error out of workspace
*** l4 cond | fail add * VCL_Error Workspace overflow
*** l4 test | expect * 1000 End
**** l4 match| 1000 End c
*** l4 cond | fail clear
**** l4 done |
**** dT 0.573
**** l2 fail | 1001 VCL_Log c r2
**** l2 done | failed as expected
**** l3 match| 1001 VCL_Log c r0
*** l3 test | expect 0 = VCL_Log ^r1
**** l3 match| 1001 VCL_Log c r1
*** l3 cond | fail clear
*** l3 test | expect 1 = VCL_Log ^r3
**** l3 match| 1001 VCL_Log c r3
**** l3 done |
* diag 0.0 Assert error in logexp_failchk(), ../../../../bin/vinyltest/vtest2/src/vtc_logexp.c line 484:
* diag 0.0 Condition(r == LEM_FAIL) not true. (errno=60 Operation timed out)
* diag 0.0 Backtrace:
* diag 0.0 ip=0x1046b7e8c sp=0x16ba11b60
* diag 0.0 ip=0x1046b8418 sp=0x16ba11b80
* diag 0.0 ip=0x1045bc570 sp=0x16ba11bf0
* diag 0.0 ip=0x1046b6de0 sp=0x16ba12d00
* diag 0.0 ip=0x1045bf734 sp=0x16ba12d40
* diag 0.0 ip=0x1045bf3e8 sp=0x16ba12d90
* diag 0.0 ip=0x1046a4218 sp=0x16ba12e00
* diag 0.0 ip=0x10469f918 sp=0x16ba12f00
* diag 0.0 ip=0x10469ec60 sp=0x16ba12f40
* diag 0.0 ip=0x1045bec58 sp=0x16ba12f90
* diag 0.0 ip=0x19e21ac0c sp=0x16ba12fd0 <_pthread_start+0x88>
* diag 0.0