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
