**** dT 0.000
* top TEST ../../../../bin/varnishtest/tests/s00002.vtc starting
**** top extmacro def pwd=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest
**** top extmacro def date(...)
**** top extmacro def string(...)
**** top extmacro def localhost=127.0.0.1
**** top extmacro def bad_backend=127.0.0.1:41523
**** top extmacro def listen_addr=127.0.0.1:0
**** top extmacro def bad_ip=192.0.2.255
**** top extmacro def topbuild=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub
**** top macro def testdir=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests
**** top macro def tmpdir=/home/linux1/VT/_vtest_tmp/vtc.735142.151db195
** top === varnishtest "Check grace with sick backends"
* top VTEST Check grace with sick backends
** top === barrier b1 cond 2
** top === barrier b2 cond 2
** top === server s1 {
** s1 Starting server
**** s1 macro def s1_addr=127.0.0.1
**** s1 macro def s1_port=36317
**** s1 macro def s1_sock=127.0.0.1:36317
* s1 Listen on 127.0.0.1:36317
** top === varnish v1 -vcl {
** s1 Started on 127.0.0.1:36317 (1 iterations)
**** dT 0.014
** v1 Launch
*** v1 CMD: cd ${pwd} && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.735142.151db195/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 35083' -P /home/linux1/VT/_vtest_tmp/vtc.735142.151db195/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs
*** v1 CMD: cd /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.735142.151db195/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 35083' -P /home/linux1/VT/_vtest_tmp/vtc.735142.151db195/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs
**** dT 0.015
*** v1 PID: 735206
**** v1 macro def v1_pid=735206
**** v1 macro def v1_name=/home/linux1/VT/_vtest_tmp/vtc.735142.151db195/v1
**** dT 0.037
*** v1 debug|Debug: Version: varnish-trunk revision fc506dbf3b7e9d27bcca46ac2820a93090379e07
*** v1 debug|Debug: Platform: Linux,4.18.0-348.20.1.el8_5.s390x,s390x,-junix,-sdefault,-sdefault,-hcritbit
*** v1 debug|200 327
*** v1 debug|-----------------------------
*** v1 debug|Varnish Cache CLI 1.0
*** v1 debug|-----------------------------
*** v1 debug|Linux,4.18.0-348.20.1.el8_5.s390x,s390x,-junix,-sdefault,-sdefault,-hcritbit
*** v1 debug|varnish-trunk revision 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.135
**** v1 CLIPOLL 1 0x1 0x0 0x0
*** v1 CLI connection fd = 7
*** v1 CLI RX 107
**** v1 CLI RX|zjfqekchfprkzouvxomxrttnozdppzds
**** v1 CLI RX|
**** v1 CLI RX|Authentication required.
**** v1 CLI TX|auth 643c80060282f89d6c0339caaceb3ff821cf3d7346c585901c5fee12659e6d73
*** v1 CLI RX 200
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Varnish Cache CLI 1.0
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Linux,4.18.0-348.20.1.el8_5.s390x,s390x,-junix,-sdefault,-sdefault,-hcritbit
**** v1 CLI RX|varnish-trunk revision 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.
**** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1 CLI TX|vcl 4.1;
**** v1 CLI TX|
**** v1 CLI TX|\tbackend b {
**** v1 CLI TX|\t\t.host = "127.0.0.1";
**** v1 CLI TX|\t\t.port = "36317";
**** v1 CLI TX|\t\t.probe = {
**** v1 CLI TX|\t\t\t.url = "/";
**** v1 CLI TX|\t\t\t.timeout = 30ms;
**** v1 CLI TX|\t\t\t.interval = 1s;
**** v1 CLI TX|\t\t\t.window = 2;
**** v1 CLI TX|\t\t\t.threshold = 1;
**** v1 CLI TX|\t\t\t.initial = 0;
**** v1 CLI TX|\t\t}
**** v1 CLI TX|\t}
**** v1 CLI TX|\tsub vcl_backend_response {
**** v1 CLI TX|\t\tset beresp.ttl = 1s;
**** v1 CLI TX|\t\tset beresp.grace = 1m;
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|%XJEIFLH|)Xspa8P
**** dT 0.237
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.463
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.563
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.663
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.765
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.867
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.969
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.072
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.176
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.279
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.382
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.482
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.582
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.685
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.788
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.889
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.989
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.051
*** v1 CLI RX 200
**** v1 CLI RX|VCL compiled.
**** v1 CLI TX|vcl.use vcl1
**** dT 2.055
*** v1 CLI RX 200
**** v1 CLI RX|VCL 'vcl1' now active
** v1 Start
**** v1 CLI TX|start
**** dT 2.094
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.197
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.417
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.483
*** v1 CLI RX 200
*** v1 wait-running
**** v1 CLI TX|status
**** dT 2.487
*** v1 CLI RX 200
**** v1 CLI RX|Child in state running
**** v1 CLI TX|debug.listen_address
**** dT 2.517
**** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1649273026.912693/vgc.so 1auto
**** v1 vsl| 0 Backend_health - b Went sick -------- 0 1 2 0.000000 0.000000 ""
**** v1 vsl| 0 Backend_health - b Still sick -------- 0 1 2 0.000000 0.000000 ""
**** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1649273026.912693/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:35321
**** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:35321
**** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:35321
**** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:35321
**** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:35321
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:35321
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:35321
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:35321
**** v1 vsl| 0 CLI - Wr 200 0
**** v1 vsl| 0 Backend_health - b Still sick 4---Xr-- 0 1 2 0.000000 0.000000 "Poll error 110 (Connection timed out)"
**** dT 2.547
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 35321
**** v1 CLI TX|debug.xid 999
**** dT 2.611
*** v1 CLI RX 200
**** v1 CLI RX|XID is 999 chunk 1
**** v1 CLI TX|debug.listen_address
**** dT 2.622
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 35321
**** v1 vsl| 0 CLI - Rd debug.xid 999
**** v1 vsl| 0 CLI - Wr 200 18 XID is 999 chunk 1
**** dT 2.666
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 35321
** v1 Listen on 127.0.0.1 35321
**** v1 macro def v1_addr=127.0.0.1
**** v1 macro def v1_port=35321
**** v1 macro def v1_sock=127.0.0.1:35321
**** v1 macro def v1_a0_addr=127.0.0.1
**** v1 macro def v1_a0_port=35321
**** v1 macro def v1_a0_sock=127.0.0.1:35321
** top === barrier b1 sync
**** top Barrier(b1) wait 1 of 2
**** dT 2.723
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 35321
**** dT 2.769
*** s1 accepted fd 5 127.0.0.1 59098
** s1 === rxreq
**** s1 rxhdr|GET / HTTP/1.1\r
**** s1 rxhdr|Host: 127.0.0.1\r
**** s1 rxhdr|Connection: close\r
**** s1 rxhdr|\r
**** s1 rxhdrlen = 54
**** s1 http[ 0] |GET
**** s1 http[ 1] |/
**** s1 http[ 2] |HTTP/1.1
**** s1 http[ 3] |Host: 127.0.0.1
**** s1 http[ 4] |Connection: close
**** s1 bodylen = 0
** s1 === expect req.url == "/"
**** s1 EXPECT req.url (/) == "/" match
** s1 === txresp -proto HTTP/1.0 -hdr "nbr: 1" -body "hi"
**** s1 txresp|HTTP/1.0 200 OK\r
**** s1 txresp|nbr: 1\r
**** s1 txresp|Content-Length: 2\r
**** s1 txresp|\r
**** s1 txresp|hi
** s1 === accept
**** dT 2.770
**** s1 Accepting
*** v1 debug|Debug: Child (735528) Started
*** v1 debug|Child launched OK
*** v1 debug|Info: Child (735528) said Child starts
**** dT 3.504
*** s1 Accepted socket fd is 5
** s1 === rxreq
**** s1 rxhdr|GET / HTTP/1.1\r
**** s1 rxhdr|Host: 127.0.0.1\r
**** s1 rxhdr|Connection: close\r
**** s1 rxhdr|\r
**** s1 rxhdrlen = 54
**** s1 http[ 0] |GET
**** s1 http[ 1] |/
**** s1 http[ 2] |HTTP/1.1
**** s1 http[ 3] |Host: 127.0.0.1
**** s1 http[ 4] |Connection: close
**** s1 bodylen = 0
** s1 === expect req.url == "/"
**** s1 EXPECT req.url (/) == "/" match
** s1 === txresp -proto HTTP/1.0 -hdr "nbr: 2" -body "hi"
**** s1 txresp|HTTP/1.0 200 OK\r
**** s1 txresp|nbr: 2\r
**** s1 txresp|Content-Length: 2\r
**** s1 txresp|\r
**** s1 txresp|hi
** s1 === barrier b1 sync
**** s1 Barrier(b1) wake 2
** s1 === accept
**** s1 Accepting
**** dT 3.507
** top === client c1 {
** c1 Starting client
** c1 Waiting for client
** c1 Started on 127.0.0.1:35321 (1 iterations)
*** c1 Connect to 127.0.0.1:35321
**** dT 3.508
*** c1 connected fd 17 from 127.0.0.1 40530 to 127.0.0.1:35321
** c1 === txreq -url "/"
**** c1 txreq|GET / HTTP/1.1\r
**** c1 txreq|Host: 127.0.0.1\r
**** c1 txreq|\r
** c1 === rxresp
**** dT 3.532
**** c1 rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c1 rxhdr|Date: Wed, 06 Apr 2022 19:23:50 GMT\r
**** c1 rxhdr|Server: Varnish\r
**** c1 rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1 rxhdr|Retry-After: 5\r
**** c1 rxhdr|X-Varnish: 1001\r
**** c1 rxhdr|Age: 0\r
**** c1 rxhdr|Via: 1.1 varnish (Varnish/7.1)\r
**** c1 rxhdr|Content-Length: 281\r
**** c1 rxhdr|Connection: keep-alive\r
**** c1 rxhdr|\r
**** c1 rxhdrlen = 249
**** c1 http[ 0] |HTTP/1.1
**** c1 http[ 1] |503
**** c1 http[ 2] |Backend fetch failed
**** c1 http[ 3] |Date: Wed, 06 Apr 2022 19:23:50 GMT
**** c1 http[ 4] |Server: Varnish
**** c1 http[ 5] |Content-Type: text/html; charset=utf-8
**** c1 http[ 6] |Retry-After: 5
**** c1 http[ 7] |X-Varnish: 1001
**** c1 http[ 8] |Age: 0
**** c1 http[ 9] |Via: 1.1 varnish (Varnish/7.1)
**** c1 http[10] |Content-Length: 281
**** c1 http[11] |Connection: keep-alive
**** c1 c-l|
**** c1 c-l|
**** c1 c-l|
**** c1 c-l| 503 Backend fetch failed
**** c1 c-l|
**** c1 c-l|
**** c1 c-l| Error 503 Backend fetch failed
**** c1 c-l| Backend fetch failed
**** c1 c-l| Guru Meditation:
**** c1 c-l| XID: 1002
**** c1 c-l|
**** c1 c-l| Varnish cache server
**** c1 c-l|
**** c1 c-l|
**** c1 bodylen = 281
** c1 === expect resp.http.foo == "bar"
---- c1 EXPECT resp.http.foo () == "bar" failed
* top RESETTING after ../../../../bin/varnishtest/tests/s00002.vtc
** s1 Waiting for server (4/-1)
**** dT 3.537
** v1 Wait
**** v1 CLI TX|panic.show
**** dT 3.540
**** v1 vsl| 1000 Begin c sess 0 HTTP/1
**** v1 vsl| 1000 SessOpen c 127.0.0.1 40530 a0 127.0.0.1 35321 1649273030.288523 25
**** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:35321
**** v1 vsl| 1000 Debug c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:35321
**** v1 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:35321
**** v1 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:35321
**** v1 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:35321
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:35321
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:35321
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:35321
**** v1 vsl| 1000 Link c req 1001 rxreq
**** v1 vsl| 1002 Begin b bereq 1001 fetch
**** v1 vsl| 1002 VCL_use b vcl1
**** v1 vsl| 1002 Timestamp b Start: 1649273030.289856 0.000000 0.000000
**** v1 vsl| 1002 BereqMethod b GET
**** v1 vsl| 1002 BereqURL b /
**** 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: 1649273030.289875 0.000018 0.000018
**** v1 vsl| 1002 FetchError b backend b: unhealthy
**** v1 vsl| 1002 Timestamp b Beresp: 1649273030.289881 0.000025 0.000006
**** v1 vsl| 1002 Timestamp b Error: 1649273030.289883 0.000026 0.000001
**** v1 vsl| 1002 BerespProtocol b HTTP/1.1
**** v1 vsl| 1002 BerespStatus b 503
**** v1 vsl| 1002 BerespReason b Backend fetch failed
**** v1 vsl| 1002 BerespHeader b Date: Wed, 06 Apr 2022 19:23:50 GMT
**** v1 vsl| 1002 BerespHeader b Server: Varnish
**** v1 vsl| 1002 VCL_call b BACKEND_ERROR
**** v1 vsl| 1002 BerespHeader b Content-Type: text/html; charset=utf-8
**** v1 vsl| 1002 BerespHeader b Retry-After: 5
**** v1 vsl| 1002 VCL_return b deliver
**** v1 vsl| 1002 Storage b malloc Transient
**** v1 vsl| 1002 Length b 281
**** v1 vsl| 1002 BereqAcct b 0 0 0 0 0 0
**** v1 vsl| 1002 End b
**** v1 vsl| 1001 Begin c req 1000 rxreq
**** v1 vsl| 1001 Timestamp c Start: 1649273030.288569 0.000000 0.000000
**** v1 vsl| 1001 Timestamp c Req: 1649273030.288569 0.000000 0.000000
**** v1 vsl| 1001 VCL_use c vcl1
**** v1 vsl| 1001 ReqStart c 127.0.0.1 40530 a0
**** v1 vsl| 1001 ReqMethod c GET
**** v1 vsl| 1001 ReqURL c /
**** v1 vsl| 1001 ReqProtocol c HTTP/1.1
**** v1 vsl| 1001 ReqHeader c Host: 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: 1649273030.289976 0.001406 0.001406
**** v1 vsl| 1001 RespProtocol c HTTP/1.1
**** v1 vsl| 1001 RespStatus c 503
**** v1 vsl| 1001 RespReason c Backend fetch failed
**** v1 vsl| 1001 RespHeader c Date: Wed, 06 Apr 2022 19:23:50 GMT
**** v1 vsl| 1001 RespHeader c Server: Varnish
**** v1 vsl| 1001 RespHeader c Content-Type: text/html; charset=utf-8
**** v1 vsl| 1001 RespHeader c Retry-After: 5
**** 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 VCL_call c DELIVER
**** v1 vsl| 1001 VCL_return c deliver
**** v1 vsl| 1001 Timestamp c Process: 1649273030.290002 0.001433 0.000026
**** v1 vsl| 1001 Filters c
**** v1 vsl| 1001 RespHeader c Content-Length: 281
**** v1 vsl| 1001 RespHeader c Connection: keep-alive
**** v1 vsl| 1001 Timestamp c Resp: 1649273030.290031 0.001462 0.000029
**** v1 vsl| 1001 ReqAcct c 35 0 35 249 281 530
**** v1 vsl| 1001 End c
**** v1 vsl| 0 Backend_health - b Went healthy 4---X-RH 1 1 2 0.018077 0.018077 "HTTP/1.0 200 OK"
**** dT 3.791
*** v1 CLI RX 300
**** v1 CLI RX|Child has not panicked or panic has been cleared
**** dT 3.823
*** v1 debug|Info: manager stopping child
*** v1 debug|Debug: Stopping Child
**** dT 3.843
**** v1 vsl| 0 CLI - EOF on CLI connection, worker stops
**** dT 3.903
*** v1 debug|Info: Child (735528) ended
*** v1 debug|Info: Child (735528) said Child dies
*** v1 debug|Debug: Child cleanup complete
*** v1 debug|Info: manager dies
**** v1 STDOUT EOF
**** dT 3.946
** v1 WAIT4 pid=735206 status=0x0000 (user 0.202908 sys 0.029098)
* top TEST ../../../../bin/varnishtest/tests/s00002.vtc FAILED
# top TEST ../../../../bin/varnishtest/tests/s00002.vtc FAILED (3.946) exit=2
FAIL tests/s00002.vtc (exit status: 2)