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
