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

Any suggestions?

On Sun, May 26, 2013 at 10:00 PM, Alex Domoradov <alex.hha_at_gmail.com> 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
>
> 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.
>
> 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?
>
> Thanks in advance
Received on Mon May 27 2013 - 17:17:47 MDT