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

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 May 28 2013 - 10:00:48 MDT