HTTP/304 response from backend takes 15s to be returned to client
Wido den Hollander
wido at widodh.nl
Wed Feb 23 15:35:01 CET 2011
Hi,
On Wed, 2011-02-23 at 15:28 +0100, Adrian Lienhard wrote:
> 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
>
There was a fix regarding this in 2.1.5, I suggest you upgrade to that
version.
Wido
> Any help appreciated.
>
> Cheers,
> Adrian
>
> BTW: Should I anyway rather do pipe for static resources that are never cached?
I think pass is fine?
>
>
>
> 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
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> http://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
More information about the varnish-misc
mailing list