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)? If so, is anyone working on trying to solve it? 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. Thanks, Chris
