Amos, any idea? On Tue, May 28, 2013 at 1:00 PM, Alex Domoradov <alex.hha@xxxxxxxxx> wrote: > 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?
