[squid-users] Bug ID 3806 & HEAD

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
Received on Wed Jun 12 2013 - 07:54:19 MDT