**** dT    0.001
*    top   TEST ../../../../bin/varnishtest/tests/r02339.vtc starting
**** top   extmacro def pwd=/root/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest
**** top   extmacro def date(...)
**** top   extmacro def string(...)
**** top   extmacro def localhost=127.0.0.1
**** top   extmacro def bad_backend=127.0.0.1:43132
**** top   extmacro def listen_addr=127.0.0.1:0
**** top   extmacro def bad_ip=192.0.2.255
**** top   extmacro def topbuild=/root/VT/varnish-cache/varnish-trunk/_build/sub
**** dT    0.002
**** top   macro def testdir=/root/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests
**** top   macro def tmpdir=/root/VT/_vtest_tmp/vtc.47339.7f2ac2f1
**** dT    0.003
**   top   === varnishtest "VMOD purge"
*    top   VTEST VMOD purge
**   top   === server s1 -repeat 12 {
**** dT    0.004
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=46914
**** s1    macro def s1_sock=127.0.0.1:46914
*    s1    Listen on 127.0.0.1:46914
**** dT    0.005
**   top   === varnish v1 -cliok "param.set thread_pools 1"
**** dT    0.006
**   s1    Started on 127.0.0.1:46914 (12 iterations)
**** dT    0.086
**   v1    Launch
**** dT    0.087
***  v1    CMD: cd ${pwd} && exec varnishd  -d -n /root/VT/_vtest_tmp/vtc.47339.7f2ac2f1/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 22632' -P /root/VT/_vtest_tmp/vtc.47339.7f2ac2f1/v1/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs 
***  v1    CMD: cd /root/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd  -d -n /root/VT/_vtest_tmp/vtc.47339.7f2ac2f1/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 22632' -P /root/VT/_vtest_tmp/vtc.47339.7f2ac2f1/v1/varnishd.pid -p vmod_path=/root/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs 
**** dT    0.090
***  v1    PID: 47355
**** v1    macro def v1_pid=47355
**** dT    0.091
**** v1    macro def v1_name=/root/VT/_vtest_tmp/vtc.47339.7f2ac2f1/v1
**** dT    0.617
***  v1    debug|Debug: Version: varnish-trunk revision fc506dbf3b7e9d27bcca46ac2820a93090379e07
***  v1    debug|Debug: Platform: FreeBSD,13.0-RELEASE,arm,-jnone,-sdefault,-sdefault,-hcritbit
**** dT    0.618
***  v1    debug|200 312     
***  v1    debug|-----------------------------
***  v1    debug|Varnish Cache CLI 1.0
***  v1    debug|-----------------------------
***  v1    debug|FreeBSD,13.0-RELEASE,arm,-jnone,-sdefault,-sdefault,-hcritbit
***  v1    debug|varnish-trunk revision fc506dbf3b7e9d27bcca46ac2820a93090379e07
***  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.649
**** v1    CLIPOLL 1 0x1 0x0 0x0
***  v1    CLI connection fd = 6
**** dT    0.652
***  v1    CLI RX  107
**** v1    CLI RX|athajgbyxtwkcfayscxdsfbyiwpreswm
**** v1    CLI RX|
**** v1    CLI RX|Authentication required.
**** dT    0.654
**** v1    CLI TX|auth 8a6be926292f1f604aee25dfec17e07c4bcf0fcc1092ecfe53ac403578d7b3f5
**** dT    0.658
***  v1    CLI RX  200
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Varnish Cache CLI 1.0
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|FreeBSD,13.0-RELEASE,arm,-jnone,-sdefault,-sdefault,-hcritbit
**** v1    CLI RX|varnish-trunk revision fc506dbf3b7e9d27bcca46ac2820a93090379e07
**** v1    CLI RX|
**** v1    CLI RX|Type 'help' for command list.
**** v1    CLI RX|Type 'quit' to close CLI session.
**** v1    CLI RX|Type 'start' to launch worker process.
**** dT    0.659
**** v1    CLI TX|param.set thread_pools 1
**** dT    0.698
***  v1    CLI RX  200
**   v1    CLI 200 <param.set thread_pools 1>
**   top   === varnish v1 -cliok "param.set vsl_mask +ExpKill"
**** v1    CLI TX|param.set vsl_mask +ExpKill
**** dT    0.739
***  v1    CLI RX  200
**   v1    CLI 200 <param.set vsl_mask +ExpKill>
**   top   === varnish v1 -vcl+backend {
**** dT    0.740
**** 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 = "46914"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\timport purge;
**** v1    CLI TX|\timport vtc;
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_recv {
**** v1    CLI TX|\t\tif (req.url == "recv") { purge.hard(); }
**** v1    CLI TX|\t\tif (req.url == "pass") { return (pass); }
**** v1    CLI TX|\t\tif (req.url == "purge") { return (purge); }
**** v1    CLI TX|\t\tif (req.url == "synth") { return (synth(200)); }
**** v1    CLI TX|\t}
**** v1    CLI TX|\tsub vcl_hash {
**** v1    CLI TX|\t\tif (req.url == "hash") { purge.hard(); }
**** v1    CLI TX|\t}
**** v1    CLI TX|\tsub vcl_miss {
**** v1    CLI TX|\t\tif (req.url == "miss") { purge.hard(); }
**** v1    CLI TX|\t}
**** v1    CLI TX|\tsub vcl_hit {
**** v1    CLI TX|\t\tif (req.url == "hit") { purge.hard(); }
**** v1    CLI TX|\t}
**** v1    CLI TX|\tsub vcl_purge {
**** v1    CLI TX|\t\tif (req.url == "purge") { purge.hard(); }
**** v1    CLI TX|\t}
**** v1    CLI TX|\tsub vcl_pass {
**** v1    CLI TX|\t\tif (req.url == "pass") { purge.hard(); }
**** v1    CLI TX|\t}
**** v1    CLI TX|\tsub vcl_deliver {
**** v1    CLI TX|\t\tif (req.url == "deliver") { purge.hard(); }
**** v1    CLI TX|\t}
**** v1    CLI TX|\tsub vcl_synth {
**** v1    CLI TX|\t\tif (req.url == "synth") { purge.hard(); }
**** v1    CLI TX|\t}
**** v1    CLI TX|\tsub vcl_backend_fetch {
**** v1    CLI TX|\t\tif (bereq.url == "fetch") { purge.hard(); }
**** v1    CLI TX|\t\tif (bereq.url == "error") {
**** v1    CLI TX|\t\t\tset bereq.backend = vtc.no_backend();
**** v1    CLI TX|\t\t}
**** v1    CLI TX|\t}
**** v1    CLI TX|\tsub vcl_backend_error {
**** v1    CLI TX|\t\tif (bereq.url == "error") { purge.hard(); }
**** v1    CLI TX|\t}
**** v1    CLI TX|\tsub vcl_backend_response {
**** v1    CLI TX|\t\tif (bereq.url == "response") { purge.hard(); }
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    0.763
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.864
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.966
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.089
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.201
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.310
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.412
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.513
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.615
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.717
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.818
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.920
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    2.022
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    2.124
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    2.226
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    2.328
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    2.430
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    2.531
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    2.633
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    2.734
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    2.868
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    2.970
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    3.072
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    3.173
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    3.275
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    3.377
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    3.478
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    3.580
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    3.681
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    3.787
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    3.889
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    3.991
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    4.093
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    4.194
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    4.296
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    4.398
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    4.501
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    4.601
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    4.702
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    4.804
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    4.905
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    5.007
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    5.109
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    5.210
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    5.312
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    5.414
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    5.516
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    5.618
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    5.720
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    5.822
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    5.924
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    6.025
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    6.127
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    6.228
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    6.330
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    6.432
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    6.534
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    6.636
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    6.738
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    6.840
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    6.941
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    7.043
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    7.145
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    7.247
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    7.349
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    7.450
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    7.552
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    7.654
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    7.756
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    7.858
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    7.960
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    8.062
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    8.163
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    8.265
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    8.373
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    8.474
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    8.575
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    8.677
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    8.779
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    8.881
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    8.983
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    9.084
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    9.186
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    9.288
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    9.390
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    9.492
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    9.593
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    9.695
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    9.796
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    9.898
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    10.000
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    10.102
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    10.204
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    10.305
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    10.407
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    10.508
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    10.610
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    10.737
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    10.838
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    10.940
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    11.042
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    11.143
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    11.245
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    11.346
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    11.448
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    11.550
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    11.652
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    11.754
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    11.856
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    11.957
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    12.059
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    12.161
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    12.263
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    12.365
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    12.467
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    12.569
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    12.670
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    12.772
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    12.874
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    12.976
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    13.078
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    13.180
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    13.281
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    13.383
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    13.484
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    13.586
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    13.688
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    13.790
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    13.891
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    13.993
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    14.096
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    14.197
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    14.299
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    14.400
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    14.502
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    14.604
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    14.706
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    14.807
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    14.909
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    15.011
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    15.113
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    15.214
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    15.316
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    15.418
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    15.520
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    15.621
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    15.723
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    15.825
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    15.927
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    16.029
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    16.131
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    16.233
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    16.335
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    16.436
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    16.538
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    16.639
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    16.740
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    16.842
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    16.944
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    17.046
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    17.148
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    17.250
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    17.352
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    17.454
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    17.556
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    17.690
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    17.792
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    17.894
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    17.996
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    18.098
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    18.200
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    18.302
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    18.404
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    18.506
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    18.607
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    18.719
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    18.819
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    18.920
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    19.022
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    19.123
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    19.225
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    19.327
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    19.429
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    19.530
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    19.632
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    19.733
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    19.835
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    19.937
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    20.039
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    20.141
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    20.243
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    20.345
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    20.447
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    20.549
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    20.651
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    20.753
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    20.855
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    20.868
***  v1    CLI RX  200
**** v1    CLI RX|VCL compiled.
**** v1    CLI TX|vcl.use vcl1
**** dT    20.909
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl1' now active
**   v1    Start
**** v1    CLI TX|start
**** dT    20.957
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    21.059
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    21.162
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    21.201
***  v1    debug|Debug: Child (47398) Started
**** dT    21.264
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    21.364
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    21.466
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    21.567
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    21.669
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    21.771
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    21.872
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    21.974
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    22.076
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    23.511
***  v1    debug|Child launched OK
**** dT    23.578
***  v1    CLI RX  200
***  v1    wait-running
**** v1    CLI TX|status
**** dT    23.579
***  v1    debug|Info: Child (47398) said Child starts
**** dT    23.609
**** v1    vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1649411439.105882/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl1.1649411439.105882/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:18770
**** v1    vsl|          0 Debug           - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:18770
**** v1    vsl|          0 Error           - Kernel filtering: sock=3, errno=2 No such file or directory
**** v1    vsl|          0 CLI             - Wr 200 0 
**** dT    23.619
***  v1    CLI RX  200
**** v1    CLI RX|Child in state running
**** v1    CLI TX|debug.listen_address
**** dT    23.660
***  v1    CLI RX  200
**** dT    23.661
**** v1    CLI RX|a0 127.0.0.1 18770
**** v1    CLI TX|debug.xid 999
**** dT    23.701
***  v1    CLI RX  200
**** v1    CLI RX|XID is 999 chunk 1
**** v1    CLI TX|debug.listen_address
**** dT    23.710
**** v1    vsl|          0 CLI             - Rd debug.listen_address 
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 18770

**** v1    vsl|          0 CLI             - Rd debug.xid 999 
**** v1    vsl|          0 CLI             - Wr 200 18 XID is 999 chunk 1
**** dT    23.742
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 18770
**   v1    Listen on 127.0.0.1 18770
**** v1    macro def v1_addr=127.0.0.1
**** v1    macro def v1_port=18770
**** v1    macro def v1_sock=127.0.0.1:18770
**** dT    23.743
**** v1    macro def v1_a0_addr=127.0.0.1
**** v1    macro def v1_a0_port=18770
**** v1    macro def v1_a0_sock=127.0.0.1:18770
**   top   === varnish v1 -cliok "param.set timeout_idle 2"
**** v1    CLI TX|param.set timeout_idle 2
**** dT    23.783
***  v1    CLI RX  200
**   v1    CLI 200 <param.set timeout_idle 2>
**   top   === logexpect l0 -v v1 -g raw {
**** dT    23.785
**   l0    === expect * 0 ExpKill	"EXP_Expired x=1002"
**** dT    23.787
**   top   === logexpect l2 -v v1 -g raw {
**** dT    23.789
**   l2    === expect * 1002	Begin		"bereq 1001 fetch"
**** dT    23.790
**   top   === logexpect l1 -v v1 {
**** dT    23.791
**   l1    === expect * 1003	VCL_call	HIT
**   l1    === expect 0 =	VCL_return	deliver
**   l1    === expect * 1004	VCL_call	MISS
**** dT    23.792
**   l1    === expect 0 =	VCL_return	fetch
**   l1    === expect * 1007	VCL_call	RECV
**   l1    === expect 0 =	VCL_Error	purge
**   l1    === expect 0 =	VCL_return	fail
**   l1    === expect * 1009	VCL_call	HASH
**** dT    23.793
**   l1    === expect 0 =	VCL_Error	purge
**   l1    === expect 0 =	VCL_return	fail
**   l1    === expect * 1011	VCL_call	PURGE
**   l1    === expect 0 =	VCL_Error	purge
**   l1    === expect * 1013	VCL_call	PASS
**   l1    === expect 0 =	VCL_Error	purge
**   l1    === expect * 1015	VCL_call	DELIVER
**** dT    23.794
**   l1    === expect 0 =	VCL_Error	purge
**   l1    === expect * 1018	VCL_call	SYNTH
**   l1    === expect 0 =	VCL_Error	purge
**   l1    === expect * 1021	VCL_call	BACKEND_FETCH
**   l1    === expect 0 =	VCL_Error	purge
**   l1    === expect * 1024	VCL_call	BACKEND_ERROR
**** dT    23.795
**   l1    === expect 0 =	VCL_Error	purge
**   l1    === expect * 1027	VCL_call	BACKEND_RESPONSE
**   l1    === expect 0 =	VCL_Error	purge
**** dT    23.796
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**** l0    begin|
**** dT    23.797
***  l0    test | expect * 0 ExpKill EXP_Expired x=1002
**** l2    begin|
***  l2    test | expect * 1002 Begin bereq 1001 fetch
**** l1    begin|
***  l1    test | expect * 1003 VCL_call HIT
**   c1    Started on 127.0.0.1:18770 (1 iterations)
***  c1    Connect to 127.0.0.1:18770
**** dT    23.799
***  c1    connected fd 31 from 127.0.0.1 15751 to 127.0.0.1:18770
**   c1    === txreq -url hit
**** c1    txreq|GET hit HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**** dT    23.800
**   c1    === rxresp
**** dT    23.811
***  s1    accepted fd 4 127.0.0.1 15796
**   s1    === rxreq
**** v1    vsl|          0 CLI             - Rd debug.listen_address 
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 18770

**** v1    vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    vsl|       1000 SessOpen        c 127.0.0.1 15751 a0 127.0.0.1 18770 1649411462.169568 19
**** v1    vsl|       1000 Debug           c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=127.0.0.1:18770
**** v1    vsl|       1000 Debug           c sockopt: Test confirmed SO_SNDTIMEO non heredity for a0=127.0.0.1:18770
**** v1    vsl|       1000 Debug           c sockopt: Test confirmed SO_RCVTIMEO non heredity for a0=127.0.0.1:18770
**** v1    vsl|       1000 Debug           c sockopt: Test confirmed TCP_NODELAY non heredity for a0=127.0.0.1:18770
**** v1    vsl|       1000 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1000 Debug           c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** dT    23.812
**** v1    vsl|       1000 Debug           c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1000 Debug           c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1000 Debug           c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1000 Link            c req 1001 rxreq
**** dT    23.813
**** s1    rxhdr|GET hit HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1002\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 105
**** s1    http[ 0] |GET
**** s1    http[ 1] |hit
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Accept-Encoding: gzip
**** s1    http[ 6] |X-Varnish: 1002
**** s1    bodylen = 0
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**** dT    23.817
***  s1    shutting fd 4
**** dT    23.830
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Content-Length: 0\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:02 GMT\r
**** c1    rxhdr|X-Varnish: 1001\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 varnish (Varnish/7.1)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 178
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |Content-Length: 0
**** c1    http[ 4] |Date: Fri, 08 Apr 2022 09:51:02 GMT
**** c1    http[ 5] |X-Varnish: 1001
**** c1    http[ 6] |Age: 0
**** c1    http[ 7] |Via: 1.1 varnish (Varnish/7.1)
**** dT    23.831
**** c1    http[ 8] |Accept-Ranges: bytes
**** c1    http[ 9] |Connection: keep-alive
**** c1    bodylen = 0
**   c1    === expect resp.status == 200
**** c1    EXPECT resp.status (200) == "200" match
**   c1    === txreq -url hit
**** c1    txreq|GET hit HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    23.832
**** l2    match|       1002 Begin           b bereq 1001 fetch
**** l2    done |
**** dT    23.836
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Content-Length: 0\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:02 GMT\r
**** c1    rxhdr|X-Varnish: 1003 1002\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 varnish (Varnish/7.1)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 183
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |Content-Length: 0
**** c1    http[ 4] |Date: Fri, 08 Apr 2022 09:51:02 GMT
**** c1    http[ 5] |X-Varnish: 1003 1002
**** c1    http[ 6] |Age: 0
**** c1    http[ 7] |Via: 1.1 varnish (Varnish/7.1)
**** c1    http[ 8] |Accept-Ranges: bytes
**** c1    http[ 9] |Connection: keep-alive
**** c1    bodylen = 0
**   c1    === expect resp.status == 200
**** c1    EXPECT resp.status (200) == "200" match
**   c1    === txreq -url miss
**** c1    txreq|GET miss HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**** dT    23.837
**   c1    === rxresp
**** dT    23.839
***  s1    accepted fd 4 127.0.0.1 62613
**   s1    === rxreq
**** dT    23.840
**** s1    rxhdr|GET miss HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1005\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 106
**** s1    http[ 0] |GET
**** s1    http[ 1] |miss
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Accept-Encoding: gzip
**** s1    http[ 6] |X-Varnish: 1005
**** s1    bodylen = 0
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**** dT    23.841
***  s1    shutting fd 4
**** dT    23.842
**** l1    match|       1003 VCL_call        c HIT
***  l1    test | expect 0 = VCL_return deliver
**** l1    match|       1003 VCL_return      c deliver
***  l1    test | expect * 1004 VCL_call MISS
**** dT    23.854
**** l0    match|          0 ExpKill         - EXP_Expired x=1002 t=-0
**** l0    done |
**** dT    23.857
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Content-Length: 0\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:02 GMT\r
**** c1    rxhdr|X-Varnish: 1004\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 varnish (Varnish/7.1)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 178
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |Content-Length: 0
**** c1    http[ 4] |Date: Fri, 08 Apr 2022 09:51:02 GMT
**** c1    http[ 5] |X-Varnish: 1004
**** c1    http[ 6] |Age: 0
**** c1    http[ 7] |Via: 1.1 varnish (Varnish/7.1)
**** c1    http[ 8] |Accept-Ranges: bytes
**** c1    http[ 9] |Connection: keep-alive
**** c1    bodylen = 0
**   c1    === expect resp.status == 200
**** c1    EXPECT resp.status (200) == "200" match
***  c1    closing fd 31
**   c1    Ending
**** dT    23.858
**   top   === logexpect l0 -wait
**   l0    Waiting for logexp
**   top   === logexpect l2 -wait
**   l2    Waiting for logexp
**   top   === client c1 {
**   c1    Starting client
**** dT    23.859
**   c1    Waiting for client
**   c1    Started on 127.0.0.1:18770 (1 iterations)
***  c1    Connect to 127.0.0.1:18770
**** dT    23.860
***  c1    connected fd 31 from 127.0.0.1 49263 to 127.0.0.1:18770
**   c1    === txreq -url recv
**** dT    23.861
**** c1    txreq|GET recv HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    23.865
**** c1    rxhdr|HTTP/1.1 503 VCL failed\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:02 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|X-Varnish: 1007\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|Content-Length: 251\r
**** c1    rxhdr|Connection: close\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 194
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |VCL failed
**** c1    http[ 3] |Date: Fri, 08 Apr 2022 09:51:02 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |X-Varnish: 1007
**** c1    http[ 6] |Content-Type: text/html; charset=utf-8
**** c1    http[ 7] |Retry-After: 5
**** c1    http[ 8] |Content-Length: 251
**** c1    http[ 9] |Connection: close
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 VCL failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 VCL failed</h1>
**** c1    c-l|    <p>VCL failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1007</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 251
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
**   c1    === expect_close
**** c1    Expecting close (fd = 31)
**** dT    23.867
**** c1    fd=31 EOF, as expected
***  c1    closing fd 31
**   c1    Ending
**   top   === client c1 {
**   c1    Starting client
**** dT    23.868
**   c1    Waiting for client
**   c1    Started on 127.0.0.1:18770 (1 iterations)
***  c1    Connect to 127.0.0.1:18770
**** dT    23.869
***  c1    connected fd 31 from 127.0.0.1 37697 to 127.0.0.1:18770
**   c1    === txreq -url hash
**** dT    23.870
**** c1    txreq|GET hash HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    23.874
**** c1    rxhdr|HTTP/1.1 503 VCL failed\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:02 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|X-Varnish: 1009\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|Content-Length: 251\r
**** c1    rxhdr|Connection: close\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 194
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |VCL failed
**** c1    http[ 3] |Date: Fri, 08 Apr 2022 09:51:02 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |X-Varnish: 1009
**** c1    http[ 6] |Content-Type: text/html; charset=utf-8
**** c1    http[ 7] |Retry-After: 5
**** c1    http[ 8] |Content-Length: 251
**** c1    http[ 9] |Connection: close
**** dT    23.875
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 VCL failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 VCL failed</h1>
**** c1    c-l|    <p>VCL failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1009</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 251
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
**   c1    === expect_close
**** c1    Expecting close (fd = 31)
**** c1    fd=31 EOF, as expected
***  c1    closing fd 31
**** dT    23.876
**   c1    Ending
**   top   === client c1 {
**   c1    Starting client
**** dT    23.877
**   c1    Waiting for client
**   c1    Started on 127.0.0.1:18770 (1 iterations)
**** dT    23.878
***  c1    Connect to 127.0.0.1:18770
***  c1    connected fd 31 from 127.0.0.1 52284 to 127.0.0.1:18770
**** dT    23.879
**   c1    === txreq -url purge
**** c1    txreq|GET purge HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    23.884
**** c1    rxhdr|HTTP/1.1 503 VCL failed\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:02 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|X-Varnish: 1011\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|Content-Length: 251\r
**** c1    rxhdr|Connection: close\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 194
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |VCL failed
**** c1    http[ 3] |Date: Fri, 08 Apr 2022 09:51:02 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |X-Varnish: 1011
**** c1    http[ 6] |Content-Type: text/html; charset=utf-8
**** c1    http[ 7] |Retry-After: 5
**** c1    http[ 8] |Content-Length: 251
**** c1    http[ 9] |Connection: close
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 VCL failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 VCL failed</h1>
**** c1    c-l|    <p>VCL failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1011</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 251
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
**   c1    === expect_close
**** c1    Expecting close (fd = 31)
**** dT    23.885
**** c1    fd=31 EOF, as expected
***  c1    closing fd 31
**   c1    Ending
**** dT    23.886
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**   c1    Started on 127.0.0.1:18770 (1 iterations)
***  c1    Connect to 127.0.0.1:18770
**** dT    23.887
***  c1    connected fd 31 from 127.0.0.1 52445 to 127.0.0.1:18770
**   c1    === txreq -url pass
**** c1    txreq|GET pass HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**** dT    23.888
**   c1    === rxresp
**** dT    23.893
**** c1    rxhdr|HTTP/1.1 503 VCL failed\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:02 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|X-Varnish: 1013\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|Content-Length: 251\r
**** c1    rxhdr|Connection: close\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 194
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |VCL failed
**** c1    http[ 3] |Date: Fri, 08 Apr 2022 09:51:02 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |X-Varnish: 1013
**** c1    http[ 6] |Content-Type: text/html; charset=utf-8
**** c1    http[ 7] |Retry-After: 5
**** c1    http[ 8] |Content-Length: 251
**** c1    http[ 9] |Connection: close
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 VCL failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 VCL failed</h1>
**** c1    c-l|    <p>VCL failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1013</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 251
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
**   c1    === expect_close
**** c1    Expecting close (fd = 31)
**** dT    23.894
**** c1    fd=31 EOF, as expected
***  c1    closing fd 31
**   c1    Ending
**** dT    23.895
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**   c1    Started on 127.0.0.1:18770 (1 iterations)
***  c1    Connect to 127.0.0.1:18770
**** dT    23.896
***  c1    connected fd 31 from 127.0.0.1 20369 to 127.0.0.1:18770
**   c1    === txreq -url deliver
**** c1    txreq|GET deliver HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**** dT    23.897
**   c1    === rxresp
**** dT    23.900
**** l1    match|       1004 VCL_call        c MISS
***  l1    test | expect 0 = VCL_return fetch
**** l1    match|       1004 VCL_return      c fetch
***  l1    test | expect * 1007 VCL_call RECV
**** dT    23.902
***  s1    accepted fd 4 127.0.0.1 28149
**   s1    === rxreq
**** dT    23.904
**** s1    rxhdr|GET deliver HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1016\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 109
**** s1    http[ 0] |GET
**** s1    http[ 1] |deliver
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Accept-Encoding: gzip
**** s1    http[ 6] |X-Varnish: 1016
**** s1    bodylen = 0
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
***  s1    shutting fd 4
**** dT    23.913
**** v1    vsl|       1002 Begin           b bereq 1001 fetch
**** v1    vsl|       1002 VCL_use         b vcl1
**** v1    vsl|       1002 Timestamp       b Start: 1649411462.173277 0.000000 0.000000
**** v1    vsl|       1002 BereqMethod     b GET
**** v1    vsl|       1002 BereqURL        b hit
**** v1    vsl|       1002 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1002 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1002 BereqHeader     b X-Varnish: 1002
**** v1    vsl|       1002 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1002 VCL_return      b fetch
**** v1    vsl|       1002 Timestamp       b Fetch: 1649411462.173643 0.000366 0.000366
**** v1    vsl|       1002 Timestamp       b Connected: 1649411462.174502 0.001225 0.000859
**** v1    vsl|       1002 BackendOpen     b 21 s1 127.0.0.1 46914 127.0.0.1 15796 connect
**** v1    vsl|       1002 Timestamp       b Bereq: 1649411462.175264 0.001987 0.000761
**** v1    vsl|       1002 Timestamp       b Beresp: 1649411462.178927 0.005650 0.003662
**** v1    vsl|       1002 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1002 BerespStatus    b 200
**** v1    vsl|       1002 BerespReason    b OK
**** v1    vsl|       1002 BerespHeader    b Content-Length: 0
**** v1    vsl|       1002 BerespHeader    b Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1002 TTL             b RFC 120 10 0 1649411462 1649411462 1649411462 0 0 cacheable
**** v1    vsl|       1002 VCL_call        b BACKEND_RESPONSE
**** dT    23.914
**** v1    vsl|       1002 VCL_return      b deliver
**** v1    vsl|       1002 Timestamp       b Process: 1649411462.181160 0.007883 0.002233
**** v1    vsl|       1002 Filters         b 
**** v1    vsl|       1002 Storage         b malloc s0
**** v1    vsl|       1002 Fetch_Body      b 0 none -
**** v1    vsl|       1002 BackendClose    b 21 s1 recycle
**** v1    vsl|       1002 Timestamp       b BerespBody: 1649411462.192064 0.018787 0.010904
**** v1    vsl|       1002 Length          b 0
**** v1    vsl|       1002 BereqAcct       b 105 0 105 38 0 38
**** v1    vsl|       1002 End             b 
**** v1    vsl|       1001 Begin           c req 1000 rxreq
**** v1    vsl|       1001 Timestamp       c Start: 1649411462.170353 0.000000 0.000000
**** v1    vsl|       1001 Timestamp       c Req: 1649411462.170353 0.000000 0.000000
**** v1    vsl|       1001 VCL_use         c vcl1
**** v1    vsl|       1001 ReqStart        c 127.0.0.1 15751 a0
**** v1    vsl|       1001 ReqMethod       c GET
**** v1    vsl|       1001 ReqURL          c hit
**** v1    vsl|       1001 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1001 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1001 VCL_call        c RECV
**** v1    vsl|       1001 VCL_return      c hash
**** v1    vsl|       1001 VCL_call        c HASH
**** v1    vsl|       1001 VCL_return      c lookup
**** v1    vsl|       1001 VCL_call        c MISS
**** v1    vsl|       1001 VCL_return      c fetch
**** v1    vsl|       1001 Link            c bereq 1002 fetch
**** v1    vsl|       1001 Timestamp       c Fetch: 1649411462.192491 0.022137 0.022137
**** v1    vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    vsl|       1001 RespStatus      c 200
**** v1    vsl|       1001 RespReason      c OK
**** v1    vsl|       1001 RespHeader      c Content-Length: 0
**** v1    vsl|       1001 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    vsl|       1001 RespHeader      c Age: 0
**** v1    vsl|       1001 RespHeader      c Via: 1.1 varnish (Varnish/7.1)
**** v1    vsl|       1001 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1001 VCL_call        c DELIVER
**** v1    vsl|       1001 VCL_return      c deliver
**** v1    vsl|       1001 Timestamp       c Process: 1649411462.192932 0.022579 0.000441
**** v1    vsl|       1001 Filters         c 
**** v1    vsl|       1001 RespHeader      c Connection: keep-alive
**** v1    vsl|       1001 Timestamp       c Resp: 1649411462.197584 0.027230 0.004651
**** v1    vsl|       1001 ReqAcct         c 37 0 37 178 0 178
**** v1    vsl|       1001 End             c 
**** v1    vsl|       1000 Link            c req 1003 rxreq
**** v1    vsl|          0 ExpKill         - EXP_Rearm p=0x20ecf000 E=0.000000 e=1649411462.197905 f=0x0
**** v1    vsl|       1003 Begin           c req 1000 rxreq
**** v1    vsl|       1003 Timestamp       c Start: 1649411462.197904 0.000000 0.000000
**** v1    vsl|       1003 Timestamp       c Req: 1649411462.197904 0.000000 0.000000
**** v1    vsl|       1003 VCL_use         c vcl1
**** v1    vsl|       1003 ReqStart        c 127.0.0.1 15751 a0
**** v1    vsl|       1003 ReqMethod       c GET
**** dT    23.915
**** v1    vsl|       1003 ReqURL          c hit
**** v1    vsl|       1003 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1003 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1003 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1003 VCL_call        c RECV
**** v1    vsl|       1003 VCL_return      c hash
**** v1    vsl|       1003 VCL_call        c HASH
**** v1    vsl|       1003 VCL_return      c lookup
**** v1    vsl|       1003 Hit             c 1002 119.981023 10.000000 0.000000
**** v1    vsl|       1003 VCL_call        c HIT
**** v1    vsl|       1003 VCL_return      c deliver
**** v1    vsl|       1003 RespProtocol    c HTTP/1.1
**** v1    vsl|       1003 RespStatus      c 200
**** v1    vsl|       1003 RespReason      c OK
**** v1    vsl|       1003 RespHeader      c Content-Length: 0
**** v1    vsl|       1003 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1003 RespHeader      c X-Varnish: 1003 1002
**** v1    vsl|       1003 RespHeader      c Age: 0
**** v1    vsl|       1003 RespHeader      c Via: 1.1 varnish (Varnish/7.1)
**** v1    vsl|       1003 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1003 VCL_call        c DELIVER
**** v1    vsl|       1003 VCL_return      c deliver
**** v1    vsl|       1003 Timestamp       c Process: 1649411462.198771 0.000866 0.000866
**** v1    vsl|       1003 Filters         c 
**** v1    vsl|       1003 RespHeader      c Connection: keep-alive
**** v1    vsl|       1003 Timestamp       c Resp: 1649411462.201595 0.003690 0.002824
**** v1    vsl|       1003 ReqAcct         c 37 0 37 183 0 183
**** v1    vsl|       1003 End             c 
**** v1    vsl|       1000 Link            c req 1004 rxreq
**** v1    vsl|          0 ExpKill         - EXP_Inbox flg=1e p=0x20ecf000 e=0.000000 f=0x0
**** v1    vsl|          0 ExpKill         - EXP_When p=0x20ecf000 e=1649411462.197905 f=0x1e
**** v1    vsl|          0 ExpKill         - EXP_expire p=0x20ecf000 e=-0.010947 f=0x0
**** v1    vsl|          0 ExpKill         - EXP_Expired x=1002 t=-0
**** v1    vsl|          0 ExpKill         - EXP_Inbox flg=1e p=0x20ecf080 e=0.000000 f=0x0
**** v1    vsl|          0 ExpKill         - EXP_When p=0x20ecf080 e=1649411592.206023 f=0x1e
**** v1    vsl|          0 ExpKill         - EXP_expire p=0x20ecf080 e=129.987734 f=0x0
**** v1    vsl|       1005 Begin           b bereq 1004 fetch
**** v1    vsl|       1005 VCL_use         b vcl1
**** v1    vsl|       1005 Timestamp       b Start: 1649411462.202491 0.000000 0.000000
**** v1    vsl|       1005 BereqMethod     b GET
**** v1    vsl|       1005 BereqURL        b miss
**** v1    vsl|       1005 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1005 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1005 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1005 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1005 BereqHeader     b X-Varnish: 1005
**** v1    vsl|       1005 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1005 VCL_return      b fetch
**** v1    vsl|       1005 Timestamp       b Fetch: 1649411462.202666 0.000174 0.000174
**** v1    vsl|       1005 Timestamp       b Connected: 1649411462.203699 0.001208 0.001033
**** v1    vsl|       1005 BackendOpen     b 21 s1 127.0.0.1 46914 127.0.0.1 62613 connect
**** v1    vsl|       1005 Timestamp       b Bereq: 1649411462.205780 0.003288 0.002080
**** v1    vsl|       1005 Timestamp       b Beresp: 1649411462.206022 0.003530 0.000242
**** v1    vsl|       1005 BerespProtocol  b HTTP/1.1
**** dT    23.916
**** v1    vsl|       1005 BerespStatus    b 200
**** v1    vsl|       1005 BerespReason    b OK
**** v1    vsl|       1005 BerespHeader    b Content-Length: 0
**** v1    vsl|       1005 BerespHeader    b Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1005 TTL             b RFC 120 10 0 1649411462 1649411462 1649411462 0 0 cacheable
**** v1    vsl|       1005 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1005 VCL_return      b deliver
**** v1    vsl|       1005 Timestamp       b Process: 1649411462.206329 0.003837 0.000306
**** v1    vsl|       1005 Filters         b 
**** v1    vsl|       1005 Storage         b malloc s0
**** v1    vsl|       1005 Fetch_Body      b 0 none -
**** v1    vsl|       1005 BackendClose    b 21 s1 recycle
**** v1    vsl|       1005 Timestamp       b BerespBody: 1649411462.218410 0.015918 0.012081
**** v1    vsl|       1005 Length          b 0
**** v1    vsl|       1005 BereqAcct       b 106 0 106 38 0 38
**** v1    vsl|       1005 End             b 
**** v1    vsl|       1006 Begin           c sess 0 HTTP/1
**** v1    vsl|       1006 SessOpen        c 127.0.0.1 49263 a0 127.0.0.1 18770 1649411462.226090 20
**** v1    vsl|       1006 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1006 Debug           c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|       1006 Debug           c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1006 Debug           c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1006 Debug           c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|       1006 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1006 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1006 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1006 Link            c req 1007 rxreq
**** v1    vsl|       1007 Begin           c req 1006 rxreq
**** v1    vsl|       1007 Timestamp       c Start: 1649411462.226598 0.000000 0.000000
**** v1    vsl|       1007 Timestamp       c Req: 1649411462.226598 0.000000 0.000000
**** v1    vsl|       1007 VCL_use         c vcl1
**** v1    vsl|       1007 ReqStart        c 127.0.0.1 49263 a0
**** v1    vsl|       1007 ReqMethod       c GET
**** v1    vsl|       1007 ReqURL          c recv
**** v1    vsl|       1007 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1007 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1007 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1007 VCL_call        c RECV
**** v1    vsl|       1007 VCL_Error       c purge can only happen in vcl_hit{} or vcl_miss{}
**** v1    vsl|       1007 VCL_return      c fail
**** v1    vsl|       1007 RespProtocol    c HTTP/1.1
**** v1    vsl|       1007 RespStatus      c 503
**** v1    vsl|       1007 RespReason      c VCL failed
**** v1    vsl|       1007 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1007 RespHeader      c Server: Varnish
**** v1    vsl|       1007 RespHeader      c X-Varnish: 1007
**** v1    vsl|       1007 VCL_call        c SYNTH
**** v1    vsl|       1007 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1007 RespHeader      c Retry-After: 5
**** v1    vsl|       1007 VCL_return      c deliver
**** v1    vsl|       1007 Timestamp       c Process: 1649411462.227409 0.000810 0.000810
**** v1    vsl|       1007 RespHeader      c Content-Length: 251
**** v1    vsl|       1007 Storage         c malloc Transient
**** dT    23.917
**** v1    vsl|       1007 Filters         c 
**** v1    vsl|       1007 RespHeader      c Connection: close
**** v1    vsl|       1007 Timestamp       c Resp: 1649411462.231051 0.004452 0.003641
**** v1    vsl|       1007 ReqAcct         c 38 0 38 194 251 445
**** v1    vsl|       1007 End             c 
**** v1    vsl|       1006 SessClose       c VCL_FAILURE 0.009
**** v1    vsl|       1006 End             c 
**** v1    vsl|       1008 Begin           c sess 0 HTTP/1
**** v1    vsl|       1008 SessOpen        c 127.0.0.1 37697 a0 127.0.0.1 18770 1649411462.235555 21
**** v1    vsl|       1008 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1008 Debug           c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|       1008 Debug           c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1008 Debug           c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1008 Debug           c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|       1008 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1008 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1008 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1008 Link            c req 1009 rxreq
**** v1    vsl|       1009 Begin           c req 1008 rxreq
**** v1    vsl|       1009 Timestamp       c Start: 1649411462.236030 0.000000 0.000000
**** v1    vsl|       1009 Timestamp       c Req: 1649411462.236030 0.000000 0.000000
**** v1    vsl|       1009 VCL_use         c vcl1
**** v1    vsl|       1009 ReqStart        c 127.0.0.1 37697 a0
**** v1    vsl|       1009 ReqMethod       c GET
**** v1    vsl|       1009 ReqURL          c hash
**** v1    vsl|       1009 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1009 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1009 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1009 VCL_call        c RECV
**** v1    vsl|       1009 VCL_return      c hash
**** v1    vsl|       1009 VCL_call        c HASH
**** v1    vsl|       1009 VCL_Error       c purge can only happen in vcl_hit{} or vcl_miss{}
**** v1    vsl|       1009 VCL_return      c fail
**** v1    vsl|       1009 RespProtocol    c HTTP/1.1
**** v1    vsl|       1009 RespStatus      c 503
**** v1    vsl|       1009 RespReason      c VCL failed
**** v1    vsl|       1009 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1009 RespHeader      c Server: Varnish
**** v1    vsl|       1009 RespHeader      c X-Varnish: 1009
**** v1    vsl|       1009 VCL_call        c SYNTH
**** v1    vsl|       1009 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1009 RespHeader      c Retry-After: 5
**** v1    vsl|       1009 VCL_return      c deliver
**** v1    vsl|       1009 Timestamp       c Process: 1649411462.236706 0.000675 0.000675
**** v1    vsl|       1009 RespHeader      c Content-Length: 251
**** v1    vsl|       1009 Storage         c malloc Transient
**** v1    vsl|       1009 Filters         c 
**** v1    vsl|       1009 RespHeader      c Connection: close
**** v1    vsl|       1009 Timestamp       c Resp: 1649411462.239892 0.003861 0.003186
**** v1    vsl|       1009 ReqAcct         c 38 0 38 194 251 445
**** v1    vsl|       1009 End             c 
**** v1    vsl|       1008 SessClose       c VCL_FAILURE 0.009
**** v1    vsl|       1008 End             c 
**** v1    vsl|       1010 Begin           c sess 0 HTTP/1
**** v1    vsl|       1010 SessOpen        c 127.0.0.1 52284 a0 127.0.0.1 18770 1649411462.244549 20
**** dT    23.918
**** v1    vsl|       1010 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1010 Debug           c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|       1010 Debug           c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1010 Debug           c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1010 Debug           c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|       1010 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1010 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1010 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1010 Link            c req 1011 rxreq
**** v1    vsl|       1011 Begin           c req 1010 rxreq
**** v1    vsl|       1011 Timestamp       c Start: 1649411462.245029 0.000000 0.000000
**** v1    vsl|       1011 Timestamp       c Req: 1649411462.245029 0.000000 0.000000
**** v1    vsl|       1011 VCL_use         c vcl1
**** v1    vsl|       1011 ReqStart        c 127.0.0.1 52284 a0
**** v1    vsl|       1011 ReqMethod       c GET
**** v1    vsl|       1011 ReqURL          c purge
**** v1    vsl|       1011 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1011 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1011 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1011 VCL_call        c RECV
**** v1    vsl|       1011 VCL_return      c purge
**** v1    vsl|       1011 VCL_call        c HASH
**** v1    vsl|       1011 VCL_return      c lookup
**** v1    vsl|       1011 VCL_call        c PURGE
**** v1    vsl|       1011 VCL_Error       c purge can only happen in vcl_hit{} or vcl_miss{}
**** v1    vsl|       1011 VCL_return      c fail
**** v1    vsl|       1011 RespProtocol    c HTTP/1.1
**** v1    vsl|       1011 RespStatus      c 503
**** v1    vsl|       1011 RespReason      c VCL failed
**** v1    vsl|       1011 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1011 RespHeader      c Server: Varnish
**** v1    vsl|       1011 RespHeader      c X-Varnish: 1011
**** v1    vsl|       1011 VCL_call        c SYNTH
**** v1    vsl|       1011 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1011 RespHeader      c Retry-After: 5
**** v1    vsl|       1011 VCL_return      c deliver
**** v1    vsl|       1011 Timestamp       c Process: 1649411462.246154 0.001125 0.001125
**** v1    vsl|       1011 RespHeader      c Content-Length: 251
**** v1    vsl|       1011 Storage         c malloc Transient
**** v1    vsl|       1011 Filters         c 
**** v1    vsl|       1011 RespHeader      c Connection: close
**** v1    vsl|       1011 Timestamp       c Resp: 1649411462.249261 0.004232 0.003107
**** v1    vsl|       1011 ReqAcct         c 39 0 39 194 251 445
**** v1    vsl|       1011 End             c 
**** v1    vsl|       1010 SessClose       c VCL_FAILURE 0.008
**** v1    vsl|       1010 End             c 
**** v1    vsl|       1012 Begin           c sess 0 HTTP/1
**** dT    23.919
**** v1    vsl|       1012 SessOpen        c 127.0.0.1 52445 a0 127.0.0.1 18770 1649411462.253988 21
**** v1    vsl|       1012 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1012 Debug           c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|       1012 Debug           c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1012 Debug           c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1012 Debug           c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|       1012 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1012 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1012 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1012 Link            c req 1013 rxreq
**** v1    vsl|       1013 Begin           c req 1012 rxreq
**** v1    vsl|       1013 Timestamp       c Start: 1649411462.254384 0.000000 0.000000
**** v1    vsl|       1013 Timestamp       c Req: 1649411462.254384 0.000000 0.000000
**** v1    vsl|       1013 VCL_use         c vcl1
**** v1    vsl|       1013 ReqStart        c 127.0.0.1 52445 a0
**** v1    vsl|       1013 ReqMethod       c GET
**** v1    vsl|       1013 ReqURL          c pass
**** 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 VCL_call        c RECV
**** v1    vsl|       1013 VCL_return      c pass
**** v1    vsl|       1013 VCL_call        c HASH
**** v1    vsl|       1013 VCL_return      c lookup
**** v1    vsl|       1013 VCL_call        c PASS
**** v1    vsl|       1013 VCL_Error       c purge can only happen in vcl_hit{} or vcl_miss{}
**** v1    vsl|       1013 VCL_return      c fail
**** v1    vsl|       1013 RespProtocol    c HTTP/1.1
**** v1    vsl|       1013 RespStatus      c 503
**** v1    vsl|       1013 RespReason      c VCL failed
**** v1    vsl|       1013 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1013 RespHeader      c Server: Varnish
**** v1    vsl|       1013 RespHeader      c X-Varnish: 1013
**** v1    vsl|       1013 VCL_call        c SYNTH
**** v1    vsl|       1013 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1013 RespHeader      c Retry-After: 5
**** v1    vsl|       1013 VCL_return      c deliver
**** v1    vsl|       1013 Timestamp       c Process: 1649411462.255102 0.000718 0.000718
**** v1    vsl|       1013 RespHeader      c Content-Length: 251
**** v1    vsl|       1013 Storage         c malloc Transient
**** v1    vsl|       1013 Filters         c 
**** v1    vsl|       1013 RespHeader      c Connection: close
**** v1    vsl|       1013 Timestamp       c Resp: 1649411462.258220 0.003835 0.003117
**** v1    vsl|       1013 ReqAcct         c 38 0 38 194 251 445
**** v1    vsl|       1013 End             c 
**** v1    vsl|       1012 SessClose       c VCL_FAILURE 0.008
**** v1    vsl|       1012 End             c 
**** v1    vsl|       1014 Begin           c sess 0 HTTP/1
**** v1    vsl|       1014 SessOpen        c 127.0.0.1 20369 a0 127.0.0.1 18770 1649411462.262204 20
**** v1    vsl|       1014 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1014 Debug           c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|       1014 Debug           c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1014 Debug           c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1014 Debug           c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** dT    23.920
**** v1    vsl|       1014 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1014 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1014 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1014 Link            c req 1015 rxreq
**** v1    vsl|       1004 Begin           c req 1000 rxreq
**** v1    vsl|       1004 Timestamp       c Start: 1649411462.201823 0.000000 0.000000
**** v1    vsl|       1004 Timestamp       c Req: 1649411462.201823 0.000000 0.000000
**** v1    vsl|       1004 VCL_use         c vcl1
**** v1    vsl|       1004 ReqStart        c 127.0.0.1 15751 a0
**** v1    vsl|       1004 ReqMethod       c GET
**** v1    vsl|       1004 ReqURL          c miss
**** v1    vsl|       1004 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1004 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1004 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1004 VCL_call        c RECV
**** v1    vsl|       1004 VCL_return      c hash
**** v1    vsl|       1004 VCL_call        c HASH
**** v1    vsl|       1004 VCL_return      c lookup
**** v1    vsl|       1004 VCL_call        c MISS
**** v1    vsl|       1004 VCL_return      c fetch
**** v1    vsl|       1004 Link            c bereq 1005 fetch
**** v1    vsl|       1004 Timestamp       c Fetch: 1649411462.218666 0.016842 0.016842
**** v1    vsl|       1004 RespProtocol    c HTTP/1.1
**** v1    vsl|       1004 RespStatus      c 200
**** v1    vsl|       1004 RespReason      c OK
**** v1    vsl|       1004 RespHeader      c Content-Length: 0
**** v1    vsl|       1004 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1004 RespHeader      c X-Varnish: 1004
**** v1    vsl|       1004 RespHeader      c Age: 0
**** v1    vsl|       1004 RespHeader      c Via: 1.1 varnish (Varnish/7.1)
**** v1    vsl|       1004 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1004 VCL_call        c DELIVER
**** v1    vsl|       1004 VCL_return      c deliver
**** v1    vsl|       1004 Timestamp       c Process: 1649411462.219686 0.017862 0.001020
**** v1    vsl|       1004 Filters         c 
**** v1    vsl|       1004 RespHeader      c Connection: keep-alive
**** v1    vsl|       1004 Timestamp       c Resp: 1649411462.263450 0.061626 0.043763
**** v1    vsl|       1004 ReqAcct         c 38 0 38 178 0 178
**** v1    vsl|       1004 End             c 
**** v1    vsl|       1000 SessClose       c REM_CLOSE 0.096
**** v1    vsl|       1000 End             c 
**** dT    23.925
**** c1    rxhdr|HTTP/1.1 503 VCL failed\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:02 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|X-Varnish: 1015\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|Content-Length: 251\r
**** c1    rxhdr|Connection: close\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 194
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |VCL failed
**** c1    http[ 3] |Date: Fri, 08 Apr 2022 09:51:02 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |X-Varnish: 1015
**** c1    http[ 6] |Content-Type: text/html; charset=utf-8
**** c1    http[ 7] |Retry-After: 5
**** c1    http[ 8] |Content-Length: 251
**** c1    http[ 9] |Connection: close
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 VCL failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 VCL failed</h1>
**** c1    c-l|    <p>VCL failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1015</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 251
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
**   c1    === expect_close
**** c1    Expecting close (fd = 31)
**** dT    23.926
**** c1    fd=31 EOF, as expected
***  c1    closing fd 31
**   c1    Ending
**** dT    23.927
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**** dT    23.934
**   c1    Started on 127.0.0.1:18770 (1 iterations)
***  c1    Connect to 127.0.0.1:18770
**** dT    23.935
***  c1    connected fd 31 from 127.0.0.1 46736 to 127.0.0.1:18770
**** dT    23.936
**   c1    === txreq -url synth
**** c1    txreq|GET synth HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**** dT    23.946
**   c1    === rxresp
**** dT    23.947
**** c1    rxhdr|HTTP/1.1 500 Internal Server Error\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 38
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |500
**** c1    http[ 2] |Internal Server Error
**** c1    bodylen = 0
**   c1    === expect resp.status == 500
**** c1    EXPECT resp.status (500) == "500" match
**   c1    === expect_close
**** c1    Expecting close (fd = 31)
**** c1    fd=31 EOF, as expected
***  c1    closing fd 31
**   c1    Ending
**** dT    23.948
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**** dT    23.956
**   c1    Started on 127.0.0.1:18770 (1 iterations)
***  c1    Connect to 127.0.0.1:18770
**** dT    23.957
***  c1    connected fd 31 from 127.0.0.1 55513 to 127.0.0.1:18770
**   c1    === txreq -url fetch
**** dT    23.958
**** c1    txreq|GET fetch HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**** dT    23.970
**   c1    === rxresp
**** dT    23.971
**** c1    rxhdr|HTTP/1.1 503 Service Unavailable\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:02 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|X-Varnish: 1020\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|Content-Length: 278\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 208
**** dT    23.972
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |Service Unavailable
**** c1    http[ 3] |Date: Fri, 08 Apr 2022 09:51:02 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |X-Varnish: 1020
**** c1    http[ 6] |Content-Type: text/html; charset=utf-8
**** c1    http[ 7] |Retry-After: 5
**** c1    http[ 8] |Content-Length: 278
**** c1    http[ 9] |Connection: keep-alive
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 Service Unavailable</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 Service Unavailable</h1>
**** c1    c-l|    <p>Service Unavailable</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1020</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 278
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
**   c1    === expect_close
**** c1    Expecting close (fd = 31)
**** dT    24.021
**** v1    vsl|       1016 Begin           b bereq 1015 fetch
**** v1    vsl|       1016 VCL_use         b vcl1
**** v1    vsl|       1016 Timestamp       b Start: 1649411462.265602 0.000000 0.000000
**** v1    vsl|       1016 BereqMethod     b GET
**** v1    vsl|       1016 BereqURL        b deliver
**** v1    vsl|       1016 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1016 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1016 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1016 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1016 BereqHeader     b X-Varnish: 1016
**** v1    vsl|       1016 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1016 VCL_return      b fetch
**** v1    vsl|       1016 Timestamp       b Fetch: 1649411462.266002 0.000400 0.000400
**** v1    vsl|       1016 Timestamp       b Connected: 1649411462.267226 0.001623 0.001223
**** v1    vsl|       1016 BackendOpen     b 19 s1 127.0.0.1 46914 127.0.0.1 28149 connect
**** v1    vsl|       1016 Timestamp       b Bereq: 1649411462.269354 0.003751 0.002128
**** v1    vsl|       1016 Timestamp       b Beresp: 1649411462.269577 0.003975 0.000223
**** v1    vsl|       1016 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1016 BerespStatus    b 200
**** v1    vsl|       1016 BerespReason    b OK
**** v1    vsl|       1016 BerespHeader    b Content-Length: 0
**** v1    vsl|       1016 BerespHeader    b Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1016 TTL             b RFC 120 10 0 1649411462 1649411462 1649411462 0 0 cacheable
**** dT    24.022
**** v1    vsl|       1016 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1016 VCL_return      b deliver
**** v1    vsl|       1016 Timestamp       b Process: 1649411462.270106 0.004504 0.000528
**** v1    vsl|       1016 Filters         b 
**** v1    vsl|       1016 Storage         b malloc s0
**** v1    vsl|       1016 Fetch_Body      b 0 none -
**** v1    vsl|       1016 BackendClose    b 19 s1 recycle
**** v1    vsl|       1016 Timestamp       b BerespBody: 1649411462.285598 0.019995 0.015491
**** v1    vsl|       1016 Length          b 0
**** v1    vsl|       1016 BereqAcct       b 109 0 109 38 0 38
**** v1    vsl|       1016 End             b 
**** v1    vsl|          0 ExpKill         - EXP_expire p=0x20ecf080 e=129.918826 f=0x0
**** v1    vsl|          0 ExpKill         - EXP_Inbox flg=1e p=0x20ee4000 e=0.000000 f=0x0
**** v1    vsl|          0 ExpKill         - EXP_When p=0x20ee4000 e=1649411592.269578 f=0x1e
**** v1    vsl|          0 ExpKill         - EXP_expire p=0x20ecf080 e=129.918687 f=0x0
**** v1    vsl|       1015 Begin           c req 1014 rxreq
**** v1    vsl|       1015 Timestamp       c Start: 1649411462.262590 0.000000 0.000000
**** v1    vsl|       1015 Timestamp       c Req: 1649411462.262590 0.000000 0.000000
**** v1    vsl|       1015 VCL_use         c vcl1
**** v1    vsl|       1015 ReqStart        c 127.0.0.1 20369 a0
**** v1    vsl|       1015 ReqMethod       c GET
**** v1    vsl|       1015 ReqURL          c deliver
**** v1    vsl|       1015 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1015 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1015 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1015 VCL_call        c RECV
**** v1    vsl|       1015 VCL_return      c hash
**** v1    vsl|       1015 VCL_call        c HASH
**** v1    vsl|       1015 VCL_return      c lookup
**** v1    vsl|       1015 VCL_call        c MISS
**** v1    vsl|       1015 VCL_return      c fetch
**** v1    vsl|       1015 Link            c bereq 1016 fetch
**** v1    vsl|       1015 Timestamp       c Fetch: 1649411462.285933 0.023343 0.023343
**** v1    vsl|       1015 RespProtocol    c HTTP/1.1
**** v1    vsl|       1015 RespStatus      c 200
**** v1    vsl|       1015 RespReason      c OK
**** v1    vsl|       1015 RespHeader      c Content-Length: 0
**** v1    vsl|       1015 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1015 RespHeader      c X-Varnish: 1015
**** v1    vsl|       1015 RespHeader      c Age: 0
**** v1    vsl|       1015 RespHeader      c Via: 1.1 varnish (Varnish/7.1)
**** v1    vsl|       1015 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1015 VCL_call        c DELIVER
**** v1    vsl|       1015 VCL_Error       c purge can only happen in vcl_hit{} or vcl_miss{}
**** v1    vsl|       1015 VCL_return      c fail
**** v1    vsl|       1015 Timestamp       c Process: 1649411462.286229 0.023638 0.000295
**** v1    vsl|       1015 RespProtocol    c HTTP/1.1
**** v1    vsl|       1015 RespStatus      c 503
**** v1    vsl|       1015 RespReason      c VCL failed
**** v1    vsl|       1015 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1015 RespHeader      c Server: Varnish
**** v1    vsl|       1015 RespHeader      c X-Varnish: 1015
**** v1    vsl|       1015 VCL_call        c SYNTH
**** v1    vsl|       1015 RespHeader      c Content-Type: text/html; charset=utf-8
**** dT    24.023
**** v1    vsl|       1015 RespHeader      c Retry-After: 5
**** v1    vsl|       1015 VCL_return      c deliver
**** v1    vsl|       1015 Timestamp       c Process: 1649411462.286506 0.023916 0.000277
**** v1    vsl|       1015 RespHeader      c Content-Length: 251
**** v1    vsl|       1015 Storage         c malloc Transient
**** v1    vsl|       1015 Filters         c 
**** v1    vsl|       1015 RespHeader      c Connection: close
**** v1    vsl|       1015 Timestamp       c Resp: 1649411462.290182 0.027591 0.003675
**** v1    vsl|       1015 ReqAcct         c 41 0 41 194 251 445
**** v1    vsl|       1015 End             c 
**** v1    vsl|       1014 SessClose       c VCL_FAILURE 0.030
**** v1    vsl|       1014 End             c 
**** v1    vsl|       1017 Begin           c sess 0 HTTP/1
**** v1    vsl|       1017 SessOpen        c 127.0.0.1 46736 a0 127.0.0.1 18770 1649411462.299670 21
**** v1    vsl|       1017 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1017 Debug           c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|       1017 Debug           c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1017 Debug           c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1017 Debug           c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|       1017 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1017 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1017 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1017 Link            c req 1018 rxreq
**** v1    vsl|       1018 Begin           c req 1017 rxreq
**** v1    vsl|       1018 Timestamp       c Start: 1649411462.309473 0.000000 0.000000
**** v1    vsl|       1018 Timestamp       c Req: 1649411462.309473 0.000000 0.000000
**** v1    vsl|       1018 VCL_use         c vcl1
**** v1    vsl|       1018 ReqStart        c 127.0.0.1 46736 a0
**** v1    vsl|       1018 ReqMethod       c GET
**** v1    vsl|       1018 ReqURL          c synth
**** v1    vsl|       1018 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1018 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1018 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1018 VCL_call        c RECV
**** v1    vsl|       1018 VCL_return      c synth
**** v1    vsl|       1018 VCL_call        c HASH
**** v1    vsl|       1018 VCL_return      c lookup
**** v1    vsl|       1018 RespProtocol    c HTTP/1.1
**** v1    vsl|       1018 RespStatus      c 200
**** v1    vsl|       1018 RespReason      c OK
**** v1    vsl|       1018 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1018 RespHeader      c Server: Varnish
**** v1    vsl|       1018 RespHeader      c X-Varnish: 1018
**** v1    vsl|       1018 VCL_call        c SYNTH
**** v1    vsl|       1018 VCL_Error       c purge can only happen in vcl_hit{} or vcl_miss{}
**** v1    vsl|       1018 VCL_return      c fail
**** v1    vsl|       1018 Timestamp       c Process: 1649411462.310133 0.000660 0.000660
**** v1    vsl|       1018 RespProtocol    c HTTP/1.1
**** v1    vsl|       1018 RespStatus      c 500
**** v1    vsl|       1018 RespReason      c Internal Server Error
**** v1    vsl|       1018 Timestamp       c Resp: 1649411462.310434 0.000960 0.000300
**** v1    vsl|       1018 ReqAcct         c 39 0 39 38 0 38
**** v1    vsl|       1018 End             c 
**** v1    vsl|       1017 SessClose       c VCL_FAILURE 0.011
**** v1    vsl|       1017 End             c 
**** dT    24.024
**** v1    vsl|       1019 Begin           c sess 0 HTTP/1
**** v1    vsl|       1019 SessOpen        c 127.0.0.1 55513 a0 127.0.0.1 18770 1649411462.321648 19
**** v1    vsl|       1019 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1019 Debug           c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|       1019 Debug           c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1019 Debug           c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1019 Debug           c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|       1019 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1019 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1019 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1019 Link            c req 1020 rxreq
**** v1    vsl|       1021 Begin           b bereq 1020 fetch
**** v1    vsl|       1021 VCL_use         b vcl1
**** v1    vsl|       1021 Timestamp       b Start: 1649411462.332437 0.000000 0.000000
**** v1    vsl|       1021 BereqMethod     b GET
**** v1    vsl|       1021 BereqURL        b fetch
**** 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 Accept-Encoding: gzip
**** v1    vsl|       1021 BereqHeader     b X-Varnish: 1021
**** v1    vsl|       1021 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1021 VCL_Error       b purge can only happen in vcl_hit{} or vcl_miss{}
**** v1    vsl|       1021 VCL_return      b fail
**** v1    vsl|       1021 BereqAcct       b 0 0 0 0 0 0
**** v1    vsl|       1021 End             b 
**** v1    vsl|       1020 Begin           c req 1019 rxreq
**** v1    vsl|       1020 Timestamp       c Start: 1649411462.331528 0.000000 0.000000
**** v1    vsl|       1020 Timestamp       c Req: 1649411462.331528 0.000000 0.000000
**** v1    vsl|       1020 VCL_use         c vcl1
**** v1    vsl|       1020 ReqStart        c 127.0.0.1 55513 a0
**** v1    vsl|       1020 ReqMethod       c GET
**** v1    vsl|       1020 ReqURL          c fetch
**** 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 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: 1649411462.332859 0.001330 0.001330
**** v1    vsl|       1020 RespProtocol    c HTTP/1.1
**** v1    vsl|       1020 RespStatus      c 503
**** v1    vsl|       1020 RespReason      c Service Unavailable
**** v1    vsl|       1020 RespHeader      c Date: Fri, 08 Apr 2022 09:51:02 GMT
**** v1    vsl|       1020 RespHeader      c Server: Varnish
**** v1    vsl|       1020 RespHeader      c X-Varnish: 1020
**** v1    vsl|       1020 VCL_call        c SYNTH
**** v1    vsl|       1020 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1020 RespHeader      c Retry-After: 5
**** v1    vsl|       1020 VCL_return      c deliver
**** dT    24.025
**** v1    vsl|       1020 Timestamp       c Process: 1649411462.333283 0.001754 0.000424
**** v1    vsl|       1020 RespHeader      c Content-Length: 278
**** v1    vsl|       1020 Storage         c malloc Transient
**** v1    vsl|       1020 Filters         c 
**** v1    vsl|       1020 RespHeader      c Connection: keep-alive
**** v1    vsl|       1020 Timestamp       c Resp: 1649411462.334248 0.002720 0.000965
**** v1    vsl|       1020 ReqAcct         c 39 0 39 208 278 486
**** v1    vsl|       1020 End             c 
**** dT    24.656
**** v1    vsl|          0 Debug           - sockopt: Not setting unmodified SO_LINGER for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Not setting unmodified SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Not setting unmodified TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Not setting unmodified TCP_KEEPIDLE for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Not setting unmodified TCP_KEEPCNT for a0=127.0.0.1:18770
**** v1    vsl|          0 Debug           - sockopt: Not setting unmodified TCP_KEEPINTVL for a0=127.0.0.1:18770
**** dT    25.974
**** c1    fd=31 EOF, as expected
***  c1    closing fd 31
**   c1    Ending
**** dT    25.975
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**** dT    26.005
**   c1    Started on 127.0.0.1:18770 (1 iterations)
***  c1    Connect to 127.0.0.1:18770
**** dT    26.011
**** v1    vsl|       1019 SessClose       c RX_CLOSE_IDLE 2.017
**** v1    vsl|       1019 End             c 
**** v1    vsl|       1022 Begin           c sess 0 HTTP/1
**** v1    vsl|       1022 SessOpen        c 127.0.0.1 55514 a0 127.0.0.1 18770 1649411464.371031 20
**** v1    vsl|       1022 Debug           c sockopt: Not testing nonhereditary SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: Not testing nonhereditary SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: Not testing nonhereditary SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: Not testing nonhereditary TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1022 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:18770
**** dT    26.036
***  c1    connected fd 31 from 127.0.0.1 55514 to 127.0.0.1:18770
**   c1    === txreq -url error
**** c1    txreq|GET error HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**** dT    26.071
**   c1    === rxresp
**** dT    26.117
**** v1    vsl|       1022 Link            c req 1023 rxreq
**** v1    vsl|       1024 Begin           b bereq 1023 fetch
**** v1    vsl|       1024 VCL_use         b vcl1
**** v1    vsl|       1024 Timestamp       b Start: 1649411464.433411 0.000000 0.000000
**** v1    vsl|       1024 BereqMethod     b GET
**** v1    vsl|       1024 BereqURL        b error
**** 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 Accept-Encoding: gzip
**** v1    vsl|       1024 BereqHeader     b X-Varnish: 1024
**** v1    vsl|       1024 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1024 VCL_return      b fetch
**** v1    vsl|       1024 Timestamp       b Fetch: 1649411464.433664 0.000252 0.000252
**** v1    vsl|       1024 FetchError      b No backend
**** v1    vsl|       1024 Timestamp       b Beresp: 1649411464.433694 0.000282 0.000029
**** v1    vsl|       1024 Timestamp       b Error: 1649411464.433714 0.000303 0.000020
**** v1    vsl|       1024 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1024 BerespStatus    b 503
**** v1    vsl|       1024 BerespReason    b Backend fetch failed
**** v1    vsl|       1024 BerespHeader    b Date: Fri, 08 Apr 2022 09:51:04 GMT
**** v1    vsl|       1024 BerespHeader    b Server: Varnish
**** v1    vsl|       1024 VCL_call        b BACKEND_ERROR
**** v1    vsl|       1024 VCL_Error       b purge can only happen in vcl_hit{} or vcl_miss{}
**** v1    vsl|       1024 VCL_return      b fail
**** v1    vsl|       1024 BereqAcct       b 0 0 0 0 0 0
**** v1    vsl|       1024 End             b 
**** v1    vsl|       1023 Begin           c req 1022 rxreq
**** v1    vsl|       1023 Timestamp       c Start: 1649411464.432449 0.000000 0.000000
**** v1    vsl|       1023 Timestamp       c Req: 1649411464.432449 0.000000 0.000000
**** v1    vsl|       1023 VCL_use         c vcl1
**** v1    vsl|       1023 ReqStart        c 127.0.0.1 55514 a0
**** v1    vsl|       1023 ReqMethod       c GET
**** dT    26.118
**** v1    vsl|       1023 ReqURL          c error
**** 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 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: 1649411464.434099 0.001649 0.001649
**** v1    vsl|       1023 RespProtocol    c HTTP/1.1
**** v1    vsl|       1023 RespStatus      c 503
**** v1    vsl|       1023 RespReason      c Service Unavailable
**** v1    vsl|       1023 RespHeader      c Date: Fri, 08 Apr 2022 09:51:04 GMT
**** v1    vsl|       1023 RespHeader      c Server: Varnish
**** v1    vsl|       1023 RespHeader      c X-Varnish: 1023
**** v1    vsl|       1023 VCL_call        c SYNTH
**** v1    vsl|       1023 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1023 RespHeader      c Retry-After: 5
**** v1    vsl|       1023 VCL_return      c deliver
**** v1    vsl|       1023 Timestamp       c Process: 1649411464.434419 0.001970 0.000320
**** v1    vsl|       1023 RespHeader      c Content-Length: 278
**** v1    vsl|       1023 Storage         c malloc Transient
**** v1    vsl|       1023 Filters         c 
**** v1    vsl|       1023 RespHeader      c Connection: keep-alive
**** v1    vsl|       1023 Timestamp       c Resp: 1649411464.435247 0.002798 0.000828
**** v1    vsl|       1023 ReqAcct         c 39 0 39 208 278 486
**** v1    vsl|       1023 End             c 
**** dT    26.143
**** c1    rxhdr|HTTP/1.1 503 Service Unavailable\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:04 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|X-Varnish: 1023\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|Content-Length: 278\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 208
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |Service Unavailable
**** c1    http[ 3] |Date: Fri, 08 Apr 2022 09:51:04 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |X-Varnish: 1023
**** c1    http[ 6] |Content-Type: text/html; charset=utf-8
**** c1    http[ 7] |Retry-After: 5
**** c1    http[ 8] |Content-Length: 278
**** c1    http[ 9] |Connection: keep-alive
**** dT    26.144
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 Service Unavailable</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 Service Unavailable</h1>
**** c1    c-l|    <p>Service Unavailable</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1023</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 278
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
**   c1    === expect_close
**** c1    Expecting close (fd = 31)
**** dT    26.530
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411464 1.0
**** dT    28.081
**** c1    fd=31 EOF, as expected
***  c1    closing fd 31
**   c1    Ending
**** dT    28.082
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**** dT    28.091
**** v1    vsl|       1022 SessClose       c RX_CLOSE_IDLE 2.074
**** v1    vsl|       1022 End             c 
**** dT    28.124
**   c1    Started on 127.0.0.1:18770 (1 iterations)
***  c1    Connect to 127.0.0.1:18770
**** dT    28.126
***  c1    connected fd 31 from 127.0.0.1 55515 to 127.0.0.1:18770
**   c1    === txreq -url response
**** c1    txreq|GET response HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**** dT    28.158
***  s1    accepted fd 4 127.0.0.1 55516
**   s1    === rxreq
**** dT    28.160
**** s1    rxhdr|GET response HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1027\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 110
**** s1    http[ 0] |GET
**** s1    http[ 1] |response
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Accept-Encoding: gzip
**** s1    http[ 6] |X-Varnish: 1027
**** s1    bodylen = 0
**   s1    === txresp
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Content-Length: 0\r
**** s1    txresp|\r
**** dT    28.161
***  s1    shutting fd 4
**** dT    28.163
**   c1    === rxresp
**** dT    28.165
**** c1    rxhdr|HTTP/1.1 503 Service Unavailable\r
**** c1    rxhdr|Date: Fri, 08 Apr 2022 09:51:06 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|X-Varnish: 1026\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|Content-Length: 278\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 208
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |Service Unavailable
**** dT    28.166
**** c1    http[ 3] |Date: Fri, 08 Apr 2022 09:51:06 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |X-Varnish: 1026
**** c1    http[ 6] |Content-Type: text/html; charset=utf-8
**** c1    http[ 7] |Retry-After: 5
**** c1    http[ 8] |Content-Length: 278
**** c1    http[ 9] |Connection: keep-alive
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 Service Unavailable</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 Service Unavailable</h1>
**** c1    c-l|    <p>Service Unavailable</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1026</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 278
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
**** dT    28.191
**   c1    === expect_close
**** c1    Expecting close (fd = 31)
**** dT    28.193
**** v1    vsl|       1025 Begin           c sess 0 HTTP/1
**** v1    vsl|       1025 SessOpen        c 127.0.0.1 55515 a0 127.0.0.1 18770 1649411466.490135 19
**** v1    vsl|       1025 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1025 Debug           c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:18770
**** v1    vsl|       1025 Debug           c sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1025 Debug           c sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:18770
**** v1    vsl|       1025 Debug           c sockopt: Setting TCP_NODELAY for a0=127.0.0.1:18770
**** v1    vsl|       1025 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1025 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1025 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:18770
**** v1    vsl|       1025 Link            c req 1026 rxreq
**** v1    vsl|       1027 Begin           b bereq 1026 fetch
**** v1    vsl|       1027 VCL_use         b vcl1
**** v1    vsl|       1027 Timestamp       b Start: 1649411466.521983 0.000000 0.000000
**** v1    vsl|       1027 BereqMethod     b GET
**** v1    vsl|       1027 BereqURL        b response
**** v1    vsl|       1027 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1027 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1027 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1027 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1027 BereqHeader     b X-Varnish: 1027
**** v1    vsl|       1027 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1027 VCL_return      b fetch
**** v1    vsl|       1027 Timestamp       b Fetch: 1649411466.522219 0.000236 0.000236
**** v1    vsl|       1027 Timestamp       b Connected: 1649411466.523505 0.001521 0.001285
**** v1    vsl|       1027 BackendOpen     b 21 s1 127.0.0.1 46914 127.0.0.1 55516 connect
**** dT    28.194
**** v1    vsl|       1027 Timestamp       b Bereq: 1649411466.525720 0.003737 0.002215
**** v1    vsl|       1027 Timestamp       b Beresp: 1649411466.525972 0.003988 0.000251
**** v1    vsl|       1027 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1027 BerespStatus    b 200
**** v1    vsl|       1027 BerespReason    b OK
**** v1    vsl|       1027 BerespHeader    b Content-Length: 0
**** v1    vsl|       1027 BerespHeader    b Date: Fri, 08 Apr 2022 09:51:06 GMT
**** v1    vsl|       1027 TTL             b RFC 120 10 0 1649411467 1649411467 1649411466 0 0 cacheable
**** v1    vsl|       1027 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1027 VCL_Error       b purge can only happen in vcl_hit{} or vcl_miss{}
**** v1    vsl|       1027 VCL_return      b fail
**** v1    vsl|       1027 BackendClose    b 21 s1 close Backend/VCL requested close
**** v1    vsl|       1027 BereqAcct       b 110 0 110 38 0 38
**** v1    vsl|       1027 End             b 
**** v1    vsl|       1026 Begin           c req 1025 rxreq
**** v1    vsl|       1026 Timestamp       c Start: 1649411466.521039 0.000000 0.000000
**** v1    vsl|       1026 Timestamp       c Req: 1649411466.521039 0.000000 0.000000
**** v1    vsl|       1026 VCL_use         c vcl1
**** v1    vsl|       1026 ReqStart        c 127.0.0.1 55515 a0
**** v1    vsl|       1026 ReqMethod       c GET
**** v1    vsl|       1026 ReqURL          c response
**** v1    vsl|       1026 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1026 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1026 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1026 VCL_call        c RECV
**** v1    vsl|       1026 VCL_return      c hash
**** v1    vsl|       1026 VCL_call        c HASH
**** v1    vsl|       1026 VCL_return      c lookup
**** v1    vsl|       1026 VCL_call        c MISS
**** v1    vsl|       1026 VCL_return      c fetch
**** v1    vsl|       1026 Link            c bereq 1027 fetch
**** v1    vsl|       1026 Timestamp       c Fetch: 1649411466.526964 0.005924 0.005924
**** v1    vsl|       1026 RespProtocol    c HTTP/1.1
**** v1    vsl|       1026 RespStatus      c 503
**** v1    vsl|       1026 RespReason      c Service Unavailable
**** v1    vsl|       1026 RespHeader      c Date: Fri, 08 Apr 2022 09:51:06 GMT
**** v1    vsl|       1026 RespHeader      c Server: Varnish
**** v1    vsl|       1026 RespHeader      c X-Varnish: 1026
**** v1    vsl|       1026 VCL_call        c SYNTH
**** v1    vsl|       1026 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1026 RespHeader      c Retry-After: 5
**** v1    vsl|       1026 VCL_return      c deliver
**** v1    vsl|       1026 Timestamp       c Process: 1649411466.527347 0.006307 0.000382
**** v1    vsl|       1026 RespHeader      c Content-Length: 278
**** v1    vsl|       1026 Storage         c malloc Transient
**** v1    vsl|       1026 Filters         c 
**** v1    vsl|       1026 RespHeader      c Connection: keep-alive
**** v1    vsl|       1026 Timestamp       c Resp: 1649411466.528114 0.007075 0.000767
**** v1    vsl|       1026 ReqAcct         c 42 0 42 208 278 486
**** v1    vsl|       1026 End             c 
**** dT    29.556
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411467 1.0
**** dT    30.177
**** v1    vsl|       1025 SessClose       c RX_CLOSE_IDLE 2.048
**** v1    vsl|       1025 End             c 
**** dT    30.174
**** c1    fd=31 EOF, as expected
**** dT    30.190
***  c1    closing fd 31
**** dT    30.191
**   c1    Ending
**** dT    30.192
**   top   === logexpect l1 -wait
**   l1    Waiting for logexp
**** dT    32.566
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411470 1.0
**** dT    35.587
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411473 1.0
**** dT    38.605
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411476 1.0
**** dT    41.588
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411479 1.0
**** dT    44.612
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411482 1.0
**** dT    47.666
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411485 1.0
**** dT    50.577
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411488 1.0
**** dT    53.603
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411491 1.0
**** dT    56.636
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411494 1.0
**** dT    59.668
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1649411497 1.0
#    top  TEST ../../../../bin/varnishtest/tests/r02339.vtc TIMED OUT (kill -9)
#    top  TEST ../../../../bin/varnishtest/tests/r02339.vtc FAILED (60.017) signal=9
FAIL tests/r02339.vtc (exit status: 2)