**** dT 0.000
* top TEST ../../../../bin/varnishtest/tests/e00003.vtc starting
**** top extmacro def pkg_version=trunk
**** top extmacro def pkg_branch=trunk
**** top extmacro def pwd=/tmp/vtest.clang/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:46339
**** top extmacro def listen_addr=127.0.0.1:0
**** top extmacro def bad_ip=192.0.2.255
**** top extmacro def topbuild=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub
**** top extmacro def topsrc=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/../..
**** top macro def testdir=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests
**** top macro def tmpdir=/tmp/vtest.clang/_vtest_tmp/vtc.1386.570483f1
**** top macro def vtcid=vtc.1386.570483f1
** top === varnishtest "ESI include"
* top VTEST ESI include
** top === feature cmd "command -v diff"
**** dT 0.006
** top === server s1 {
** s1 Starting server
**** s1 macro def s1_addr=127.0.0.1
**** s1 macro def s1_port=44991
**** s1 macro def s1_sock=127.0.0.1:44991
* s1 Listen on 127.0.0.1:44991
** top === varnish v1 -vcl+backend {
**** dT 0.010
** s1 Started on 127.0.0.1:44991 (1 iterations)
**** dT 0.033
** v1 Launch
*** v1 CMD: cd ${pwd} && exec varnishd -d -n /tmp/vtest.clang/_vtest_tmp/vtc.1386.570483f1/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 33085' -P /tmp/vtest.clang/_vtest_tmp/vtc.1386.570483f1/v1/varnishd.pid -p vmod_path=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/vmod/.libs
*** v1 CMD: cd /tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /tmp/vtest.clang/_vtest_tmp/vtc.1386.570483f1/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 33085' -P /tmp/vtest.clang/_vtest_tmp/vtc.1386.570483f1/v1/varnishd.pid -p vmod_path=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/vmod/.libs
**** dT 0.034
*** v1 PID: 1490
**** v1 macro def v1_pid=1490
**** v1 macro def v1_name=/tmp/vtest.clang/_vtest_tmp/vtc.1386.570483f1/v1
**** dT 0.076
*** v1 debug|Debug: Version: varnish-trunk revision d6237329599edd78fc4e815ced49b51380db0902
*** v1 debug|Debug: Platform: Linux,4.19.0-17-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
*** v1 debug|200 316
*** v1 debug|-----------------------------
*** v1 debug|Varnish Cache CLI 1.0
*** v1 debug|-----------------------------
*** v1 debug|Linux,4.19.0-17-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
*** v1 debug|varnish-trunk revision d6237329599edd78fc4e815ced49b51380db0902
*** 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.177
**** v1 CLIPOLL 1 0x1 0x0 0x0
*** v1 CLI connection fd = 7
**** dT 0.178
*** v1 CLI RX 107
**** v1 CLI RX|krotjdynjpzlcoqeylqoenarpzrjwkkm
**** v1 CLI RX|
**** v1 CLI RX|Authentication required.
**** v1 CLI TX|auth dd738a4ec6f92b9dfab49a991cedf79429348c7ae499325d61ada3602e3bc04c
**** dT 0.179
*** v1 CLI RX 200
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Varnish Cache CLI 1.0
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Linux,4.19.0-17-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
**** v1 CLI RX|varnish-trunk revision d6237329599edd78fc4e815ced49b51380db0902
**** 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.180
**** 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 = "44991"; }
**** v1 CLI TX|
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_synth {
**** v1 CLI TX|\t\tset resp.body = """
**** v1 CLI TX|\t\t""";
**** v1 CLI TX|\t\treturn (deliver);
**** v1 CLI TX|\t}
**** v1 CLI TX|\tsub vcl_recv {
**** v1 CLI TX|\t\tif (req.esi_level > 0) {
**** v1 CLI TX|\t\t\tset req.url = req.url + req.esi_level;
**** v1 CLI TX|\t\t\tif (req.url ~ "^/synth") {
**** v1 CLI TX|\t\t\t\treturn (synth(3200));
**** v1 CLI TX|\t\t\t}
**** v1 CLI TX|\t\t} else {
**** v1 CLI TX|\t\t\tset req.http.esi0 = "foo";
**** v1 CLI TX|\t\t}
**** v1 CLI TX|\t}
**** v1 CLI TX|\tsub vcl_backend_response {
**** v1 CLI TX|\t\tif (bereq.url == "/") {
**** v1 CLI TX|\t\t\tset beresp.do_esi = true;
**** v1 CLI TX|\t\t}
**** v1 CLI TX|\t}
**** v1 CLI TX|\tsub vcl_deliver {
**** v1 CLI TX|\t\tset resp.http.can_esi = obj.can_esi;
**** v1 CLI TX|
**** v1 CLI TX|\t\t# make ReqAcct deterministic
**** v1 CLI TX|\t\tunset resp.http.via;
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|%XJEIFLH|)Xspa8P
**** dT 0.286
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.390
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.492
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.593
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.697
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.809
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.909
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.013
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.115
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.216
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.318
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.349
*** v1 CLI RX 200
**** v1 CLI RX|VCL compiled.
**** v1 CLI TX|vcl.use vcl1
**** dT 1.350
*** v1 CLI RX 200
**** v1 CLI RX|VCL 'vcl1' now active
** v1 Start
**** v1 CLI TX|start
**** dT 1.421
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.433
*** v1 debug|Debug: Child (1899) Started
**** dT 1.466
*** v1 debug|Child launched OK
**** dT 1.468
*** v1 CLI RX 200
*** v1 wait-running
**** v1 CLI TX|status
*** v1 CLI RX 200
**** v1 CLI RX|Child in state running
**** v1 CLI TX|debug.listen_address
*** v1 debug|Info: Child (1899) said Child starts
**** dT 1.510
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 40263
**** v1 CLI TX|debug.xid 1000
**** dT 1.522
**** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1747985872.295205/vgc.so 1auto
**** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1747985872.295205/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:40263
**** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:40263
**** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:40263
**** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:40263
**** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:40263
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:40263
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:40263
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:40263
**** v1 vsl| 0 CLI - Wr 200 0
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 40263
**** dT 1.557
*** v1 CLI RX 200
**** v1 CLI RX|XID is 1000 chunk 1
**** v1 CLI TX|debug.listen_address
**** dT 1.605
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 40263
** v1 Listen on 127.0.0.1 40263
**** v1 macro def v1_addr=127.0.0.1
**** v1 macro def v1_port=40263
**** dT 1.606
**** v1 macro def v1_sock=127.0.0.1:40263
**** v1 macro def v1_a0_addr=127.0.0.1
**** v1 macro def v1_a0_port=40263
**** v1 macro def v1_a0_sock=127.0.0.1:40263
** top === logexpect l1 -v v1 -g request {
** l1 === expect 0 1001 Begin "^req .* rxreq"
** l1 === expect * = ReqAcct "^45 0 45 182 75 257$"
** l1 === expect 0 = End
** top === logexpect l2 -v v1 -g request {
** l2 === expect * 1002 Begin "^bereq "
** l2 === expect * = End
** top === logexpect l3 -v v1 -g request {
** l3 === expect * 1003 Begin "^req .* esi"
** l3 === expect * = ReqAcct "^0 0 0 0 18 18$"
** l3 === expect 0 = End
**** dT 1.607
** top === logexpect l4 -v v1 -g request {
** l4 === expect * 1004 Begin "^bereq "
** l4 === expect * = End
** top === logexpect l5 -v v1 -g request {
** l5 === expect * 1006 Begin "^req .* rxreq"
** l5 === expect * = ReqAcct "^45 0 45 187 75 262$"
** l5 === expect 0 = End
** top === client c1 {
** top === client c1 -run
** c1 Starting client
**** dT 1.610
** c1 Waiting for client
**** dT 1.616
**** l5 begin|
*** l5 test | expect * 1006 Begin ^req .* rxreq
**** dT 1.617
**** l4 begin|
*** l4 test | expect * 1004 Begin ^bereq
**** l3 begin|
*** l3 test | expect * 1003 Begin ^req .* esi
**** l1 begin|
*** l1 test | expect 0 1001 Begin ^req .* rxreq
** c1 Started on 127.0.0.1:40263 (1 iterations)
*** c1 Connect to 127.0.0.1:40263
*** c1 connected fd 42 from 127.0.0.1 50656 to 127.0.0.1:40263
** c1 === txreq -hdr "Host: foo"
**** dT 1.618
**** c1 txreq|GET / HTTP/1.1\r
**** c1 txreq|Host: foo\r
**** c1 txreq|User-Agent: c1\r
**** c1 txreq|\r
** c1 === rxresp
**** dT 1.622
**** 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 19 a0 127.0.0.1 40263
**** v1 vsl| 1000 Begin c sess 0 HTTP/1
**** v1 vsl| 1000 SessOpen c 127.0.0.1 50656 a0 127.0.0.1 40263 1747985873.736839 21
**** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:40263
**** v1 vsl| 1000 Debug c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:40263
**** v1 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:40263
**** v1 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:40263
**** v1 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:40263
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:40263
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:40263
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:40263
**** v1 vsl| 1000 Link c req 1001 rxreq
**** l2 begin|
*** l2 test | expect * 1002 Begin ^bereq
**** dT 1.624
*** s1 accepted fd 5 127.0.0.1 44410
** s1 === rxreq
**** s1 rxhdr|GET / HTTP/1.1\r
**** s1 rxhdr|Host: foo\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|esi0: foo\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] |/
**** s1 http[ 2] |HTTP/1.1
**** s1 http[ 3] |Host: foo
**** 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] |esi0: foo
**** s1 http[ 8] |Accept-Encoding: gzip
**** s1 http[ 9] |X-Varnish: 1002
**** s1 bodylen = 0
** s1 === expect req.http.esi0 == "foo"
**** s1 EXPECT req.http.esi0 (foo) == "foo" match
** s1 === txresp -body {
**** s1 txresp|HTTP/1.1 200 OK\r
**** s1 txresp|Date: Fri, 23 May 2025 07:37:53 GMT\r
**** s1 txresp|Server: s1\r
**** s1 txresp|Content-Length: 116\r
**** s1 txresp|\r
**** s1 txresp|
**** s1 txresp|\t\t
**** s1 txresp|\t\tBefore include
**** s1 txresp|\t\tAfter include
**** s1 txresp|\t\t
**** s1 txresp|\t
** s1 === rxreq
**** dT 1.745
**** c1 rxhdr|HTTP/1.1 200 OK\r
**** c1 rxhdr|Date: Fri, 23 May 2025 07:37:53 GMT\r
**** c1 rxhdr|Server: s1\r
**** c1 rxhdr|X-Varnish: 1001\r
**** c1 rxhdr|Age: 0\r
**** c1 rxhdr|Accept-Ranges: bytes\r
**** c1 rxhdr|can_esi: true\r
**** c1 rxhdr|Connection: keep-alive\r
**** c1 rxhdr|Transfer-Encoding: chunked\r
**** c1 rxhdr|\r
**** c1 rxhdrlen = 182
**** dT 1.746
**** c1 http[ 0] |HTTP/1.1
**** c1 http[ 1] |200
**** c1 http[ 2] |OK
**** c1 http[ 3] |Date: Fri, 23 May 2025 07:37:53 GMT
**** c1 http[ 4] |Server: s1
**** c1 http[ 5] |X-Varnish: 1001
**** c1 http[ 6] |Age: 0
**** c1 http[ 7] |Accept-Ranges: bytes
**** c1 http[ 8] |can_esi: true
**** c1 http[ 9] |Connection: keep-alive
**** c1 http[10] |Transfer-Encoding: chunked
**** c1 len|001d\r
**** c1 chunk|
**** c1 chunk|\t\t
**** c1 chunk|\t\tBefore include
**** c1 chunk|\t\t
**** s1 rxhdr|GET /body1 HTTP/1.1\r
**** s1 rxhdr|Host: foo\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 = 147
**** s1 http[ 0] |GET
**** s1 http[ 1] |/body1
**** s1 http[ 2] |HTTP/1.1
**** s1 http[ 3] |Host: foo
**** 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 == "/body1"
**** s1 EXPECT req.url (/body1) == "/body1" match
** s1 === expect req.http.esi0 != "foo"
**** s1 EXPECT req.http.esi0 () != "foo" match
** s1 === txresp -body {
**** s1 txresp|HTTP/1.1 200 OK\r
**** s1 txresp|Date: Fri, 23 May 2025 07:37:53 GMT\r
**** s1 txresp|Server: s1\r
**** s1 txresp|Content-Length: 18\r
**** s1 txresp|\r
**** s1 txresp|
**** s1 txresp|\t\tIncluded file
**** s1 txresp|\t
*** s1 shutting fd 5 (server run)
** s1 Ending
**** dT 1.757
**** c1 len|0012\r
**** c1 chunk|
**** c1 chunk|\t\tIncluded file
**** c1 chunk|\t
**** dT 1.758
**** c1 len|003\r
**** c1 chunk|
**** c1 chunk|\t\t
**** c1 len|0019\r
**** c1 chunk|After include
**** c1 chunk|\t\t
**** c1 chunk|\t
**** c1 len|0\r
**** c1 chunked|
**** c1 chunked|\t\t
**** c1 chunked|\t\tBefore include
**** c1 chunked|\t\t
**** c1 chunked|\t\tIncluded file
**** c1 chunked|\t
**** c1 chunked|\t\tAfter include
**** c1 chunked|\t\t
**** c1 chunked|\t
**** c1 bodylen = 75
** c1 === expect resp.bodylen == 75
**** c1 EXPECT resp.bodylen (75) == "75" match
** c1 === expect resp.status == 200
**** c1 EXPECT resp.status (200) == "200" match
** c1 === expect resp.http.can_esi == "true"
**** c1 EXPECT resp.http.can_esi (true) == "true" match
** c1 === delay .1
*** c1 delaying 0.1 second(s)
**** dT 1.849
**** v1 vsl| 1003 Begin c req 1001 esi 1
**** v1 vsl| 1003 Timestamp c Start: 1747985873.859237 0.000000 0.000000
**** v1 vsl| 1003 ReqURL c /body
**** v1 vsl| 1003 ReqStart c 127.0.0.1 50656 a0
**** v1 vsl| 1003 ReqMethod c GET
**** v1 vsl| 1003 ReqURL c /body
**** v1 vsl| 1003 ReqProtocol c HTTP/1.1
**** v1 vsl| 1003 ReqHeader c Host: foo
**** 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 ReqURL c /body1
**** 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: 1747985873.865180 0.005943 0.005943
**** 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 Date: Fri, 23 May 2025 07:37:53 GMT
**** v1 vsl| 1003 RespHeader c Server: s1
**** v1 vsl| 1003 RespHeader c Content-Length: 18
**** 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 RespHeader c can_esi: false
**** v1 vsl| 1003 RespUnset c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1003 VCL_return c deliver
**** v1 vsl| 1003 Timestamp c Process: 1747985873.865208 0.005971 0.000028
**** v1 vsl| 1003 Filters c
**** v1 vsl| 1003 Timestamp c Resp: 1747985873.872666 0.013429 0.007458
**** v1 vsl| 1003 ReqAcct c 0 0 0 0 18 18
**** v1 vsl| 1003 End c
**** v1 vsl| 1004 Begin b bereq 1003 fetch
**** v1 vsl| 1004 VCL_use b vcl1
**** v1 vsl| 1004 Timestamp b Start: 1747985873.860139 0.000000 0.000000
**** v1 vsl| 1004 BereqMethod b GET
**** v1 vsl| 1004 BereqURL b /body1
**** v1 vsl| 1004 BereqProtocol b HTTP/1.1
**** v1 vsl| 1004 BereqHeader b Host: foo
**** 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: 1747985873.860272 0.000133 0.000133
**** v1 vsl| 1004 Timestamp b Connected: 1747985873.860281 0.000142 0.000009
**** v1 vsl| 1004 BackendOpen b 24 s1 127.0.0.1 44991 127.0.0.1 44410 reuse
**** v1 vsl| 1004 Timestamp b Bereq: 1747985873.860344 0.000205 0.000062
**** 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 Date: Fri, 23 May 2025 07:37:53 GMT
**** v1 vsl| 1004 BerespHeader b Server: s1
**** v1 vsl| 1004 BerespHeader b Content-Length: 18
**** v1 vsl| 1004 Timestamp b Beresp: 1747985873.862084 0.001945 0.001739
**** v1 vsl| 1004 TTL b RFC 120 10 0 1747985874 1747985874 1747985873 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: 1747985873.862225 0.002086 0.000141
**** v1 vsl| 1004 Filters b
**** v1 vsl| 1004 Storage b malloc s0
**** v1 vsl| 1004 Fetch_Body b 3 length stream
**** v1 vsl| 1004 BackendClose b 24 s1 recycle
**** v1 vsl| 1004 Timestamp b BerespBody: 1747985873.872630 0.012491 0.010404
**** v1 vsl| 1004 Length b 18
**** v1 vsl| 1004 BereqAcct b 147 0 147 88 18 106
**** v1 vsl| 1004 End b
**** v1 vsl| 1005 Begin c req 1001 esi 1
**** v1 vsl| 1005 Timestamp c Start: 1747985873.872865 0.000000 0.000000
**** v1 vsl| 1005 ReqURL c /synth
**** v1 vsl| 1005 ReqStart c 127.0.0.1 50656 a0
**** v1 vsl| 1005 ReqMethod c GET
**** v1 vsl| 1005 ReqURL c /synth
**** v1 vsl| 1005 ReqProtocol c HTTP/1.1
**** v1 vsl| 1005 ReqHeader c Host: foo
**** v1 vsl| 1005 ReqHeader c User-Agent: c1
**** v1 vsl| 1005 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1005 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1005 VCL_call c RECV
**** v1 vsl| 1005 ReqURL c /synth1
**** v1 vsl| 1005 VCL_return c synth
**** v1 vsl| 1005 VCL_call c HASH
**** v1 vsl| 1005 VCL_return c lookup
**** v1 vsl| 1005 RespProtocol c HTTP/1.1
**** v1 vsl| 1005 RespStatus c 200
**** v1 vsl| 1005 RespReason c OK
**** v1 vsl| 1005 RespHeader c Date: Fri, 23 May 2025 07:37:53 GMT
**** v1 vsl| 1005 RespHeader c Server: Varnish
**** v1 vsl| 1005 RespHeader c X-Varnish: 1005
**** v1 vsl| 1005 VCL_call c SYNTH
**** v1 vsl| 1005 VCL_return c deliver
**** v1 vsl| 1005 Timestamp c Process: 1747985873.873141 0.000276 0.000276
**** v1 vsl| 1005 RespHeader c Content-Length: 3
**** v1 vsl| 1005 Storage c malloc Transient
**** v1 vsl| 1005 Filters c
**** v1 vsl| 1005 Timestamp c Resp: 1747985873.873352 0.000487 0.000211
**** v1 vsl| 1005 ReqAcct c 0 0 0 0 3 3
**** v1 vsl| 1005 End c
**** v1 vsl| 1001 Begin c req 1000 rxreq
**** v1 vsl| 1001 Timestamp c Start: 1747985873.736917 0.000000 0.000000
**** v1 vsl| 1001 Timestamp c Req: 1747985873.736917 0.000000 0.000000
**** v1 vsl| 1001 VCL_use c vcl1
**** v1 vsl| 1001 ReqStart c 127.0.0.1 50656 a0
**** v1 vsl| 1001 ReqMethod c GET
**** v1 vsl| 1001 ReqURL c /
**** v1 vsl| 1001 ReqProtocol c HTTP/1.1
**** v1 vsl| 1001 ReqHeader c Host: foo
**** 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 ReqHeader c esi0: foo
**** 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: 1747985873.858425 0.121508 0.121508
**** 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 Date: Fri, 23 May 2025 07:37:53 GMT
**** v1 vsl| 1001 RespHeader c Server: s1
**** v1 vsl| 1001 RespHeader c Content-Length: 116
**** 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 RespHeader c can_esi: true
**** v1 vsl| 1001 RespUnset c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1001 VCL_return c deliver
**** v1 vsl| 1001 Timestamp c Process: 1747985873.859144 0.122226 0.000718
**** v1 vsl| 1001 Filters c esi
**** v1 vsl| 1001 RespUnset c Content-Length: 116
**** v1 vsl| 1001 RespHeader c Connection: keep-alive
**** v1 vsl| 1001 RespHeader c Transfer-Encoding: chunked
**** v1 vsl| 1001 Link c req 1003 esi 1
**** v1 vsl| 1001 Link c req 1005 esi 1
**** v1 vsl| 1001 Timestamp c Resp: 1747985873.873414 0.136497 0.014270
**** v1 vsl| 1001 ReqAcct c 45 0 45 182 75 257
**** v1 vsl| 1001 End c
**** dT 1.860
** c1 === txreq -hdr "Host: foo"
**** c1 txreq|GET / HTTP/1.1\r
**** c1 txreq|Host: foo\r
**** c1 txreq|User-Agent: c1\r
**** c1 txreq|\r
** c1 === rxresp
**** dT 1.866
**** c1 rxhdr|HTTP/1.1 200 OK\r
**** c1 rxhdr|Date: Fri, 23 May 2025 07:37:53 GMT\r
**** c1 rxhdr|Server: s1\r
**** c1 rxhdr|X-Varnish: 1006 1002\r
**** c1 rxhdr|Age: 0\r
**** c1 rxhdr|Accept-Ranges: bytes\r
**** c1 rxhdr|can_esi: true\r
**** c1 rxhdr|Connection: keep-alive\r
**** c1 rxhdr|Transfer-Encoding: chunked\r
**** c1 rxhdr|\r
**** c1 rxhdrlen = 187
**** c1 http[ 0] |HTTP/1.1
**** c1 http[ 1] |200
**** c1 http[ 2] |OK
**** c1 http[ 3] |Date: Fri, 23 May 2025 07:37:53 GMT
**** c1 http[ 4] |Server: s1
**** c1 http[ 5] |X-Varnish: 1006 1002
**** c1 http[ 6] |Age: 0
**** c1 http[ 7] |Accept-Ranges: bytes
**** c1 http[ 8] |can_esi: true
**** c1 http[ 9] |Connection: keep-alive
**** c1 http[10] |Transfer-Encoding: chunked
**** c1 len|001d\r
**** c1 chunk|
**** c1 chunk|\t\t
**** c1 chunk|\t\tBefore include
**** c1 chunk|\t\t
**** c1 len|0012\r
**** c1 chunk|
**** c1 chunk|\t\tIncluded file
**** c1 chunk|\t
**** c1 len|003\r
**** c1 chunk|
**** c1 chunk|\t\t
**** c1 len|0019\r
**** c1 chunk|After include
**** c1 chunk|\t\t
**** c1 chunk|\t
**** c1 len|0\r
**** c1 chunked|
**** c1 chunked|\t\t
**** c1 chunked|\t\tBefore include
**** c1 chunked|\t\t
**** c1 chunked|\t\tIncluded file
**** c1 chunked|\t
**** c1 chunked|\t\tAfter include
**** c1 chunked|\t\t
**** c1 chunked|\t
**** c1 bodylen = 75
** c1 === expect resp.bodylen == 75
**** c1 EXPECT resp.bodylen (75) == "75" match
** c1 === expect resp.status == 200
**** c1 EXPECT resp.status (200) == "200" match
** c1 === expect resp.http.can_esi == "true"
**** c1 EXPECT resp.http.can_esi (true) == "true" match
*** c1 closing fd 42
** c1 Ending
** top === varnish v1 -expect esi_req == 4
**** dT 1.868
**** l1 err | 1006 Begin c req 1000 rxreq
---- l1 bad | expectation failed
---- l3 bad | outstanding expectations
---- l5 bad | outstanding expectations
**** dT 1.877
---- l4 bad | outstanding expectations
---- l2 bad | outstanding expectations
**** dT 1.949
**** v1 vsl| 1000 Link c req 1006 rxreq
**** dT 1.950
**** v1 vsl| 1007 Begin c req 1006 esi 1
**** v1 vsl| 1007 Timestamp c Start: 1747985873.976260 0.000000 0.000000
**** v1 vsl| 1007 ReqURL c /body
**** v1 vsl| 1007 ReqStart c 127.0.0.1 50656 a0
**** v1 vsl| 1007 ReqMethod c GET
**** v1 vsl| 1007 ReqURL c /body
**** v1 vsl| 1007 ReqProtocol c HTTP/1.1
**** v1 vsl| 1007 ReqHeader c Host: foo
**** v1 vsl| 1007 ReqHeader c User-Agent: c1
**** v1 vsl| 1007 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1007 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1007 VCL_call c RECV
**** v1 vsl| 1007 ReqURL c /body1
**** v1 vsl| 1007 VCL_return c hash
**** v1 vsl| 1007 VCL_call c HASH
**** v1 vsl| 1007 VCL_return c lookup
**** v1 vsl| 1007 Hit c 1004 119.886048 10.000000 0.000000
**** v1 vsl| 1007 VCL_call c HIT
**** v1 vsl| 1007 VCL_return c deliver
**** v1 vsl| 1007 RespProtocol c HTTP/1.1
**** v1 vsl| 1007 RespStatus c 200
**** v1 vsl| 1007 RespReason c OK
**** v1 vsl| 1007 RespHeader c Date: Fri, 23 May 2025 07:37:53 GMT
**** v1 vsl| 1007 RespHeader c Server: s1
**** v1 vsl| 1007 RespHeader c Content-Length: 18
**** v1 vsl| 1007 RespHeader c X-Varnish: 1007 1004
**** v1 vsl| 1007 RespHeader c Age: 0
**** v1 vsl| 1007 RespHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1007 RespHeader c Accept-Ranges: bytes
**** v1 vsl| 1007 VCL_call c DELIVER
**** v1 vsl| 1007 RespHeader c can_esi: false
**** v1 vsl| 1007 RespUnset c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1007 VCL_return c deliver
**** v1 vsl| 1007 Timestamp c Process: 1747985873.976314 0.000054 0.000054
**** v1 vsl| 1007 Filters c
**** v1 vsl| 1007 Timestamp c Resp: 1747985873.976343 0.000083 0.000029
**** v1 vsl| 1007 ReqAcct c 0 0 0 0 18 18
**** v1 vsl| 1007 End c
**** v1 vsl| 1008 Begin c req 1006 esi 1
**** v1 vsl| 1008 Timestamp c Start: 1747985873.976376 0.000000 0.000000
**** v1 vsl| 1008 ReqURL c /synth
**** v1 vsl| 1008 ReqStart c 127.0.0.1 50656 a0
**** v1 vsl| 1008 ReqMethod c GET
**** v1 vsl| 1008 ReqURL c /synth
**** v1 vsl| 1008 ReqProtocol c HTTP/1.1
**** v1 vsl| 1008 ReqHeader c Host: foo
**** v1 vsl| 1008 ReqHeader c User-Agent: c1
**** v1 vsl| 1008 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1008 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1008 VCL_call c RECV
**** v1 vsl| 1008 ReqURL c /synth1
**** v1 vsl| 1008 VCL_return c synth
**** v1 vsl| 1008 VCL_call c HASH
**** v1 vsl| 1008 VCL_return c lookup
**** v1 vsl| 1008 RespProtocol c HTTP/1.1
**** v1 vsl| 1008 RespStatus c 200
**** v1 vsl| 1008 RespReason c OK
**** v1 vsl| 1008 RespHeader c Date: Fri, 23 May 2025 07:37:53 GMT
**** v1 vsl| 1008 RespHeader c Server: Varnish
**** v1 vsl| 1008 RespHeader c X-Varnish: 1008
**** v1 vsl| 1008 VCL_call c SYNTH
**** v1 vsl| 1008 VCL_return c deliver
**** v1 vsl| 1008 Timestamp c Process: 1747985873.976408 0.000032 0.000032
**** v1 vsl| 1008 RespHeader c Content-Length: 3
**** v1 vsl| 1008 Storage c malloc Transient
**** v1 vsl| 1008 Filters c
**** v1 vsl| 1008 Timestamp c Resp: 1747985873.976451 0.000075 0.000043
**** v1 vsl| 1008 ReqAcct c 0 0 0 0 3 3
**** v1 vsl| 1008 End c
**** v1 vsl| 1006 Begin c req 1000 rxreq
**** v1 vsl| 1006 Timestamp c Start: 1747985873.976036 0.000000 0.000000
**** v1 vsl| 1006 Timestamp c Req: 1747985873.976036 0.000000 0.000000
**** v1 vsl| 1006 VCL_use c vcl1
**** v1 vsl| 1006 ReqStart c 127.0.0.1 50656 a0
**** v1 vsl| 1006 ReqMethod c GET
**** v1 vsl| 1006 ReqURL c /
**** v1 vsl| 1006 ReqProtocol c HTTP/1.1
**** v1 vsl| 1006 ReqHeader c Host: foo
**** v1 vsl| 1006 ReqHeader c User-Agent: c1
**** v1 vsl| 1006 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1006 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1006 VCL_call c RECV
**** v1 vsl| 1006 ReqHeader c esi0: foo
**** v1 vsl| 1006 VCL_return c hash
**** v1 vsl| 1006 VCL_call c HASH
**** v1 vsl| 1006 VCL_return c lookup
**** v1 vsl| 1006 Hit c 1002 119.764760 10.000000 0.000000 116 116
**** v1 vsl| 1006 VCL_call c HIT
**** v1 vsl| 1006 VCL_return c deliver
**** v1 vsl| 1006 RespProtocol c HTTP/1.1
**** v1 vsl| 1006 RespStatus c 200
**** v1 vsl| 1006 RespReason c OK
**** v1 vsl| 1006 RespHeader c Date: Fri, 23 May 2025 07:37:53 GMT
**** v1 vsl| 1006 RespHeader c Server: s1
**** v1 vsl| 1006 RespHeader c Content-Length: 116
**** v1 vsl| 1006 RespHeader c X-Varnish: 1006 1002
**** v1 vsl| 1006 RespHeader c Age: 0
**** v1 vsl| 1006 RespHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1006 RespHeader c Accept-Ranges: bytes
**** v1 vsl| 1006 VCL_call c DELIVER
**** v1 vsl| 1006 RespHeader c can_esi: true
**** v1 vsl| 1006 RespUnset c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1006 VCL_return c deliver
**** v1 vsl| 1006 Timestamp c Process: 1747985873.976175 0.000138 0.000138
**** v1 vsl| 1006 Filters c esi
**** v1 vsl| 1006 RespUnset c Content-Length: 116
**** v1 vsl| 1006 RespHeader c Connection: keep-alive
**** v1 vsl| 1006 RespHeader c Transfer-Encoding: chunked
**** v1 vsl| 1006 Link c req 1007 esi 1
**** v1 vsl| 1006 Link c req 1008 esi 1
**** v1 vsl| 1006 Timestamp c Resp: 1747985873.976490 0.000453 0.000315
**** v1 vsl| 1006 ReqAcct c 45 0 45 187 75 262
**** v1 vsl| 1006 End c
**** v1 vsl| 1000 SessClose c REM_CLOSE 0.248
**** v1 vsl| 1000 End c
**** dT 1.969
** v1 as expected: esi_req (4) == 4 (4)
* top Aborting execution, test failed
* top RESETTING after ../../../../bin/varnishtest/tests/e00003.vtc
** l1 Waiting for logexp
**** dT 1.970
** l2 Waiting for logexp
** l3 Waiting for logexp
** l4 Waiting for logexp
** l5 Waiting for logexp
** s1 Waiting for server (4/-1)
** v1 Wait
**** v1 CLI TX|panic.show
**** dT 2.013
*** v1 CLI RX 300
**** v1 CLI RX|Child has not panicked or panic has been cleared
**** dT 2.015
*** v1 debug|Info: manager stopping child
*** v1 debug|Debug: Stopping Child
**** dT 2.051
**** v1 vsl| 0 CLI - EOF on CLI connection, worker stops
**** dT 2.121
*** v1 debug|Info: Child (1899) said Child dies
*** v1 debug|Info: Child (1899) ended
*** v1 debug|Debug: Child cleanup complete
*** v1 debug|Info: manager dies
**** v1 STDOUT EOF
**** dT 2.152
** v1 WAIT4 pid=1490 status=0x0000 (user 0.321308 sys 0.302703)
* top TEST ../../../../bin/varnishtest/tests/e00003.vtc FAILED
* diag 0.0 /usr/bin/diff
# top TEST ../../../../bin/varnishtest/tests/e00003.vtc FAILED (2.161) exit=2
FAIL tests/e00003.vtc (exit status: 2)