Weird situation with unexpected 206 from the backend, hit-for-pass and default_ttl
Thomas Parmelan
tom+varnish at ankh.fr.eu.org
Sat Feb 27 16:51:13 CET 2010
Hi,
I'm having quite a hard time trying to figure out what is going on
exactly here, sorry for the length but I prefer to give as much detail
as possible.
I'm using varnish on several varnish servers with the same VCL
configuration. I have varnish 2.0.4 and 2.0.6, Debian GNU/Linux on amd64
hardware (etch and lenny). All servers happen to have the same weird
behaviour regardless of those differences :
All is going well, great performances and cache hit ratio, everyone is
happy, unless some servers randomly start to make too many backend
connexions. After eliminating the usual suspects (cookies,
accept-encoding), I started investigating what kind of requests were
there, and I realized that somehow most of the requests where hitpass
for objects that were previously successfully cached on the same varnish
server. But the objects impacted are not necessarily the same on every
varnish server, and are not always the same, nor at the same time.
After some help from the irc channel (thanks everybody), I started to
track some "culprits" with "varnishtop -b -i TxURL", then searching the
last "varnishlog -c -o" entry for this object, and finally searching the
request id referenced in its HitPass entry.
On every case I tracked like this, the scenario was the same, and if I
understand things correctly (I'll give commented varnishlog just after),
it is like this:
- a request comes from the object, it's a miss so we ask the backend
for it. It is a pretty simple GET request, WITHOUT "Range" header
- the backend, I don't know why, sometimes (and sometimes only)
answers with 206 Partial Content, wich I believe is totally wrong
and will be tracked down by them, but let's keep this to the varnish
side
- so because of that 206 answer, a hit for pass cache entry is
created, with a certain TTL which in my case seems to be way too
long
- later on, for each simple (no Range header) request for this object,
we hit the hitpass entry and pass to the backend
I think I have different problems here, one on the backend obviously,
but the others with varnish :
- seeing as wrong as this backend answer is, I think it shouldn't be
dealt with "normally" by varnish, it would me more interesting to
let the next request have its chance to populate the cache with a
valid (200) answer, in order to keep the following requests being
able to be served from the cache. Is this something that should be
changed in varnish, or in the vcl (and how) ?
- the TTL used for the HitPass object seems to be the default_ttl (-t
86400 in my setup); I tried to keep it low (0s or 10s) from the vcl
config, like this :
sub vcl_fetch {
if (!obj.cacheable) {
set obj.ttl = 0s;
return (pass);
}
/* ... */
}
but I doesn't seem to work. I have the feeling that the HitPass TTL
is somehow forced to the default_ttl value (which I think is not
what the documentation implied). What is going on exactly here and
how can this be changed from the vcl ?
- I also tried to purge the hit-for-pass culprit with the CLI (purge
req.host == the.host && req.url == /the/url), but it didn't work
(the object was still there after). Any idea how to purge such
objects ? Is this a bug ?
Here are the varnishlog outputs. Firt, here is a pass because of the
HitPass object, with a correct (200) answer :
18 ReqStart c 89.80.252.34 1069 1643273915
18 RxRequest c GET
18 RxURL c /elements/css/v7/styles_services.css
18 RxProtocol c HTTP/1.1
18 RxHeader c Accept: */*
18 RxHeader c Referer: http://www.sfr.fr/fr/adsl.jsp?version=6004&contener=2
18 RxHeader c Accept-Language: fr
18 RxHeader c Accept-Encoding: gzip, deflate
18 RxHeader c User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729)
18 RxHeader c Host: img.s-sfr.fr
18 RxHeader c Connection: Keep-Alive
18 VCL_call c recv lookup
18 VCL_call c hash hash
18 HitPass c 1641180098
18 VCL_call c pass pass
18 Backend c 30 s_sfr s_sfr
18 ObjProtocol c HTTP/1.1
18 ObjStatus c 200
18 ObjResponse c OK
18 ObjHeader c Date: Sat, 27 Feb 2010 14:27:59 GMT
18 ObjHeader c Server: Apache/2.2.13 (Fedora)
18 ObjHeader c Last-Modified: Tue, 09 Feb 2010 09:59:57 GMT
18 ObjHeader c Via: http2
18 ObjHeader c Cache-Control: public
18 ObjHeader c Expires: Sat, 27 Feb 2010 16:20:53 GMT
18 ObjHeader c Vary: Accept-Encoding
18 ObjHeader c Content-Type: text/css;charset=ISO-8859-15
18 TTL c 1643273915 RFC 6773 1267280879 1267280879 1267287653 0 0
18 VCL_call c fetch deliver
18 Length c 3284
18 VCL_call c deliver deliver
18 TxProtocol c HTTP/1.1
18 TxStatus c 200
18 TxResponse c OK
18 TxHeader c Server: Apache/2.2.13 (Fedora)
18 TxHeader c Last-Modified: Tue, 09 Feb 2010 09:59:57 GMT
18 TxHeader c Via: http2
18 TxHeader c Cache-Control: public
18 TxHeader c Expires: Sat, 27 Feb 2010 16:20:53 GMT
18 TxHeader c Vary: Accept-Encoding
18 TxHeader c Content-Type: text/css;charset=ISO-8859-15
18 TxHeader c Content-Length: 3284
18 TxHeader c Date: Sat, 27 Feb 2010 14:27:59 GMT
18 TxHeader c X-Varnish: 1643273915
18 TxHeader c Age: 0
18 TxHeader c Via: 1.1 varnish
18 TxHeader c Connection: keep-alive
18 ReqEnd c 1643273915 1267280879.342154026 1267280879.351441145 0.075042009 0.009259224 0.000027895
=> so, the HitPass was created by request id 1641180098. Let's see that
request :
59 ReqStart c 77.205.33.140 52401 1641180098
59 RxRequest c GET
59 RxURL c /elements/css/v7/styles_services.css
59 RxProtocol c HTTP/1.1
59 RxHeader c Accept: */*
59 RxHeader c Referer: http://www.sfr.fr/fr/adsl.jsp
59 RxHeader c Accept-Language: fr
59 RxHeader c User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.0; Trident/4.0; GTB6.4; SLCC1; .NET CLR 2.0.50727; .NET CLR 1.1.4322; .NET CLR 3.5.30729; .NET CLR 3.0.30729)
59 RxHeader c Accept-Encoding: gzip, deflate
59 RxHeader c Host: img.s-sfr.fr
59 RxHeader c Connection: Keep-Alive
59 VCL_call c recv lookup
59 VCL_call c hash hash
59 VCL_call c miss fetch
59 Backend c 21 s_sfr s_sfr
59 ObjProtocol c HTTP/1.1
59 ObjStatus c 206
59 ObjResponse c Partial Content
59 ObjHeader c Date: Fri, 26 Feb 2010 22:01:08 GMT
59 ObjHeader c Server: Apache/2.2.13 (Fedora)
59 ObjHeader c Last-Modified: Tue, 09 Feb 2010 09:59:57 GMT
59 ObjHeader c Via: http4
59 ObjHeader c Cache-Control: public
59 ObjHeader c Expires: Fri, 26 Feb 2010 23:08:27 GMT
59 ObjHeader c Content-Type: text/css;charset=ISO-8859-15
59 TTL c 1641180098 RFC 4038 1267221668 1267221668 1267225707 0 0
59 VCL_call c fetch
59 TTL c 1641180098 VCL 0 1267221668
59 VCL_return c pass
59 Length c 2211
59 VCL_call c deliver deliver
59 TxProtocol c HTTP/1.1
59 TxStatus c 206
59 TxResponse c Partial Content
59 TxHeader c Server: Apache/2.2.13 (Fedora)
59 TxHeader c Last-Modified: Tue, 09 Feb 2010 09:59:57 GMT
59 TxHeader c Via: http4
59 TxHeader c Cache-Control: public
59 TxHeader c Expires: Fri, 26 Feb 2010 23:08:27 GMT
59 TxHeader c Content-Type: text/css;charset=ISO-8859-15
59 TxHeader c Content-Length: 2211
59 TxHeader c Date: Fri, 26 Feb 2010 22:01:08 GMT
59 TxHeader c X-Varnish: 1641180098
59 TxHeader c Age: 0
59 TxHeader c Via: 1.1 varnish
59 TxHeader c Connection: keep-alive
59 ReqEnd c 1641180098 1267221668.117854595 1267221668.127019882 2.395729065 0.009134293 0.000030994
=> Here is the "wrong" 206 answer. No Range header was in the request so
200 and the full content was expected. Also no Content-Range in the
backend answer, that's also very strange. Anyway, its TTL would be 4038
calculated from the HTTP headers (RFC 4038), then it is forced to 0 from
VCL (VCL 0), then we go to pass.
Now pay attention to the Date: headers from the backend answers (yes,
the backend time is correct ;)). The HitPass object was created "Fri, 26
Feb 2010 22:01:08 GMT" with a calculated TTL of 4038 (forced to 0 from
VCL but it doesn't work), so it should be purged about 4038s later, but
it is still there for a request made "Sat, 27 Feb 2010 14:27:59 GMT",
thats much, much more !!
That should not be possible, unless default_ttl (-t 86400 in my setup)
is used instead of the computed TTL...
Many thanks in advance for any explanation or advice on this situation !
Best regards,
Tom
--
Thomas Parmelan -+- Thomas.Parmelan at free.fr -+- tom at ankh.fr.EU.org
More information about the varnish-misc
mailing list