**** dT    0.000
*    top   TEST ../../../../bin/varnishtest/tests/e00035.vtc starting
**** top   extmacro def pwd=/home/linux1/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:43301
**** top   extmacro def listen_addr=127.0.0.1:0
**** top   extmacro def bad_ip=192.0.2.255
**** top   extmacro def topbuild=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub
**** top   macro def testdir=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests
**** top   macro def tmpdir=/home/linux1/VT/_vtest_tmp/vtc.2028594.4ab6b748
**   top   === varnishtest "ESI fragment fetch fail"
*    top   VTEST ESI fragment fetch fail
**   top   === server s1 {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=32791
**** s1    macro def s1_sock=127.0.0.1:32791
*    s1    Listen on 127.0.0.1:32791
**   top   === varnish v1 -cliok "param.set feature +esi_disable_xml_check"
**** dT    0.004
**   s1    Started on 127.0.0.1:32791 (1 iterations)
**** dT    0.019
**   v1    Launch
***  v1    CMD: cd ${pwd} && exec varnishd  -d -n /home/linux1/VT/_vtest_tmp/vtc.2028594.4ab6b748/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 -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 36313' -P /home/linux1/VT/_vtest_tmp/vtc.2028594.4ab6b748/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs 
***  v1    CMD: cd /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd  -d -n /home/linux1/VT/_vtest_tmp/vtc.2028594.4ab6b748/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 -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 36313' -P /home/linux1/VT/_vtest_tmp/vtc.2028594.4ab6b748/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs 
***  v1    PID: 2028693
**** v1    macro def v1_pid=2028693
**** v1    macro def v1_name=/home/linux1/VT/_vtest_tmp/vtc.2028594.4ab6b748/v1
**** dT    0.054
***  v1    debug|Debug: Version: varnish-trunk revision a53079e385abcfba4bfe88414a52e94c1dc444c5
***  v1    debug|Debug: Platform: Linux,4.18.0-348.20.1.el8_5.s390x,s390x,-junix,-sdefault,-sdefault,-hcritbit
***  v1    debug|200 327     
***  v1    debug|-----------------------------
***  v1    debug|Varnish Cache CLI 1.0
***  v1    debug|-----------------------------
***  v1    debug|Linux,4.18.0-348.20.1.el8_5.s390x,s390x,-junix,-sdefault,-sdefault,-hcritbit
***  v1    debug|varnish-trunk revision a53079e385abcfba4bfe88414a52e94c1dc444c5
***  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.155
**** v1    CLIPOLL 1 0x1 0x0 0x0
***  v1    CLI connection fd = 7
***  v1    CLI RX  107
**** v1    CLI RX|pkfgfdoqpsbeldbfdxjrlieinwwcjhhn
**** v1    CLI RX|
**** v1    CLI RX|Authentication required.
**** v1    CLI TX|auth 34dfbfddb026c71f4efbabbc7316bf9a2988d973096b3c7a666cbbd7e8d5d1f2
***  v1    CLI RX  200
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Varnish Cache CLI 1.0
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Linux,4.18.0-348.20.1.el8_5.s390x,s390x,-junix,-sdefault,-sdefault,-hcritbit
**** v1    CLI RX|varnish-trunk revision a53079e385abcfba4bfe88414a52e94c1dc444c5
**** 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 feature +esi_disable_xml_check
**** dT    0.215
***  v1    CLI RX  200
**   v1    CLI 200 <param.set feature +esi_disable_xml_check>
**   top   === varnish v1 -cliok "param.set feature +esi_include_onerror"
**** v1    CLI TX|param.set feature +esi_include_onerror
**** dT    0.255
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.261
***  v1    CLI RX  200
**   v1    CLI 200 <param.set feature +esi_include_onerror>
**   top   === varnish v1 -vcl+backend {
**** 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 = "32791"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_response {
**** v1    CLI TX|\t\tset beresp.do_esi = beresp.http.surrogate-control ~ "ESI/1.0";
**** v1    CLI TX|\t\tunset beresp.http.surrogate-control;
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    0.356
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.457
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.557
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.627
***  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.659
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.699
***  v1    debug|Debug: Child (2029054) Started
**** dT    0.753
***  v1    debug|Child launched OK
***  v1    debug|Info: Child (2029054) said Child starts
***  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
**** dT    0.780
**** v1    vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1648594202.231520/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl1.1648594202.231520/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:36221
**** v1    vsl|          0 Debug           - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:36221
**** v1    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:36221
**** v1    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:36221
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:36221
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:36221
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:36221
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:36221
**** v1    vsl|          0 CLI             - Wr 200 0 
**** dT    0.817
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 36221
**** v1    CLI TX|debug.xid 999
**** dT    0.911
***  v1    CLI RX  200
**** v1    CLI RX|XID is 999 chunk 1
**** v1    CLI TX|debug.listen_address
**** dT    0.914
**** v1    vsl|          0 CLI             - Rd debug.listen_address 
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 36221

**** v1    vsl|          0 CLI             - Rd debug.xid 999 
**** v1    vsl|          0 CLI             - Wr 200 18 XID is 999 chunk 1
**** dT    0.981
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 36221
**   v1    Listen on 127.0.0.1 36221
**** v1    macro def v1_addr=127.0.0.1
**** v1    macro def v1_port=36221
**** v1    macro def v1_sock=127.0.0.1:36221
**** v1    macro def v1_a0_addr=127.0.0.1
**** v1    macro def v1_a0_port=36221
**** v1    macro def v1_a0_sock=127.0.0.1:36221
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**** dT    1.017
**** v1    vsl|          0 CLI             - Rd debug.listen_address 
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 36221

**** dT    1.019
**   c1    Started on 127.0.0.1:36221 (1 iterations)
***  c1    Connect to 127.0.0.1:36221
***  c1    connected fd 17 from 127.0.0.1 45898 to 127.0.0.1:36221
**   c1    === txreq -url "/abort"
**** c1    txreq|GET /abort HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === non_fatal
**   c1    === rxresp
***  s1    accepted fd 5 127.0.0.1 46314
**   s1    === rxreq
**** s1    rxhdr|GET /abort HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1002\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 108
**** s1    http[ 0] |GET
**** s1    http[ 1] |/abort
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Accept-Encoding: gzip
**** s1    http[ 6] |X-Varnish: 1002
**** s1    bodylen = 0
**   s1    === expect req.url == "/abort"
**** s1    EXPECT req.url (/abort) == "/abort" match
**   s1    === txresp -hdr {surrogate-control: content="ESI/1.0"} \
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|surrogate-control: content="ESI/1.0"\r
**** s1    txresp|Content-Length: 39\r
**** s1    txresp|\r
**** s1    txresp|before <esi:include src="/fail"/> after
**   s1    === rxreq
**** dT    1.039
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Date: Tue, 29 Mar 2022 22:50:02 GMT\r
**** c1    rxhdr|X-Varnish: 1001\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 varnish (Varnish/7.1)\r
**** c1    rxhdr|Accept-Ranges: bytes\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: Tue, 29 Mar 2022 22:50:02 GMT
**** c1    http[ 4] |X-Varnish: 1001
**** c1    http[ 5] |Age: 0
**** c1    http[ 6] |Via: 1.1 varnish (Varnish/7.1)
**** c1    http[ 7] |Accept-Ranges: bytes
**** c1    http[ 8] |Connection: keep-alive
**** c1    http[ 9] |Transfer-Encoding: chunked
**** c1    len|007\r
**** c1    chunk|before 
**** s1    rxhdr|GET /fail HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1004\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 107
**** s1    http[ 0] |GET
**** s1    http[ 1] |/fail
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Accept-Encoding: gzip
**** s1    http[ 6] |X-Varnish: 1004
**** s1    bodylen = 0
**   s1    === expect req.url == "/fail"
**** s1    EXPECT req.url (/fail) == "/fail" match
**   s1    === txresp -hdr "content-length: 100" -nolen
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|content-length: 100\r
**** s1    txresp|\r
**   s1    === delay 0.1
***  s1    delaying 0.1 second(s)
**** dT    1.119
**** v1    vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    vsl|       1000 SessOpen        c 127.0.0.1 45898 a0 127.0.0.1 36221 1648594202.989211 25
**** v1    vsl|       1000 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1000 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1000 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1000 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1000 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1000 Link            c req 1001 rxreq
**** v1    vsl|       1002 Begin           b bereq 1001 fetch
**** v1    vsl|       1002 VCL_use         b vcl1
**** v1    vsl|       1002 Timestamp       b Start: 1648594202.989289 0.000000 0.000000
**** v1    vsl|       1002 BereqMethod     b GET
**** v1    vsl|       1002 BereqURL        b /abort
**** v1    vsl|       1002 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1002 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** 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
**** v1    vsl|       1002 Timestamp       b Fetch: 1648594202.989298 0.000009 0.000009
**** v1    vsl|       1002 Timestamp       b Connected: 1648594202.989322 0.000032 0.000023
**** v1    vsl|       1002 BackendOpen     b 28 s1 127.0.0.1 32791 127.0.0.1 46314 connect
**** v1    vsl|       1002 Timestamp       b Bereq: 1648594202.989334 0.000045 0.000012
**** v1    vsl|       1002 Timestamp       b Beresp: 1648594202.989440 0.000150 0.000105
**** 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 surrogate-control: content="ESI/1.0"
**** v1    vsl|       1002 BerespHeader    b Content-Length: 39
**** v1    vsl|       1002 BerespHeader    b Date: Tue, 29 Mar 2022 22:50:02 GMT
**** v1    vsl|       1002 TTL             b RFC 120 10 0 1648594203 1648594203 1648594202 0 0 cacheable
**** v1    vsl|       1002 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1002 BerespUnset     b surrogate-control: content="ESI/1.0"
**** v1    vsl|       1002 VCL_return      b deliver
**** v1    vsl|       1002 Timestamp       b Process: 1648594202.989483 0.000193 0.000042
**** v1    vsl|       1002 Filters         b  esi
**** v1    vsl|       1002 Storage         b malloc s0
**** v1    vsl|       1002 Fetch_Body      b 3 length -
**** v1    vsl|       1002 BackendClose    b 28 s1 recycle
**** v1    vsl|       1002 Timestamp       b BerespBody: 1648594203.008428 0.019138 0.018944
**** v1    vsl|       1002 Length          b 39
**** v1    vsl|       1002 BereqAcct       b 108 0 108 77 39 116
**** v1    vsl|       1002 End             b 
**** dT    1.142
***  s1    shutting fd 5
**   s1    Ending
**** c1    chunked|before 
**** c1    bodylen = 7
**   c1    === expect resp.body == "before "
**** c1    EXPECT resp.body (before ) == "before " match
***  c1    closing fd 17
**   c1    Ending
**** dT    1.148
**   top   === server s1 -wait
**   s1    Waiting for server (4/-1)
**   top   === server s1 {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=32791
**** s1    macro def s1_sock=127.0.0.1:32791
*    s1    Listen on 127.0.0.1:32791
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**   c1    Started on 127.0.0.1:36221 (1 iterations)
***  c1    Connect to 127.0.0.1:36221
***  c1    connected fd 5 from 127.0.0.1 45904 to 127.0.0.1:36221
**   c1    === fatal
**   c1    === txreq -url "/continue"
**** c1    txreq|GET /continue HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    1.176
**   s1    Started on 127.0.0.1:32791 (1 iterations)
**** dT    1.223
**** v1    vsl|       1004 Begin           b bereq 1003 fetch
**** v1    vsl|       1004 VCL_use         b vcl1
**** v1    vsl|       1004 Timestamp       b Start: 1648594203.008908 0.000000 0.000000
**** v1    vsl|       1004 BereqMethod     b GET
**** v1    vsl|       1004 BereqURL        b /fail
**** v1    vsl|       1004 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1004 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1004 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** 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: 1648594203.008914 0.000005 0.000005
**** v1    vsl|       1004 Timestamp       b Connected: 1648594203.008916 0.000007 0.000001
**** v1    vsl|       1004 BackendOpen     b 28 s1 127.0.0.1 32791 127.0.0.1 46314 reuse
**** v1    vsl|       1004 Timestamp       b Bereq: 1648594203.008924 0.000015 0.000008
**** v1    vsl|       1004 Timestamp       b Beresp: 1648594203.009006 0.000097 0.000082
**** 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 content-length: 100
**** v1    vsl|       1004 BerespHeader    b Date: Tue, 29 Mar 2022 22:50:03 GMT
**** v1    vsl|       1004 TTL             b RFC 120 10 0 1648594203 1648594203 1648594203 0 0 cacheable
**** v1    vsl|       1004 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1004 VCL_return      b deliver
**** v1    vsl|       1004 Timestamp       b Process: 1648594203.009016 0.000108 0.000010
**** v1    vsl|       1004 Filters         b 
**** v1    vsl|       1004 Storage         b malloc s0
**** v1    vsl|       1004 Fetch_Body      b 3 length stream
**** v1    vsl|       1004 FetchError      b straight insufficient bytes
**** v1    vsl|       1004 BackendClose    b 28 s1 close Failure receiving req.body
**** v1    vsl|       1004 BereqAcct       b 107 0 107 40 0 40
**** v1    vsl|       1004 End             b 
**** v1    vsl|       1003 Begin           c req 1001 esi
**** v1    vsl|       1003 Timestamp       c Start: 1648594203.008724 0.000000 0.000000
**** v1    vsl|       1003 ReqURL          c /fail
**** v1    vsl|       1003 ReqStart        c 127.0.0.1 45898 a0
**** v1    vsl|       1003 ReqMethod       c GET
**** v1    vsl|       1003 ReqURL          c /fail
**** v1    vsl|       1003 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1003 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1003 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** 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: 1648594203.009026 0.000302 0.000302
**** 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 content-length: 100
**** v1    vsl|       1003 RespHeader      c Date: Tue, 29 Mar 2022 22:50:03 GMT
**** v1    vsl|       1003 RespHeader      c X-Varnish: 1003
**** v1    vsl|       1003 RespHeader      c Age: 0
**** v1    vsl|       1003 RespHeader      c Via: 1.1 varnish (Varnish/7.1)
**** 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: 1648594203.009030 0.000306 0.000004
**** v1    vsl|       1003 Filters         c 
**** v1    vsl|       1003 Timestamp       c Resp: 1648594203.112411 0.103686 0.103380
**** v1    vsl|       1003 ReqAcct         c 0 0 0 0 0 0
**** v1    vsl|       1003 End             c 
**** v1    vsl|       1001 Begin           c req 1000 rxreq
**** v1    vsl|       1001 Timestamp       c Start: 1648594202.989237 0.000000 0.000000
**** v1    vsl|       1001 Timestamp       c Req: 1648594202.989237 0.000000 0.000000
**** v1    vsl|       1001 VCL_use         c vcl1
**** v1    vsl|       1001 ReqStart        c 127.0.0.1 45898 a0
**** v1    vsl|       1001 ReqMethod       c GET
**** v1    vsl|       1001 ReqURL          c /abort
**** v1    vsl|       1001 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1001 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** 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: 1648594203.008689 0.019451 0.019451
**** 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 Content-Length: 39
**** v1    vsl|       1001 RespHeader      c Date: Tue, 29 Mar 2022 22:50:02 GMT
**** v1    vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    vsl|       1001 RespHeader      c Age: 0
**** v1    vsl|       1001 RespHeader      c Via: 1.1 varnish (Varnish/7.1)
**** 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: 1648594203.008702 0.019465 0.000013
**** v1    vsl|       1001 Filters         c  esi
**** v1    vsl|       1001 RespUnset       c Content-Length: 39
**** v1    vsl|       1001 RespHeader      c Connection: keep-alive
**** v1    vsl|       1001 RespHeader      c Transfer-Encoding: chunked
**** v1    vsl|       1001 Link            c req 1003 esi
**** v1    vsl|       1001 Timestamp       c Resp: 1648594203.112459 0.123221 0.103756
**** v1    vsl|       1001 ReqAcct         c 40 0 40 187 7 194
**** v1    vsl|       1001 End             c 
**** v1    vsl|       1000 SessClose       c REM_CLOSE 0.123
**** v1    vsl|       1000 End             c 
**** v1    vsl|       1005 Begin           c sess 0 HTTP/1
**** v1    vsl|       1005 SessOpen        c 127.0.0.1 45904 a0 127.0.0.1 36221 1648594203.192760 26
**** v1    vsl|       1005 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1005 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1005 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1005 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1005 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1005 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1005 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1005 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:36221
**** v1    vsl|       1005 Link            c req 1006 rxreq
**** dT    1.224
***  s1    accepted fd 17 127.0.0.1 46322
**   s1    === rxreq
**** dT    1.225
**** s1    rxhdr|GET /continue HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1007\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 111
**** s1    http[ 0] |GET
**** s1    http[ 1] |/continue
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Accept-Encoding: gzip
**** s1    http[ 6] |X-Varnish: 1007
**** s1    bodylen = 0
**   s1    === expect req.url == "/continue"
**** s1    EXPECT req.url (/continue) == "/continue" match
**   s1    === txresp -hdr {surrogate-control: content="ESI/1.0"} \
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|surrogate-control: content="ESI/1.0"\r
**** s1    txresp|Content-Length: 58\r
**** s1    txresp|\r
**** s1    txresp|before <esi:include src="/fail" onerror="continue"/> after
**   s1    === rxreq
**** dT    1.250
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Date: Tue, 29 Mar 2022 22:50:03 GMT\r
**** c1    rxhdr|X-Varnish: 1006\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 varnish (Varnish/7.1)\r
**** c1    rxhdr|Accept-Ranges: bytes\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: Tue, 29 Mar 2022 22:50:03 GMT
**** c1    http[ 4] |X-Varnish: 1006
**** c1    http[ 5] |Age: 0
**** c1    http[ 6] |Via: 1.1 varnish (Varnish/7.1)
**** c1    http[ 7] |Accept-Ranges: bytes
**** c1    http[ 8] |Connection: keep-alive
**** c1    http[ 9] |Transfer-Encoding: chunked
**** c1    len|007\r
**** c1    chunk|before 
**** dT    1.256
**** s1    rxhdr|GET /fail HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1009\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 107
**** s1    http[ 0] |GET
**** s1    http[ 1] |/fail
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Accept-Encoding: gzip
**** s1    http[ 6] |X-Varnish: 1009
**** s1    bodylen = 0
**   s1    === expect req.url == "/fail"
**** s1    EXPECT req.url (/fail) == "/fail" match
**   s1    === txresp -hdr "content-length: 100" -nolen
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|content-length: 100\r
**** s1    txresp|\r
**** dT    1.257
**   s1    === delay 0.1
***  s1    delaying 0.1 second(s)
**** dT    1.331
**** v1    vsl|       1007 Begin           b bereq 1006 fetch
**** v1    vsl|       1007 VCL_use         b vcl1
**** v1    vsl|       1007 Timestamp       b Start: 1648594203.194491 0.000000 0.000000
**** v1    vsl|       1007 BereqMethod     b GET
**** v1    vsl|       1007 BereqURL        b /continue
**** v1    vsl|       1007 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1007 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1007 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1007 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1007 BereqHeader     b X-Varnish: 1007
**** v1    vsl|       1007 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1007 VCL_return      b fetch
**** v1    vsl|       1007 Timestamp       b Fetch: 1648594203.194512 0.000020 0.000020
**** v1    vsl|       1007 Timestamp       b Connected: 1648594203.194610 0.000118 0.000097
**** v1    vsl|       1007 BackendOpen     b 28 s1 127.0.0.1 32791 127.0.0.1 46322 connect
**** v1    vsl|       1007 Timestamp       b Bereq: 1648594203.194630 0.000138 0.000020
**** v1    vsl|       1007 Timestamp       b Beresp: 1648594203.194744 0.000253 0.000114
**** v1    vsl|       1007 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1007 BerespStatus    b 200
**** v1    vsl|       1007 BerespReason    b OK
**** v1    vsl|       1007 BerespHeader    b surrogate-control: content="ESI/1.0"
**** v1    vsl|       1007 BerespHeader    b Content-Length: 58
**** v1    vsl|       1007 BerespHeader    b Date: Tue, 29 Mar 2022 22:50:03 GMT
**** v1    vsl|       1007 TTL             b RFC 120 10 0 1648594203 1648594203 1648594203 0 0 cacheable
**** v1    vsl|       1007 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1007 BerespUnset     b surrogate-control: content="ESI/1.0"
**** v1    vsl|       1007 VCL_return      b deliver
**** v1    vsl|       1007 Timestamp       b Process: 1648594203.194774 0.000282 0.000029
**** v1    vsl|       1007 Filters         b  esi
**** v1    vsl|       1007 Storage         b malloc s0
**** v1    vsl|       1007 Fetch_Body      b 3 length -
**** v1    vsl|       1007 BackendClose    b 28 s1 recycle
**** v1    vsl|       1007 Timestamp       b BerespBody: 1648594203.205057 0.010565 0.010283
**** v1    vsl|       1007 Length          b 58
**** v1    vsl|       1007 BereqAcct       b 111 0 111 77 58 135
**** v1    vsl|       1007 End             b 
**** dT    1.362
***  s1    shutting fd 17
**   s1    Ending
**** c1    len|00116\r
**** c1    chunk|<!DOCTYPE html>
**** c1    chunk|<html>
**** c1    chunk|  <head>
**** c1    chunk|    <title>503 Service Unavailable</title>
**** c1    chunk|  </head>
**** c1    chunk|  <body>
**** c1    chunk|    <h1>Error 503 Service Unavailable</h1>
**** c1    chunk|    <p>Service Unavailable</p>
**** c1    chunk|    <h3>Guru Meditation:</h3>
**** c1    chunk|    <p>XID: 1008</p>
**** c1    chunk|    <hr>
**** c1    chunk|    <p>Varnish cache server</p>
**** c1    chunk|  </body>
**** c1    chunk|</html>
**** c1    len|006\r
**** c1    chunk| after
**** c1    len|0\r
**** c1    chunked|before <!DOCTYPE html>
**** c1    chunked|<html>
**** c1    chunked|  <head>
**** c1    chunked|    <title>503 Service Unavailable</title>
**** c1    chunked|  </head>
**** c1    chunked|  <body>
**** c1    chunked|    <h1>Error 503 Service Unavailable</h1>
**** c1    chunked|    <p>Service Unavailable</p>
**** c1    chunked|    <h3>Guru Meditation:</h3>
**** c1    chunked|    <p>XID: 1008</p>
**** c1    chunked|    <hr>
**** c1    chunked|    <p>Varnish cache server</p>
**** c1    chunked|  </body>
**** c1    chunked|</html>
**** c1    chunked| after
**** c1    bodylen = 291
**   c1    === expect resp.body == "before  after"
---- c1    EXPECT resp.body (before <!DOCTYPE html>
<html>
  <head>
    <title>503 Service Unavailable</title>
  </head>
  <body>
    <h1>Error 503 Service Unavailable</h1>
    <p>Service Unavailable</p>
    <h3>Guru Meditation:</h3>
    <p>XID: 1008</p>
    <hr>
    <p>Varnish cache server</p>
  </body>
</html>
 after) == "before  after" failed
**** dT    1.363
*    top   RESETTING after ../../../../bin/varnishtest/tests/e00035.vtc
**   s1    Waiting for server (4/-1)
**   v1    Wait
**** v1    CLI TX|panic.show
**** dT    1.423
***  v1    CLI RX  300
**** v1    CLI RX|Child has not panicked or panic has been cleared
**** dT    1.428
***  v1    debug|Info: manager stopping child
***  v1    debug|Debug: Stopping Child
**** dT    1.432
**** v1    vsl|       1009 Begin           b bereq 1008 fetch
**** v1    vsl|       1009 VCL_use         b vcl1
**** v1    vsl|       1009 Timestamp       b Start: 1648594203.220615 0.000000 0.000000
**** v1    vsl|       1009 BereqMethod     b GET
**** v1    vsl|       1009 BereqURL        b /fail
**** v1    vsl|       1009 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1009 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1009 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1009 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1009 BereqHeader     b X-Varnish: 1009
**** v1    vsl|       1009 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1009 VCL_return      b fetch
**** v1    vsl|       1009 Timestamp       b Fetch: 1648594203.220628 0.000013 0.000013
**** v1    vsl|       1009 Timestamp       b Connected: 1648594203.220631 0.000016 0.000003
**** v1    vsl|       1009 BackendOpen     b 28 s1 127.0.0.1 32791 127.0.0.1 46322 reuse
**** v1    vsl|       1009 Timestamp       b Bereq: 1648594203.220649 0.000034 0.000017
**** v1    vsl|       1009 Timestamp       b Beresp: 1648594203.331820 0.111205 0.111171
**** v1    vsl|       1009 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1009 BerespStatus    b 200
**** v1    vsl|       1009 BerespReason    b OK
**** v1    vsl|       1009 BerespHeader    b content-length: 100
**** v1    vsl|       1009 BerespHeader    b Date: Tue, 29 Mar 2022 22:50:03 GMT
**** v1    vsl|       1009 TTL             b RFC 120 10 0 1648594203 1648594203 1648594203 0 0 cacheable
**** v1    vsl|       1009 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1009 VCL_return      b deliver
**** v1    vsl|       1009 Timestamp       b Process: 1648594203.331867 0.111252 0.000046
**** v1    vsl|       1009 Filters         b 
**** v1    vsl|       1009 Storage         b malloc s0
**** v1    vsl|       1009 Fetch_Body      b 3 length stream
**** v1    vsl|       1009 FetchError      b straight insufficient bytes
**** v1    vsl|       1009 BackendClose    b 28 s1 close Failure receiving req.body
**** dT    1.433
**** v1    vsl|       1009 BereqAcct       b 107 0 107 40 0 40
**** v1    vsl|       1009 End             b 
**** v1    vsl|       1008 Begin           c req 1006 esi
**** v1    vsl|       1008 Timestamp       c Start: 1648594203.219600 0.000000 0.000000
**** v1    vsl|       1008 ReqURL          c /fail
**** v1    vsl|       1008 ReqStart        c 127.0.0.1 45904 a0
**** v1    vsl|       1008 ReqMethod       c GET
**** v1    vsl|       1008 ReqURL          c /fail
**** v1    vsl|       1008 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1008 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1008 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1008 VCL_call        c RECV
**** v1    vsl|       1008 VCL_return      c hash
**** v1    vsl|       1008 VCL_call        c HASH
**** v1    vsl|       1008 VCL_return      c lookup
**** v1    vsl|       1008 VCL_call        c MISS
**** v1    vsl|       1008 VCL_return      c fetch
**** v1    vsl|       1008 Link            c bereq 1009 fetch
**** v1    vsl|       1008 Timestamp       c Fetch: 1648594203.331944 0.112344 0.112344
**** v1    vsl|       1008 RespProtocol    c HTTP/1.1
**** v1    vsl|       1008 RespStatus      c 503
**** v1    vsl|       1008 RespReason      c Service Unavailable
**** v1    vsl|       1008 RespHeader      c Date: Tue, 29 Mar 2022 22:50:03 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 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1008 RespHeader      c Retry-After: 5
**** v1    vsl|       1008 VCL_return      c deliver
**** v1    vsl|       1008 Timestamp       c Process: 1648594203.331981 0.112380 0.000036
**** v1    vsl|       1008 RespHeader      c Content-Length: 278
**** v1    vsl|       1008 Storage         c malloc Transient
**** v1    vsl|       1008 Filters         c 
**** v1    vsl|       1008 Timestamp       c Resp: 1648594203.332013 0.112413 0.000032
**** v1    vsl|       1008 ReqAcct         c 0 0 0 0 278 278
**** v1    vsl|       1008 End             c 
**** v1    vsl|       1006 Begin           c req 1005 rxreq
**** v1    vsl|       1006 Timestamp       c Start: 1648594203.192790 0.000000 0.000000
**** v1    vsl|       1006 Timestamp       c Req: 1648594203.192790 0.000000 0.000000
**** v1    vsl|       1006 VCL_use         c vcl1
**** v1    vsl|       1006 ReqStart        c 127.0.0.1 45904 a0
**** v1    vsl|       1006 ReqMethod       c GET
**** v1    vsl|       1006 ReqURL          c /continue
**** v1    vsl|       1006 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1006 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1006 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1006 VCL_call        c RECV
**** v1    vsl|       1006 VCL_return      c hash
**** v1    vsl|       1006 VCL_call        c HASH
**** v1    vsl|       1006 VCL_return      c lookup
**** v1    vsl|       1006 VCL_call        c MISS
**** v1    vsl|       1006 VCL_return      c fetch
**** v1    vsl|       1006 Link            c bereq 1007 fetch
**** v1    vsl|       1006 Timestamp       c Fetch: 1648594203.219535 0.026745 0.026745
**** 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 Content-Length: 58
**** v1    vsl|       1006 RespHeader      c Date: Tue, 29 Mar 2022 22:50:03 GMT
**** v1    vsl|       1006 RespHeader      c X-Varnish: 1006
**** v1    vsl|       1006 RespHeader      c Age: 0
**** v1    vsl|       1006 RespHeader      c Via: 1.1 varnish (Varnish/7.1)
**** v1    vsl|       1006 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1006 VCL_call        c DELIVER
**** v1    vsl|       1006 VCL_return      c deliver
**** v1    vsl|       1006 Timestamp       c Process: 1648594203.219555 0.026765 0.000019
**** v1    vsl|       1006 Filters         c  esi
**** v1    vsl|       1006 RespUnset       c Content-Length: 58
**** v1    vsl|       1006 RespHeader      c Connection: keep-alive
**** v1    vsl|       1006 RespHeader      c Transfer-Encoding: chunked
**** v1    vsl|       1006 Link            c req 1008 esi
**** v1    vsl|       1006 Timestamp       c Resp: 1648594203.332061 0.139271 0.112505
**** v1    vsl|       1006 ReqAcct         c 43 0 43 187 291 478
**** v1    vsl|       1006 End             c 
**** v1    vsl|          0 CLI             - EOF on CLI connection, worker stops
**** dT    1.546
***  v1    debug|Info: Child (2029054) ended
***  v1    debug|Info: Child (2029054) said Child dies
***  v1    debug|Debug: Child cleanup complete
***  v1    debug|Info: manager dies
**** v1    STDOUT EOF
**** dT    1.548
**   v1    WAIT4 pid=2028693 status=0x0000 (user 0.198550 sys 0.044678)
*    top   TEST ../../../../bin/varnishtest/tests/e00035.vtc FAILED
#    top  TEST ../../../../bin/varnishtest/tests/e00035.vtc FAILED (1.550) exit=2
FAIL tests/e00035.vtc (exit status: 2)