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
