On Tue, May 28, 2013 at 9:37 AM, Amos Jeffries <squid3@xxxxxxxxxxxxx> 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?