**** dT    0.000
*    top   TEST ../../../vmod/tests/std_c00001.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/vmod
**** 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:40901
**** 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/vmod/../../../vmod/tests
**** top   macro def tmpdir=/tmp/vtest.clang/_vtest_tmp/vtc.351.07fef1ed
**   top   === varnishtest "Test std.rollback"
*    top   VTEST Test std.rollback
**   top   === feature !workspace_emulator
**   top   === server s1 {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=33281
**** s1    macro def s1_sock=127.0.0.1:33281
*    s1    Listen on 127.0.0.1:33281
**   top   === varnish v1 -vcl+backend {
**** dT    0.004
**   s1    Started on 127.0.0.1:33281 (1 iterations)
**** dT    0.036
**   v1    Launch
***  v1    CMD: cd ${pwd} && exec varnishd  -d -n /tmp/vtest.clang/_vtest_tmp/vtc.351.07fef1ed/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 -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 37307' -P /tmp/vtest.clang/_vtest_tmp/vtc.351.07fef1ed/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/vmod && exec varnishd  -d -n /tmp/vtest.clang/_vtest_tmp/vtc.351.07fef1ed/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 -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 37307' -P /tmp/vtest.clang/_vtest_tmp/vtc.351.07fef1ed/v1/varnishd.pid -p vmod_path=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/vmod/.libs 
***  v1    PID: 371
**** v1    macro def v1_pid=371
**** v1    macro def v1_name=/tmp/vtest.clang/_vtest_tmp/vtc.351.07fef1ed/v1
**** dT    0.096
***  v1    debug|Debug: Version: varnish-trunk revision b18568ace231f1354f2af6fffc72c5da8c7201f3
***  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 b18568ace231f1354f2af6fffc72c5da8c7201f3
***  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.196
**** v1    CLIPOLL 1 0x1 0x0 0x0
***  v1    CLI connection fd = 7
***  v1    CLI RX  107
**** v1    CLI RX|ojntmprikywgggpkrzjjbddrpokpduxj
**** v1    CLI RX|
**** v1    CLI RX|Authentication required.
**** dT    0.197
**** v1    CLI TX|auth 6cddb8e7157dcaa7929e43203af45006982294f9fcbf3425ff34b574a404a4de
***  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 b18568ace231f1354f2af6fffc72c5da8c7201f3
**** 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|backend s1 { .host = "127.0.0.1"; .port = "33281"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\timport std;
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_recv {
**** v1    CLI TX|\t\tif (req.url == "/foo") {
**** v1    CLI TX|\t\t\tset req.http.foobar = "bar";
**** v1    CLI TX|\t\t}
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_deliver {
**** v1    CLI TX|\t\tif (resp.status == 400) {
**** v1    CLI TX|\t\t\tstd.rollback(req);
**** v1    CLI TX|\t\t\tset req.url = "/bar";
**** v1    CLI TX|\t\t\treturn (restart);
**** v1    CLI TX|\t\t}
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    0.312
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.416
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.520
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.624
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.724
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.828
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.928
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.032
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.054
***  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    1.112
***  v1    debug|Debug: Child (479) Started
**** dT    1.149
***  v1    debug|Child launched OK
**** dT    1.168
***  v1    CLI RX  200
***  v1    wait-running
**** v1    CLI TX|status
***  v1    debug|Info: Child (479) said Child starts
***  v1    CLI RX  200
**** v1    CLI RX|Child in state running
**** v1    CLI TX|debug.listen_address
**** dT    1.215
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 35351
**** v1    CLI TX|debug.xid 1000
**** dT    1.240
**** v1    vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1684407183.519457/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl1.1684407183.519457/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:35351
**** v1    vsl|          0 Debug           - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:35351
**** v1    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:35351
**** v1    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:35351
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:35351
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:35351
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:35351
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:35351
**** 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 35351

**** dT    1.260
***  v1    CLI RX  200
**** v1    CLI RX|XID is 1000 chunk 1
**** v1    CLI TX|debug.listen_address
**** dT    1.311
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 35351
**   v1    Listen on 127.0.0.1 35351
**** v1    macro def v1_addr=127.0.0.1
**** v1    macro def v1_port=35351
**** v1    macro def v1_sock=127.0.0.1:35351
**** v1    macro def v1_a0_addr=127.0.0.1
**** v1    macro def v1_a0_port=35351
**** v1    macro def v1_a0_sock=127.0.0.1:35351
**   top   === client c1 {
**   c1    Starting client
**** dT    1.312
**   c1    Waiting for client
**** dT    1.332
**   c1    Started on 127.0.0.1:35351 (1 iterations)
***  c1    Connect to 127.0.0.1:35351
***  c1    connected fd 17 from 127.0.0.1 34590 to 127.0.0.1:35351
**   c1    === txreq -url "/foo" -hdr "foobar: foo"
**** c1    txreq|GET /foo HTTP/1.1\r
**** c1    txreq|foobar: foo\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    1.338
***  s1    accepted fd 5 127.0.0.1 37308
**   s1    === rxreq
**** dT    1.339
**** s1    rxhdr|GET /foo HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** s1    rxhdr|foobar: bar\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1002\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 148
**** s1    http[ 0] |GET
**** s1    http[ 1] |/foo
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |foobar: bar
**** s1    http[ 7] |Accept-Encoding: gzip
**** s1    http[ 8] |X-Varnish: 1002
**** s1    bodylen = 0
**   s1    === expect req.url == "/foo"
**** s1    EXPECT req.url (/foo) == "/foo" match
**   s1    === expect req.http.foobar == "bar"
**** s1    EXPECT req.http.foobar (bar) == "bar" match
**   s1    === txresp -status 400
**** dT    1.340
**** s1    txresp|HTTP/1.1 400 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:04 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**   s1    === accept
**** s1    Accepting
**** dT    1.344
**** 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 35351

**** v1    vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    vsl|       1000 SessOpen        c 127.0.0.1 34590 a0 127.0.0.1 35351 1684407184.657677 23
**** v1    vsl|       1000 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1000 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1000 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1000 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1000 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1000 Link            c req 1001 rxreq
**** dT    1.354
***  s1    Accepted socket fd is 5
**   s1    === rxreq
**** dT    1.355
**** s1    rxhdr|GET /bar HTTP/1.1\r
**** s1    rxhdr|foobar: foo\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1004\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 91
**** s1    http[ 0] |GET
**** s1    http[ 1] |/bar
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |foobar: foo
**** s1    http[ 4] |Host: 127.0.0.1
**** s1    http[ 5] |Accept-Encoding: gzip
**** s1    http[ 6] |X-Varnish: 1004
**** s1    bodylen = 0
**   s1    === expect req.url == "/bar"
**** s1    EXPECT req.url (/bar) == "/bar" match
**   s1    === expect req.http.foobar == "foo"
**** s1    EXPECT req.http.foobar (foo) == "foo" match
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:04 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**   s1    === accept
**** s1    Accepting
**** dT    1.369
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Date: Thu, 18 May 2023 10:53:04 GMT\r
**** c1    rxhdr|Content-Length: 0\r
**** c1    rxhdr|X-Varnish: 1003\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 175
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |Date: Thu, 18 May 2023 10:53:04 GMT
**** c1    http[ 4] |Content-Length: 0
**** c1    http[ 5] |X-Varnish: 1003
**** c1    http[ 6] |Age: 0
**** c1    http[ 7] |Via: 1.1 v1 (Varnish/trunk)
**** c1    http[ 8] |Accept-Ranges: bytes
**** c1    http[ 9] |Connection: keep-alive
**** c1    bodylen = 0
***  c1    closing fd 17
**   c1    Ending
**** dT    1.370
**   top   === varnish v1 -vcl+backend {
**** v1    CLI TX|vcl.inline vcl2 << %XJEIFLH|)Xspa8P
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|backend s1 { .host = "127.0.0.1"; .port = "33281"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\timport std;
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_fetch {
**** v1    CLI TX|\t\tif (bereq.url == "/baz") {
**** v1    CLI TX|\t\t\tset bereq.http.foobar = "qux";
**** v1    CLI TX|\t\t}
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_response {
**** v1    CLI TX|\t\tif (beresp.status == 400) {
**** v1    CLI TX|\t\t\tstd.rollback(bereq);
**** v1    CLI TX|\t\t\tset bereq.url = "/qux";
**** v1    CLI TX|\t\t\treturn (retry);
**** v1    CLI TX|\t\t}
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    1.448
**** v1    vsl|       1002 Begin           b bereq 1001 fetch
**** v1    vsl|       1002 VCL_use         b vcl1
**** v1    vsl|       1002 Timestamp       b Start: 1684407184.657886 0.000000 0.000000
**** v1    vsl|       1002 BereqMethod     b GET
**** v1    vsl|       1002 BereqURL        b /foo
**** 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 Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1002 BereqHeader     b foobar: bar
**** 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: 1684407184.657914 0.000027 0.000027
**** v1    vsl|       1002 Timestamp       b Connected: 1684407184.657998 0.000111 0.000084
**** v1    vsl|       1002 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37308 connect
**** v1    vsl|       1002 Timestamp       b Bereq: 1684407184.658048 0.000161 0.000050
**** v1    vsl|       1002 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1002 BerespStatus    b 400
**** v1    vsl|       1002 BerespReason    b OK
**** v1    vsl|       1002 BerespHeader    b Date: Thu, 18 May 2023 10:53:04 GMT
**** v1    vsl|       1002 BerespHeader    b Content-Length: 0
**** v1    vsl|       1002 Timestamp       b Beresp: 1684407184.661568 0.003681 0.003520
**** v1    vsl|       1002 TTL             b RFC -1 10 0 1684407185 1684407185 1684407184 0 0 cacheable
**** v1    vsl|       1002 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1002 TTL             b VCL 120 10 0 1684407185 cacheable
**** v1    vsl|       1002 TTL             b VCL 120 10 0 1684407185 uncacheable
**** v1    vsl|       1002 VCL_return      b deliver
**** v1    vsl|       1002 Timestamp       b Process: 1684407184.661594 0.003707 0.000025
**** v1    vsl|       1002 Filters         b 
**** v1    vsl|       1002 Storage         b malloc Transient
**** v1    vsl|       1002 Fetch_Body      b 0 none -
**** v1    vsl|       1002 BackendClose    b 26 s1 recycle
**** v1    vsl|       1002 Timestamp       b BerespBody: 1684407184.674000 0.016113 0.012406
**** v1    vsl|       1002 Length          b 0
**** v1    vsl|       1002 BereqAcct       b 148 0 148 75 0 75
**** v1    vsl|       1002 End             b 
**** v1    vsl|       1001 Begin           c req 1000 rxreq
**** v1    vsl|       1001 Timestamp       c Start: 1684407184.657739 0.000000 0.000000
**** v1    vsl|       1001 Timestamp       c Req: 1684407184.657739 0.000000 0.000000
**** v1    vsl|       1001 VCL_use         c vcl1
**** v1    vsl|       1001 ReqStart        c 127.0.0.1 34590 a0
**** v1    vsl|       1001 ReqMethod       c GET
**** v1    vsl|       1001 ReqURL          c /foo
**** v1    vsl|       1001 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1001 ReqHeader       c foobar: foo
**** 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 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1001 VCL_call        c RECV
**** v1    vsl|       1001 ReqUnset        c foobar: foo
**** v1    vsl|       1001 ReqHeader       c foobar: bar
**** 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: 1684407184.674081 0.016342 0.016342
**** v1    vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    vsl|       1001 RespStatus      c 400
**** v1    vsl|       1001 RespReason      c OK
**** v1    vsl|       1001 RespHeader      c Date: Thu, 18 May 2023 10:53:04 GMT
**** v1    vsl|       1001 RespHeader      c Content-Length: 0
**** 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 VCL_call        c DELIVER
**** v1    vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    vsl|       1001 RespStatus      c 400
**** v1    vsl|       1001 RespReason      c OK
**** v1    vsl|       1001 RespHeader      c Date: Thu, 18 May 2023 10:53:04 GMT
**** v1    vsl|       1001 RespHeader      c Content-Length: 0
**** 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 ReqURL          c /bar
**** v1    vsl|       1001 VCL_return      c restart
**** v1    vsl|       1001 Timestamp       c Process: 1684407184.674132 0.016392 0.000050
**** v1    vsl|       1001 Timestamp       c Restart: 1684407184.674135 0.016396 0.000003
**** v1    vsl|       1001 Link            c req 1003 restart
**** v1    vsl|       1001 End             c 
**** v1    vsl|       1004 Begin           b bereq 1003 fetch
**** v1    vsl|       1004 VCL_use         b vcl1
**** v1    vsl|       1004 Timestamp       b Start: 1684407184.674195 0.000000 0.000000
**** v1    vsl|       1004 BereqMethod     b GET
**** v1    vsl|       1004 BereqURL        b /bar
**** v1    vsl|       1004 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1004 BereqHeader     b foobar: foo
**** v1    vsl|       1004 BereqHeader     b Host: 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: 1684407184.674213 0.000018 0.000018
**** v1    vsl|       1004 Timestamp       b Connected: 1684407184.674310 0.000115 0.000097
**** v1    vsl|       1004 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37310 connect
**** v1    vsl|       1004 Timestamp       b Bereq: 1684407184.674353 0.000157 0.000042
**** 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: Thu, 18 May 2023 10:53:04 GMT
**** v1    vsl|       1004 BerespHeader    b Content-Length: 0
**** v1    vsl|       1004 Timestamp       b Beresp: 1684407184.677788 0.003593 0.003435
**** v1    vsl|       1004 TTL             b RFC 120 10 0 1684407185 1684407185 1684407184 0 0 cacheable
**** v1    vsl|       1004 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1004 VCL_return      b deliver
**** v1    vsl|       1004 Timestamp       b Process: 1684407184.677835 0.003639 0.000046
**** v1    vsl|       1004 Filters         b 
**** v1    vsl|       1004 Storage         b malloc s0
**** v1    vsl|       1004 Fetch_Body      b 0 none -
**** v1    vsl|       1004 BackendClose    b 26 s1 recycle
**** v1    vsl|       1004 Timestamp       b BerespBody: 1684407184.689967 0.015771 0.012131
**** v1    vsl|       1004 Length          b 0
**** v1    vsl|       1004 BereqAcct       b 91 0 91 75 0 75
**** v1    vsl|       1004 End             b 
**** v1    vsl|       1003 Begin           c req 1001 restart
**** v1    vsl|       1003 Timestamp       c Start: 1684407184.674135 0.016396 0.000000
**** v1    vsl|       1003 ReqStart        c 127.0.0.1 34590 a0
**** v1    vsl|       1003 ReqMethod       c GET
**** v1    vsl|       1003 ReqURL          c /bar
**** v1    vsl|       1003 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1003 ReqHeader       c foobar: foo
**** v1    vsl|       1003 ReqHeader       c Host: 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: 1684407184.690018 0.032278 0.015882
**** 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: Thu, 18 May 2023 10:53:04 GMT
**** v1    vsl|       1003 RespHeader      c Content-Length: 0
**** 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 VCL_return      c deliver
**** v1    vsl|       1003 Timestamp       c Process: 1684407184.690061 0.032322 0.000043
**** v1    vsl|       1003 Filters         c 
**** v1    vsl|       1003 RespHeader      c Connection: keep-alive
**** v1    vsl|       1003 Timestamp       c Resp: 1684407184.690127 0.032387 0.000065
**** v1    vsl|       1003 ReqAcct         c 51 0 51 175 0 175
**** v1    vsl|       1003 End             c 
**** v1    vsl|       1000 SessClose       c REM_CLOSE 0.033
**** v1    vsl|       1000 End             c 
**** dT    2.264
***  v1    CLI RX  200
**** v1    CLI TX|vcl.use vcl2
**** v1    vsl|          0 CLI             - Rd vcl.load vcl2 vcl_vcl2.1684407184.692105/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl2.1684407184.692105/vgc.so" as "vcl2"
**** dT    2.272
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl2' now active
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**** dT    2.276
**   c1    Started on 127.0.0.1:35351 (1 iterations)
***  c1    Connect to 127.0.0.1:35351
***  c1    connected fd 17 from 127.0.0.1 34604 to 127.0.0.1:35351
**   c1    === txreq -url "/baz" -hdr "foobar: baz"
**** c1    txreq|GET /baz HTTP/1.1\r
**** c1    txreq|foobar: baz\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    2.278
***  s1    Accepted socket fd is 5
**   s1    === rxreq
**** s1    rxhdr|GET /baz HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\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: 1007\r
**** s1    rxhdr|foobar: qux\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 148
**** s1    http[ 0] |GET
**** s1    http[ 1] |/baz
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1007
**** s1    http[ 8] |foobar: qux
**** s1    bodylen = 0
**   s1    === expect req.url == "/baz"
**** s1    EXPECT req.url (/baz) == "/baz" match
**   s1    === expect req.http.foobar == "qux"
**** s1    EXPECT req.http.foobar (qux) == "qux" match
**   s1    === txresp -status 400
**** s1    txresp|HTTP/1.1 400 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:05 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**   s1    === accept
**** s1    Accepting
**** dT    2.292
***  s1    Accepted socket fd is 5
**   s1    === rxreq
**** dT    2.293
**** s1    rxhdr|GET /qux HTTP/1.1\r
**** s1    rxhdr|foobar: baz\r
**** s1    rxhdr|Host: 127.0.0.1\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: 1008\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 148
**** s1    http[ 0] |GET
**** s1    http[ 1] |/qux
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |foobar: baz
**** s1    http[ 4] |Host: 127.0.0.1
**** 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: 1008
**** s1    bodylen = 0
**   s1    === expect req.url == "/qux"
**** s1    EXPECT req.url (/qux) == "/qux" match
**   s1    === expect req.http.foobar == "baz"
**** s1    EXPECT req.http.foobar (baz) == "baz" match
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:05 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
***  s1    shutting fd 5
**   s1    Ending
**** dT    2.308
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Date: Thu, 18 May 2023 10:53:05 GMT\r
**** c1    rxhdr|Content-Length: 0\r
**** c1    rxhdr|X-Varnish: 1006\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 175
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |Date: Thu, 18 May 2023 10:53:05 GMT
**** c1    http[ 4] |Content-Length: 0
**** c1    http[ 5] |X-Varnish: 1006
**** c1    http[ 6] |Age: 0
**** c1    http[ 7] |Via: 1.1 v1 (Varnish/trunk)
**** c1    http[ 8] |Accept-Ranges: bytes
**** c1    http[ 9] |Connection: keep-alive
**** c1    bodylen = 0
***  c1    closing fd 17
**   c1    Ending
**** dT    2.313
**   top   === server s1 -wait
**   s1    Waiting for server (4/-1)
**   top   === varnish v1 -cliok "param.set workspace_client 12000"
**** v1    CLI TX|param.set workspace_client 12000
**** dT    2.356
***  v1    CLI RX  200
**   v1    CLI 200 <param.set workspace_client 12000>
**   top   === varnish v1 -cliok "param.set workspace_backend 12000"
**** v1    CLI TX|param.set workspace_backend 12000
**** dT    2.368
**** v1    vsl|          0 CLI             - Rd vcl.use vcl2
**** v1    vsl|          0 CLI             - Wr 200 0 
**** v1    vsl|       1005 Begin           c sess 0 HTTP/1
**** v1    vsl|       1005 SessOpen        c 127.0.0.1 34604 a0 127.0.0.1 35351 1684407185.598115 24
**** v1    vsl|       1005 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1005 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1005 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1005 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1005 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1005 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1005 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1005 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1005 Link            c req 1006 rxreq
**** v1    vsl|       1007 Begin           b bereq 1006 fetch
**** v1    vsl|       1007 VCL_use         b vcl2
**** v1    vsl|       1007 Timestamp       b Start: 1684407185.598267 0.000000 0.000000
**** v1    vsl|       1007 BereqMethod     b GET
**** v1    vsl|       1007 BereqURL        b /baz
**** v1    vsl|       1007 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1007 BereqHeader     b foobar: baz
**** 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 Via: 1.1 v1 (Varnish/trunk)
**** 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 BereqUnset      b foobar: baz
**** v1    vsl|       1007 BereqHeader     b foobar: qux
**** v1    vsl|       1007 VCL_return      b fetch
**** v1    vsl|       1007 Timestamp       b Fetch: 1684407185.598296 0.000028 0.000028
**** v1    vsl|       1007 Timestamp       b Connected: 1684407185.598378 0.000110 0.000081
**** v1    vsl|       1007 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37322 connect
**** v1    vsl|       1007 Timestamp       b Bereq: 1684407185.598414 0.000146 0.000036
**** v1    vsl|       1007 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1007 BerespStatus    b 400
**** v1    vsl|       1007 BerespReason    b OK
**** v1    vsl|       1007 BerespHeader    b Date: Thu, 18 May 2023 10:53:05 GMT
**** v1    vsl|       1007 BerespHeader    b Content-Length: 0
**** v1    vsl|       1007 Timestamp       b Beresp: 1684407185.600340 0.002072 0.001925
**** v1    vsl|       1007 TTL             b RFC -1 10 0 1684407186 1684407186 1684407185 0 0 cacheable
**** v1    vsl|       1007 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1007 BackendClose    b 26 s1 recycle
**** v1    vsl|       1007 BereqURL        b /qux
**** v1    vsl|       1007 VCL_return      b retry
**** v1    vsl|       1007 Timestamp       b Retry: 1684407185.614022 0.015754 0.013682
**** v1    vsl|       1007 Link            b bereq 1008 retry
**** v1    vsl|       1007 End             b 
**** v1    vsl|       1008 Begin           b bereq 1007 retry
**** v1    vsl|       1008 Timestamp       b Start: 1684407185.614022 0.015754 0.000000
**** v1    vsl|       1008 BereqMethod     b GET
**** v1    vsl|       1008 BereqURL        b /qux
**** v1    vsl|       1008 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1008 BereqHeader     b foobar: baz
**** v1    vsl|       1008 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1008 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1008 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1008 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1008 BereqHeader     b X-Varnish: 1008
**** v1    vsl|       1008 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1008 VCL_return      b fetch
**** v1    vsl|       1008 Timestamp       b Fetch: 1684407185.614044 0.015776 0.000022
**** v1    vsl|       1008 Timestamp       b Connected: 1684407185.614211 0.015944 0.000167
**** v1    vsl|       1008 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37324 connect
**** v1    vsl|       1008 Timestamp       b Bereq: 1684407185.614256 0.015988 0.000044
**** v1    vsl|       1008 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1008 BerespStatus    b 200
**** v1    vsl|       1008 BerespReason    b OK
**** v1    vsl|       1008 BerespHeader    b Date: Thu, 18 May 2023 10:53:05 GMT
**** v1    vsl|       1008 BerespHeader    b Content-Length: 0
**** v1    vsl|       1008 Timestamp       b Beresp: 1684407185.614797 0.016529 0.000540
**** v1    vsl|       1008 TTL             b RFC 120 10 0 1684407186 1684407186 1684407185 0 0 cacheable
**** v1    vsl|       1008 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1008 VCL_return      b deliver
**** v1    vsl|       1008 Timestamp       b Process: 1684407185.614843 0.016576 0.000046
**** v1    vsl|       1008 Filters         b 
**** v1    vsl|       1008 Storage         b malloc s0
**** v1    vsl|       1008 Fetch_Body      b 0 none -
**** v1    vsl|       1008 BackendClose    b 26 s1 recycle
**** v1    vsl|       1008 Timestamp       b BerespBody: 1684407185.625882 0.027614 0.011038
**** v1    vsl|       1008 Length          b 0
**** v1    vsl|       1008 BereqAcct       b 296 0 296 150 0 150
**** v1    vsl|       1008 End             b 
**** v1    vsl|       1006 Begin           c req 1005 rxreq
**** v1    vsl|       1006 Timestamp       c Start: 1684407185.598161 0.000000 0.000000
**** v1    vsl|       1006 Timestamp       c Req: 1684407185.598161 0.000000 0.000000
**** v1    vsl|       1006 VCL_use         c vcl2
**** v1    vsl|       1006 ReqStart        c 127.0.0.1 34604 a0
**** v1    vsl|       1006 ReqMethod       c GET
**** v1    vsl|       1006 ReqURL          c /baz
**** v1    vsl|       1006 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1006 ReqHeader       c foobar: baz
**** 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 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** 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: 1684407185.629793 0.031632 0.031632
**** 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: Thu, 18 May 2023 10:53:05 GMT
**** v1    vsl|       1006 RespHeader      c Content-Length: 0
**** v1    vsl|       1006 RespHeader      c X-Varnish: 1006
**** 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 VCL_return      c deliver
**** v1    vsl|       1006 Timestamp       c Process: 1684407185.629830 0.031669 0.000037
**** v1    vsl|       1006 Filters         c 
**** v1    vsl|       1006 RespHeader      c Connection: keep-alive
**** v1    vsl|       1006 Timestamp       c Resp: 1684407185.629886 0.031724 0.000055
**** v1    vsl|       1006 ReqAcct         c 51 0 51 175 0 175
**** v1    vsl|       1006 End             c 
**** v1    vsl|       1005 SessClose       c REM_CLOSE 0.032
**** v1    vsl|       1005 End             c 
**** dT    2.400
***  v1    CLI RX  200
**   v1    CLI 200 <param.set workspace_backend 12000>
**   top   === varnish v1 -vcl+backend {
**** v1    CLI TX|vcl.inline vcl3 << %XJEIFLH|)Xspa8P
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|backend s1 { .host = "127.0.0.1"; .port = "33281"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\timport std;
**** v1    CLI TX|\timport vtc;
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_recv {
**** v1    CLI TX|\t\tset req.http.test = "1";
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_fetch {
**** v1    CLI TX|\t\tunset bereq.http.test;
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_response {
**** v1    CLI TX|\t\tstd.rollback(bereq);
**** v1    CLI TX|\t\tset beresp.http.test = bereq.http.test;
**** v1    CLI TX|\t\tvtc.workspace_alloc(backend, -10);
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    2.897
***  v1    CLI RX  200
**** v1    CLI TX|vcl.use vcl3
**** dT    2.900
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl3' now active
**   top   === server s1 {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=33281
**** s1    macro def s1_sock=127.0.0.1:33281
*    s1    Listen on 127.0.0.1:33281
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**** dT    2.908
**   s1    Started on 127.0.0.1:33281 (1 iterations)
**** dT    2.909
**   c1    Started on 127.0.0.1:35351 (1 iterations)
***  c1    Connect to 127.0.0.1:35351
***  c1    connected fd 17 from 127.0.0.1 34616 to 127.0.0.1:35351
**   c1    === txreq -url /1
**** c1    txreq|GET /1 HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    2.912
***  s1    accepted fd 5 127.0.0.1 37334
**   s1    === rxreq
**** s1    rxhdr|GET /1 HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\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: 1011\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 133
**** s1    http[ 0] |GET
**** s1    http[ 1] |/1
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1011
**** s1    bodylen = 0
**   s1    === expect req.url == "/1"
**** s1    EXPECT req.url (/1) == "/1" match
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:06 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
***  s1    shutting fd 5
**   s1    Ending
**** dT    2.925
**** c1    rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|X-Varnish: 1010\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c1    rxhdr|Content-Length: 274\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 153
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |Backend fetch failed
**** c1    http[ 3] |Server: Varnish
**** c1    http[ 4] |X-Varnish: 1010
**** c1    http[ 5] |Age: 0
**** c1    http[ 6] |Via: 1.1 v1 (Varnish/trunk)
**** c1    http[ 7] |Content-Length: 274
**** c1    http[ 8] |Connection: keep-alive
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 Backend fetch failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error  Backend fetch failed</h1>
**** c1    c-l|    <p>Backend fetch failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: </p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 274
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
**   c1    === expect resp.http.test == <undef>
**** c1    EXPECT resp.http.test (<undef>) == "<undef>" match
***  c1    closing fd 17
**   c1    Ending
**   top   === server s1 -wait
**   s1    Waiting for server (4/-1)
**   top   === varnish v1 -vcl+backend {
**** v1    CLI TX|vcl.inline vcl4 << %XJEIFLH|)Xspa8P
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|backend s1 { .host = "127.0.0.1"; .port = "33281"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\timport std;
**** v1    CLI TX|\timport vtc;
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_fetch {
**** v1    CLI TX|\t\tvtc.workspace_alloc(backend, 1000);
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_response {
**** v1    CLI TX|\t\tif (bereq.retries == 0) {
**** v1    CLI TX|\t\t\tvtc.workspace_alloc(backend, -10);
**** v1    CLI TX|\t\t\tstd.rollback(bereq);
**** v1    CLI TX|\t\t\treturn (retry);
**** v1    CLI TX|\t\t}
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    2.984
**** v1    vsl|          0 CLI             - Rd vcl.load vcl3 vcl_vcl3.1684407185.721934/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl3.1684407185.721934/vgc.so" as "vcl3"
**** v1    vsl|          0 CLI             - Rd vcl.use vcl3
**** v1    vsl|          0 CLI             - Wr 200 0 
**** v1    vsl|       1009 Begin           c sess 0 HTTP/1
**** v1    vsl|       1009 SessOpen        c 127.0.0.1 34616 a0 127.0.0.1 35351 1684407186.230929 25
**** v1    vsl|       1009 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1009 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1009 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1009 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1009 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1009 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1009 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1009 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1009 Link            c req 1010 rxreq
**** v1    vsl|       1011 Begin           b bereq 1010 fetch
**** v1    vsl|       1011 VCL_use         b vcl3
**** v1    vsl|       1011 Timestamp       b Start: 1684407186.233798 0.000000 0.000000
**** v1    vsl|       1011 BereqMethod     b GET
**** v1    vsl|       1011 BereqURL        b /1
**** v1    vsl|       1011 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1011 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1011 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1011 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1011 BereqHeader     b test: 1
**** v1    vsl|       1011 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1011 BereqHeader     b X-Varnish: 1011
**** v1    vsl|       1011 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1011 BereqUnset      b test: 1
**** v1    vsl|       1011 VCL_return      b fetch
**** v1    vsl|       1011 Timestamp       b Fetch: 1684407186.233840 0.000041 0.000041
**** v1    vsl|       1011 Timestamp       b Connected: 1684407186.233907 0.000108 0.000066
**** v1    vsl|       1011 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37334 connect
**** v1    vsl|       1011 Timestamp       b Bereq: 1684407186.233944 0.000145 0.000036
**** v1    vsl|       1011 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1011 BerespStatus    b 200
**** v1    vsl|       1011 BerespReason    b OK
**** v1    vsl|       1011 BerespHeader    b Date: Thu, 18 May 2023 10:53:06 GMT
**** v1    vsl|       1011 BerespHeader    b Content-Length: 0
**** v1    vsl|       1011 Timestamp       b Beresp: 1684407186.234435 0.000636 0.000490
**** v1    vsl|       1011 TTL             b RFC 120 10 0 1684407186 1684407186 1684407186 0 0 cacheable
**** v1    vsl|       1011 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1011 BackendClose    b 26 s1 recycle
**** v1    vsl|       1011 BerespHeader    b test: 1
**** v1    vsl|       1011 VCL_return      b deliver
**** v1    vsl|       1011 Timestamp       b Process: 1684407186.245839 0.012040 0.011404
**** v1    vsl|       1011 FetchError      b No backend connection (rollback?)
**** v1    vsl|       1011 Timestamp       b Error: 1684407186.245848 0.012049 0.000008
**** v1    vsl|       1011 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1011 BerespStatus    b 503
**** v1    vsl|       1011 BerespReason    b Backend fetch failed
**** v1    vsl|       1011 Error           b out of workspace (bo)
**** v1    vsl|       1011 LostHeader      b Date: 
**** v1    vsl|       1011 BerespHeader    b Server: Varnish
**** v1    vsl|       1011 VCL_call        b BACKEND_ERROR
**** v1    vsl|       1011 LostHeader      b Content-Type:
**** v1    vsl|       1011 LostHeader      b Retry-After:
**** v1    vsl|       1011 VCL_return      b deliver
**** v1    vsl|       1011 Storage         b malloc Transient
**** v1    vsl|       1011 Length          b 274
**** v1    vsl|       1011 BereqAcct       b 133 0 133 75 0 75
**** v1    vsl|       1011 End             b 
**** v1    vsl|       1010 Begin           c req 1009 rxreq
**** v1    vsl|       1010 Timestamp       c Start: 1684407186.230973 0.000000 0.000000
**** v1    vsl|       1010 Timestamp       c Req: 1684407186.230973 0.000000 0.000000
**** v1    vsl|       1010 VCL_use         c vcl3
**** v1    vsl|       1010 ReqStart        c 127.0.0.1 34616 a0
**** v1    vsl|       1010 ReqMethod       c GET
**** v1    vsl|       1010 ReqURL          c /1
**** v1    vsl|       1010 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1010 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1010 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1010 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1010 VCL_call        c RECV
**** v1    vsl|       1010 ReqHeader       c test: 1
**** v1    vsl|       1010 VCL_return      c hash
**** v1    vsl|       1010 VCL_call        c HASH
**** v1    vsl|       1010 VCL_return      c lookup
**** v1    vsl|       1010 VCL_call        c MISS
**** v1    vsl|       1010 VCL_return      c fetch
**** v1    vsl|       1010 Link            c bereq 1011 fetch
**** v1    vsl|       1010 Timestamp       c Fetch: 1684407186.245998 0.015024 0.015024
**** v1    vsl|       1010 RespProtocol    c HTTP/1.1
**** v1    vsl|       1010 RespStatus      c 503
**** v1    vsl|       1010 RespReason      c Backend fetch failed
**** v1    vsl|       1010 RespHeader      c Server: Varnish
**** v1    vsl|       1010 RespHeader      c X-Varnish: 1010
**** v1    vsl|       1010 RespHeader      c Age: 0
**** v1    vsl|       1010 RespHeader      c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1010 VCL_call        c DELIVER
**** v1    vsl|       1010 VCL_return      c deliver
**** v1    vsl|       1010 Timestamp       c Process: 1684407186.246029 0.015056 0.000031
**** v1    vsl|       1010 Filters         c 
**** v1    vsl|       1010 RespHeader      c Content-Length: 274
**** v1    vsl|       1010 RespHeader      c Connection: keep-alive
**** v1    vsl|       1010 Timestamp       c Resp: 1684407186.246076 0.015102 0.000046
**** v1    vsl|       1010 ReqAcct         c 36 0 36 153 274 427
**** v1    vsl|       1010 End             c 
**** v1    vsl|       1009 SessClose       c REM_CLOSE 0.017
**** v1    vsl|       1009 End             c 
**** dT    3.745
***  v1    CLI RX  200
**** v1    CLI TX|vcl.use vcl4
**** dT    3.748
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl4' now active
**   top   === server s1 -repeat 2 -keepalive {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=33281
**** s1    macro def s1_sock=127.0.0.1:33281
*    s1    Listen on 127.0.0.1:33281
**   top   === client c2 {
**   c2    Starting client
**   c2    Waiting for client
**** dT    3.752
**   s1    Started on 127.0.0.1:33281 (2 iterations using keepalive)
**   c2    Started on 127.0.0.1:35351 (1 iterations)
***  c2    Connect to 127.0.0.1:35351
***  c2    connected fd 17 from 127.0.0.1 34624 to 127.0.0.1:35351
**   c2    === txreq -url /2
**** c2    txreq|GET /2 HTTP/1.1\r
**** c2    txreq|Host: 127.0.0.1\r
**** c2    txreq|\r
**   c2    === rxresp
**** dT    3.756
***  s1    accepted fd 5 127.0.0.1 37342
**   s1    === rxreq
**** s1    rxhdr|GET /2 HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\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: 1014\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 133
**** s1    http[ 0] |GET
**** s1    http[ 1] |/2
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1014
**** s1    bodylen = 0
**   s1    === expect req.url == "/2"
**** s1    EXPECT req.url (/2) == "/2" match
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:07 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**   s1    === rxreq
**** dT    3.772
**** s1    rxhdr|GET /2 HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\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: 1015\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 133
**** s1    http[ 0] |GET
**** s1    http[ 1] |/2
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1015
**** s1    bodylen = 0
**   s1    === expect req.url == "/2"
**** s1    EXPECT req.url (/2) == "/2" match
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:07 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
***  s1    shutting fd 5
**   s1    Ending
**** dT    3.796
**** c2    rxhdr|HTTP/1.1 200 OK\r
**** c2    rxhdr|Date: Thu, 18 May 2023 10:53:07 GMT\r
**** c2    rxhdr|Content-Length: 0\r
**** c2    rxhdr|X-Varnish: 1013\r
**** c2    rxhdr|Age: 0\r
**** c2    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c2    rxhdr|Accept-Ranges: bytes\r
**** c2    rxhdr|Connection: keep-alive\r
**** c2    rxhdr|\r
**** c2    rxhdrlen = 175
**** c2    http[ 0] |HTTP/1.1
**** c2    http[ 1] |200
**** c2    http[ 2] |OK
**** c2    http[ 3] |Date: Thu, 18 May 2023 10:53:07 GMT
**** c2    http[ 4] |Content-Length: 0
**** c2    http[ 5] |X-Varnish: 1013
**** c2    http[ 6] |Age: 0
**** c2    http[ 7] |Via: 1.1 v1 (Varnish/trunk)
**** c2    http[ 8] |Accept-Ranges: bytes
**** c2    http[ 9] |Connection: keep-alive
**** c2    bodylen = 0
**   c2    === expect resp.status == 200
**** c2    EXPECT resp.status (200) == "200" match
***  c2    closing fd 17
**   c2    Ending
**** dT    3.806
**   top   === server s1 -wait
**   s1    Waiting for server (4/-1)
**   top   === varnish v1 -vcl+backend {
**** v1    CLI TX|vcl.inline vcl5 << %XJEIFLH|)Xspa8P
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|backend s1 { .host = "127.0.0.1"; .port = "33281"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\timport std;
**** v1    CLI TX|\timport vtc;
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_fetch {
**** v1    CLI TX|\t\tset bereq.http.fetch = "Fetch value " + bereq.retries;
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_response {
**** v1    CLI TX|\t\tif (bereq.retries == 0) {
**** v1    CLI TX|\t\t\tstd.rollback(bereq);
**** v1    CLI TX|\t\t\tset bereq.http.response = "123";
**** v1    CLI TX|\t\t\tset bereq.http.response2 = "Another response";
**** v1    CLI TX|\t\t\tif (bereq.url == "/4") {
**** v1    CLI TX|\t\t\t\tvtc.workspace_alloc(backend, -10);
**** v1    CLI TX|\t\t\t} else if (bereq.url == "/5") {
**** v1    CLI TX|\t\t\t\tvtc.workspace_alloc(backend, -10);
**** v1    CLI TX|\t\t\t\tstd.rollback(bereq);
**** v1    CLI TX|\t\t\t}
**** v1    CLI TX|\t\t\treturn (retry);
**** v1    CLI TX|\t\t}
**** v1    CLI TX|\t\tset beresp.http.fetch = bereq.http.fetch;
**** v1    CLI TX|\t\tset beresp.http.response = bereq.http.response;
**** v1    CLI TX|\t\tset beresp.http.response2 = bereq.http.response2;
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** v1    vsl|          0 CLI             - Rd vcl.load vcl4 vcl_vcl4.1684407186.246973/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl4.1684407186.246973/vgc.so" as "vcl4"
**** v1    vsl|          0 CLI             - Rd vcl.use vcl4
**** v1    vsl|          0 CLI             - Wr 200 0 
**** v1    vsl|       1012 Begin           c sess 0 HTTP/1
**** v1    vsl|       1012 SessOpen        c 127.0.0.1 34624 a0 127.0.0.1 35351 1684407187.074058 23
**** v1    vsl|       1012 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1012 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1012 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1012 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1012 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1012 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1012 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1012 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1012 Link            c req 1013 rxreq
**** v1    vsl|       1014 Begin           b bereq 1013 fetch
**** v1    vsl|       1014 VCL_use         b vcl4
**** v1    vsl|       1014 Timestamp       b Start: 1684407187.074262 0.000000 0.000000
**** v1    vsl|       1014 BereqMethod     b GET
**** v1    vsl|       1014 BereqURL        b /2
**** v1    vsl|       1014 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1014 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1014 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1014 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1014 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1014 BereqHeader     b X-Varnish: 1014
**** v1    vsl|       1014 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1014 VCL_return      b fetch
**** v1    vsl|       1014 Timestamp       b Fetch: 1684407187.074304 0.000042 0.000042
**** v1    vsl|       1014 Timestamp       b Connected: 1684407187.074447 0.000185 0.000142
**** v1    vsl|       1014 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37342 connect
**** v1    vsl|       1014 Timestamp       b Bereq: 1684407187.074486 0.000224 0.000039
**** v1    vsl|       1014 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1014 BerespStatus    b 200
**** v1    vsl|       1014 BerespReason    b OK
**** v1    vsl|       1014 BerespHeader    b Date: Thu, 18 May 2023 10:53:07 GMT
**** v1    vsl|       1014 BerespHeader    b Content-Length: 0
**** v1    vsl|       1014 Timestamp       b Beresp: 1684407187.078322 0.004060 0.003835
**** v1    vsl|       1014 TTL             b RFC 120 10 0 1684407187 1684407187 1684407187 0 0 cacheable
**** v1    vsl|       1014 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1014 BackendClose    b 26 s1 recycle
**** v1    vsl|       1014 VCL_return      b retry
**** v1    vsl|       1014 Timestamp       b Retry: 1684407187.090762 0.016500 0.012440
**** v1    vsl|       1014 Link            b bereq 1015 retry
**** v1    vsl|       1014 End             b 
**** v1    vsl|       1015 Begin           b bereq 1014 retry
**** v1    vsl|       1015 Timestamp       b Start: 1684407187.090762 0.016500 0.000000
**** v1    vsl|       1015 BereqMethod     b GET
**** v1    vsl|       1015 BereqURL        b /2
**** v1    vsl|       1015 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1015 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1015 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1015 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1015 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1015 BereqHeader     b X-Varnish: 1015
**** v1    vsl|       1015 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1015 VCL_return      b fetch
**** v1    vsl|       1015 Timestamp       b Fetch: 1684407187.090791 0.016529 0.000029
**** v1    vsl|       1015 Timestamp       b Connected: 1684407187.090797 0.016535 0.000006
**** v1    vsl|       1015 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37342 reuse
**** v1    vsl|       1015 Timestamp       b Bereq: 1684407187.090883 0.016621 0.000085
**** v1    vsl|       1015 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1015 BerespStatus    b 200
**** v1    vsl|       1015 BerespReason    b OK
**** v1    vsl|       1015 BerespHeader    b Date: Thu, 18 May 2023 10:53:07 GMT
**** v1    vsl|       1015 BerespHeader    b Content-Length: 0
**** v1    vsl|       1015 Timestamp       b Beresp: 1684407187.100799 0.026537 0.009916
**** v1    vsl|       1015 TTL             b RFC 120 10 0 1684407187 1684407187 1684407187 0 0 cacheable
**** v1    vsl|       1015 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1015 VCL_return      b deliver
**** v1    vsl|       1015 Timestamp       b Process: 1684407187.100840 0.026578 0.000041
**** v1    vsl|       1015 Filters         b 
**** v1    vsl|       1015 Storage         b malloc s0
**** v1    vsl|       1015 Fetch_Body      b 0 none -
**** v1    vsl|       1015 BackendClose    b 26 s1 recycle
**** v1    vsl|       1015 Timestamp       b BerespBody: 1684407187.114048 0.039786 0.013208
**** v1    vsl|       1015 Length          b 0
**** v1    vsl|       1015 BereqAcct       b 266 0 266 150 0 150
**** v1    vsl|       1015 End             b 
**** v1    vsl|       1013 Begin           c req 1012 rxreq
**** v1    vsl|       1013 Timestamp       c Start: 1684407187.074103 0.000000 0.000000
**** v1    vsl|       1013 Timestamp       c Req: 1684407187.074103 0.000000 0.000000
**** v1    vsl|       1013 VCL_use         c vcl4
**** v1    vsl|       1013 ReqStart        c 127.0.0.1 34624 a0
**** v1    vsl|       1013 ReqMethod       c GET
**** v1    vsl|       1013 ReqURL          c /2
**** v1    vsl|       1013 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1013 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1013 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1013 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1013 VCL_call        c RECV
**** v1    vsl|       1013 VCL_return      c hash
**** v1    vsl|       1013 VCL_call        c HASH
**** v1    vsl|       1013 VCL_return      c lookup
**** v1    vsl|       1013 VCL_call        c MISS
**** v1    vsl|       1013 VCL_return      c fetch
**** v1    vsl|       1013 Link            c bereq 1014 fetch
**** v1    vsl|       1013 Timestamp       c Fetch: 1684407187.117806 0.043702 0.043702
**** v1    vsl|       1013 RespProtocol    c HTTP/1.1
**** v1    vsl|       1013 RespStatus      c 200
**** v1    vsl|       1013 RespReason      c OK
**** v1    vsl|       1013 RespHeader      c Date: Thu, 18 May 2023 10:53:07 GMT
**** v1    vsl|       1013 RespHeader      c Content-Length: 0
**** v1    vsl|       1013 RespHeader      c X-Varnish: 1013
**** v1    vsl|       1013 RespHeader      c Age: 0
**** v1    vsl|       1013 RespHeader      c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1013 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1013 VCL_call        c DELIVER
**** v1    vsl|       1013 VCL_return      c deliver
**** v1    vsl|       1013 Timestamp       c Process: 1684407187.117850 0.043746 0.000043
**** v1    vsl|       1013 Filters         c 
**** v1    vsl|       1013 RespHeader      c Connection: keep-alive
**** v1    vsl|       1013 Timestamp       c Resp: 1684407187.117912 0.043808 0.000062
**** v1    vsl|       1013 ReqAcct         c 36 0 36 175 0 175
**** v1    vsl|       1013 End             c 
**** v1    vsl|       1012 SessClose       c REM_CLOSE 0.044
**** v1    vsl|       1012 End             c 
**** dT    4.460
***  v1    CLI RX  200
**** v1    CLI TX|vcl.use vcl5
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl5' now active
**   top   === server s1 -repeat 5 -keepalive {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=33281
**** s1    macro def s1_sock=127.0.0.1:33281
*    s1    Listen on 127.0.0.1:33281
**   top   === client c3 {
**   c3    Starting client
**   c3    Waiting for client
**   s1    Started on 127.0.0.1:33281 (5 iterations using keepalive)
**   c3    Started on 127.0.0.1:35351 (1 iterations)
***  c3    Connect to 127.0.0.1:35351
***  c3    connected fd 17 from 127.0.0.1 34630 to 127.0.0.1:35351
**   c3    === txreq -url /3
**** c3    txreq|GET /3 HTTP/1.1\r
**** c3    txreq|Host: 127.0.0.1\r
**** c3    txreq|\r
**   c3    === rxresp
**** dT    4.461
***  s1    accepted fd 5 127.0.0.1 37348
**   s1    === rxreq
**** s1    rxhdr|GET /3 HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\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: 1018\r
**** s1    rxhdr|fetch: Fetch value 0\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 155
**** s1    http[ 0] |GET
**** s1    http[ 1] |/3
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1018
**** s1    http[ 8] |fetch: Fetch value 0
**** s1    bodylen = 0
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:07 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**   s1    === rxreq
**** dT    4.474
**** s1    rxhdr|GET /3 HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\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|response: 123\r
**** s1    rxhdr|response2: Another response\r
**** s1    rxhdr|X-Varnish: 1019\r
**** s1    rxhdr|fetch: Fetch value 1\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 199
**** s1    http[ 0] |GET
**** s1    http[ 1] |/3
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |response: 123
**** s1    http[ 8] |response2: Another response
**** s1    http[ 9] |X-Varnish: 1019
**** s1    http[10] |fetch: Fetch value 1
**** s1    bodylen = 0
**   s1    === txresp
**** dT    4.475
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:07 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**   s1    === rxreq
**** dT    4.486
**** c3    rxhdr|HTTP/1.1 200 OK\r
**** c3    rxhdr|Date: Thu, 18 May 2023 10:53:07 GMT\r
**** c3    rxhdr|Content-Length: 0\r
**** c3    rxhdr|fetch: Fetch value 1\r
**** c3    rxhdr|response: 123\r
**** c3    rxhdr|response2: Another response\r
**** c3    rxhdr|X-Varnish: 1017\r
**** c3    rxhdr|Age: 0\r
**** c3    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c3    rxhdr|Accept-Ranges: bytes\r
**** c3    rxhdr|Connection: keep-alive\r
**** c3    rxhdr|\r
**** c3    rxhdrlen = 241
**** c3    http[ 0] |HTTP/1.1
**** c3    http[ 1] |200
**** c3    http[ 2] |OK
**** c3    http[ 3] |Date: Thu, 18 May 2023 10:53:07 GMT
**** c3    http[ 4] |Content-Length: 0
**** c3    http[ 5] |fetch: Fetch value 1
**** c3    http[ 6] |response: 123
**** c3    http[ 7] |response2: Another response
**** c3    http[ 8] |X-Varnish: 1017
**** c3    http[ 9] |Age: 0
**** c3    http[10] |Via: 1.1 v1 (Varnish/trunk)
**** c3    http[11] |Accept-Ranges: bytes
**** c3    http[12] |Connection: keep-alive
**** c3    bodylen = 0
**   c3    === expect resp.status == 200
**** c3    EXPECT resp.status (200) == "200" match
**   c3    === expect resp.http.fetch == "Fetch value 1"
**** c3    EXPECT resp.http.fetch (Fetch value 1) == "Fetch value 1" match
**   c3    === expect resp.http.response == "123"
**** c3    EXPECT resp.http.response (123) == "123" match
**   c3    === expect resp.http.response2 == "Another response"
**** c3    EXPECT resp.http.response2 (Another response) == "Another response" match
**   c3    === txreq -url /4
**** c3    txreq|GET /4 HTTP/1.1\r
**** c3    txreq|Host: 127.0.0.1\r
**** c3    txreq|\r
**   c3    === rxresp
**** s1    rxhdr|GET /4 HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\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: 1021\r
**** s1    rxhdr|fetch: Fetch value 0\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 155
**** s1    http[ 0] |GET
**** s1    http[ 1] |/4
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1021
**** s1    http[ 8] |fetch: Fetch value 0
**** s1    bodylen = 0
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:07 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**   s1    === rxreq
**** dT    4.497
**** c3    rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c3    rxhdr|Server: Varnish\r
**** c3    rxhdr|X-Varnish: 1020\r
**** c3    rxhdr|Age: 0\r
**** c3    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c3    rxhdr|Content-Length: 271\r
**** c3    rxhdr|Connection: keep-alive\r
**** c3    rxhdr|\r
**** c3    rxhdrlen = 153
**** c3    http[ 0] |HTTP/1.1
**** c3    http[ 1] |503
**** c3    http[ 2] |Backend fetch failed
**** c3    http[ 3] |Server: Varnish
**** c3    http[ 4] |X-Varnish: 1020
**** c3    http[ 5] |Age: 0
**** c3    http[ 6] |Via: 1.1 v1 (Varnish/trunk)
**** c3    http[ 7] |Content-Length: 271
**** c3    http[ 8] |Connection: keep-alive
**** c3    c-l|<!DOCTYPE html>
**** c3    c-l|<html>
**** c3    c-l|  <head>
**** c3    c-l|    <title> Backend fetch failed</title>
**** c3    c-l|  </head>
**** c3    c-l|  <body>
**** c3    c-l|    <h1>Error  Backend fetch failed</h1>
**** c3    c-l|    <p>Backend fetch failed</p>
**** c3    c-l|    <h3>Guru Meditation:</h3>
**** c3    c-l|    <p>XID: </p>
**** c3    c-l|    <hr>
**** c3    c-l|    <p>Varnish cache server</p>
**** c3    c-l|  </body>
**** c3    c-l|</html>
**** c3    bodylen = 271
**   c3    === expect resp.status == 503
**** c3    EXPECT resp.status (503) == "503" match
**   c3    === txreq -url /5
**** c3    txreq|GET /5 HTTP/1.1\r
**** c3    txreq|Host: 127.0.0.1\r
**** c3    txreq|\r
**   c3    === rxresp
**** dT    4.498
**** s1    rxhdr|GET /5 HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\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: 1024\r
**** s1    rxhdr|fetch: Fetch value 0\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 155
**** s1    http[ 0] |GET
**** s1    http[ 1] |/5
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1024
**** s1    http[ 8] |fetch: Fetch value 0
**** s1    bodylen = 0
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:07 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**   s1    === rxreq
**** dT    4.508
**** s1    rxhdr|GET /5 HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\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: 1025\r
**** s1    rxhdr|fetch: Fetch value 1\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 155
**** s1    http[ 0] |GET
**** s1    http[ 1] |/5
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1025
**** s1    http[ 8] |fetch: Fetch value 1
**** s1    bodylen = 0
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:07 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
***  s1    shutting fd 5
**   s1    Ending
**** dT    4.520
**** c3    rxhdr|HTTP/1.1 200 OK\r
**** c3    rxhdr|Date: Thu, 18 May 2023 10:53:07 GMT\r
**** c3    rxhdr|Content-Length: 0\r
**** c3    rxhdr|fetch: Fetch value 1\r
**** c3    rxhdr|response: \r
**** c3    rxhdr|response2: \r
**** c3    rxhdr|X-Varnish: 1023\r
**** c3    rxhdr|Age: 0\r
**** c3    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c3    rxhdr|Accept-Ranges: bytes\r
**** c3    rxhdr|Connection: keep-alive\r
**** c3    rxhdr|\r
**** c3    rxhdrlen = 222
**** c3    http[ 0] |HTTP/1.1
**** c3    http[ 1] |200
**** c3    http[ 2] |OK
**** c3    http[ 3] |Date: Thu, 18 May 2023 10:53:07 GMT
**** c3    http[ 4] |Content-Length: 0
**** c3    http[ 5] |fetch: Fetch value 1
**** c3    http[ 6] |response: 
**** c3    http[ 7] |response2: 
**** c3    http[ 8] |X-Varnish: 1023
**** c3    http[ 9] |Age: 0
**** c3    http[10] |Via: 1.1 v1 (Varnish/trunk)
**** c3    http[11] |Accept-Ranges: bytes
**** c3    http[12] |Connection: keep-alive
**** c3    bodylen = 0
**   c3    === expect resp.status == 200
**** c3    EXPECT resp.status (200) == "200" match
**   c3    === expect resp.http.fetch == "Fetch value 1"
**** c3    EXPECT resp.http.fetch (Fetch value 1) == "Fetch value 1" match
**   c3    === expect resp.http.response == ""
**** c3    EXPECT resp.http.response () == "" match
**   c3    === expect resp.http.response2 == ""
**** c3    EXPECT resp.http.response2 () == "" match
***  c3    closing fd 17
**   c3    Ending
**   top   === server s1 -wait
**   s1    Waiting for server (4/-1)
**   top   === varnish v1 -vcl+backend {
**** v1    CLI TX|vcl.inline vcl6 << %XJEIFLH|)Xspa8P
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|backend s1 { .host = "127.0.0.1"; .port = "33281"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\timport std;
**** v1    CLI TX|\timport debug;
**** v1    CLI TX|\timport vtc;
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_recv {
**** v1    CLI TX|\t\tunset req.http.test;
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_deliver {
**** v1    CLI TX|\t\tif (req.url ~ "/veto") {
**** v1    CLI TX|\t\t\tdebug.fail_task_fini();
**** v1    CLI TX|\t\t}
**** v1    CLI TX|\t\tif (req.url ~ "/ok") {
**** v1    CLI TX|\t\t\tdebug.ok_task_fini();
**** v1    CLI TX|\t\t}
**** v1    CLI TX|\t\tstd.rollback(req);
**** v1    CLI TX|\t\tset resp.http.test = req.http.test;
**** v1    CLI TX|\t\tvtc.workspace_alloc(client, -200);
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    4.528
**** v1    vsl|          0 CLI             - Rd vcl.load vcl5 vcl_vcl5.1684407187.128306/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl5.1684407187.128306/vgc.so" as "vcl5"
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1684407187 1.0
**** v1    vsl|          0 CLI             - Rd vcl.use vcl5
**** v1    vsl|          0 CLI             - Wr 200 0 
**** v1    vsl|       1016 Begin           c sess 0 HTTP/1
**** v1    vsl|       1016 SessOpen        c 127.0.0.1 34630 a0 127.0.0.1 35351 1684407187.782345 24
**** v1    vsl|       1016 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1016 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1016 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1016 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1016 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1016 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1016 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1016 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:35351
**** v1    vsl|       1016 Link            c req 1017 rxreq
**** v1    vsl|       1018 Begin           b bereq 1017 fetch
**** v1    vsl|       1018 VCL_use         b vcl5
**** v1    vsl|       1018 Timestamp       b Start: 1684407187.782520 0.000000 0.000000
**** v1    vsl|       1018 BereqMethod     b GET
**** v1    vsl|       1018 BereqURL        b /3
**** v1    vsl|       1018 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1018 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1018 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1018 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1018 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1018 BereqHeader     b X-Varnish: 1018
**** v1    vsl|       1018 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1018 BereqHeader     b fetch: Fetch value 0
**** v1    vsl|       1018 VCL_return      b fetch
**** v1    vsl|       1018 Timestamp       b Fetch: 1684407187.782567 0.000046 0.000046
**** v1    vsl|       1018 Timestamp       b Connected: 1684407187.782648 0.000128 0.000081
**** v1    vsl|       1018 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37348 connect
**** v1    vsl|       1018 Timestamp       b Bereq: 1684407187.782687 0.000166 0.000038
**** v1    vsl|       1018 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1018 BerespStatus    b 200
**** v1    vsl|       1018 BerespReason    b OK
**** v1    vsl|       1018 BerespHeader    b Date: Thu, 18 May 2023 10:53:07 GMT
**** v1    vsl|       1018 BerespHeader    b Content-Length: 0
**** v1    vsl|       1018 Timestamp       b Beresp: 1684407187.785679 0.003159 0.002992
**** v1    vsl|       1018 TTL             b RFC 120 10 0 1684407188 1684407188 1684407187 0 0 cacheable
**** v1    vsl|       1018 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1018 BackendClose    b 26 s1 recycle
**** v1    vsl|       1018 BereqHeader     b response: 123
**** v1    vsl|       1018 BereqHeader     b response2: Another response
**** v1    vsl|       1018 VCL_return      b retry
**** v1    vsl|       1018 Timestamp       b Retry: 1684407187.795823 0.013302 0.010143
**** v1    vsl|       1018 Link            b bereq 1019 retry
**** v1    vsl|       1018 End             b 
**** v1    vsl|       1019 Begin           b bereq 1018 retry
**** v1    vsl|       1019 Timestamp       b Start: 1684407187.795823 0.013302 0.000000
**** v1    vsl|       1019 BereqMethod     b GET
**** v1    vsl|       1019 BereqURL        b /3
**** v1    vsl|       1019 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1019 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1019 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1019 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1019 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1019 BereqHeader     b response: 123
**** v1    vsl|       1019 BereqHeader     b response2: Another response
**** v1    vsl|       1019 BereqHeader     b X-Varnish: 1019
**** v1    vsl|       1019 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1019 BereqHeader     b fetch: Fetch value 1
**** v1    vsl|       1019 VCL_return      b fetch
**** v1    vsl|       1019 Timestamp       b Fetch: 1684407187.795842 0.013322 0.000019
**** v1    vsl|       1019 Timestamp       b Connected: 1684407187.795847 0.013326 0.000004
**** v1    vsl|       1019 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37348 reuse
**** v1    vsl|       1019 Timestamp       b Bereq: 1684407187.795928 0.013407 0.000080
**** v1    vsl|       1019 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1019 BerespStatus    b 200
**** v1    vsl|       1019 BerespReason    b OK
**** v1    vsl|       1019 BerespHeader    b Date: Thu, 18 May 2023 10:53:07 GMT
**** v1    vsl|       1019 BerespHeader    b Content-Length: 0
**** v1    vsl|       1019 Timestamp       b Beresp: 1684407187.796558 0.014038 0.000630
**** v1    vsl|       1019 TTL             b RFC 120 10 0 1684407188 1684407188 1684407187 0 0 cacheable
**** v1    vsl|       1019 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1019 BerespHeader    b fetch: Fetch value 1
**** v1    vsl|       1019 BerespHeader    b response: 123
**** v1    vsl|       1019 BerespHeader    b response2: Another response
**** v1    vsl|       1019 VCL_return      b deliver
**** v1    vsl|       1019 Timestamp       b Process: 1684407187.796588 0.014067 0.000029
**** v1    vsl|       1019 Filters         b 
**** v1    vsl|       1019 Storage         b malloc s0
**** v1    vsl|       1019 Fetch_Body      b 0 none -
**** v1    vsl|       1019 BackendClose    b 26 s1 recycle
**** v1    vsl|       1019 Timestamp       b BerespBody: 1684407187.806726 0.024205 0.010138
**** v1    vsl|       1019 Length          b 0
**** v1    vsl|       1019 BereqAcct       b 354 0 354 150 0 150
**** v1    vsl|       1019 End             b 
**** v1    vsl|       1017 Begin           c req 1016 rxreq
**** v1    vsl|       1017 Timestamp       c Start: 1684407187.782387 0.000000 0.000000
**** v1    vsl|       1017 Timestamp       c Req: 1684407187.782387 0.000000 0.000000
**** v1    vsl|       1017 VCL_use         c vcl5
**** v1    vsl|       1017 ReqStart        c 127.0.0.1 34630 a0
**** v1    vsl|       1017 ReqMethod       c GET
**** v1    vsl|       1017 ReqURL          c /3
**** v1    vsl|       1017 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1017 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1017 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1017 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1017 VCL_call        c RECV
**** v1    vsl|       1017 VCL_return      c hash
**** v1    vsl|       1017 VCL_call        c HASH
**** v1    vsl|       1017 VCL_return      c lookup
**** v1    vsl|       1017 VCL_call        c MISS
**** v1    vsl|       1017 VCL_return      c fetch
**** v1    vsl|       1017 Link            c bereq 1018 fetch
**** v1    vsl|       1017 Timestamp       c Fetch: 1684407187.806764 0.024377 0.024377
**** v1    vsl|       1017 RespProtocol    c HTTP/1.1
**** v1    vsl|       1017 RespStatus      c 200
**** v1    vsl|       1017 RespReason      c OK
**** v1    vsl|       1017 RespHeader      c Date: Thu, 18 May 2023 10:53:07 GMT
**** v1    vsl|       1017 RespHeader      c Content-Length: 0
**** v1    vsl|       1017 RespHeader      c fetch: Fetch value 1
**** v1    vsl|       1017 RespHeader      c response: 123
**** v1    vsl|       1017 RespHeader      c response2: Another response
**** v1    vsl|       1017 RespHeader      c X-Varnish: 1017
**** v1    vsl|       1017 RespHeader      c Age: 0
**** v1    vsl|       1017 RespHeader      c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1017 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1017 VCL_call        c DELIVER
**** v1    vsl|       1017 VCL_return      c deliver
**** v1    vsl|       1017 Timestamp       c Process: 1684407187.806791 0.024404 0.000026
**** v1    vsl|       1017 Filters         c 
**** v1    vsl|       1017 RespHeader      c Connection: keep-alive
**** v1    vsl|       1017 Timestamp       c Resp: 1684407187.806835 0.024448 0.000044
**** v1    vsl|       1017 ReqAcct         c 36 0 36 241 0 241
**** v1    vsl|       1017 End             c 
**** v1    vsl|       1016 Link            c req 1020 rxreq
**** v1    vsl|       1021 Begin           b bereq 1020 fetch
**** v1    vsl|       1021 VCL_use         b vcl5
**** v1    vsl|       1021 Timestamp       b Start: 1684407187.807649 0.000000 0.000000
**** v1    vsl|       1021 BereqMethod     b GET
**** v1    vsl|       1021 BereqURL        b /4
**** v1    vsl|       1021 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1021 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1021 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1021 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1021 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1021 BereqHeader     b X-Varnish: 1021
**** v1    vsl|       1021 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1021 BereqHeader     b fetch: Fetch value 0
**** v1    vsl|       1021 VCL_return      b fetch
**** v1    vsl|       1021 Timestamp       b Fetch: 1684407187.807669 0.000019 0.000019
**** v1    vsl|       1021 Timestamp       b Connected: 1684407187.807674 0.000024 0.000004
**** v1    vsl|       1021 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37348 reuse
**** v1    vsl|       1021 Timestamp       b Bereq: 1684407187.807708 0.000058 0.000033
**** v1    vsl|       1021 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1021 BerespStatus    b 200
**** v1    vsl|       1021 BerespReason    b OK
**** v1    vsl|       1021 BerespHeader    b Date: Thu, 18 May 2023 10:53:07 GMT
**** v1    vsl|       1021 BerespHeader    b Content-Length: 0
**** v1    vsl|       1021 Timestamp       b Beresp: 1684407187.808193 0.000543 0.000484
**** v1    vsl|       1021 TTL             b RFC 120 10 0 1684407188 1684407188 1684407187 0 0 cacheable
**** v1    vsl|       1021 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1021 BackendClose    b 26 s1 recycle
**** v1    vsl|       1021 BereqHeader     b response: 123
**** v1    vsl|       1021 BereqHeader     b response2: Another response
**** v1    vsl|       1021 VCL_return      b retry
**** v1    vsl|       1021 Timestamp       b Retry: 1684407187.818324 0.010674 0.010131
**** v1    vsl|       1021 Link            b bereq 1022 retry
**** v1    vsl|       1021 End             b 
**** v1    vsl|       1022 Begin           b bereq 1021 retry
**** v1    vsl|       1022 Timestamp       b Start: 1684407187.818324 0.010674 0.000000
**** v1    vsl|       1022 BereqMethod     b GET
**** v1    vsl|       1022 BereqURL        b /4
**** v1    vsl|       1022 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1022 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1022 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1022 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1022 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1022 BereqHeader     b response: 123
**** v1    vsl|       1022 BereqHeader     b response2: Another response
**** v1    vsl|       1022 Error           b out of workspace (bo)
**** v1    vsl|       1022 LostHeader      b X-Varnish: 1022
**** v1    vsl|       1022 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1022 LostHeader      b fetch:
**** v1    vsl|       1022 VCL_return      b fetch
**** v1    vsl|       1022 Timestamp       b Fetch: 1684407187.818344 0.010694 0.000019
**** v1    vsl|       1022 FetchError      b out of workspace
**** v1    vsl|       1022 Timestamp       b Beresp: 1684407187.818348 0.010698 0.000004
**** v1    vsl|       1022 Timestamp       b Error: 1684407187.818349 0.010699 0.000001
**** v1    vsl|       1022 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1022 BerespStatus    b 503
**** v1    vsl|       1022 BerespReason    b Backend fetch failed
**** v1    vsl|       1022 Error           b out of workspace (bo)
**** v1    vsl|       1022 LostHeader      b Date: 
**** v1    vsl|       1022 BerespHeader    b Server: Varnish
**** v1    vsl|       1022 VCL_call        b BACKEND_ERROR
**** v1    vsl|       1022 LostHeader      b Content-Type:
**** v1    vsl|       1022 LostHeader      b Retry-After:
**** v1    vsl|       1022 VCL_return      b deliver
**** v1    vsl|       1022 Storage         b malloc Transient
**** v1    vsl|       1022 Length          b 271
**** v1    vsl|       1022 BereqAcct       b 155 0 155 75 0 75
**** v1    vsl|       1022 End             b 
**** v1    vsl|       1020 Begin           c req 1016 rxreq
**** v1    vsl|       1020 Timestamp       c Start: 1684407187.807578 0.000000 0.000000
**** v1    vsl|       1020 Timestamp       c Req: 1684407187.807578 0.000000 0.000000
**** v1    vsl|       1020 VCL_use         c vcl5
**** v1    vsl|       1020 ReqStart        c 127.0.0.1 34630 a0
**** v1    vsl|       1020 ReqMethod       c GET
**** v1    vsl|       1020 ReqURL          c /4
**** v1    vsl|       1020 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1020 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1020 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1020 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1020 VCL_call        c RECV
**** v1    vsl|       1020 VCL_return      c hash
**** v1    vsl|       1020 VCL_call        c HASH
**** v1    vsl|       1020 VCL_return      c lookup
**** v1    vsl|       1020 VCL_call        c MISS
**** v1    vsl|       1020 VCL_return      c fetch
**** v1    vsl|       1020 Link            c bereq 1021 fetch
**** v1    vsl|       1020 Timestamp       c Fetch: 1684407187.818416 0.010837 0.010837
**** v1    vsl|       1020 RespProtocol    c HTTP/1.1
**** v1    vsl|       1020 RespStatus      c 503
**** v1    vsl|       1020 RespReason      c Backend fetch failed
**** v1    vsl|       1020 RespHeader      c Server: Varnish
**** v1    vsl|       1020 RespHeader      c X-Varnish: 1020
**** v1    vsl|       1020 RespHeader      c Age: 0
**** v1    vsl|       1020 RespHeader      c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1020 VCL_call        c DELIVER
**** v1    vsl|       1020 VCL_return      c deliver
**** v1    vsl|       1020 Timestamp       c Process: 1684407187.818435 0.010856 0.000019
**** v1    vsl|       1020 Filters         c 
**** v1    vsl|       1020 RespHeader      c Content-Length: 271
**** v1    vsl|       1020 RespHeader      c Connection: keep-alive
**** v1    vsl|       1020 Timestamp       c Resp: 1684407187.818478 0.010899 0.000043
**** v1    vsl|       1020 ReqAcct         c 36 0 36 153 271 424
**** v1    vsl|       1020 End             c 
**** v1    vsl|       1016 Link            c req 1023 rxreq
**** v1    vsl|       1024 Begin           b bereq 1023 fetch
**** v1    vsl|       1024 VCL_use         b vcl5
**** v1    vsl|       1024 Timestamp       b Start: 1684407187.819064 0.000000 0.000000
**** v1    vsl|       1024 BereqMethod     b GET
**** v1    vsl|       1024 BereqURL        b /5
**** v1    vsl|       1024 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1024 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1024 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1024 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1024 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1024 BereqHeader     b X-Varnish: 1024
**** v1    vsl|       1024 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1024 BereqHeader     b fetch: Fetch value 0
**** v1    vsl|       1024 VCL_return      b fetch
**** v1    vsl|       1024 Timestamp       b Fetch: 1684407187.819083 0.000018 0.000018
**** v1    vsl|       1024 Timestamp       b Connected: 1684407187.819086 0.000022 0.000003
**** v1    vsl|       1024 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37348 reuse
**** v1    vsl|       1024 Timestamp       b Bereq: 1684407187.819121 0.000056 0.000034
**** v1    vsl|       1024 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1024 BerespStatus    b 200
**** v1    vsl|       1024 BerespReason    b OK
**** v1    vsl|       1024 BerespHeader    b Date: Thu, 18 May 2023 10:53:07 GMT
**** v1    vsl|       1024 BerespHeader    b Content-Length: 0
**** v1    vsl|       1024 Timestamp       b Beresp: 1684407187.819603 0.000539 0.000482
**** v1    vsl|       1024 TTL             b RFC 120 10 0 1684407188 1684407188 1684407187 0 0 cacheable
**** v1    vsl|       1024 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1024 BackendClose    b 26 s1 recycle
**** v1    vsl|       1024 BereqHeader     b response: 123
**** v1    vsl|       1024 BereqHeader     b response2: Another response
**** v1    vsl|       1024 VCL_return      b retry
**** v1    vsl|       1024 Timestamp       b Retry: 1684407187.829692 0.010628 0.010089
**** v1    vsl|       1024 Link            b bereq 1025 retry
**** v1    vsl|       1024 End             b 
**** v1    vsl|       1025 Begin           b bereq 1024 retry
**** v1    vsl|       1025 Timestamp       b Start: 1684407187.829692 0.010628 0.000000
**** v1    vsl|       1025 BereqMethod     b GET
**** v1    vsl|       1025 BereqURL        b /5
**** v1    vsl|       1025 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1025 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1025 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1025 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1025 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1025 BereqHeader     b X-Varnish: 1025
**** v1    vsl|       1025 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1025 BereqHeader     b fetch: Fetch value 1
**** v1    vsl|       1025 VCL_return      b fetch
**** v1    vsl|       1025 Timestamp       b Fetch: 1684407187.829714 0.010649 0.000021
**** v1    vsl|       1025 Timestamp       b Connected: 1684407187.829719 0.010655 0.000005
**** v1    vsl|       1025 BackendOpen     b 26 s1 127.0.0.1 33281 127.0.0.1 37348 reuse
**** v1    vsl|       1025 Timestamp       b Bereq: 1684407187.829797 0.010733 0.000077
**** v1    vsl|       1025 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1025 BerespStatus    b 200
**** v1    vsl|       1025 BerespReason    b OK
**** v1    vsl|       1025 BerespHeader    b Date: Thu, 18 May 2023 10:53:07 GMT
**** v1    vsl|       1025 BerespHeader    b Content-Length: 0
**** v1    vsl|       1025 Timestamp       b Beresp: 1684407187.830367 0.011303 0.000570
**** v1    vsl|       1025 TTL             b RFC 120 10 0 1684407188 1684407188 1684407187 0 0 cacheable
**** v1    vsl|       1025 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1025 BerespHeader    b fetch: Fetch value 1
**** v1    vsl|       1025 BerespHeader    b response: 
**** v1    vsl|       1025 BerespHeader    b response2: 
**** v1    vsl|       1025 VCL_return      b deliver
**** v1    vsl|       1025 Timestamp       b Process: 1684407187.830402 0.011337 0.000034
**** v1    vsl|       1025 Filters         b 
**** v1    vsl|       1025 Storage         b malloc s0
**** v1    vsl|       1025 Fetch_Body      b 0 none -
**** v1    vsl|       1025 BackendClose    b 26 s1 recycle
**** v1    vsl|       1025 Timestamp       b BerespBody: 1684407187.840849 0.021785 0.010447
**** v1    vsl|       1025 Length          b 0
**** v1    vsl|       1025 BereqAcct       b 310 0 310 150 0 150
**** v1    vsl|       1025 End             b 
**** v1    vsl|       1023 Begin           c req 1016 rxreq
**** v1    vsl|       1023 Timestamp       c Start: 1684407187.819000 0.000000 0.000000
**** v1    vsl|       1023 Timestamp       c Req: 1684407187.819000 0.000000 0.000000
**** v1    vsl|       1023 VCL_use         c vcl5
**** v1    vsl|       1023 ReqStart        c 127.0.0.1 34630 a0
**** v1    vsl|       1023 ReqMethod       c GET
**** v1    vsl|       1023 ReqURL          c /5
**** v1    vsl|       1023 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1023 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1023 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1023 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1023 VCL_call        c RECV
**** v1    vsl|       1023 VCL_return      c hash
**** v1    vsl|       1023 VCL_call        c HASH
**** v1    vsl|       1023 VCL_return      c lookup
**** v1    vsl|       1023 VCL_call        c MISS
**** v1    vsl|       1023 VCL_return      c fetch
**** v1    vsl|       1023 Link            c bereq 1024 fetch
**** v1    vsl|       1023 Timestamp       c Fetch: 1684407187.840891 0.021891 0.021891
**** v1    vsl|       1023 RespProtocol    c HTTP/1.1
**** v1    vsl|       1023 RespStatus      c 200
**** v1    vsl|       1023 RespReason      c OK
**** v1    vsl|       1023 RespHeader      c Date: Thu, 18 May 2023 10:53:07 GMT
**** v1    vsl|       1023 RespHeader      c Content-Length: 0
**** v1    vsl|       1023 RespHeader      c fetch: Fetch value 1
**** v1    vsl|       1023 RespHeader      c response: 
**** v1    vsl|       1023 RespHeader      c response2: 
**** v1    vsl|       1023 RespHeader      c X-Varnish: 1023
**** v1    vsl|       1023 RespHeader      c Age: 0
**** v1    vsl|       1023 RespHeader      c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1023 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1023 VCL_call        c DELIVER
**** v1    vsl|       1023 VCL_return      c deliver
**** v1    vsl|       1023 Timestamp       c Process: 1684407187.840974 0.021973 0.000082
**** v1    vsl|       1023 Filters         c 
**** v1    vsl|       1023 RespHeader      c Connection: keep-alive
**** v1    vsl|       1023 Timestamp       c Resp: 1684407187.841011 0.022011 0.000037
**** v1    vsl|       1023 ReqAcct         c 36 0 36 222 0 222
**** v1    vsl|       1023 End             c 
**** v1    vsl|       1016 SessClose       c REM_CLOSE 0.059
**** v1    vsl|       1016 End             c 
**** dT    4.956
***  v1    CLI RX  200
**** v1    CLI TX|vcl.use vcl6
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl6' now active
**   top   === server s1 -repeat 3 -keepalive {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=33281
**** s1    macro def s1_sock=127.0.0.1:33281
*    s1    Listen on 127.0.0.1:33281
**   top   === client c4 {
**   c4    Starting client
**   c4    Waiting for client
**   s1    Started on 127.0.0.1:33281 (3 iterations using keepalive)
**   c4    Started on 127.0.0.1:35351 (1 iterations)
***  c4    Connect to 127.0.0.1:35351
***  c4    connected fd 17 from 127.0.0.1 34634 to 127.0.0.1:35351
**   c4    === txreq -url /6 -hdr "test: 1"
**** c4    txreq|GET /6 HTTP/1.1\r
**** c4    txreq|test: 1\r
**** c4    txreq|Host: 127.0.0.1\r
**** c4    txreq|\r
**   c4    === rxresp
**** dT    4.960
***  s1    accepted fd 5 127.0.0.1 37352
**   s1    === rxreq
**** s1    rxhdr|GET /6 HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\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: 1028\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 133
**** s1    http[ 0] |GET
**** s1    http[ 1] |/6
**** 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] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1028
**** s1    bodylen = 0
**   s1    === expect req.url ~ "^/6"
**** s1    EXPECT req.url (/6) ~ "^/6" match
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Date: Thu, 18 May 2023 10:53:08 GMT\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**   s1    === rxreq
**** dT    4.982
**** c4    rxhdr|HTTP/1.1 200 OK\r
**** c4    rxhdr|Date: Thu, 18 May 2023 10:53:08 GMT\r
**** c4    rxhdr|Content-Length: 0\r
**** c4    rxhdr|X-Varnish: 1027\r
**** c4    rxhdr|Age: 0\r
**** c4    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c4    rxhdr|test: 1\r
**** c4    rxhdr|Connection: keep-alive\r
**** c4    rxhdr|\r
**** c4    rxhdrlen = 162
**** c4    http[ 0] |HTTP/1.1
**** c4    http[ 1] |200
**** c4    http[ 2] |OK
**** c4    http[ 3] |Date: Thu, 18 May 2023 10:53:08 GMT
**** c4    http[ 4] |Content-Length: 0
**** c4    http[ 5] |X-Varnish: 1027
**** c4    http[ 6] |Age: 0
**** c4    http[ 7] |Via: 1.1 v1 (Varnish/trunk)
**** c4    http[ 8] |test: 1
**** c4    http[ 9] |Connection: keep-alive
**** c4    bodylen = 0
**   c4    === expect resp.status == 200
**** c4    EXPECT resp.status (200) == "200" match
**   c4    === expect resp.http.test == "1"
**** c4    EXPECT resp.http.test (1) == "1" match
**   c4    === txreq -url /6/veto/ok -hdr "test: 1"
**** c4    txreq|GET /6/veto/ok HTTP/1.1\r
**** c4    txreq|test: 1\r
**** c4    txreq|Host: 127.0.0.1\r
**** c4    txreq|\r
**   c4    === rxresp
**** dT    4.984
**** s1    rxhdrlen = 0
---- s1    HTTP header is incomplete
**** c4    rxhdrlen = 0
---- c4    HTTP header is incomplete
**** dT    4.985
***  v1    debug|Error: Child (479) died signal=6
*    top   RESETTING after ../../../vmod/tests/std_c00001.vtc
**   s1    Waiting for server (4/-1)
**   v1    Wait
**** v1    CLI TX|panic.show
***  v1    debug|Error: Child (479) Panic at: Thu, 18 May 2023 10:53:08 GMT
***  v1    debug|Assert error in VBO_GetBusyObj(), ../../../../bin/varnishd/cache/cache_busyobj.c line 124:
***  v1    debug|  Condition(p < bo->end) not true.
***  v1    debug|version = varnish-trunk revision b18568ace231f1354f2af6fffc72c5da8c7201f3, vrt api = 17.0
***  v1    debug|ident = Linux,4.19.0-17-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,epoll
***  v1    debug|now = 855006.035744 (mono), 1684407188.304089 (real)
***  v1    debug|Backtrace:
***  v1    debug|  0x462e00: varnishd() [0x462e00]
***  v1    debug|  0x462b13: varnishd() [0x462b13]
***  v1    debug|  0x535235: varnishd(VAS_Fail+0x55) [0x535235]
***  v1    debug|  0x42df84: varnishd(VBO_GetBusyObj+0x404) [0x42df84]
***  v1    debug|  0x4426ee: varnishd(VBF_Fetch+0x29e) [0x4426ee]
***  v1    debug|  0x471b09: varnishd() [0x471b09]
***  v1    debug|  0x46d25c: varnishd(CNT_Request+0x7fc) [0x46d25c]
***  v1    debug|  0x4b6ed3: varnishd() [0x4b6ed3]
***  v1    debug|  0x4b6172: varnishd() [0x4b6172]
***  v1    debug|  0x4a584f: varnishd() [0x4a584f]
***  v1    debug|argv = {
***  v1    debug|  [0] = \"varnishd\",
***  v1    debug|  [1] = \"-d\",
***  v1    debug|  [2] = \"-n\",
***  v1    debug|  [3] = \"/tmp/vtest.clang/_vtest_tmp/vtc.351.07fef1ed/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\",
***  v1    debug|  [18] = \"-p\",
***  v1    debug|  [19] = \"h2_initial_window_size=1m\",
***  v1    debug|  [20] = \"-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 37307\",
***  v1    debug|  [26] = \"-P\",
***  v1    debug|  [27] = \"/tmp/vtest.clang/_vtest_tmp/vtc.351.07fef1ed/v1/varnishd.pid\",
***  v1    debug|  [28] = \"-p\",
***  v1    debug|  [29] = \"vmod_path=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/vmod/.libs\",
***  v1    debug|}
***  v1    debug|pthread.self = 0x7fb802c1a700
***  v1    debug|pthread.name = (cache-worker)
***  v1    debug|pthread.attr = {
***  v1    debug|  guard = 4096,
***  v1    debug|  stack_bottom = 0x7fb802c07000,
***  v1    debug|  stack_top = 0x7fb802c1b000,
***  v1    debug|  stack_size = 81920,
***  v1    debug|}
***  v1    debug|thr.req = 0x7fb7fb2e70e0 {
***  v1    debug|  vxid = 1029, transport = HTTP/1 {
***  v1    debug|    state = HTTP1::Proc
***  v1    debug|  }
***  v1    debug|  step = Req Step miss
***  v1    debug|  req_body = none,
***  v1    debug|  restarts = 0, esi_level = 0,
***  v1    debug|  vary_b = (nil), vary_e = (nil),
***  v1    debug|  d_ttl = -1.000000, d_grace = -1.000000,
***  v1    debug|  storage = (nil),
***  v1    debug|  director_hint = 0x7fb80281e8d0 {
***  v1    debug|    cli_name = vcl6.s1,
***  v1    debug|    admin_health = healthy, changed = 1684407188.277486,
***  v1    debug|    type = backend {
***  v1    debug|      conn_pool = 0x7fb802847320 {
***  v1    debug|        ident = 0x8bef0c2e4895bb748b71acc62893bdeed2ac75dba36243cf837493e6db774477,
***  v1    debug|        vrt_endpoint = 0x7fb802824530 {
***  v1    debug|          ipv4 = 127.0.0.1, port = 33281,
***  v1    debug|        },
***  v1    debug|      },
***  v1    debug|      hosthdr = 127.0.0.1,
***  v1    debug|      n_conn = 0,
***  v1    debug|    },
***  v1    debug|  },
***  v1    debug|  sess = 0x7fb7fae1ab20 {
***  v1    debug|    fd = 25, vxid = 1026,
***  v1    debug|    t_open = 1684407188.281546,
***  v1    debug|    t_idle = 1684407188.303505,
***  v1    debug|    ws = 0x7fb7fae1ab60 {
***  v1    debug|      id = \"ses\",
***  v1    debug|      {s, f, r, e} = {0x7fb7fae1abb8, +96, (nil), +576},
***  v1    debug|    },
***  v1    debug|    transport = HTTP/1 {
***  v1    debug|      state = HTTP1::Proc
***  v1    debug|    }
***  v1    debug|    client = 127.0.0.1 34634 127.0.0.1:35351,
***  v1    debug|    local.endpoint = 127.0.0.1:35351,
***  v1    debug|    local.socket = a0,
***  v1    debug|    local.ip = 127.0.0.1:35351,
***  v1    debug|    remote.ip = 127.0.0.1:34634,
***  v1    debug|    server.ip = 127.0.0.1:35351,
***  v1    debug|    client.ip = 127.0.0.1:34634,
***  v1    debug|  },
***  v1    debug|  worker = 0x7fb802c185d8 {
***  v1    debug|    ws = 0x7fb802c18660 {
***  v1    debug|      id = \"wrk\",
***  v1    debug|      {s, f, r, e} = {0x7fb802c17b70, +0, (nil), +2040},
***  v1    debug|    },
***  v1    debug|    VCL::method = MISS,
***  v1    debug|    VCL::methods = {RECV, HASH, MISS},
***  v1    debug|  },
***  v1    debug|  ws = 0x7fb7fb2e7240 {
***  v1    debug|    id = \"req\",
***  v1    debug|    {s, f, r, e} = {0x7fb7fb2ec158, +120, (nil), +77664},
***  v1    debug|  },
***  v1    debug|  http_conn = 0x7fb7fb2ec0d0 {
***  v1    debug|    fd = 25 (@0x7fb7fae1ab44),
***  v1    debug|    doclose = null(Not Closing)
***  v1    debug|    ws = 0x7fb7fb2e7240 {
***  v1    debug|      [Already dumped, see above]
***  v1    debug|    },
***  v1    debug|    {rxbuf_b, rxbuf_e} = {0x7fb7fb2ec158, 0x7fb7fb2ec18d},
***  v1    debug|    {pipeline_b, pipeline_e} = {(nil), (nil)},
***  v1    debug|    content_length = -1,
***  v1    debug|    body_status = none,
***  v1    debug|    first_byte_timeout = 0.000000,
***  v1    debug|    between_bytes_timeout = 0.000000,
***  v1    debug|  },
***  v1    debug|  http[req] = 0x7fb7fb2e72e0 {
***  v1    debug|    ws = 0x7fb7fb2e7240 {
***  v1    debug|      [Already dumped, see above]
***  v1    debug|    },
***  v1    debug|    hdrs {
***  v1    debug|      \"GET\",
***  v1    debug|      \"/6/veto/ok\",
***  v1    debug|      \"HTTP/1.1\",
***  v1    debug|      \"Host: 127.0.0.1\",
***  v1    debug|      \"X-Forwarded-For: 127.0.0.1\",
***  v1    debug|      \"Via: 1.1 v1 (Varnish/trunk)\",
***  v1    debug|    },
***  v1    debug|  },
***  v1    debug|  vdc = 0x7fb7fb2ec090 {
***  v1    debug|    nxt = (nil),
***  v1    debug|    retval = 0,
***  v1    debug|  },
***  v1    debug|  vcl[vcl] = 0x7fb8028478c0 {
***  v1    debug|    name = \"vcl6\",
***  v1    debug|    busy = 2,
***  v1    debug|    discard = 0,
***  v1    debug|    state = auto,
***  v1    debug|    temp = warm,
***  v1    debug|    conf = 0x7fb80090ac80 {
***  v1    debug|      syntax = \"41\",
***  v1    debug|      srcname = {
***  v1    debug|        [0] = \"<vcl.inline>\",
***  v1    debug|        [1] = \"<builtin>\",
***  v1    debug|      },
***  v1    debug|      instances = {
***  v1    debug|      },
***  v1    debug|    },
***  v1    debug|  },
***  v1    debug|  vpi = 0x7fb802c17b60 {
***  v1    debug|    handling (VCL::return) = 0x5 (fetch),
***  v1    debug|    ref = 40,
***  v1    debug|    vpi_ref = 0x7fb80090b9b0 {
***  v1    debug|      source = 1 (\"<builtin>\"),
***  v1    debug|      offset = 3675,
***  v1    debug|      line = 155,
***  v1    debug|      pos = 1,
***  v1    debug|      src = \"}\"
***  v1    debug|    },
***  v1    debug|  },
***  v1    debug|  objcore[REQ] = 0x7fb7f7e21240 {
***  v1    debug|    refcnt = 1,
***  v1    debug|    flags = {busy},
***  v1    debug|    exp_flags = {},
***  v1    debug|    boc = 0x7fb7f7e241c0 {
***  v1    debug|      refcnt = 1,
***  v1    debug|      state = invalid,
***  v1    debug|      vary = (nil),
***  v1    debug|      stevedore_priv = (nil),
***  v1    debug|    },
***  v1    debug|    exp = {0.000000, 0.000000, 0.000000, 0.000000},
***  v1    debug|    objhead = 0x7fb7f7e24230,
***  v1    debug|    stevedore = (nil),
***  v1    debug|  },
***  v1    debug|  flags = {
***  v1    debug|  },
***  v1    debug|  privs = 0x7fb7fb2e72d0 {
***  v1    debug|  },
***  v1    debug|  top = 0x7fb7fb2ec138 {
***  v1    debug|    req = 0x7fb7fb2e70e0 {
***  v1    debug|      [Already dumped, see above]
***  v1    debug|    },
***  v1    debug|    privs = 0x7fb7fb2ec150 {
***  v1    debug|    },
***  v1    debug|    vcl[vcl0] = NULL
***  v1    debug|  },
***  v1    debug|},
***  v1    debug|thr.busyobj = NULL
***  v1    debug|thr.worker = 0x7fb802c185d8 {
***  v1    debug|  [Already dumped, see above]
***  v1    debug|},
***  v1    debug|vmods = {
***  v1    debug|  std = {0x7fb80284d0e0, Varnish trunk b18568ace231f1354f2af6fffc72c5da8c7201f3, 0.0},
***  v1    debug|  vtc = {0x7fb80284d150, Varnish trunk b18568ace231f1354f2af6fffc72c5da8c7201f3, 0.0},
***  v1    debug|  debug = {0x7fb80284d1c0, Varnish trunk b18568ace231f1354f2af6fffc72c5da8c7201f3, 17.0},
***  v1    debug|},
***  v1    debug|pools = {
***  v1    debug|  pool = 0x7fb800400000 {
***  v1    debug|    nidle = 9,
***  v1    debug|    nthr = 10,
***  v1    debug|    lqueue = 0
***  v1    debug|  },
***  v1    debug|  pool = 0x7fb800400640 {
***  v1    debug|    nidle = 8,
***  v1    debug|    nthr = 11,
***  v1    debug|    lqueue = 0
***  v1    debug|  },
***  v1    debug|},
***  v1    debug|
***  v1    debug|
***  v1    debug|Debug: Child cleanup complete
**** dT    5.028
***  v1    CLI RX  200
**** v1    CLI RX|Panic at: Thu, 18 May 2023 10:53:08 GMT
**** v1    CLI RX|Assert error in VBO_GetBusyObj(), ../../../../bin/varnishd/cache/cache_busyobj.c line 124:
**** v1    CLI RX|  Condition(p < bo->end) not true.
**** v1    CLI RX|version = varnish-trunk revision b18568ace231f1354f2af6fffc72c5da8c7201f3, vrt api = 17.0
**** v1    CLI RX|ident = Linux,4.19.0-17-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,epoll
**** v1    CLI RX|now = 855006.035744 (mono), 1684407188.304089 (real)
**** v1    CLI RX|Backtrace:
**** v1    CLI RX|  0x462e00: varnishd() [0x462e00]
**** v1    CLI RX|  0x462b13: varnishd() [0x462b13]
**** v1    CLI RX|  0x535235: varnishd(VAS_Fail+0x55) [0x535235]
**** v1    CLI RX|  0x42df84: varnishd(VBO_GetBusyObj+0x404) [0x42df84]
**** v1    CLI RX|  0x4426ee: varnishd(VBF_Fetch+0x29e) [0x4426ee]
**** v1    CLI RX|  0x471b09: varnishd() [0x471b09]
**** v1    CLI RX|  0x46d25c: varnishd(CNT_Request+0x7fc) [0x46d25c]
**** v1    CLI RX|  0x4b6ed3: varnishd() [0x4b6ed3]
**** v1    CLI RX|  0x4b6172: varnishd() [0x4b6172]
**** v1    CLI RX|  0x4a584f: varnishd() [0x4a584f]
**** v1    CLI RX|argv = {
**** v1    CLI RX|  [0] = \"varnishd\",
**** v1    CLI RX|  [1] = \"-d\",
**** v1    CLI RX|  [2] = \"-n\",
**** v1    CLI RX|  [3] = \"/tmp/vtest.clang/_vtest_tmp/vtc.351.07fef1ed/v1\",
**** v1    CLI RX|  [4] = \"-i\",
**** v1    CLI RX|  [5] = \"v1\",
**** v1    CLI RX|  [6] = \"-l\",
**** v1    CLI RX|  [7] = \"2m\",
**** v1    CLI RX|  [8] = \"-p\",
**** v1    CLI RX|  [9] = \"auto_restart=off\",
**** v1    CLI RX|  [10] = \"-p\",
**** v1    CLI RX|  [11] = \"syslog_cli_traffic=off\",
**** v1    CLI RX|  [12] = \"-p\",
**** v1    CLI RX|  [13] = \"thread_pool_min=10\",
**** v1    CLI RX|  [14] = \"-p\",
**** v1    CLI RX|  [15] = \"debug=+vtc_mode\",
**** v1    CLI RX|  [16] = \"-p\",
**** v1    CLI RX|  [17] = \"vsl_mask=+Debug\",
**** v1    CLI RX|  [18] = \"-p\",
**** v1    CLI RX|  [19] = \"h2_initial_window_size=1m\",
**** v1    CLI RX|  [20] = \"-p\",
**** v1    CLI RX|  [21] = \"h2_rx_window_low_water=64k\",
**** v1    CLI RX|  [22] = \"-a\",
**** v1    CLI RX|  [23] = \"127.0.0.1:0\",
**** v1    CLI RX|  [24] = \"-M\",
**** v1    CLI RX|  [25] = \"127.0.0.1 37307\",
**** v1    CLI RX|  [26] = \"-P\",
**** v1    CLI RX|  [27] = \"/tmp/vtest.clang/_vtest_tmp/vtc.351.07fef1ed/v1/varnishd.pid\",
**** v1    CLI RX|  [28] = \"-p\",
**** v1    CLI RX|  [29] = \"vmod_path=/tmp/vtest.clang/varnish-cache/varnish-trunk/_build/sub/vmod/.libs\",
**** v1    CLI RX|}
**** v1    CLI RX|pthread.self = 0x7fb802c1a700
**** v1    CLI RX|pthread.name = (cache-worker)
**** v1    CLI RX|pthread.attr = {
**** v1    CLI RX|  guard = 4096,
**** v1    CLI RX|  stack_bottom = 0x7fb802c07000,
**** v1    CLI RX|  stack_top = 0x7fb802c1b000,
**** v1    CLI RX|  stack_size = 81920,
**** v1    CLI RX|}
**** v1    CLI RX|thr.req = 0x7fb7fb2e70e0 {
**** v1    CLI RX|  vxid = 1029, transport = HTTP/1 {
**** v1    CLI RX|    state = HTTP1::Proc
**** v1    CLI RX|  }
**** v1    CLI RX|  step = Req Step miss
**** v1    CLI RX|  req_body = none,
**** v1    CLI RX|  restarts = 0, esi_level = 0,
**** v1    CLI RX|  vary_b = (nil), vary_e = (nil),
**** v1    CLI RX|  d_ttl = -1.000000, d_grace = -1.000000,
**** v1    CLI RX|  storage = (nil),
**** v1    CLI RX|  director_hint = 0x7fb80281e8d0 {
**** v1    CLI RX|    cli_name = vcl6.s1,
**** v1    CLI RX|    admin_health = healthy, changed = 1684407188.277486,
**** v1    CLI RX|    type = backend {
**** v1    CLI RX|      conn_pool = 0x7fb802847320 {
**** v1    CLI RX|        ident = 0x8bef0c2e4895bb748b71acc62893bdeed2ac75dba36243cf837493e6db774477,
**** v1    CLI RX|        vrt_endpoint = 0x7fb802824530 {
**** v1    CLI RX|          ipv4 = 127.0.0.1, port = 33281,
**** v1    CLI RX|        },
**** v1    CLI RX|      },
**** v1    CLI RX|      hosthdr = 127.0.0.1,
**** v1    CLI RX|      n_conn = 0,
**** v1    CLI RX|    },
**** v1    CLI RX|  },
**** v1    CLI RX|  sess = 0x7fb7fae1ab20 {
**** v1    CLI RX|    fd = 25, vxid = 1026,
**** v1    CLI RX|    t_open = 1684407188.281546,
**** v1    CLI RX|    t_idle = 1684407188.303505,
**** v1    CLI RX|    ws = 0x7fb7fae1ab60 {
**** v1    CLI RX|      id = \"ses\",
**** v1    CLI RX|      {s, f, r, e} = {0x7fb7fae1abb8, +96, (nil), +576},
**** v1    CLI RX|    },
**** v1    CLI RX|    transport = HTTP/1 {
**** v1    CLI RX|      state = HTTP1::Proc
**** v1    CLI RX|    }
**** v1    CLI RX|    client = 127.0.0.1 34634 127.0.0.1:35351,
**** v1    CLI RX|    local.endpoint = 127.0.0.1:35351,
**** v1    CLI RX|    local.socket = a0,
**** v1    CLI RX|    local.ip = 127.0.0.1:35351,
**** v1    CLI RX|    remote.ip = 127.0.0.1:34634,
**** v1    CLI RX|    server.ip = 127.0.0.1:35351,
**** v1    CLI RX|    client.ip = 127.0.0.1:34634,
**** v1    CLI RX|  },
**** v1    CLI RX|  worker = 0x7fb802c185d8 {
**** v1    CLI RX|    ws = 0x7fb802c18660 {
**** v1    CLI RX|      id = \"wrk\",
**** v1    CLI RX|      {s, f, r, e} = {0x7fb802c17b70, +0, (nil), +2040},
**** v1    CLI RX|    },
**** v1    CLI RX|    VCL::method = MISS,
**** v1    CLI RX|    VCL::methods = {RECV, HASH, MISS},
**** v1    CLI RX|  },
**** v1    CLI RX|  ws = 0x7fb7fb2e7240 {
**** v1    CLI RX|    id = \"req\",
**** v1    CLI RX|    {s, f, r, e} = {0x7fb7fb2ec158, +120, (nil), +77664},
**** v1    CLI RX|  },
**** v1    CLI RX|  http_conn = 0x7fb7fb2ec0d0 {
**** v1    CLI RX|    fd = 25 (@0x7fb7fae1ab44),
**** v1    CLI RX|    doclose = null(Not Closing)
**** v1    CLI RX|    ws = 0x7fb7fb2e7240 {
**** v1    CLI RX|      [Already dumped, see above]
**** v1    CLI RX|    },
**** v1    CLI RX|    {rxbuf_b, rxbuf_e} = {0x7fb7fb2ec158, 0x7fb7fb2ec18d},
**** v1    CLI RX|    {pipeline_b, pipeline_e} = {(nil), (nil)},
**** v1    CLI RX|    content_length = -1,
**** v1    CLI RX|    body_status = none,
**** v1    CLI RX|    first_byte_timeout = 0.000000,
**** v1    CLI RX|    between_bytes_timeout = 0.000000,
**** v1    CLI RX|  },
**** v1    CLI RX|  http[req] = 0x7fb7fb2e72e0 {
**** v1    CLI RX|    ws = 0x7fb7fb2e7240 {
**** v1    CLI RX|      [Already dumped, see above]
**** v1    CLI RX|    },
**** v1    CLI RX|    hdrs {
**** v1    CLI RX|      \"GET\",
**** v1    CLI RX|      \"/6/veto/ok\",
**** v1    CLI RX|      \"HTTP/1.1\",
**** v1    CLI RX|      \"Host: 127.0.0.1\",
**** v1    CLI RX|      \"X-Forwarded-For: 127.0.0.1\",
**** v1    CLI RX|      \"Via: 1.1 v1 (Varnish/trunk)\",
**** v1    CLI RX|    },
**** v1    CLI RX|  },
**** v1    CLI RX|  vdc = 0x7fb7fb2ec090 {
**** v1    CLI RX|    nxt = (nil),
**** v1    CLI RX|    retval = 0,
**** v1    CLI RX|  },
**** v1    CLI RX|  vcl[vcl] = 0x7fb8028478c0 {
**** v1    CLI RX|    name = \"vcl6\",
**** v1    CLI RX|    busy = 2,
**** v1    CLI RX|    discard = 0,
**** v1    CLI RX|    state = auto,
**** v1    CLI RX|    temp = warm,
**** v1    CLI RX|    conf = 0x7fb80090ac80 {
**** v1    CLI RX|      syntax = \"41\",
**** v1    CLI RX|      srcname = {
**** v1    CLI RX|        [0] = \"<vcl.inline>\",
**** v1    CLI RX|        [1] = \"<builtin>\",
**** v1    CLI RX|      },
**** v1    CLI RX|      instances = {
**** v1    CLI RX|      },
**** v1    CLI RX|    },
**** v1    CLI RX|  },
**** v1    CLI RX|  vpi = 0x7fb802c17b60 {
**** v1    CLI RX|    handling (VCL::return) = 0x5 (fetch),
**** v1    CLI RX|    ref = 40,
**** v1    CLI RX|    vpi_ref = 0x7fb80090b9b0 {
**** v1    CLI RX|      source = 1 (\"<builtin>\"),
**** v1    CLI RX|      offset = 3675,
**** v1    CLI RX|      line = 155,
**** v1    CLI RX|      pos = 1,
**** v1    CLI RX|      src = \"}\"
**** v1    CLI RX|    },
**** v1    CLI RX|  },
**** v1    CLI RX|  objcore[REQ] = 0x7fb7f7e21240 {
**** v1    CLI RX|    refcnt = 1,
**** v1    CLI RX|    flags = {busy},
**** v1    CLI RX|    exp_flags = {},
**** v1    CLI RX|    boc = 0x7fb7f7e241c0 {
**** v1    CLI RX|      refcnt = 1,
**** v1    CLI RX|      state = invalid,
**** v1    CLI RX|      vary = (nil),
**** v1    CLI RX|      stevedore_priv = (nil),
**** v1    CLI RX|    },
**** v1    CLI RX|    exp = {0.000000, 0.000000, 0.000000, 0.000000},
**** v1    CLI RX|    objhead = 0x7fb7f7e24230,
**** v1    CLI RX|    stevedore = (nil),
**** v1    CLI RX|  },
**** v1    CLI RX|  flags = {
**** v1    CLI RX|  },
**** v1    CLI RX|  privs = 0x7fb7fb2e72d0 {
**** v1    CLI RX|  },
**** v1    CLI RX|  top = 0x7fb7fb2ec138 {
**** v1    CLI RX|    req = 0x7fb7fb2e70e0 {
**** v1    CLI RX|      [Already dumped, see above]
**** v1    CLI RX|    },
**** v1    CLI RX|    privs = 0x7fb7fb2ec150 {
**** v1    CLI RX|    },
**** v1    CLI RX|    vcl[vcl0] = NULL
**** v1    CLI RX|  },
**** v1    CLI RX|},
**** v1    CLI RX|thr.busyobj = NULL
**** v1    CLI RX|thr.worker = 0x7fb802c185d8 {
**** v1    CLI RX|  [Already dumped, see above]
**** v1    CLI RX|},
**** v1    CLI RX|vmods = {
**** v1    CLI RX|  std = {0x7fb80284d0e0, Varnish trunk b18568ace231f1354f2af6fffc72c5da8c7201f3, 0.0},
**** v1    CLI RX|  vtc = {0x7fb80284d150, Varnish trunk b18568ace231f1354f2af6fffc72c5da8c7201f3, 0.0},
**** v1    CLI RX|  debug = {0x7fb80284d1c0, Varnish trunk b18568ace231f1354f2af6fffc72c5da8c7201f3, 17.0},
**** v1    CLI RX|},
**** v1    CLI RX|pools = {
**** v1    CLI RX|  pool = 0x7fb800400000 {
**** v1    CLI RX|    nidle = 9,
**** v1    CLI RX|    nthr = 10,
**** v1    CLI RX|    lqueue = 0
**** v1    CLI RX|  },
**** v1    CLI RX|  pool = 0x7fb800400640 {
**** v1    CLI RX|    nidle = 8,
**** v1    CLI RX|    nthr = 11,
**** v1    CLI RX|    lqueue = 0
**** v1    CLI RX|  },
**** v1    CLI RX|},
**** v1    CLI RX|
**** v1    CLI RX|
---- v1    Unexpected panic
*    top   failure during reset
#    top  TEST ../../../vmod/tests/std_c00001.vtc FAILED (5.035) exit=2
FAIL tests/std_c00001.vtc (exit status: 2)