Last active
November 15, 2021 12:42
-
-
Save nigoroll/bc22ee1cfb2f8c24492a2e6d5e640905 to your computer and use it in GitHub Desktop.
SunOS r02722.vtc as of 27d680d57e1f736cc46e03bb8eb106f1d11b400e
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
**** dT 0.000 | |
* top TEST tests/r02722.vtc starting | |
**** top extmacro def pwd=/tmp/dridi/varnish-cache/bin/varnishtest | |
**** top extmacro def date(...) | |
**** top extmacro def string(...) | |
**** top extmacro def localhost=fc00:a462:8e9e:946a:5df3:31c6:d23:18dc | |
**** top extmacro def bad_backend=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:34448 | |
**** top extmacro def listen_addr=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:0 | |
**** top extmacro def bad_ip=192.0.2.255 | |
**** top extmacro def topbuild=/tmp/dridi/varnish-cache | |
**** top macro def testdir=/tmp/dridi/varnish-cache/bin/varnishtest/tests | |
**** top macro def tmpdir=/tmp/vtc.932503.476d6ce4 | |
** top === varnishtest "TCP vs UDS sockopt inheritance" | |
* top VTEST TCP vs UDS sockopt inheritance | |
** top === server s0 { | |
**** s0 macro def s0_addr=fc00:a462:8e9e:946a:5df3:31c6:d23:18dc | |
**** s0 macro def s0_port=60455 | |
**** s0 macro def s0_sock=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:60455 | |
** s0 Starting dispatch server | |
**** dT 0.001 | |
** top === varnish v1 -arg {-a TCP=:0 -a "UDS=${tmpdir}/v1.sock"} | |
** s0 Dispatch started on [fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:60455 | |
**** dT 0.009 | |
** top === varnish v1 -cliok "param.set debug +flush_head" | |
** v1 Launch | |
*** v1 CMD: cd ${pwd} && exec varnishd -d -n /tmp/vtc.932503.476d6ce4/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 -M 'fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 41845' -P /tmp/vtc.932503.476d6ce4/v1/varnishd.pid -p vmod_path=/tmp/dridi/varnish-cache/vmod/.libs -a TCP=:0 -a "UDS=/tmp/vtc.932503.476d6ce4/v1.sock" | |
*** v1 CMD: cd /tmp/dridi/varnish-cache/bin/varnishtest && exec varnishd -d -n /tmp/vtc.932503.476d6ce4/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 -M 'fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 41845' -P /tmp/vtc.932503.476d6ce4/v1/varnishd.pid -p vmod_path=/tmp/dridi/varnish-cache/vmod/.libs -a TCP=:0 -a "UDS=/tmp/vtc.932503.476d6ce4/v1.sock" | |
**** dT 0.010 | |
*** v1 PID: 932541 | |
**** v1 macro def v1_pid=932541 | |
**** v1 macro def v1_name=/tmp/vtc.932503.476d6ce4/v1 | |
**** dT 0.041 | |
*** v1 debug|Debug: Version: varnish-trunk revision 27d680d57e1f736cc46e03bb8eb106f1d11b400e | |
*** v1 debug|Debug: Platform: -jsolaris,-sdefault,-sdefault,-hcritbit | |
*** v1 debug|200 290 | |
*** v1 debug|----------------------------- | |
*** v1 debug|Varnish Cache CLI 1.0 | |
*** v1 debug|----------------------------- | |
*** v1 debug|-jsolaris,-sdefault,-sdefault,-hcritbit | |
*** v1 debug|varnish-trunk revision 27d680d57e1f736cc46e03bb8eb106f1d11b400e | |
*** 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.140 | |
**** v1 CLIPOLL 1 0x1 0x0 0x0 | |
*** v1 CLI connection fd = 6 | |
*** v1 CLI RX 107 | |
**** v1 CLI RX|uualklynlxzvgvgnpvryczuryiivsqyf | |
**** v1 CLI RX| | |
**** v1 CLI RX|Authentication required. | |
**** v1 CLI TX|auth b06bd540c57ecd67bd3da838c69b80276649e02f98ae75f784c6459620727b3c | |
*** v1 CLI RX 200 | |
**** v1 CLI RX|----------------------------- | |
**** v1 CLI RX|Varnish Cache CLI 1.0 | |
**** v1 CLI RX|----------------------------- | |
**** v1 CLI RX|-jsolaris,-sdefault,-sdefault,-hcritbit | |
**** v1 CLI RX|varnish-trunk revision 27d680d57e1f736cc46e03bb8eb106f1d11b400e | |
**** 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.141 | |
**** v1 CLI TX|param.set debug +flush_head | |
*** v1 CLI RX 200 | |
** v1 CLI 200 <param.set debug +flush_head> | |
** top === varnish v1 -cliok "param.set timeout_idle 1" | |
**** v1 CLI TX|param.set timeout_idle 1 | |
*** v1 CLI RX 200 | |
** v1 CLI 200 <param.set timeout_idle 1> | |
** top === varnish v1 -vcl+backend { } -start | |
**** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P | |
**** v1 CLI TX|vcl 4.1; | |
**** v1 CLI TX|backend s0 { .host = "fc00:a462:8e9e:946a:5df3:31c6:d23:18dc"; .port = "60455"; } | |
**** v1 CLI TX| | |
**** v1 CLI TX| | |
**** v1 CLI TX|%XJEIFLH|)Xspa8P | |
**** dT 0.241 | |
*** v1 vsl|No VSL chunk found (child not started ?) | |
**** dT 0.341 | |
*** v1 vsl|No VSL chunk found (child not started ?) | |
**** dT 0.441 | |
*** v1 vsl|No VSL chunk found (child not started ?) | |
**** dT 0.476 | |
*** v1 CLI RX 200 | |
**** v1 CLI RX|Message from VCC-compiler: | |
**** v1 CLI RX|Security: Privilege proc_setid missing, will not change uid/gid | |
**** v1 CLI RX|Message from C-compiler: | |
**** v1 CLI RX|Security: Privilege proc_setid missing, will not change uid/gid | |
**** v1 CLI RX|Message from dlopen: | |
**** v1 CLI RX|Security: Privilege proc_setid missing, will not change uid/gid | |
**** v1 CLI RX|VCL compiled. | |
**** v1 CLI TX|vcl.use vcl1 | |
*** v1 CLI RX 200 | |
** v1 Start | |
**** v1 CLI TX|start | |
**** dT 0.484 | |
*** v1 debug|Debug: Child (932645) Started | |
**** dT 0.516 | |
*** v1 CLI RX 200 | |
*** v1 wait-running | |
**** v1 CLI TX|status | |
*** v1 debug|Info: Child (932645) said Security: Privilege proc_setid missing, will not change uid/gid | |
*** v1 debug|Info: Child (932645) said Child starts | |
*** v1 CLI RX 200 | |
**** v1 CLI RX|Child in state running | |
**** v1 CLI TX|debug.listen_address | |
*** v1 CLI RX 200 | |
**** v1 CLI RX|TCP :: 63005 | |
**** v1 CLI RX|TCP 0.0.0.0 40697 | |
**** v1 CLI RX|UDS /tmp/vtc.932503.476d6ce4/v1.sock - | |
**** v1 CLI TX|debug.xid 999 | |
*** v1 CLI RX 200 | |
**** v1 CLI RX|XID is 999 | |
**** v1 CLI TX|debug.listen_address | |
*** v1 CLI RX 200 | |
**** v1 CLI RX|TCP :: 63005 | |
**** v1 CLI RX|TCP 0.0.0.0 40697 | |
**** v1 CLI RX|UDS /tmp/vtc.932503.476d6ce4/v1.sock - | |
** v1 Listen on :: 63005 | |
**** v1 macro def v1_addr=:: | |
**** v1 macro def v1_port=63005 | |
**** v1 macro def v1_sock=[::]:63005 | |
**** v1 macro def v1_TCP_addr=:: | |
**** v1 macro def v1_TCP_port=63005 | |
**** v1 macro def v1_TCP_sock=[::]:63005 | |
**** v1 macro def v1_UDS_addr=0.0.0.0 | |
**** v1 macro def v1_UDS_port=0 | |
**** v1 macro def v1_UDS_sock=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** dT 0.541 | |
**** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1636979873.656174/vgc.so 1auto | |
**** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1636979873.656174/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 TCP=:::63005 | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for TCP=:::63005 | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for TCP=:::63005 | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for TCP=:::63005 | |
**** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for TCP=:::63005 | |
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for TCP=:::63005 | |
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for TCP=:::63005 | |
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for TCP=:::63005 | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for TCP=0.0.0.0:40697 | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for TCP=0.0.0.0:40697 | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for TCP=0.0.0.0:40697 | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for TCP=0.0.0.0:40697 | |
**** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for TCP=0.0.0.0:40697 | |
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for TCP=0.0.0.0:40697 | |
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for TCP=0.0.0.0:40697 | |
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for TCP=0.0.0.0:40697 | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 0 Debug - sockopt: Not setting incompatible TCP_NODELAY for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 0 Debug - sockopt: Not setting incompatible TCP_KEEPIDLE for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 0 Debug - sockopt: Not setting incompatible TCP_KEEPCNT for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 0 Debug - sockopt: Not setting incompatible TCP_KEEPINTVL for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 0 CLI - Wr 200 0 | |
**** v1 vsl| 0 CLI - Rd debug.listen_address | |
**** v1 vsl| 0 CLI - Wr 200 70 TCP :: 63005 | |
TCP 0.0.0.0 40697 | |
UDS /tmp/vtc.932503.476d6ce4/v1.sock - | |
**** v1 vsl| 0 CLI - Rd debug.xid 999 | |
**** v1 vsl| 0 CLI - Wr 200 10 XID is 999 | |
**** v1 vsl| 0 CLI - Rd debug.listen_address | |
**** v1 vsl| 0 CLI - Wr 200 70 TCP :: 63005 | |
TCP 0.0.0.0 40697 | |
UDS /tmp/vtc.932503.476d6ce4/v1.sock - | |
**** dT 0.616 | |
** top === client c1 { | |
** top === client c1 -run | |
** c1 Starting client | |
** c1 Waiting for client | |
** c1 Started on [::]:63005 (1 iterations) | |
*** c1 Connect to [::]:63005 | |
**** dT 0.617 | |
*** c1 connected fd 16 from ::1 64288 to [::]:63005 | |
** c1 === txreq -req POST -hdr "Content-Length: 100" | |
**** c1 txreq|POST / HTTP/1.1\r | |
**** c1 txreq|Content-Length: 100\r | |
**** c1 txreq|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r | |
**** c1 txreq|\r | |
** c1 === send some | |
**** c1 send|some | |
** c1 === rxresp | |
*** s0 dispatch fd 4 -> s1 | |
*** s1 start with fd 4 | |
** s1 === rxreqhdrs | |
**** dT 0.641 | |
**** v1 vsl| 1000 Begin c sess 0 HTTP/1 | |
**** v1 vsl| 1000 SessOpen c ::1 64288 TCP ::1 63005 1636979874.131996 19 | |
**** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for TCP=:::63005 | |
**** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for TCP=:::63005 | |
**** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for TCP=:::63005 | |
**** v1 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for TCP=:::63005 | |
**** v1 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for TCP=:::63005 | |
**** v1 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for TCP=:::63005 | |
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for TCP=:::63005 | |
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for TCP=:::63005 | |
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for TCP=:::63005 | |
**** v1 vsl| 1000 Link c req 1001 rxreq | |
**** dT 1.617 | |
**** s1 rxhdr|POST / HTTP/1.1\r | |
**** s1 rxhdr|Content-Length: 100\r | |
**** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r | |
**** s1 rxhdr|X-Forwarded-For: ::1\r | |
**** s1 rxhdr|X-Varnish: 1002\r | |
**** s1 rxhdr|\r | |
**** s1 rxhdrlen = 125 | |
**** s1 http[ 0] |POST | |
**** s1 http[ 1] |/ | |
**** s1 http[ 2] |HTTP/1.1 | |
**** s1 http[ 3] |Content-Length: 100 | |
**** s1 http[ 4] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc | |
**** s1 http[ 5] |X-Forwarded-For: ::1 | |
**** s1 http[ 6] |X-Varnish: 1002 | |
** s1 === non_fatal | |
** s1 === rxreqbody | |
**** s1 bodylen = <undef> | |
** s1 === txresp | |
**** s1 txresp|HTTP/1.1 200 OK\r | |
**** s1 txresp|Content-Length: 0\r | |
**** s1 txresp|\r | |
*** s1 shutting fd 4 | |
** s1 Ending | |
**** dT 1.618 | |
**** c1 rxhdr|HTTP/1.1 503 Backend fetch failed\r | |
**** c1 rxhdr|Date: Mon, 15 Nov 2021 12:37:55 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.0)\r | |
**** c1 rxhdr|Content-Length: 281\r | |
**** c1 rxhdr|Connection: close\r | |
**** c1 rxhdr|\r | |
**** c1 rxhdrlen = 244 | |
**** c1 http[ 0] |HTTP/1.1 | |
**** c1 http[ 1] |503 | |
**** c1 http[ 2] |Backend fetch failed | |
**** c1 http[ 3] |Date: Mon, 15 Nov 2021 12:37:55 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.0) | |
**** c1 http[10] |Content-Length: 281 | |
**** c1 http[11] |Connection: close | |
**** c1 c-l|<!DOCTYPE html> | |
**** c1 c-l|<html> | |
**** c1 c-l| <head> | |
**** c1 c-l| <title>503 Backend fetch failed</title> | |
**** c1 c-l| </head> | |
**** c1 c-l| <body> | |
**** c1 c-l| <h1>Error 503 Backend fetch failed</h1> | |
**** c1 c-l| <p>Backend fetch failed</p> | |
**** c1 c-l| <h3>Guru Meditation:</h3> | |
**** c1 c-l| <p>XID: 1002</p> | |
**** c1 c-l| <hr> | |
**** c1 c-l| <p>Varnish cache server</p> | |
**** c1 c-l| </body> | |
**** c1 c-l|</html> | |
**** c1 bodylen = 281 | |
** c1 === expect resp.status == 503 | |
**** c1 EXPECT resp.status (503) == "503" match | |
*** c1 closing fd 16 | |
** c1 Ending | |
** top === client c1 -run | |
** c1 Starting client | |
** c1 Waiting for client | |
** c1 Started on [::]:63005 (1 iterations) | |
*** c1 Connect to [::]:63005 | |
*** c1 connected fd 4 from ::1 34819 to [::]:63005 | |
** c1 === txreq -req POST -hdr "Content-Length: 100" | |
**** c1 txreq|POST / HTTP/1.1\r | |
**** c1 txreq|Content-Length: 100\r | |
**** c1 txreq|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r | |
**** c1 txreq|\r | |
** c1 === send some | |
**** c1 send|some | |
** c1 === rxresp | |
*** s0 dispatch fd 17 -> s2 | |
*** s2 start with fd 17 | |
** s2 === rxreqhdrs | |
**** dT 1.642 | |
**** v1 vsl| 1002 Begin b bereq 1001 pass | |
**** v1 vsl| 1002 VCL_use b vcl1 | |
**** v1 vsl| 1002 Timestamp b Start: 1636979874.132499 0.000000 0.000000 | |
**** v1 vsl| 1002 BereqMethod b POST | |
**** v1 vsl| 1002 BereqURL b / | |
**** v1 vsl| 1002 BereqProtocol b HTTP/1.1 | |
**** v1 vsl| 1002 BereqHeader b Content-Length: 100 | |
**** v1 vsl| 1002 BereqHeader b Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc | |
**** v1 vsl| 1002 BereqHeader b X-Forwarded-For: ::1 | |
**** 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: 1636979874.132545 0.000046 0.000046 | |
**** v1 vsl| 1002 Timestamp b Connected: 1636979874.132615 0.000116 0.000070 | |
**** v1 vsl| 1002 BackendOpen b 27 s0 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 60455 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 56245 connect | |
**** v1 vsl| 1002 FetchError b req.body read error: 11 (Resource temporarily unavailable) | |
**** v1 vsl| 1002 FetchError b backend write error: 11 (Resource temporarily unavailable) | |
**** v1 vsl| 1002 Timestamp b Bereq: 1636979875.132430 0.999931 0.999815 | |
**** v1 vsl| 1002 BackendClose b 27 s0 close | |
**** v1 vsl| 1002 Timestamp b Beresp: 1636979875.132461 0.999962 0.000030 | |
**** v1 vsl| 1002 Timestamp b Error: 1636979875.132468 0.999969 0.000006 | |
**** 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: Mon, 15 Nov 2021 12:37:55 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 umem Transient | |
**** v1 vsl| 1002 Length b 281 | |
**** v1 vsl| 1002 BereqAcct b 125 0 125 0 0 0 | |
**** v1 vsl| 1002 End b | |
**** v1 vsl| 1001 Begin c req 1000 rxreq | |
**** v1 vsl| 1001 Timestamp c Start: 1636979874.132227 0.000000 0.000000 | |
**** v1 vsl| 1001 Timestamp c Req: 1636979874.132227 0.000000 0.000000 | |
**** v1 vsl| 1001 VCL_use c vcl1 | |
**** v1 vsl| 1001 ReqStart c ::1 64288 TCP | |
**** v1 vsl| 1001 ReqMethod c POST | |
**** v1 vsl| 1001 ReqURL c / | |
**** v1 vsl| 1001 ReqProtocol c HTTP/1.1 | |
**** v1 vsl| 1001 ReqHeader c Content-Length: 100 | |
**** v1 vsl| 1001 ReqHeader c Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc | |
**** v1 vsl| 1001 ReqHeader c X-Forwarded-For: ::1 | |
**** v1 vsl| 1001 VCL_call c RECV | |
**** v1 vsl| 1001 VCL_return c pass | |
**** v1 vsl| 1001 VCL_call c HASH | |
**** v1 vsl| 1001 VCL_return c lookup | |
**** v1 vsl| 1001 VCL_call c PASS | |
**** v1 vsl| 1001 VCL_return c fetch | |
**** v1 vsl| 1001 Link c bereq 1002 pass | |
**** v1 vsl| 1001 Storage c umem Transient | |
**** v1 vsl| 1001 FetchError c Resource temporarily unavailable | |
**** v1 vsl| 1001 FetchError c straight insufficient bytes | |
**** v1 vsl| 1001 Timestamp c ReqBody: 1636979875.132351 1.000123 1.000123 | |
**** v1 vsl| 1001 Timestamp c Fetch: 1636979875.132578 1.000351 0.000227 | |
**** 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: Mon, 15 Nov 2021 12:37:55 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.0) | |
**** v1 vsl| 1001 VCL_call c DELIVER | |
**** v1 vsl| 1001 VCL_return c deliver | |
**** v1 vsl| 1001 Timestamp c Process: 1636979875.132630 1.000403 0.000051 | |
**** v1 vsl| 1001 Filters c | |
**** v1 vsl| 1001 RespHeader c Content-Length: 281 | |
**** v1 vsl| 1001 RespHeader c Connection: close | |
**** v1 vsl| 1001 Timestamp c Resp: 1636979875.132692 1.000465 0.000062 | |
**** v1 vsl| 1001 ReqAcct c 86 0 86 244 281 525 | |
**** v1 vsl| 1001 End c | |
**** v1 vsl| 1000 SessClose c RX_BODY 1.001 | |
**** v1 vsl| 1000 End c | |
**** v1 vsl| 1003 Begin c sess 0 HTTP/1 | |
**** v1 vsl| 1003 SessOpen c ::1 34819 TCP ::1 63005 1636979875.133392 23 | |
**** v1 vsl| 1003 Debug c sockopt: SO_LINGER may be inherited for TCP=:::63005 | |
**** v1 vsl| 1003 Debug c sockopt: Setting SO_KEEPALIVE for TCP=:::63005 | |
**** v1 vsl| 1003 Debug c sockopt: SO_SNDTIMEO may be inherited for TCP=:::63005 | |
**** v1 vsl| 1003 Debug c sockopt: SO_RCVTIMEO may be inherited for TCP=:::63005 | |
**** v1 vsl| 1003 Debug c sockopt: TCP_NODELAY may be inherited for TCP=:::63005 | |
**** v1 vsl| 1003 Debug c sockopt: TCP_KEEPIDLE may be inherited for TCP=:::63005 | |
**** v1 vsl| 1003 Debug c sockopt: TCP_KEEPCNT may be inherited for TCP=:::63005 | |
**** v1 vsl| 1003 Debug c sockopt: TCP_KEEPINTVL may be inherited for TCP=:::63005 | |
**** v1 vsl| 1003 Link c req 1004 rxreq | |
**** dT 2.618 | |
**** s2 rxhdr|POST / HTTP/1.1\r | |
**** s2 rxhdr|Content-Length: 100\r | |
**** s2 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r | |
**** s2 rxhdr|X-Forwarded-For: ::1\r | |
**** s2 rxhdr|X-Varnish: 1005\r | |
**** s2 rxhdr|\r | |
**** s2 rxhdrlen = 125 | |
**** s2 http[ 0] |POST | |
**** s2 http[ 1] |/ | |
**** s2 http[ 2] |HTTP/1.1 | |
**** s2 http[ 3] |Content-Length: 100 | |
**** s2 http[ 4] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc | |
**** s2 http[ 5] |X-Forwarded-For: ::1 | |
**** s2 http[ 6] |X-Varnish: 1005 | |
** s2 === non_fatal | |
** s2 === rxreqbody | |
**** s2 bodylen = <undef> | |
** s2 === txresp | |
**** s2 txresp|HTTP/1.1 200 OK\r | |
**** s2 txresp|Content-Length: 0\r | |
**** s2 txresp|\r | |
*** s2 shutting fd 17 | |
** s2 Ending | |
**** c1 rxhdr|HTTP/1.1 503 Backend fetch failed\r | |
**** c1 rxhdr|Date: Mon, 15 Nov 2021 12:37:56 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: 1004\r | |
**** c1 rxhdr|Age: 0\r | |
**** c1 rxhdr|Via: 1.1 varnish (Varnish/7.0)\r | |
**** c1 rxhdr|Content-Length: 281\r | |
**** c1 rxhdr|Connection: close\r | |
**** c1 rxhdr|\r | |
**** c1 rxhdrlen = 244 | |
**** c1 http[ 0] |HTTP/1.1 | |
**** c1 http[ 1] |503 | |
**** c1 http[ 2] |Backend fetch failed | |
**** c1 http[ 3] |Date: Mon, 15 Nov 2021 12:37:56 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: 1004 | |
**** c1 http[ 8] |Age: 0 | |
**** c1 http[ 9] |Via: 1.1 varnish (Varnish/7.0) | |
**** c1 http[10] |Content-Length: 281 | |
**** c1 http[11] |Connection: close | |
**** dT 2.619 | |
**** c1 c-l|<!DOCTYPE html> | |
**** c1 c-l|<html> | |
**** c1 c-l| <head> | |
**** c1 c-l| <title>503 Backend fetch failed</title> | |
**** c1 c-l| </head> | |
**** c1 c-l| <body> | |
**** c1 c-l| <h1>Error 503 Backend fetch failed</h1> | |
**** c1 c-l| <p>Backend fetch failed</p> | |
**** c1 c-l| <h3>Guru Meditation:</h3> | |
**** c1 c-l| <p>XID: 1005</p> | |
**** c1 c-l| <hr> | |
**** c1 c-l| <p>Varnish cache server</p> | |
**** c1 c-l| </body> | |
**** c1 c-l|</html> | |
**** c1 bodylen = 281 | |
** c1 === expect resp.status == 503 | |
**** c1 EXPECT resp.status (503) == "503" match | |
*** c1 closing fd 4 | |
** c1 Ending | |
** top === varnish v1 -vsl_catchup | |
**** dT 2.642 | |
**** v1 vsl| 1005 Begin b bereq 1004 pass | |
**** v1 vsl| 1005 VCL_use b vcl1 | |
**** v1 vsl| 1005 Timestamp b Start: 1636979875.133525 0.000000 0.000000 | |
**** v1 vsl| 1005 BereqMethod b POST | |
**** v1 vsl| 1005 BereqURL b / | |
**** v1 vsl| 1005 BereqProtocol b HTTP/1.1 | |
**** v1 vsl| 1005 BereqHeader b Content-Length: 100 | |
**** v1 vsl| 1005 BereqHeader b Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc | |
**** v1 vsl| 1005 BereqHeader b X-Forwarded-For: ::1 | |
**** 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: 1636979875.133547 0.000021 0.000021 | |
**** v1 vsl| 1005 Timestamp b Connected: 1636979875.133597 0.000072 0.000050 | |
**** v1 vsl| 1005 BackendOpen b 27 s0 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 60455 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 56100 connect | |
**** v1 vsl| 1005 FetchError b req.body read error: 11 (Resource temporarily unavailable) | |
**** v1 vsl| 1005 FetchError b backend write error: 11 (Resource temporarily unavailable) | |
**** v1 vsl| 1005 Timestamp b Bereq: 1636979876.133352 0.999827 0.999755 | |
**** v1 vsl| 1005 BackendClose b 27 s0 close | |
**** v1 vsl| 1005 Timestamp b Beresp: 1636979876.133374 0.999849 0.000021 | |
**** v1 vsl| 1005 Timestamp b Error: 1636979876.133377 0.999852 0.000003 | |
**** v1 vsl| 1005 BerespProtocol b HTTP/1.1 | |
**** v1 vsl| 1005 BerespStatus b 503 | |
**** v1 vsl| 1005 BerespReason b Backend fetch failed | |
**** v1 vsl| 1005 BerespHeader b Date: Mon, 15 Nov 2021 12:37:56 GMT | |
**** v1 vsl| 1005 BerespHeader b Server: Varnish | |
**** v1 vsl| 1005 VCL_call b BACKEND_ERROR | |
**** v1 vsl| 1005 BerespHeader b Content-Type: text/html; charset=utf-8 | |
**** v1 vsl| 1005 BerespHeader b Retry-After: 5 | |
**** v1 vsl| 1005 VCL_return b deliver | |
**** v1 vsl| 1005 Storage b umem Transient | |
**** v1 vsl| 1005 Length b 281 | |
**** v1 vsl| 1005 BereqAcct b 125 0 125 0 0 0 | |
**** v1 vsl| 1005 End b | |
**** v1 vsl| 1004 Begin c req 1003 rxreq | |
**** v1 vsl| 1004 Timestamp c Start: 1636979875.133453 0.000000 0.000000 | |
**** v1 vsl| 1004 Timestamp c Req: 1636979875.133453 0.000000 0.000000 | |
**** v1 vsl| 1004 VCL_use c vcl1 | |
**** v1 vsl| 1004 ReqStart c ::1 34819 TCP | |
**** v1 vsl| 1004 ReqMethod c POST | |
**** v1 vsl| 1004 ReqURL c / | |
**** v1 vsl| 1004 ReqProtocol c HTTP/1.1 | |
**** v1 vsl| 1004 ReqHeader c Content-Length: 100 | |
**** v1 vsl| 1004 ReqHeader c Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc | |
**** v1 vsl| 1004 ReqHeader c X-Forwarded-For: ::1 | |
**** v1 vsl| 1004 VCL_call c RECV | |
**** v1 vsl| 1004 VCL_return c pass | |
**** v1 vsl| 1004 VCL_call c HASH | |
**** v1 vsl| 1004 VCL_return c lookup | |
**** v1 vsl| 1004 VCL_call c PASS | |
**** v1 vsl| 1004 VCL_return c fetch | |
**** v1 vsl| 1004 Link c bereq 1005 pass | |
**** v1 vsl| 1004 Storage c umem Transient | |
**** v1 vsl| 1004 FetchError c Resource temporarily unavailable | |
**** v1 vsl| 1004 FetchError c straight insufficient bytes | |
**** v1 vsl| 1004 Timestamp c ReqBody: 1636979876.133316 0.999863 0.999863 | |
**** v1 vsl| 1004 Timestamp c Fetch: 1636979876.133433 0.999980 0.000117 | |
**** v1 vsl| 1004 RespProtocol c HTTP/1.1 | |
**** v1 vsl| 1004 RespStatus c 503 | |
**** v1 vsl| 1004 RespReason c Backend fetch failed | |
**** v1 vsl| 1004 RespHeader c Date: Mon, 15 Nov 2021 12:37:56 GMT | |
**** v1 vsl| 1004 RespHeader c Server: Varnish | |
**** v1 vsl| 1004 RespHeader c Content-Type: text/html; charset=utf-8 | |
**** v1 vsl| 1004 RespHeader c Retry-After: 5 | |
**** 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.0) | |
**** v1 vsl| 1004 VCL_call c DELIVER | |
**** v1 vsl| 1004 VCL_return c deliver | |
**** v1 vsl| 1004 Timestamp c Process: 1636979876.133462 1.000009 0.000029 | |
**** v1 vsl| 1004 Filters c | |
**** v1 vsl| 1004 RespHeader c Content-Length: 281 | |
**** v1 vsl| 1004 RespHeader c Connection: close | |
**** v1 vsl| 1004 Timestamp c Resp: 1636979876.133502 1.000048 0.000039 | |
**** v1 vsl| 1004 ReqAcct c 86 0 86 244 281 525 | |
**** v1 vsl| 1004 End c | |
**** v1 vsl| 1003 SessClose c RX_BODY 1.000 | |
**** v1 vsl| 1003 End c | |
**** dT 2.719 | |
** top === client c1 -connect "${tmpdir}/v1.sock" | |
** top === client c1 -run | |
** c1 Starting client | |
** c1 Waiting for client | |
** c1 Started on /tmp/vtc.932503.476d6ce4/v1.sock (1 iterations) | |
*** c1 Connect to /tmp/vtc.932503.476d6ce4/v1.sock | |
*** c1 connected fd 4 to /tmp/vtc.932503.476d6ce4/v1.sock | |
** c1 === txreq -req POST -hdr "Content-Length: 100" | |
**** c1 txreq|POST / HTTP/1.1\r | |
**** c1 txreq|Content-Length: 100\r | |
**** c1 txreq|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r | |
**** c1 txreq|\r | |
** c1 === send some | |
**** c1 send|some | |
** c1 === rxresp | |
*** s0 dispatch fd 16 -> s3 | |
*** s3 start with fd 16 | |
** s3 === rxreqhdrs | |
**** dT 2.742 | |
**** v1 vsl| 1006 Begin c sess 0 HTTP/1 | |
**** v1 vsl| 1006 SessOpen c 0.0.0.0 0 UDS 0.0.0.0 0 1636979876.234280 21 | |
**** v1 vsl| 1006 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Test confirmed SO_SNDTIMEO non heredity for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Test confirmed SO_RCVTIMEO non heredity for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Not testing incompatible TCP_NODELAY for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Not testing incompatible TCP_KEEPIDLE for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Not testing incompatible TCP_KEEPCNT for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Not testing incompatible TCP_KEEPINTVL for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: SO_LINGER may be inherited for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Setting SO_KEEPALIVE for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Setting SO_SNDTIMEO for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Setting SO_RCVTIMEO for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Not setting incompatible TCP_NODELAY for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Not setting incompatible TCP_KEEPIDLE for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Not setting incompatible TCP_KEEPCNT for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Debug c sockopt: Not setting incompatible TCP_KEEPINTVL for UDS=/tmp/vtc.932503.476d6ce4/v1.sock | |
**** v1 vsl| 1006 Link c req 1007 rxreq | |
**** dT 3.543 | |
**** v1 vsl| 0 CLI - Rd ping | |
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1636979876 1.0 | |
**** dT 6.544 | |
**** v1 vsl| 0 CLI - Rd ping | |
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1636979880 1.0 | |
**** dT 9.545 | |
**** v1 vsl| 0 CLI - Rd ping | |
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1636979883 1.0 | |
**** dT 12.547 | |
**** v1 vsl| 0 CLI - Rd ping | |
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1636979886 1.0 | |
**** dT 15.548 | |
**** v1 vsl| 0 CLI - Rd ping | |
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1636979889 1.0 | |
**** dT 18.550 | |
**** v1 vsl| 0 CLI - Rd ping | |
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1636979892 1.0 | |
**** dT 21.551 | |
**** v1 vsl| 0 CLI - Rd ping | |
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1636979895 1.0 | |
**** dT 24.552 | |
**** v1 vsl| 0 CLI - Rd ping | |
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1636979898 1.0 | |
**** dT 27.554 | |
**** v1 vsl| 0 CLI - Rd ping | |
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1636979901 1.0 | |
**** dT 30.555 | |
**** v1 vsl| 0 CLI - Rd ping | |
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1636979904 1.0 | |
**** dT 32.719 | |
---- c1 HTTP rx timeout (fd:4 30000 ms) | |
* top RESETTING after tests/r02722.vtc | |
** s0 Waiting for server (3/-1) | |
** s1 Waiting for server (-1/-1) | |
** s2 Waiting for server (-1/-1) | |
** s3 Waiting for server (-1/16) | |
** v1 Wait | |
**** v1 CLI TX|panic.clear | |
*** v1 CLI RX 300 | |
**** v1 CLI RX|No panic to clear | |
*** v1 debug|Info: manager stopping child | |
*** v1 debug|Debug: | |
*** v1 debug| Stopping Child | |
**** dT 32.756 | |
**** v1 vsl| 0 CLI - EOF on CLI connection, worker stops | |
**** dT 32.819 | |
*** v1 debug|Info: Child (932645) ended | |
*** v1 debug|Info: Child (932645) said Child dies | |
*** v1 debug|Debug: Child cleanup complete | |
*** v1 debug| | |
**** dT 32.820 | |
*** v1 debug|Info: manager dies | |
**** v1 STDOUT EOF | |
**** dT 32.856 | |
** v1 WAIT4 pid=932541 status=0x0000 (user 0.297000 sys 0.094000) | |
* top TEST tests/r02722.vtc FAILED | |
# top TEST tests/r02722.vtc FAILED (32.859) exit=2 |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment