[Varnish] #1651: c00061.vtc fails on OSX (connect_timeout not working?)
Varnish
varnish-bugs at varnish-cache.org
Thu Dec 25 00:35:47 CET 2014
#1651: c00061.vtc fails on OSX (connect_timeout not working?)
----------------------+-------------------
Reporter: lkarsten | Owner:
Type: defect | Status: new
Priority: normal | Milestone:
Component: build | Version: 4.0.2
Severity: normal | Keywords:
----------------------+-------------------
c00061.vtc fails on OSX Maverick.
Observed: Test case fails after 32 seconds, after timing out 2 bgfetches
(taking 12.3s!?). The second retry (third request) does not complete
before varnishtest fails the test.
Expected result: each bgfetch should fail after 1s (there is no webserver
on ${bad_ip}), and the test should finish after 3-4 seconds.
Reducing setting first_byte_timeout to 1s gives the expected test case
result.
It appears that setting connect_timeout does not take effect.
{{{
**** top 0.0 macro def varnishd=varnishd
**** top 0.0 macro def varnishadm=varnishadm
**** top 0.0 macro def varnishstat=varnishstat
**** top 0.0 macro def varnishhist=varnishhist
**** top 0.0 macro def varnishlog=varnishlog
**** top 0.0 macro def varnishncsa=varnishncsa
**** top 0.0 macro def vmod_std=std from "/Users/lkarsten/work/varnish-
cache-git/lib/libvmod_std/.libs/libvmod_std.so"
**** top 0.0 macro def vmod_debug=debug from "/Users/lkarsten/work
/varnish-cache-git/lib/libvmod_debug/.libs/libvmod_debug.so"
**** top 0.0 macro def vmod_directors=directors from
"/Users/lkarsten/work/varnish-cache-
git/lib/libvmod_directors/.libs/libvmod_directors.so"
**** top 0.0 macro def pwd=/Users/lkarsten/work/varnish-cache-
git/bin/varnishtest
**** top 0.0 macro def topbuild=/Users/lkarsten/work/varnish-cache-git
**** top 0.0 macro def bad_ip=192.0.2.255
**** top 0.0 macro def
tmpdir=/var/folders/tp/lfqnnc595hj9rxwxkzvgtn7h0000gn/T//vtc.43347.231af40c
* top 0.0 TEST tests/c00061.vtc starting
*** top 0.0 varnishtest
* top 0.0 TEST retry in vcl_backend_error
*** top 0.0 varnish
** v1 0.0 Launch
*** v1 0.0 CMD: cd ${pwd} && ${varnishd} -d -d -n
/var/folders/tp/lfqnnc595hj9rxwxkzvgtn7h0000gn/T//vtc.43347.231af40c/v1 -l
2m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -p
sigsegv_handler=on -p thread_pool_min=10 -a '127.0.0.1:0' -M '127.0.0.1
54917' -P
/var/folders/tp/lfqnnc595hj9rxwxkzvgtn7h0000gn/T//vtc.43347.231af40c/v1/varnishd.pid
*** v1 0.0 CMD: cd /Users/lkarsten/work/varnish-cache-
git/bin/varnishtest && varnishd -d -d -n
/var/folders/tp/lfqnnc595hj9rxwxkzvgtn7h0000gn/T//vtc.43347.231af40c/v1 -l
2m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -p
sigsegv_handler=on -p thread_pool_min=10 -a '127.0.0.1:0' -M '127.0.0.1
54917' -P
/var/folders/tp/lfqnnc595hj9rxwxkzvgtn7h0000gn/T//vtc.43347.231af40c/v1/varnishd.pid
*** v1 0.0 PID: 43365
*** v1 0.0 debug| Platform:
Darwin,13.4.0,x86_64,-smalloc,-smalloc,-hcritbit\n
*** v1 0.0 debug| 200 266 \n
*** v1 0.0 debug| -----------------------------\n
*** v1 0.0 debug| Varnish Cache CLI 1.0\n
*** v1 0.0 debug| -----------------------------\n
*** v1 0.0 debug| Darwin,13.4.0,x86_64,-smalloc,-smalloc,-hcritbit\n
*** v1 0.0 debug| varnish-4.0.2 revision 887c70e\n
*** v1 0.0 debug| \n
*** v1 0.0 debug| Type 'help' for command list.\n
*** v1 0.0 debug| Type 'quit' to close CLI session.\n
*** v1 0.0 debug| Type 'start' to launch worker process.\n
*** v1 0.0 debug| \n
**** v1 0.1 CLIPOLL 1 0x1 0x0
*** v1 0.1 CLI connection fd = 7
*** v1 0.1 CLI RX 107
**** v1 0.1 CLI RX| booxicntojvhjlvzhilyblqesfjftbsx\n
**** v1 0.1 CLI RX| \n
**** v1 0.1 CLI RX| Authentication required.\n
**** v1 0.1 CLI TX| auth
ffd5c78e323a49d9720aba58ce53cba2ba45b4158b0a92b191c3d94eaf850504\n
*** v1 0.1 CLI RX 200
**** v1 0.1 CLI RX| -----------------------------\n
**** v1 0.1 CLI RX| Varnish Cache CLI 1.0\n
**** v1 0.1 CLI RX| -----------------------------\n
**** v1 0.1 CLI RX| Darwin,13.4.0,x86_64,-smalloc,-smalloc,-hcritbit\n
**** v1 0.1 CLI RX| varnish-4.0.2 revision 887c70e\n
**** v1 0.1 CLI RX| \n
**** v1 0.1 CLI RX| Type 'help' for command list.\n
**** v1 0.1 CLI RX| Type 'quit' to close CLI session.\n
**** v1 0.1 CLI RX| Type 'start' to launch worker process.\n
**** v1 0.1 CLI TX| vcl.inline vcl1 << %XJEIFLH|)Xspa8P\n
**** v1 0.1 CLI TX| vcl 4.0;\n
**** v1 0.1 CLI TX| \n
**** v1 0.1 CLI TX| \n
**** v1 0.1 CLI TX| \tbackend b1 { .host = "192.0.2.255"; }\n
**** v1 0.1 CLI TX| \n
**** v1 0.1 CLI TX| \tsub vcl_backend_error {\n
**** v1 0.1 CLI TX| \t\treturn (retry);\n
**** v1 0.1 CLI TX| \t}\n
**** v1 0.1 CLI TX| \n
**** v1 0.1 CLI TX| \tsub vcl_synth {\n
**** v1 0.1 CLI TX| \t\tset resp.status = 504;\n
**** v1 0.1 CLI TX| \t}\n
**** v1 0.1 CLI TX| \n
**** v1 0.1 CLI TX| %XJEIFLH|)Xspa8P\n
*** v1 0.2 CLI RX 200
**** v1 0.2 CLI RX| Message from VCC-compiler:\n
**** v1 0.2 CLI RX| Not running as root, no priv-sep\n
**** v1 0.2 CLI RX| Message from C-compiler:\n
**** v1 0.2 CLI RX| Not running as root, no priv-sep\n
**** v1 0.2 CLI RX| Message from dlopen:\n
**** v1 0.2 CLI RX| Not running as root, no priv-sep\n
**** v1 0.2 CLI RX| \n
**** v1 0.2 CLI RX| VCL compiled.
**** v1 0.2 CLI TX| vcl.use vcl1
*** v1 0.2 CLI RX 200
**** v1 0.2 CLI RX| VCL 'vcl1' now active
** v1 0.2 Start
**** v1 0.2 CLI TX| start
*** v1 0.2 debug| child (43388) Started\n
*** v1 0.2 CLI RX 200
*** v1 0.2 debug| Child (43388) said Not running as root, no priv-
sep\n
*** v1 0.2 wait-running
**** v1 0.2 CLI TX| status
*** v1 0.2 debug| Child (43388) said Child starts\n
*** v1 0.2 CLI RX 200
**** v1 0.2 CLI RX| Child in state running
**** v1 0.2 CLI TX| debug.xid 999
*** v1 0.2 CLI RX 200
**** v1 0.2 CLI RX| XID is 999
**** v1 0.2 CLI TX| debug.listen_address
*** v1 0.2 CLI RX 200
**** v1 0.2 CLI RX| 127.0.0.1 54922\n
** v1 0.2 Listen on 127.0.0.1 54922
**** v1 0.2 macro def v1_addr=127.0.0.1
**** v1 0.2 macro def v1_port=54922
**** v1 0.2 macro def v1_sock=127.0.0.1 54922
*** top 0.2 varnish
**** v1 0.2 CLI TX| param.set debug +syncvsl
*** v1 0.2 CLI RX 200
** v1 0.2 CLI 200 <param.set debug +syncvsl>
*** top 0.2 varnish
**** v1 0.2 CLI TX| param.set connect_timeout 1
*** v1 0.2 CLI RX 200
** v1 0.2 CLI 200 <param.set connect_timeout 1>
*** top 0.2 varnish
**** v1 0.2 CLI TX| param.set max_retries 2
*** v1 0.2 CLI RX 200
** v1 0.2 CLI 200 <param.set max_retries 2>
*** top 0.2 client
** c1 0.2 Starting client
** c1 0.2 Waiting for client
*** c1 0.2 Connect to 127.0.0.1 54922
*** c1 0.2 connected fd 8 from 127.0.0.1 54923 to 127.0.0.1 54922
*** c1 0.2 txreq
**** c1 0.2 txreq| GET / HTTP/1.1\r\n
**** c1 0.2 txreq| \r\n
*** c1 0.2 rxresp
**** v1 0.3 vsl| 1000 Begin c sess 0 HTTP/1
**** v1 0.3 vsl| 1000 SessOpen c 127.0.0.1 54923
127.0.0.1:0 127.0.0.1 54922 1419463614.447459 6
**** v1 0.3 vsl| 1001 Begin c req 1000 rxreq
**** v1 0.3 vsl| 1000 Link c req 1001 rxreq
**** v1 0.3 vsl| 1001 Timestamp c Start: 1419463614.447641
0.000000 0.000000
**** v1 0.3 vsl| 1001 Timestamp c Req: 1419463614.447641
0.000000 0.000000
**** v1 0.3 vsl| 1001 ReqStart c 127.0.0.1 54923
**** v1 0.3 vsl| 1001 ReqMethod c GET
**** v1 0.3 vsl| 1001 ReqURL c /
**** v1 0.3 vsl| 1001 ReqProtocol c HTTP/1.1
**** v1 0.3 vsl| 1001 ReqHeader c X-Forwarded-For:
127.0.0.1
**** v1 0.3 vsl| 1001 VCL_call c RECV
**** v1 0.3 vsl| 1001 VCL_return c hash
**** v1 0.3 vsl| 1001 VCL_call c HASH
**** v1 0.3 vsl| 1001 VCL_return c lookup
**** v1 0.3 vsl| 1001 Debug c XXXX MISS
**** v1 0.3 vsl| 1001 VCL_call c MISS
**** v1 0.3 vsl| 1001 VCL_return c fetch
**** v1 0.3 vsl| 1002 Begin b bereq 1001 fetch
**** v1 0.3 vsl| 1001 Link c bereq 1002 fetch
**** v1 0.3 vsl| 1002 Timestamp b Start: 1419463614.447857
0.000000 0.000000
**** v1 0.3 vsl| 1002 BereqMethod b GET
**** v1 0.3 vsl| 1002 BereqURL b /
**** v1 0.3 vsl| 1002 BereqProtocol b HTTP/1.1
**** v1 0.3 vsl| 1002 BereqHeader b X-Forwarded-For:
127.0.0.1
**** v1 0.3 vsl| 1002 BereqHeader b Accept-Encoding: gzip
**** v1 0.3 vsl| 1002 BereqHeader b X-Varnish: 1002
**** v1 0.3 vsl| 1002 VCL_call b BACKEND_FETCH
**** v1 0.3 vsl| 1002 VCL_return b fetch
**** v1 0.4 vsl| 1002 BackendOpen b 7 b1(192.0.2.255,,80)
192.168.1.9 54924
**** v1 0.4 vsl| 1002 Backend b 7 b1 b1(192.0.2.255,,80)
**** v1 0.4 vsl| 1002 BereqHeader b Host: 192.0.2.255
**** v1 0.4 vsl| 1002 Timestamp b Bereq: 1419463614.491671
0.043814 0.043814
**** v1 3.2 vsl| 0 CLI - Rd ping
**** v1 3.2 vsl| 0 CLI - Wr 200 19 PONG 1419463617
1.0
**** v1 6.2 vsl| 0 CLI - Rd ping
**** v1 6.2 vsl| 0 CLI - Wr 200 19 PONG 1419463620
1.0
**** v1 9.2 vsl| 0 CLI - Rd ping
**** v1 9.2 vsl| 0 CLI - Wr 200 19 PONG 1419463623
1.0
**** v1 12.2 vsl| 0 CLI - Rd ping
**** v1 12.2 vsl| 0 CLI - Wr 200 19 PONG 1419463626
1.0
**** v1 12.5 vsl| 1002 FetchError b http first read error:
EOF
**** v1 12.5 vsl| 1002 BackendClose b 7 b1(192.0.2.255,,80)
**** v1 12.5 vsl| 1002 Timestamp b Beresp: 1419463626.594923
12.147066 12.103252
**** v1 12.5 vsl| 1002 Timestamp b Error: 1419463626.594941
12.147084 0.000018
**** v1 12.5 vsl| 1002 BerespProtocol b HTTP/1.1
**** v1 12.5 vsl| 1002 BerespStatus b 503
**** v1 12.5 vsl| 1002 BerespReason b Service Unavailable
**** v1 12.5 vsl| 1002 BerespReason b Backend fetch failed
**** v1 12.5 vsl| 1002 BerespHeader b Date: Wed, 24 Dec 2014
23:27:06 GMT
**** v1 12.5 vsl| 1002 BerespHeader b Server: Varnish
**** v1 12.5 vsl| 1002 VCL_call b BACKEND_ERROR
**** v1 12.5 vsl| 1002 VCL_return b retry
**** v1 12.5 vsl| 1002 Timestamp b Retry: 1419463626.595129
12.147272 0.000188
**** v1 12.5 vsl| 1002 Link b bereq 1003 retry
**** v1 12.5 vsl| 1002 End b
**** v1 12.5 vsl| 1003 Begin b bereq 1002 retry
**** v1 12.5 vsl| 1003 Timestamp b Start: 1419463626.595129
12.147272 0.000000
**** v1 12.5 vsl| 1003 BereqHeader b X-Varnish: 1003
**** v1 12.5 vsl| 1003 VCL_call b BACKEND_FETCH
**** v1 12.5 vsl| 1003 VCL_return b fetch
**** v1 12.5 vsl| 1003 BackendOpen b 7 b1(192.0.2.255,,80)
192.168.1.9 54926
**** v1 12.5 vsl| 1003 Backend b 7 b1 b1(192.0.2.255,,80)
**** v1 12.5 vsl| 1003 Timestamp b Bereq: 1419463626.635396
12.187539 0.040267
**** v1 15.2 vsl| 0 CLI - Rd ping
**** v1 15.2 vsl| 0 CLI - Wr 200 19 PONG 1419463629
1.0
**** v1 18.2 vsl| 0 CLI - Rd ping
**** v1 18.2 vsl| 0 CLI - Wr 200 19 PONG 1419463632
1.0
**** v1 21.2 vsl| 0 CLI - Rd ping
**** v1 21.2 vsl| 0 CLI - Wr 200 19 PONG 1419463635
1.0
**** v1 24.2 vsl| 0 CLI - Rd ping
**** v1 24.2 vsl| 0 CLI - Wr 200 19 PONG 1419463638
1.0
**** v1 24.6 vsl| 1003 FetchError b http first read error:
EOF
**** v1 24.6 vsl| 1003 BackendClose b 7 b1(192.0.2.255,,80)
**** v1 24.6 vsl| 1003 Timestamp b Beresp: 1419463638.778148
24.330291 12.142752
**** v1 24.6 vsl| 1003 Timestamp b Error: 1419463638.778157
24.330300 0.000009
**** v1 24.6 vsl| 1003 BerespProtocol b HTTP/1.1
**** v1 24.6 vsl| 1003 BerespStatus b 503
**** v1 24.6 vsl| 1003 BerespReason b Service Unavailable
**** v1 24.6 vsl| 1003 BerespReason b Backend fetch failed
**** v1 24.6 vsl| 1003 BerespHeader b Date: Wed, 24 Dec 2014
23:27:18 GMT
**** v1 24.6 vsl| 1003 BerespHeader b Server: Varnish
**** v1 24.6 vsl| 1003 VCL_call b BACKEND_ERROR
**** v1 24.6 vsl| 1003 VCL_return b retry
**** v1 24.6 vsl| 1003 Timestamp b Retry: 1419463638.778260
24.330403 0.000103
**** v1 24.6 vsl| 1003 Link b bereq 1004 retry
**** v1 24.6 vsl| 1003 End b
**** v1 24.6 vsl| 1004 Begin b bereq 1003 retry
**** v1 24.6 vsl| 1004 Timestamp b Start: 1419463638.778260
24.330403 0.000000
**** v1 24.6 vsl| 1004 BereqHeader b X-Varnish: 1004
**** v1 24.6 vsl| 1004 VCL_call b BACKEND_FETCH
**** v1 24.6 vsl| 1004 VCL_return b fetch
**** v1 24.7 vsl| 1004 BackendOpen b 7 b1(192.0.2.255,,80)
192.168.1.9 54927
**** v1 24.7 vsl| 1004 Backend b 7 b1 b1(192.0.2.255,,80)
**** v1 24.7 vsl| 1004 Timestamp b Bereq: 1419463638.819947
24.372090 0.041687
**** v1 27.2 vsl| 0 CLI - Rd ping
**** v1 27.2 vsl| 0 CLI - Wr 200 19 PONG 1419463641
1.0
---- c1 30.2 HTTP rx timeout (fd:8 30000 ms)
* top 30.2 RESETTING after tests/c00061.vtc
**** v1 30.2 vsl| 0 CLI - Rd ping
**** v1 30.2 vsl| 0 CLI - Wr 200 19 PONG 1419463644
1.0
**** v1 31.2 CLI TX| backend.list
*** v1 31.2 CLI RX 200
**** v1 31.2 CLI RX| Backend name Refs Admin
Probe\n
**** v1 31.2 CLI RX| b1(192.0.2.255,,80) 2 probe
Healthy (no probe)
** v1 31.2 Wait
**** v1 31.2 vsl| 0 CLI - Rd backend.list
**** v1 31.2 vsl| 0 CLI - Wr 200 122 Backend name
Refs Admin Probe
b1(192.0.2.255,,80) 2 probe Healthy (no probe)
**** v1 31.2 vsl| 0 CLI - EOF on CLI connection,
worker stops
**** v1 32.2 STDOUT poll 0x11
** v1 32.2 R 43365 Status: 0000 (u 0.083265 s 0.075232)
* top 32.3 TEST tests/c00061.vtc FAILED
# top TEST tests/c00061.vtc FAILED (32.324) exit=1
}}}
After modification:
{{{
lkarsten at jungel:~/work/varnish-cache-git/bin/varnishtest$ ./varnishtest -i
tests/c00061.vtc
# top TEST tests/c00061.vtc passed (4.597)
lkarsten at jungel:~/work/varnish-cache-git/bin/varnishtest$ git df
tests/c00061.vtc
diff --git a/bin/varnishtest/tests/c00061.vtc
b/bin/varnishtest/tests/c00061.vtc
index ef2ae76..4599c27 100644
--- a/bin/varnishtest/tests/c00061.vtc
+++ b/bin/varnishtest/tests/c00061.vtc
@@ -15,6 +15,7 @@ varnish v1 -vcl {
varnish v1 -cliok "param.set debug +syncvsl"
varnish v1 -cliok "param.set connect_timeout 1"
+varnish v1 -cliok "param.set first_byte_timeout 1"
varnish v1 -cliok "param.set max_retries 2"
client c1 {
}}}
--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1651>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list