Varnish appears to hang/requests time out
Martin Aspeli
optilude at gmx.net
Sun Sep 9 19:18:19 CEST 2007
Here is a much shorter log entry that exhibits the same behaviour. This
is with trunk and 1.1.1 final (the log entry is 1.1.1 final)
$
./bin/varnishlog 0 CLI Rd ping 0 CLI Wr 0
200 PONG 1189354743
0 WorkThread 0xb0303c90 start
12 SessionOpen c 127.0.0.1 64496
12 ReqStart c 127.0.0.1 64496 1765608679
12 RxRequest c GET
12 RxURL c /optilux
12 RxProtocol c HTTP/1.1
12 RxHeader c Accept: */*
12 RxHeader c Accept-Language: en
12 RxHeader c Accept-Encoding: gzip, deflate
12 RxHeader c Cookie: __ac="NjE2NDZkNjk2ZTo2MTY0NmQ2OTZl";
wstyle=Normal%20Text
12 RxHeader c User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac
OS X; en) AppleWebKit/419.3 (KHTML, like Gecko) Safari/419.3
12 RxHeader c Connection: keep-alive
12 RxHeader c Host: localhost:8081
12 VCL_call c recv
12 VCL_return c pass
12 VCL_call c pass
12 VCL_return c pass
15 BackendOpen b default 127.0.0.1 64497 127.0.0.1 8080
15 BackendXID b 1765608679
12 Backend c 15 default
15 TxRequest b GET
15 TxURL b /optilux
15 TxProtocol b HTTP/1.1
15 TxHeader b Accept: */*
15 TxHeader b Accept-Language: en
15 TxHeader b Accept-Encoding: gzip, deflate
15 TxHeader b Cookie: __ac="NjE2NDZkNjk2ZTo2MTY0NmQ2OTZl";
wstyle=Normal%20Text
15 TxHeader b User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac
OS X; en) AppleWebKit/419.3 (KHTML, like Gecko) Safari/419.3
15 TxHeader b Host: localhost:8081
15 TxHeader b X-Varnish: 1765608679
15 TxHeader b X-Forwarded-for: 127.0.0.1
15 RxProtocol b HTTP/1.1
15 RxStatus b 200
15 RxResponse b OK
15 RxHeader b Server: Zope/(Zope 2.10.4-final, python 2.4.3,
darwin) ZServer/1.1 Plone/3.0
15 RxHeader b Date: Sun, 09 Sep 2007 16:19:04 GMT
15 RxHeader b X-Pagecache: NO-ETAG
15 RxHeader b Content-Length: 6690
15 RxHeader b Content-Language: en-gb
15 RxHeader b Content-Encoding: gzip
15 RxHeader b Expires: Thu, 11 Sep 1997 16:19:04 GMT
15 RxHeader b Vary: Accept-Encoding, Accept-Language,
15 RxHeader b Accept-Encoding
15 RxHeader b ETag: |admin|Optilux Theme|en|1|310||||330376
15 RxHeader b X-Caching-Rule-Id: plone-content-types
15 RxHeader b Cache-Control: max-age=0, s-maxage=0, private,
must-revalidate
15 RxHeader b Content-Type: text/html;charset=utf-8
15 RxHeader b X-Header-Set-Id: cache-with-etag
12 ObjProtocol c HTTP/1.1
12 ObjStatus c 200
12 ObjResponse c OK
12 ObjHeader c Server: Zope/(Zope 2.10.4-final, python 2.4.3,
darwin) ZServer/1.1 Plone/3.0
12 ObjHeader c Date: Sun, 09 Sep 2007 16:19:04 GMT
12 ObjHeader c X-Pagecache: NO-ETAG
12 ObjHeader c Content-Language: en-gb
12 ObjHeader c Content-Encoding: gzip
12 ObjHeader c Expires: Thu, 11 Sep 1997 16:19:04 GMT
12 ObjHeader c Vary: Accept-Encoding, Accept-Language,
12 ObjHeader c Accept-Encoding
12 ObjHeader c ETag: |admin|Optilux Theme|en|1|310||||330376
12 ObjHeader c X-Caching-Rule-Id: plone-content-types
12 ObjHeader c Cache-Control: max-age=0, s-maxage=0, private,
must-revalidate
12 ObjHeader c Content-Type: text/html;charset=utf-8
12 ObjHeader c X-Header-Set-Id: cache-with-etag
15 BackendReuse b default
12 TTL c 1765608679 RFC 0 1189354744 1189354744 873994744 0 0
12 VCL_call c fetch
12 VCL_return c insert
12 Length c 6690
12 VCL_call c deliver
12 VCL_return c deliver
12 TxProtocol c HTTP/1.1
12 TxStatus c 200
12 TxResponse c OK
12 TxHeader c Server: Zope/(Zope 2.10.4-final, python 2.4.3,
darwin) ZServer/1.1 Plone/3.0
12 TxHeader c Date: Sun, 09 Sep 2007 16:19:04 GMT
12 TxHeader c X-Pagecache: NO-ETAG
12 TxHeader c Content-Language: en-gb
12 TxHeader c Content-Encoding: gzip
12 TxHeader c Expires: Thu, 11 Sep 1997 16:19:04 GMT
12 TxHeader c Vary: Accept-Encoding, Accept-Language,
12 TxHeader c Accept-Encoding
12 TxHeader c ETag: |admin|Optilux Theme|en|1|310||||330376
12 TxHeader c X-Caching-Rule-Id: plone-content-types
12 TxHeader c Cache-Control: max-age=0, s-maxage=0, private,
must-revalidate
12 TxHeader c Content-Type: text/html;charset=utf-8
12 TxHeader c X-Header-Set-Id: cache-with-etag
12 TxHeader c Content-Length: 6690
12 TxHeader c X-Varnish: 1765608679
12 TxHeader c Age: 0
12 TxHeader c Via: 1.1 varnish
12 TxHeader c Connection: keep-alive
12 ReqEnd c 1765608679 1189354744.079793930
1189354744.435858965 0.000501871 0.355978012 0.000087023
0 StatAddr 127.0.0.1 0 0 1 1 0 0 1 623 6690
0 WorkThread 0xb0384c90 start
16 SessionOpen c 127.0.0.1 64501
0 WorkThread 0xb0405c90 start
17 SessionOpen c 127.0.0.1 64502
0 WorkThread 0xb0486c90 start
18 SessionOpen c 127.0.0.1 64503
12 ReqStart c 127.0.0.1 64496 1765608680
12 RxRequest c GET
12 RxURL c
/optilux/portal_kss/Optilux%20Theme/at-cachekey9321.kss
12 RxProtocol c HTTP/1.1
12 RxHeader c Accept: */*
12 RxHeader c Accept-Language: en
12 RxHeader c Accept-Encoding: gzip, deflate
12 RxHeader c Cookie: __ac="NjE2NDZkNjk2ZTo2MTY0NmQ2OTZl";
wstyle=Normal%20Text
12 RxHeader c Referer: http://localhost:8081/optilux
12 RxHeader c User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac
OS X; en) AppleWebKit/419.3 (KHTML, like Gecko) Safari/419.3
12 RxHeader c If-Modified-Since: Sun, 09 Sep 2007 16:17:57 GMT
12 RxHeader c Connection: keep-alive
12 RxHeader c Host: localhost:8081
12 VCL_call c recv
12 VCL_return c pass
12 VCL_call c pass
12 VCL_return c pass
15 BackendXID b 1765608680
12 Backend c 15 default
15 TxRequest b GET
15 TxURL b
/optilux/portal_kss/Optilux%20Theme/at-cachekey9321.kss
15 TxProtocol b HTTP/1.1
15 TxHeader b Accept: */*
15 TxHeader b Accept-Language: en
15 TxHeader b Accept-Encoding: gzip, deflate
15 TxHeader b Cookie: __ac="NjE2NDZkNjk2ZTo2MTY0NmQ2OTZl";
wstyle=Normal%20Text
15 TxHeader b Referer: http://localhost:8081/optilux
15 TxHeader b User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac
OS X; en) AppleWebKit/419.3 (KHTML, like Gecko) Safari/419.3
15 TxHeader b If-Modified-Since: Sun, 09 Sep 2007 16:17:57 GMT
15 TxHeader b Host: localhost:8081
15 TxHeader b X-Varnish: 1765608680
15 TxHeader b X-Forwarded-for: 127.0.0.1
15 RxProtocol b HTTP/1.1
15 RxStatus b 200
15 RxResponse b OK
15 RxHeader b Server: Zope/(Zope 2.10.4-final, python 2.4.3,
darwin) ZServer/1.1 Plone/3.0
15 RxHeader b Date: Sun, 09 Sep 2007 16:19:04 GMT
15 RxHeader b Content-Length: 9912
15 RxHeader b X-Cache-Headers-Set-By: CachingPolicyManager:
/optilux/caching_policy_manager
15 RxHeader b Accept-Ranges: bytes
15 RxHeader b Expires: Thu, 11 Sep 1997 16:19:04 GMT
15 RxHeader b Last-Modified: Sun, 09 Sep 2007 16:19:04 GMT
15 RxHeader b X-Caching-Rule-Id: downloads
15 RxHeader b Cache-Control: max-age=0, s-maxage=86400,
must-revalidate, proxy-revalidate
15 RxHeader b Content-Type: text/css;charset=utf-8
15 RxHeader b X-Header-Set-Id: cache-in-proxy-24-hours
12 ObjProtocol c HTTP/1.1
12 ObjStatus c 200
12 ObjResponse c OK
12 ObjHeader c Server: Zope/(Zope 2.10.4-final, python 2.4.3,
darwin) ZServer/1.1 Plone/3.0
12 ObjHeader c Date: Sun, 09 Sep 2007 16:19:04 GMT
12 ObjHeader c X-Cache-Headers-Set-By: CachingPolicyManager:
/optilux/caching_policy_manager
12 ObjHeader c Expires: Thu, 11 Sep 1997 16:19:04 GMT
12 ObjHeader c Last-Modified: Sun, 09 Sep 2007 16:19:04 GMT
12 ObjHeader c X-Caching-Rule-Id: downloads
12 ObjHeader c Cache-Control: max-age=0, s-maxage=86400,
must-revalidate, proxy-revalidate
12 ObjHeader c Content-Type: text/css;charset=utf-8
12 ObjHeader c X-Header-Set-Id: cache-in-proxy-24-hours
15 BackendReuse b default
12 TTL c 1765608680 RFC 86400 1189354744 1189354744
873994744 86400 0
12 VCL_call c fetch
12 VCL_return c insert
12 Length c 9912
12 VCL_call c deliver
12 VCL_return c deliver
12 TxProtocol c HTTP/1.1
12 TxStatus c 200
12 TxResponse c OK
12 TxHeader c Server: Zope/(Zope 2.10.4-final, python 2.4.3,
darwin) ZServer/1.1 Plone/3.0
12 TxHeader c Date: Sun, 09 Sep 2007 16:19:04 GMT
12 TxHeader c X-Cache-Headers-Set-By: CachingPolicyManager:
/optilux/caching_policy_manager
12 TxHeader c Expires: Thu, 11 Sep 1997 16:19:04 GMT
12 TxHeader c Last-Modified: Sun, 09 Sep 2007 16:19:04 GMT
12 TxHeader c X-Caching-Rule-Id: downloads
12 TxHeader c Cache-Control: max-age=0, s-maxage=86400,
must-revalidate, proxy-revalidate
12 TxHeader c Content-Type: text/css;charset=utf-8
12 TxHeader c X-Header-Set-Id: cache-in-proxy-24-hours
12 TxHeader c Content-Length: 9912
12 TxHeader c X-Varnish: 1765608680
12 TxHeader c Age: 0
12 TxHeader c Via: 1.1 varnish
12 TxHeader c Connection: keep-alive
12 ReqEnd c 1765608680 1189354744.538324118
1189354744.564362049 0.102465153 0.025976896 0.000061035
0 StatAddr 127.0.0.1 0 0 1 2 0 0 2 1204 16602
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1189354746
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1189354749
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1189354752
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1189354755
I'm not really familiar with this log format, but it seems to me a
request is being made with keep-alive that never completes? During the
last pings, Safari is hanging (and appears to have crashed). It comes
back to life if I kill varnishd. Bad browser behaviour maybe, but still
nothing like this happens when I access the backend directly.
FWIW, this problems seems most pronounced in Safari, but I have seen it
with Firefox and IE as well.
I've seen http://varnish.projects.linpro.no/ticket/55 which may be
related, but there's no mention of where it's fixed (trunk? 1.1
branch?). In any case, I saw the problem with trunk as well.
Martin
More information about the varnish-misc
mailing list