Re: [squid-users] Re: A lot of TCP_REFRESH_UNMODIFIED after upgrading squid

Amos, any idea?

On Tue, May 28, 2013 at 1:00 PM, Alex Domoradov <alex.hha_at_gmail.com> wrote:
> On Tue, May 28, 2013 at 9:37 AM, Amos Jeffries <squid3_at_treenet.co.nz> wrote:
>> On 28/05/2013 5:17 a.m., Alex Domoradov wrote:
>>>
>>> Any suggestions?
>>
>>
>> One thing you should be aware of is that between 2.6 and 3.3 Squid gained a
>> huge amount of HTTP/1.1 feature support. Including a lot of caching and
>> revalidation changes that were not in HTTP/1.0. REFRESH occuring a lot more
>> is a side affect of several of those changes.
> I see, at the moment I have upgraded only parent squid, the main squid
> still uses Version 2.6.STABLE21. Because it used about 300 clients
> online and had a lot of changes it's little difficult to upgrade. But
> that is an another story :)
>
>>> On Sun, May 26, 2013 at 10:00 PM, Alex Domoradov wrote:
>>>>
>>>> Hello all, I got a strange behavior after I have upgraded squid from
>>>> 2.6.STABLE21 to 3.3.5 on the parent proxy server.
>>>>
>>>> I have a file in the cache
>>>>
>>>> # zcat /var/log/squid/store.log-20130519.gz | grep 00000295
>>>> 1368817711.745 SWAPOUT 00 00000295 83D4FBB382014271606DD58FADD64E98
>>>> 200 1368817554 1368815579 -1 image/vnd.adobe.photoshop
>>>> 635342245/635342245 GET
>>>> http://storage.example.net/b4bf4e39486f405346adbd09505767af-index_v2.psd
>>>>
>>>> As we can see in the access log from main squid - first attempt from
>>>> client (192.168.204.208) was unsuccessful
>>>>
>>>> # cat /var/log/squid/access-alt.log | grep
>>>> b4bf4e39486f405346adbd09505767af
>>>> 1368817711.751 158444 192.168.204.208 TCP_MISS/200 635342846 GET
>>>> http://storage.example.net/b4bf4e39486f405346adbd09505767af-index_v2.psd
>>>> - FIRST_PARENT_MISS/192.168.220.2 image/vnd.adobe.photoshop
>>>>
>>>> and the file was downloaded directly from server
>>>> # zcat /var/log/squid/access.log-20130519.gz | grep
>>>> b4bf4e39486f405346adbd09505767af
>>>> 1368817552.345 0 192.168.220.1 UDP_MISS/000 94 ICP_QUERY
>>>> http://storage.example.net/b4bf4e39486f405346adbd09505767af-index_v2.psd
>>>> - NONE/- -
>>>> 1368817711.745 158442 192.168.220.1 TCP_MISS/200 635342769 GET
>>>> http://storage.example.net/b4bf4e39486f405346adbd09505767af-index_v2.psd
>>>> - DIRECT/205.251.242.180 image/vnd.adobe.photoshop
>>
>>
>> Where did this log snippet come from? the child or parent Squid?
> the first one - main (child) squid
> the second - parent squid
>
>>>> Later another client (192.168.203.121) trying to download the same
>>>> file and get hit in the parent cache.
>>>>
>>>> 1369057070.790 79814 192.168.203.121 TCP_MISS/200 635342857 GET
>>>> http://storage.example.net/b4bf4e39486f405346adbd09505767af-index_v2.psd
>>>> - PARENT_HIT/192.168.220.2 image/vnd.adobe.photoshop
>>>>
>>>> So seems that everything work fine. Today after upgrading squid on the
>>>> parent from 2.6 to 3.3.5 I have tried again download the same file
>>>>
>>>> # curl -v -O
>>>> http://storage.example.net/b4bf4e39486f405346adbd09505767af-index_v2.psd
>>>> d* About to connect() to storage.example.net port 80 (#0)
>>>> * Trying xxx.xxx.xxx.198... connected
>>>> * Connected to storage.example.net (xxx.xxx.xxx.198) port 80 (#0)
>>>>>
>>>>> GET /b4bf4e39486f405346adbd09505767af-index_v2.psd HTTP/1.1
>>>>> User-Agent: curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7
>>>>> NSS/3.14.0.0 zlib/1.2.3 libidn/1.18 libssh2/1.4.2
>>>>> Host: storage.example.net
>>>>> Accept: */*
>>>>>
>>>> % Total % Received % Xferd Average Speed Time Time Time
>>>> Current
>>>> Dload Upload Total Spent Left
>>>> Speed
>>>> 0 0 0 0 0 0 0 0 --:--:-- 0:00:01
>>>> --:--:-- 0* HTTP 1.0, assume close after body
>>>> < HTTP/1.0 200 OK
>>>> < Last-Modified: Fri, 17 May 2013 18:32:59 GMT
>>>> < Accept-Ranges: bytes
>>>> < Content-Type: image/vnd.adobe.photoshop
>>>> < Content-Length: 635342245
>>>> < x-amz-id-2:
>>>> +HuykoFgicH0hUFZQIBTU1AS8OZ7bN56vmcNxHz+1bYD8QOAwFseLuMQQElW4DZX
>>>> < x-amz-request-id: 63F9E75242B5C0B9
>>>> < Date: Sun, 26 May 2013 18:34:32 GMT
>>>> < ETag: "5b98acdf5929a2344aa9c3bbee870943"
>>>> < Server: AmazonS3
>>>> < Age: 0
>>>> < X-Cache: HIT from svn-parent.example.lan
>>>> < X-Cache-Lookup: HIT from svn-parent.example.lan:3128
>>>> < Via: 1.1 svn-parent.example.lan (squid/3.3.5)
>>>> < X-Cache: MISS from squid.example.lan
>>>> < X-Cache-Lookup: MISS from squid.example.lan:3129
>>>> < Connection: close
>>>> <
>>>> { [data not shown]
>>>> 100 605M 100 605M 0 0 82.9M 0 0:00:07 0:00:07
>>>> --:--:-- 110M* Closing connection #0
>>>>
>>>> And in the log I see the following lines
>>>>
>>>> main squid
>>>> 1369593277.244 5787 192.168.210.102 TCP_MISS/200 635342835 GET
>>>> http://storage.example.net/b4bf4e39486f405346adbd09505767af-index_v2.psd
>>>> - FIRST_PARENT_MISS/192.168.220.2 image/vnd.adobe.photoshop
>>>>
>>>> parent squid (3.3.5)
>>>> # cat /var/log/squid/access.log | grep b4bf4e39486f405346adbd09505767af
>>>> 1369593271.465 0 192.168.220.1 UDP_MISS/000 94 ICP_QUERY
>>>> http://storage.psd2html.com/b4bf4e39486f405346adbd09505767af-index_v2.psd
>>>> - HIER_NONE/- -
>>>> 1369593277.206 5741 192.168.220.1 TCP_REFRESH_UNMODIFIED/200
>>>> 635342757 GET
>>>> http://storage.psd2html.com/b4bf4e39486f405346adbd09505767af-index_v2.psd
>>>> - HIER_DIRECT/176.32.100.198 image/vnd.adobe.photoshop
>>>>
>>>> As I understand from HIER_DIRECT/176.32.100.198 the file was
>>>> downloaded directly from server instead of local cache.
>>
>>
>> "Sort of".
>> It means the response given required some form of contact with that remote
>> server. In this record we also see REFRESH, which means there was a cache
>> object "HIT" but it was stale or required revalidation before it could be
>> used. The parent proxy did that and got a "304 Unmodified" response, so it
>> updated the HIT response with any new details from the 304 headers and sent
>> the result to the child proxy as a "200 OK" response.
> As I see from curl output, download speed was - 82.9Mbyte/s and that
> mean the file was taken from cache?
>
>
>> If I was to guess I would say the parent got a max-age=0 cache control
>> header from the child proxy which made it believe the HIT was stale. 2.6
>> series are known to send that header to peers. If you can avoid that (ie
>> upgrade the child proxy as well) you will possibly see the 200 between
>> parent and child turn into a 304 and more bandwidth savings.
> Did you mean Age: 0 from curl output?
>
>> If you want to dig further into this you can try debugging the 3.3 parent
>> server HTTP headers involved with one of these transactions. "debug_options
>> 11,2" will log all the details (may produce very big logs on a busy proxy
>> though).
>>
>>
>>
>>>>
>>>> On the parent server I have the following refresh pattern
>>>>
>>>> refresh_pattern \.psd$ 129600 100 129600 override-lastmod
>>>> override-expire ignore-reload
>>>> refresh_pattern \.zip$ 129600 100 129600 override-lastmod
>>>> override-expire ignore-reload
>>>> refresh_pattern \.rar$ 129600 100 129600 override-lastmod
>>>> override-expire ignore-reload
>>>>
>>>> Did I miss something?
>>
>>
>> Yes and no. The above specification to ignore the headers involved with
>> cache object ages may be part of why the parent refreshed.
>>
>> It may be worthwhile re-evaluating why you have these in the parent proxy
>> now that its been updated to 3.3. ignore-reload is making the parent ignore
>> a max-age=0 sent by the child squid-2.6. Upgrading the child proxy as well
>> will remove that header from the child requests and make the control
>> override much less likely to be needed.
>>
>> Amos
> I see, will be try to upgrade the child as quick as possible.
>
> One more thing about refresh_pattern. In my situation do I need to use
> reload-into-ims?
Received on Tue Jun 11 2013 - 07:56:43 MDT