HTTP/304 response from backend takes 15s to be returned to client
Adrian Lienhard
adi at netstyle.ch
Wed Feb 23 15:28:32 CET 2011
Hi,
I'm experiencing a problem with passing conditional client requests that are not cached. We use Varnish to cache HTML documents. Static files like CSS are not cached (pass).
The relevant bit of vcl_recv trivially is:
sub vcl_recv {
...
if (req.url ~ "\.(css|js|jpg|jpeg|png|gif|mp3|ogg|flv|swf|pdf)$") {
return(pass);
}
...
If the client sends a conditional request (with If-Modified-Since header) the backend (Apache) responds with a HTTP/304 as expected.
The problem is that in this case it takes Varnish 15 seconds to send the 304 response to the client (this is consistently reproducible and always 15s plus a few milliseconds). If, however, the client request is not a conditional request, everything works as expected.
I've also tested with return(lookup) n vcl_recv, which always misses, but the problem is exactly the same. However if I return(pipe), it works OK.
I post the varnishlog of a failing 304 and of a succeeding 200 below (I've indicated where the 15s delay is). Maybe interesting to know is that I see the request being logged in Apache immediately. Also Apache works just fine without Varnish in front.
Versions:
- varnish-2.1.4 SVN on Debian Squeeze
- Apache (running on another host): 2.2.9
Any help appreciated.
Cheers,
Adrian
BTW: Should I anyway rather do pipe for static resources that are never cached?
Conditional request (FAIL)
==========================
HTTP/304 response takes 15s
-----------------------
12 SessionOpen c 212.103.66.219 6147 :80
12 ReqStart c 212.103.66.219 6147 391596406
12 RxRequest c GET
12 RxURL c /_cmsbox_2.2.13_85/layout/default.css
12 RxProtocol c HTTP/1.1
12 RxHeader c User-Agent: curl/7.19.7 (universal-apple-darwin10.0) libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3
12 RxHeader c Host: adrian.cmsbox.biz
12 RxHeader c Accept: */*
12 RxHeader c If-Modified-Since: Wed, 16 Feb 2011 18:05:26 GMT
12 VCL_call c recv
12 VCL_return c pass
12 VCL_call c hash
12 VCL_return c hash
12 VCL_call c pass
12 VCL_return c pass
14 BackendClose - cmsbox
14 BackendOpen b cmsbox 212.103.66.208 55801 212.103.66.211 80
12 Backend c 14 cmsbox cmsbox
14 TxRequest b GET
14 TxURL b /_cmsbox_2.2.13_85/layout/default.css
14 TxProtocol b HTTP/1.1
14 TxHeader b User-Agent: curl/7.19.7 (universal-apple-darwin10.0) libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3
14 TxHeader b Host: adrian.cmsbox.biz
14 TxHeader b Accept: */*
14 TxHeader b If-Modified-Since: Wed, 16 Feb 2011 18:05:26 GMT
14 TxHeader b X-Forwarded-For: 212.103.66.219
14 TxHeader b X-Varnish: 391596406
=============== Waits 15s here / backend loggs request immediately ===============
14 RxProtocol b HTTP/1.1
14 RxStatus b 304
14 RxResponse b Not Modified
14 RxHeader b Date: Wed, 23 Feb 2011 13:55:00 GMT
14 RxHeader b Server: Apache/2.2.9 (Debian)
14 RxHeader b ETag: "c46450-8120-49c6a201bc580"
14 RxHeader b Expires: Thu, 23 Feb 2012 13:55:00 GMT
14 RxHeader b Cache-Control: max-age=31536000
14 RxHeader b Vary: Accept-Encoding
12 TTL c 391596406 RFC 31536000 1298469297 0 0 31536000 0
12 VCL_call c fetch
12 VCL_return c pass
12 ObjProtocol c HTTP/1.1
12 ObjStatus c 304
12 ObjResponse c Not Modified
12 ObjHeader c Date: Wed, 23 Feb 2011 13:55:00 GMT
12 ObjHeader c Server: Apache/2.2.9 (Debian)
12 ObjHeader c ETag: "c46450-8120-49c6a201bc580"
12 ObjHeader c Expires: Thu, 23 Feb 2012 13:55:00 GMT
12 ObjHeader c Vary: Accept-Encoding
14 Length b 0
14 BackendClose b cmsbox
12 VCL_call c deliver
12 VCL_return c deliver
12 TxProtocol c HTTP/1.1
12 TxStatus c 304
12 TxResponse c Not Modified
12 TxHeader c Server: Apache/2.2.9 (Debian)
12 TxHeader c Expires: Thu, 23 Feb 2012 13:55:00 GMT
12 TxHeader c Vary: Accept-Encoding
12 TxHeader c Content-Length: 0
12 TxHeader c Date: Wed, 23 Feb 2011 13:55:12 GMT
12 TxHeader c X-Varnish: 391596406
12 TxHeader c Age: 15
12 TxHeader c Via: 1.1 varnish
12 TxHeader c Connection: keep-alive
12 TxHeader c X-Cache-Hits: 0
12 Length c 0
12 ReqEnd c 391596406 1298469297.322397470 1298469312.322380066 0.000116587 14.999900818 0.000081778
12 SessionClose c EOF
12 StatSess c 212.103.66.219 6147 15 1 1 0 1 1 269 0
Non-conditional request (OK)
============================
HTTP/200 response within 100ms or less
------------------------
12 SessionOpen c 212.103.66.219 23833 :80
12 ReqStart c 212.103.66.219 23833 2103978089
12 RxRequest c HEAD
12 RxURL c /_cmsbox_2.2.13_85/layout/default.css
12 RxProtocol c HTTP/1.1
12 RxHeader c User-Agent: curl/7.19.7 (universal-apple-darwin10.0) libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3
12 RxHeader c Host: adrian.cmsbox.biz
12 RxHeader c Accept: */*
12 VCL_call c recv
12 VCL_return c lookup
12 VCL_call c hash
12 VCL_return c hash
12 HitPass c 2103978045
12 VCL_call c pass
12 VCL_return c pass
15 BackendClose b cmsbox
15 BackendOpen b cmsbox 212.103.66.208 50035 212.103.66.211 80
12 Backend c 15 cmsbox cmsbox
15 TxRequest b HEAD
15 TxURL b /_cmsbox_2.2.13_85/layout/default.css
15 TxProtocol b HTTP/1.1
15 TxHeader b User-Agent: curl/7.19.7 (universal-apple-darwin10.0) libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3
15 TxHeader b Host: adrian.cmsbox.biz
15 TxHeader b Accept: */*
15 TxHeader b X-Forwarded-For: 212.103.66.219
15 TxHeader b X-Varnish: 2103978089
15 RxProtocol b HTTP/1.1
15 RxStatus b 200
15 RxResponse b OK
15 RxHeader b Date: Wed, 23 Feb 2011 09:39:32 GMT
15 RxHeader b Server: Apache/2.2.9 (Debian)
15 RxHeader b Last-Modified: Wed, 16 Feb 2011 18:05:26 GMT
15 RxHeader b ETag: "c46450-8120-49c6a201bc580"
15 RxHeader b Accept-Ranges: bytes
15 RxHeader b Content-Length: 33056
15 RxHeader b Cache-Control: max-age=31536000
15 RxHeader b Expires: Thu, 23 Feb 2012 09:39:32 GMT
15 RxHeader b Vary: Accept-Encoding
15 RxHeader b Content-Type: text/css
12 TTL c 2103978089 RFC 31536000 1298453970 0 0 31536000 0
12 VCL_call c fetch
12 VCL_return c pass
12 ObjProtocol c HTTP/1.1
12 ObjStatus c 200
12 ObjResponse c OK
12 ObjHeader c Date: Wed, 23 Feb 2011 09:39:32 GMT
12 ObjHeader c Server: Apache/2.2.9 (Debian)
12 ObjHeader c Last-Modified: Wed, 16 Feb 2011 18:05:26 GMT
12 ObjHeader c ETag: "c46450-8120-49c6a201bc580"
12 ObjHeader c Content-Length: 33056
12 ObjHeader c Expires: Thu, 23 Feb 2012 09:39:32 GMT
12 ObjHeader c Vary: Accept-Encoding
12 ObjHeader c Content-Type: text/css
15 Length b 0
15 BackendReuse b cmsbox
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: Apache/2.2.9 (Debian)
12 TxHeader c Last-Modified: Wed, 16 Feb 2011 18:05:26 GMT
12 TxHeader c Content-Length: 33056
12 TxHeader c Expires: Thu, 23 Feb 2012 09:39:32 GMT
12 TxHeader c Vary: Accept-Encoding
12 TxHeader c Content-Type: text/css
12 TxHeader c Date: Wed, 23 Feb 2011 09:39:30 GMT
12 TxHeader c X-Varnish: 2103978089
12 TxHeader c Age: 0
12 TxHeader c Via: 1.1 varnish
12 TxHeader c Connection: keep-alive
12 TxHeader c X-Cache-Hits: 0
12 Length c 0
12 ReqEnd c 2103978089 1298453970.929079056 1298453970.930070400 0.000118494 0.000920773 0.000070572
12 Debug c "herding"
12 SessionClose c no request
12 StatSess c 212.103.66.219 23833 0 1 1 0 1 1 333 0
0 ExpKill - 2103978084 -10
More information about the varnish-misc
mailing list