Re: [squid-users] Bug ID 3806 & HEAD

On 12/06/2013 3:42 p.m., Chris Bennett wrote:
> I'm using squid HEAD published by Eliezer in his repo. I think I've
> stumbled upon bug 3806 in HEAD. While examining why a particular URL
> wasn't returning a HIT, I can't work out why it isn't being served
> from a SWAPOUT object.
>
> The URL I'm testing with is:
> http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png
>
> On first retrieval, I see:
>
> # tail -f /var/log/squid/{store,access}.log | grep FreeMind
> 1371008045.318 RELEASE -1 FFFFFFFF CD5A8F439ACD8A3977F0F0847795490A 200 1371008045 -1 1371108045 x-squid-internal/vary -1/0 GET http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png
> 1371008045.318 RELEASE 00 00004274 51DE3AEF4895BC019E05B33023BA3B48 200 1371008038 1299574024 1371267238 image/png 84591/84591 GET http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png
> 1371008045.860 SWAPOUT 00 00004275 92C7C6C1D5F7573B0A7BA65BC03EA109 200 1371008045 1299574024 1371267245 image/png 84591/84591 GET http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png
> 1371008045.861 1049 192.168.1.54 TCP_MISS/200 85126 GET http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png - HIER_DIRECT/216.34.181.96 image/png
>
> On second retrieval:
>
> # tail -f /var/log/squid/{store,access}.log | grep FreeMind
> 1371008124.801 RELEASE -1 FFFFFFFF 69DAF69FF4C0F37BBC7B22CC2CCEF05B 200 1371008124 -1 1371108124 x-squid-internal/vary -1/0 GET http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png
> 1371008124.801 RELEASE 00 00004276 7E9F2FBE6EC702E9731D502BF431A5E2 200 1371008073 1299574024 1371267273 image/png 84591/84591 GET http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png
> 1371008126.337 SWAPOUT 00 00004277 92C7C6C1D5F7573B0A7BA65BC03EA109 200 1371008124 1299574024 1371267324 image/png 84591/84591 GET http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png
> 1371008126.337 2069 192.168.1.54 TCP_MISS/200 85126 GET http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png - HIER_DIRECT/216.34.181.96 image/png
>
>
> With debug_options 22,3 enabled, I see:
> 2013/06/12 13:06:08.932 kid1| ctx: exit level 0
> 2013/06/12 13:06:08.932 kid1| refresh.cc(540) getMaxAge: getMaxAge: 'http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png'
> 2013/06/12 13:06:09.194 kid1| ctx: enter level 0: 'http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png'
> 2013/06/12 13:06:09.194 kid1| refresh.cc(247) refreshCheck: refreshCheck: 'http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png'
> 2013/06/12 13:06:09.194 kid1| refresh.cc(262) refreshCheck: refreshCheck: Matched '\.png$ 15600000 90%% 15600540'
> 2013/06/12 13:06:09.194 kid1| refresh.cc(264) refreshCheck: age: 61
> 2013/06/12 13:06:09.194 kid1| refresh.cc(266) refreshCheck: check_time: Wed, 12 Jun 2013 03:37:09 GMT
> 2013/06/12 13:06:09.194 kid1| refresh.cc(268) refreshCheck: entry->timestamp: Wed, 12 Jun 2013 03:36:08 GMT
> 2013/06/12 13:06:09.194 kid1| refresh.cc(171) refreshStaleness: FRESH: expires 1371267368 >= check_time 1371008229
> 2013/06/12 13:06:09.194 kid1| refresh.cc(288) refreshCheck: Staleness = -1
> 2013/06/12 13:06:09.194 kid1| refresh.cc(373) refreshCheck: refreshCheck: object isn't stale..
> 2013/06/12 13:06:09.194 kid1| refresh.cc(375) refreshCheck: refreshCheck: returning FRESH_EXPIRES
> 2013/06/12 13:06:09.194 kid1| http.cc(482) cacheableReply: YES because HTTP status 200
>
> With 'curl -v', I see:
> > GET http://freemind.sourceforge.net/wiki/images/c/c8/FreeMind-computer-knowledge-080.png HTTP/1.1
> > User-Agent: curl/7.24.0 (x86_64-redhat-linux-gnu) libcurl/7.24.0 NSS/3.14.2.0 zlib/1.2.5 libidn/1.24 libssh2/1.4.1
> > Host: freemind.sourceforge.net
> > Accept: */*
> > Proxy-Connection: Keep-Alive
> >
> < HTTP/1.1 200 OK
> < Server: Apache/2.2.15 (CentOS)
> < Vary: Host, Accept-Encoding
> < Last-Modified: Tue, 08 Mar 2011 08:47:04 GMT
> < ETag: "14a6f-49df4a80f5200"
> < Accept-Ranges: bytes
> < Cache-Control: max-age=259200
> < Expires: Sat, 15 Jun 2013 03:38:40 GMT
> < Content-Type: image/png
> < Content-Length: 84591
> < Date: Wed, 12 Jun 2013 03:38:40 GMT
> < X-Varnish: 508989350
> < Age: 0
> < X-Cache: MISS from neo.zoran.cgb
> < X-Cache-Lookup: MISS from neo.zoran.cgb:3128
> < Via: 1.1 varnish, 1.1 neo.zoran.cgb (squid/3.HEAD-20130520-r12839)
> < Connection: keep-alive
>
> Does this sound like bug id 3806
> (http://bugs.squid-cache.org/show_bug.cgi?id=3806)?

VERY likely you have. Unfortunately we are all stumped about this one.

> If so, is anyone
> working on trying to solve it?

Alexs' comment #7 on the bug report covers the details of what needs to
be done to figure it out. Sadly none of the current dev team know enough
about the Vary handling to debug it quickly and lack time to track it down.

> If not, can anyone suggest why the requested object is not returning a
> hit on subsequent request? I am seeing hits for that same URL when
> using squid-2.6.STABLE21-6.el5.

2.6/2.7 are known to work okay. However the code there is often very
diffferent. 3.2 at least has a different memory storage mechanism for
the cache, and different abilities for handling larger objects, and no
collapsed forwarding which could be hiding issues on concurrent traffic.

Amos
Received on Wed Jun 12 2013 - 08:29:06 MDT