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

On 6/12/2013 11:28 AM, Amos Jeffries wrote:
> 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
Who was the one that worked on vary code in the past?

Eliezer
Received on Wed Jun 12 2013 - 09:19:11 MDT