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

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.

> 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?

>>
>> 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.

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.

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
Received on Tue May 28 2013 - 06:37:41 MDT