Re: unexplainable MISSes - found the problem

[Adrian Dascalu <adrian.dascalu@xxxxxxxxxxxxx>]

Ok, it's a bit late for me but for other people browsing this list I'm 
sharing my findings:

It looks like squid is really picky about the way Vary header text is 
formed: the vary headers in my case where not "identical" due to a bug 
in the backed server. A header name was repeated for the anonymous users 
(", Accept-encoding" added at the end of the list). Developer tools in 
firefox and chrome were silently correcting this and even squid 
access.log with headers (see below) was only showing an extra coma that 
was difficult to spot.



On 11/09/2010 08:56 AM, Adrian Dascalu wrote:
> On 11/09/2010 04:35 AM, Amos Jeffries wrote:
>
>    
> >   Unique ETag headers are required for that.
> >
> >      
> Hi Amos,
>
> I have understood as far but I still cant get my setup to behave as
> intended: to keep distinct versions of the same URL in cache until they
> expire. Distinct based on ETag value/ Vary header values.
>
> Here's what happens:
>
> ****************
> **A request of a logged in user (identified by the X-Username header as
> "X-Username: v81krndgi9jw8Oq7RqP9gpj/XkIgZGFzY2FsdQ==|Plone Default" and
> "ETag: |dascalu|Plone Default|1|False|||||358134") takes the object in
> cache:
>
> 1289284280.898   4387 127.0.0.1 TCP_MISS/200 76574 GET
> http://127.0.0.1:3128/VirtualHostBase/http/www.somewebsite.com:80/www/SITE/VirtualHostRoot/
> - FIRST_PARENT_MISS/17 text/html
>
> [Host: 127.0.0.1:3128\r\nUser-Agent: Mozilla/5.0 (X11; U; Linux i686;
> en-US; rv:1.9.1.9) Gecko/20100330 Fedora/3.5.9-1.fc11
> Firefox/3.5.9\r\nAccept:
> text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\r\nAccept-Language:
> en-us,en;q=0.5\r\nAccept-Encoding: gzip,deflate\r\nAccept-Charset:
> ISO-8859-1,utf-8;q=0.7,*;q=0.7\r\nReferer:
> http://www.somewebsite.com/portal_cache_settings/old-policy/rules/frontpage?portal_status_message=Changes%2520saved.\r\nCookie:
> __utma=173508663.4134765344646281700.1250060356.1289254636.1289283144.57; __utmc=173508663;
> __utmz=173508663.1289208944.50.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
> __ac="v81krndgi9jw8Oq7RqP9gpj/XkIgZGFzY2FsdQ=="; plone_skin="Plone
> Default"; __utmb=173508663.8.10.1289283144\r\nX-Username:
> v81krndgi9jw8Oq7RqP9gpj/XkIgZGFzY2FsdQ==|Plone
> Default\r\nX-Forwarded-For: 109.99.31.143\r\nX-Forwarded-Host:
> www.somewebsite.com\r\nX-Forwarded-Server:
> www.somewebsite.com\r\nConnection: Keep-Alive\r\n]
>
> [HTTP/1.0 200 OK\r\nServer: Zope/(Zope 2.9.10-final, python 2.4.3,
> linux2) ZServer/1.1 Plone/2.5.5\r\nDate: Tue, 09 Nov 2010 06:31:20
> GMT\r\nContent-Length: 75865\r\nContent-Language: en\r\nExpires: Tue, 09
> Nov 2010 06:31:24 GMT\r\nVary: Accept-Encoding, Accept,
> X-Username\r\nLast-Modified: Fri, 28 Nov 2008 07:19:49 GMT\r\nETag:
> |dascalu|Plone Default|1|False|||||358134\r\nX-Caching-Rule-Id:
> frontpage\r\nCache-Control: max-age=5, s-maxage=3600,
> public\r\nContent-Type: text/html;charset=utf-8\r\nX-Header-Set-Id:
> cache-with-etag-in-proxy\r\nX-Cache: MISS from
> squid1.somewebsite.com\r\nX-Cache-Lookup: MISS from
> squid1.somewebsite.com:3128\r\nVia: 1.0 squid1.somewebsite.com:3128
> (squid/2.7.STABLE9)\r\nConnection: keep-alive\r\n\r]
>
> *****************
> **A second request of the same user will be served from cache:
>
> 1289284489.560      0 127.0.0.1 TCP_MEM_HIT/200 76582 GET
> http://127.0.0.1:3128/VirtualHostBase/http/www.somewebsite.com:80/www/SITE/VirtualHostRoot/
> - NONE/- text/html
>
> [Host: 127.0.0.1:3128\r\nUser-Agent: Mozilla/5.0 (X11; U; Linux i686;
> en-US; rv:1.9.1.9) Gecko/20100330 Fedora/3.5.9-1.fc11
> Firefox/3.5.9\r\nAccept:
> text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\r\nAccept-Language:
> en-us,en;q=0.5\r\nAccept-Encoding: gzip,deflate\r\nAccept-Charset:
> ISO-8859-1,utf-8;q=0.7,*;q=0.7\r\nReferer:
> http://www.somewebsite.com/\r\nCookie:
> __utma=173508663.4134765344646281700.1250060356.1289254636.1289283144.57; __utmc=173508663;
> __utmz=173508663.1289208944.50.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
> __ac="v81krndgi9jw8Oq7RqP9gpj/XkIgZGFzY2FsdQ=="; plone_skin="Plone
> Default"; __utmb=173508663.9.10.1289283144\r\nX-Username:
> v81krndgi9jw8Oq7RqP9gpj/XkIgZGFzY2FsdQ==|Plone
> Default\r\nX-Forwarded-For: 109.99.31.143\r\nX-Forwarded-Host:
> www.somewebsite.com\r\nX-Forwarded-Server:
> www.somewebsite.com\r\nConnection: Keep-Alive\r\n]
>
> [HTTP/1.0 200 OK\r\nServer: Zope/(Zope 2.9.10-final, python 2.4.3,
> linux2) ZServer/1.1 Plone/2.5.5\r\nDate: Tue, 09 Nov 2010 06:31:20
> GMT\r\nContent-Length: 75865\r\nContent-Language: en\r\nExpires: Tue, 09
> Nov 2010 06:31:24 GMT\r\nVary: Accept-Encoding, Accept,
> X-Username\r\nLast-Modified: Fri, 28 Nov 2008 07:19:49 GMT\r\nETag:
> |dascalu|Plone Default|1|False|||||358134\r\nX-Caching-Rule-Id:
> frontpage\r\nCache-Control: max-age=5, s-maxage=3600,
> public\r\nContent-Type: text/html;charset=utf-8\r\nX-Header-Set-Id:
> cache-with-etag-in-proxy\r\nAge: 209\r\nX-Cache: HIT from
> squid1.somewebsite.com\r\nX-Cache-Lookup: HIT from
> squid1.somewebsite.com:3128\r\nVia: 1.0 squid1.somewebsite.com:3128
> (squid/2.7.STABLE9)\r\nConnection: keep-alive\r\n\r]
>
> ******************
> **A request from an Anonymous user (X-Username: Anonymous) will fetch a
> new version into the cache AND invalidate the above logged in user. The
> responce ETag is distinct from the logged in user (ETag:
> ||XXXDesign2006|1|False|||||358134)
>
> 1289284576.228    858 127.0.0.1 TCP_MISS/200 10900 GET
> http://127.0.0.1:3128/VirtualHostBase/http/www.somewebsite.com:80/www/SITE/VirtualHostRoot/
> - FIRST_PARENT_MISS/110 text/html
>
> [Host: 127.0.0.1:3128\r\nIf-None-Match:
> |1|False|||||358134\r\nIf-Modified-Since: Fri, 28 Nov 2008 07:19:49
> GMT\r\nAccept: text/html, image/jpeg;q=0.9, image/png;q=0.9,
> text/*;q=0.9, image/*;q=0.9, */*;q=0.8\r\nAccept-Encoding: x-gzip,
> x-deflate, gzip, deflate\r\nAccept-Charset: utf-8, utf-8;q=0.5,
> *;q=0.5\r\nAccept-Language: en-US, en\r\nCookie:
> __utmz=173508663.1289234747.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
> __utma=173508663.1869602660.1289234747.1289256045.1289283795.7;
> __utmb=173508663.3.10.1289283795\r\nX-Username:
> Anonymous\r\nX-Forwarded-For: 109.99.31.143\r\nX-Forwarded-Host:
> www.somewebsite.com\r\nX-Forwarded-Server:
> www.somewebsite.com\r\nConnection: Keep-Alive\r\n]
>
> [HTTP/1.0 200 OK\r\nServer: Zope/(Zope 2.9.10-final, python 2.4.3,
> linux2) ZServer/1.1 Plone/2.5.5\r\nDate: Tue, 09 Nov 2010 06:36:16
> GMT\r\nContent-Length: 10155\r\nContent-Language:
> en\r\nContent-Encoding: gzip\r\nExpires: Tue, 09 Nov 2010 06:36:20
> GMT\r\nVary: Accept-Encoding, Accept,
> X-Username,\r\n%09Accept-Encoding\r\nLast-Modified: Fri, 28 Nov 2008
> 07:19:49 GMT\r\nETag:
> ||XXXDesign2006|1|False|||||358134\r\nX-Caching-Rule-Id:
> frontpage\r\nCache-Control: max-age=5, s-maxage=3600,
> public\r\nContent-Type: text/html;charset=utf-8\r\nX-Header-Set-Id:
> cache-with-etag-in-proxy\r\nX-Cache: MISS from
> squid1.somewebsite.com\r\nX-Cache-Lookup: MISS from
> squid1.somewebsite.com:3128\r\nVia: 1.0 squid1.somewebsite.com:3128
> (squid/2.7.STABLE9)\r\nConnection: keep-alive\r\n\r]
>
>
> *****************
>
> As a result subsequent requests from the logged in user will result in a
> MISS. This brakes the hole purpuse of the accelerator since anonymous
> and CMS users will invalidate each other's cached objects ...
>
> Please show me what am I doing wrong? Alternatively could you point me
> to the place in squid sources where these decisions are taken? Maybe I
> can better understand what I should do by looking at the code.
>
> Many thanks,
> Adrian
>
>
>