[squid-users] Lots of "Vary object loop!"
Sebastián Goicochea
sebag at vianetcon.com.ar
Mon Sep 14 21:16:09 UTC 2015
I could finally isolate the problem, it only happens if you are using
collapsed_forwarding.
If you want, you can use this script to replicate it:
#!/bin/bash
H='--header'
echo "With Firefox"
wget -d \
$H='Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8' \
$H='Accept-Encoding: gzip, deflate' \
$H='Accept-Language: en-us,en;q=0.5' \
$H='Cache-Control: max-age=0' \
$H='Connection: keep-alive' \
-U 'Mozilla/5.0 (Windows NT 5.1; rv:10.0.2) Gecko/20100101 Firefox/10.0.2' \
-O /dev/null \
$1
echo "With Chrome"
wget -d \
$H='Accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'\
$H='Accept-Charset:ISO-8859-1,utf-8;q=0.7,*;q=0.3'\
$H='Accept-Encoding:gzip,deflate,sdch'\
$H='Accept-Language:es-ES,es;q=0.8'\
$H='Cache-Control:no-cache'\
$H='Connection:keep-alive'\
$H='Pragma:no-cache'\
-U 'User-Agent:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.32
(KHTML, like Gecko) Chrome/27.0.1425.0 Safari/537.32 SUSE/27.0.1425.0'\
-O /dev/null \
$1
# End of script
script usage: ./wgets.sh
http://www.clarin.com/external-images/GranDTUnificada_5729dd7a1487678526c23516a5083661.jpg
acess.log output:
1442250327.403 22 192.168.2.222 TCP_MISS/200 3057 GET
http://www.clarin.com/external-images/GranDTUnificada_5729dd7a1487678526c23516a5083661.jpg
- HIER_DIRECT/200.42.136.212 image/jpeg [User-Agent: Mozilla/5.0
(Windows NT 5.1; rv:10.0.2) Gecko/20100101 Firefox/10.0.2\r\nAccept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\r\nHost:
www.clarin.com\r\nConnection: keep-alive\r\nAccept-Encoding: gzip,
deflate\r\nAccept-Language: en-us,en;q=0.5\r\nCache-Control:
max-age=0\r\n] [HTTP/1.1 200 OK\r\nDate: Mon, 14 Sep 2015 16:45:34
GMT\r\nPragma: no-cache\r\nVary:
Accept-Encoding,User-Agent\r\nContent-Type: image/jpeg\r\nCache-Control:
max-age=86400\r\nTransfer-Encoding: chunked\r\nConnection:
keep-alive\r\nAccept-Ranges: bytes\r\n\r]
1442250327.431 13 192.168.2.222 TCP_MISS/200 3057 GET
http://www.clarin.com/external-images/GranDTUnificada_5729dd7a1487678526c23516a5083661.jpg
- HIER_DIRECT/200.42.136.212 image/jpeg [User-Agent: Wget/1.12
(linux-gnu)\r\nAccept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8--header=Accept-Charset:ISO-8859-1,utf-8;q=0.7,*;q=0.3--header=Accept-Encoding:gzip,deflate,sdch--header=Accept-Language:es-ES,es;q=0.8--header=Cache-Control:no-cache--header=Connection:keep-alive--header=Pragma:no-cache-U\r\nHost:
www.clarin.com\r\nConnection: Keep-Alive\r\n] [HTTP/1.1 200 OK\r\nDate:
Mon, 14 Sep 2015 16:49:59 GMT\r\nPragma: no-cache\r\nVary:
Accept-Encoding,User-Agent\r\nContent-Type: image/jpeg\r\nCache-Control:
max-age=86400\r\nTransfer-Encoding: chunked\r\nConnection:
keep-alive\r\nAccept-Ranges: bytes\r\n\r]
cache.log output:
2015/09/14 14:05:01 kid1| clientProcessHit: Vary object loop!
2015/09/14 14:05:27 kid1| varyEvaluateMatch: Oops. Not a Vary match on
second attempt,
'http://www.clarin.com/external-images/GranDTUnificada_5729dd7a1487678526c23516a5083661.jpg'
'accept-encoding="gzip,%20deflate",
user-agent="Mozilla%2F5.0%20(Windows%20NT%205.1%3B%20rv%3A10.0.2)%20Gecko%2F20100101%20Firefox%2F10.0.2"'
2015/09/14 14:05:27 kid1| clientProcessHit: Vary object loop!
2015/09/14 14:05:27 kid1| varyEvaluateMatch: Oops. Not a Vary match on
second attempt,
'http://www.clarin.com/external-images/GranDTUnificada_5729dd7a1487678526c23516a5083661.jpg'
'accept-encoding, user-agent="Wget%2F1.12%20(linux-gnu)"'
2015/09/14 14:05:27 kid1| clientProcessHit: Vary object loop!
squid -v
Squid Cache: Version 3.5.4
Service Name: squid
configure options: '--prefix=/usr/local' '--datadir=/usr/local/share'
'--bindir=/usr/local/sbin' '--libexecdir=/usr/local/lib/squid'
'--localstatedir=/var' '--sysconfdir=/etc/squid3' '--enable-delay-pools'
'--enable-ssl' '--enable-ssl-crtd' '--enable-linux-netfilter'
'--enable-eui' '--enable-snmp' '--enable-gnuregex'
'--enable-ltdl-convenience' '--enable-removal-policies=lru heap'
'--enable-http-violations' '--with-openssl'
'--with-filedescriptors=24321' '--enable-poll' '--enable-epoll'
'--enable-storeio=ufs,aufs,diskd,rock' '--disable-ipv6'
What do you think? Is this the expected behaviour?
Thanks,
Sebastian
El 04/09/15 a las 14:27, Sebastián Goicochea escribió:
> Kinkie:
>
> Request:
> GET
> http://s.ytimg.com/yts/cssbin/www-pageframedelayloaded-vflYYEH8q.css
> HTTP/1.1
> User-Agent: Opera/9.80 (X11; Linux x86_64) Presto/2.12.388 Version/12.16
> Host: s.ytimg.com
> Accept: text/html, application/xml;q=0.9, application/xhtml+xml,
> image/png, image/webp, image/jpeg, image/gif, image/x-xbitmap, */*;q=0.1
> Accept-Language: es-ES,es;q=0.9,en;q=0.8
> Accept-Encoding: gzip, deflate
> Pragma: no-cache
> Cache-Control: no-cache
> Proxy-Connection: Keep-Alive
>
> Answer:
> HTTP/1.0 200 OK
> Vary: Accept-Encoding
> Content-Encoding: gzip
> Content-Type: text/css
> Last-Modified: Tue, 25 Aug 2015 08:34:05 GMT
> Date: Tue, 25 Aug 2015 20:25:51 GMT
> Expires: Wed, 24 Aug 2016 20:25:51 GMT
> Timing-Allow-Origin: https://www.youtube.com
> X-Content-Type-Options: nosniff
> Server: sffe
> Content-Length: 2974
> X-XSS-Protection: 1; mode=block
> Cache-Control: public, max-age=31536000
> Age: 853068
> X-Cache: MISS from localhost
> X-Cache: MISS from ns2
> X-Cache-Lookup: MISS from ns2:3138
> Via: 1.0 ns2:3138 (squid/2.6.STABLE21)
>
>
>
> Thanks,
> Sebastian
>
> El 03/09/15 a las 13:37, Kinkie escribió:
>> Hi,
>> do you think you could manage to capture the headers of the
>> response triggering that error?
>> I've been looking that up, but couldn't reprduce it.
>>
>> The good news is, it's mostly harmless: worst case scenario it will
>> cause a slow cache miss.
>>
>> Thanks
>>
>> On Thu, Sep 3, 2015 at 5:20 PM, Sebastián Goicochea
>> <sebag at vianetcon.com.ar> wrote:
>>> Amos, I spent a couple of days doing some test with the info you gave me:
>>>
>>> Retested emptying the cache several times, disabled the rewriter, different
>>> config files .. all I could think of
>>>
>>>
>>> Downloaded fresh 3.5.8 tar.gz (just in case it was some 3.5.4 thing) and
>>> compiled it using this configure options:
>>>
>>> Squid Cache: Version 3.5.8
>>> Service Name: squid
>>> configure options: '--prefix=/usr/local' '--datadir=/usr/local/share'
>>> '--bindir=/usr/local/sbin' '--libexecdir=/usr/local/lib/squid'
>>> '--localstatedir=/var' '--sysconfdir=/etc/squid3' '--enable-delay-pools'
>>> '--enable-ssl' '--enable-ssl-crtd' '--enable-linux-netfilter' '--enable-eui'
>>> '--enable-snmp' '--enable-gnuregex' '--enable-ltdl-convenience'
>>> '--enable-removal-policies=lru heap' '--enable-http-violations'
>>> '--with-openssl' '--with-filedescriptors=24321' '--enable-poll'
>>> '--enable-epoll' '--enable-storeio=ufs,aufs,diskd,rock' '--disable-ipv6'
>>>
>>>
>>>
>>> And the problem appeared again, I am suspicious that the problem is in the
>>> configuration, I even removed all my refresh patterns, but:
>>>
>>> 2015/09/02 15:03:42 kid1| varyEvaluateMatch: Oops. Not a Vary match on
>>> second attempt, 'http://assets.pinterest.com/js/pinit.js'
>>> 'accept-encoding="gzip,%20deflate"'
>>> 2015/09/02 15:03:42 kid1| clientProcessHit: Vary object loop!
>>> 2015/09/02 15:03:43 kid1| varyEvaluateMatch: Oops. Not a Vary match on
>>> second attempt, 'http://static.cmptch.com/v/lib/str.html'
>>> 'accept-encoding="gzip,%20deflate,%20sdch"'
>>> 2015/09/02 15:03:43 kid1| clientProcessHit: Vary object loop!
>>> 2015/09/02 15:03:43 kid1| varyEvaluateMatch: Oops. Not a Vary match on
>>> second attempt,
>>> 'http://pstatic.bestpriceninja.com/nwp/v0_0_773/release/Shared/Extra/IFrameStoreReciever.js'
>>> 'accept-encoding="gzip,%20deflate,%20sdch"'
>>> 2015/09/02 15:03:43 kid1| clientProcessHit: Vary object loop!
>>> 2015/09/02 15:03:59 kid1| varyEvaluateMatch: Oops. Not a Vary match on
>>> second attempt, 'http://static.xvideos.com/v2/css/xv-video-styles.css?v=7'
>>> 'accept-encoding="gzip,deflate"'
>>> 2015/09/02 15:03:59 kid1| clientProcessHit: Vary object loop!
>>> 2015/09/02 15:03:59 kid1| varyEvaluateMatch: Oops. Not a Vary match on
>>> second attempt, 'http://s7.addthis.com/js/250/addthis_widget.js'
>>> 'accept-encoding="gzip,deflate"'
>>> 2015/09/02 15:03:59 kid1| clientProcessHit: Vary object loop!
>>>
>>>
>>>
>>> Later on I tested it with this short config file and the problem persisted:
>>>
>>> http_access allow localhost manager
>>> http_access deny manager
>>> acl purge method PURGE
>>> http_access allow purge localhost
>>> http_access deny purge
>>> acl all src all
>>> acl localhost src 127.0.0.1/32
>>> acl localnet src 127.0.0.0/8
>>> acl Safe_ports port 80
>>> acl snmppublic snmp_community public
>>> http_access deny !Safe_ports
>>> http_access allow all
>>> dns_v4_first on
>>> cache_mem 1024 MB
>>> maximum_object_size_in_memory 64 KB
>>> memory_cache_mode always
>>> maximum_object_size 150000 KB
>>> minimum_object_size 100 bytes
>>> collapsed_forwarding on
>>> logfile_rotate 5
>>> mime_table /etc/squid3/mime.conf
>>> debug_options ALL,1
>>> store_id_access deny all
>>> store_id_bypass on
>>> refresh_pattern ^ftp: 1440 20% 10080
>>> refresh_pattern ^gopher: 1440 0% 1440
>>> refresh_pattern ^http:\/\/movies\.apple\.com 86400 20% 86400
>>> override-expire override-lastmod ignore-no-cache ignore-private
>>> ignore-reload
>>> refresh_pattern -i \.flv$ 10080 90% 999999
>>> ignore-no-cache override-expire ignore-private
>>> refresh_pattern -i \.mov$ 10080 90% 999999
>>> ignore-no-cache override-expire ignore-private
>>> refresh_pattern windowsupdate.com/.*\.(cab|exe) 4320 100% 43200
>>> reload-into-ims
>>> refresh_pattern download.microsoft.com/.*\.(cab|exe) 4320 100% 43200
>>> reload-into-ims
>>> refresh_pattern -i \.(deb|rpm|exe|zip|tar|tgz|ram|rar|bin|ppt|doc|pdf|tiff)$
>>> 10080 90% 43200 override-expire ignore-no-cache ignore-private
>>> refresh_pattern -i (/cgi-bin/) 0 0% 0
>>> refresh_pattern . 0 20% 4320
>>> quick_abort_min 0 KB
>>> quick_abort_max 0 KB
>>> quick_abort_pct 100
>>> range_offset_limit 0
>>> negative_ttl 1 minute
>>> negative_dns_ttl 1 minute
>>> read_ahead_gap 128 KB
>>> request_header_max_size 100 KB
>>> reply_header_max_size 100 KB
>>> via off
>>> acl apache rep_header Server ^Apache
>>> half_closed_clients off
>>> cache_mgr webmaster
>>> cache_effective_user squid
>>> cache_effective_group squid
>>> httpd_suppress_version_string on
>>> snmp_access allow snmppublic localhost
>>> snmp_access deny all
>>> snmp_incoming_address 127.0.0.1
>>> error_directory /etc/squid3/errors/English
>>> max_filedescriptors 65535
>>> ipcache_size 1024
>>> forwarded_for off
>>> log_icp_queries off
>>> icp_access allow localnet
>>> icp_access deny all
>>> htcp_access allow localnet
>>> htcp_access deny all
>>> digest_rebuild_period 15 minutes
>>> digest_rewrite_period 15 minutes
>>> strip_query_terms off
>>> max_open_disk_fds 150
>>> cache_replacement_policy heap LFUDA
>>> memory_pools off
>>> http_port 9001
>>> http_port 901 tproxy
>>> if ${process_number} = 1
>>> access_log stdio:/var/log/squid/1/access.log squid
>>> cache_log /var/log/squid/1/cache.log
>>> cache_store_log none
>>> cache_swap_state /var/log/squid/1/%s.swap.state
>>> else
>>> access_log none
>>> cache_log /dev/null
>>> endif
>>> pid_filename /var/run/squid1.pid
>>> visible_hostname localhost
>>> snmp_port 1611
>>> icp_port 3131
>>> htcp_port 4828
>>> cachemgr_passwd admin thisisnotmyrealpassword
>>> memory_cache_shared off
>>> cache_dir rock /cache1/rock1 256 min-size=100 max-size=3000
>>> cache_dir rock /cache1/rock2 2000 min-size=3000 max-size=20000
>>> cache_dir diskd /cache1/diskd2 60000 16 256 min-size=20000 max-size=200000
>>> cache_dir diskd /cache2/2 100000 16 256 min-size=200000 max-size=1048576
>>> cache_dir diskd /cache2/1 680000 16 256 min-size=1048576
>>>
>>>
>>>
>>> Any ideas what could be wrong?
>>>
>>>
>>>
>>> Thanks,
>>> Sebastian
>>>
>>>
>>>
>>>
>>>
>>>
>>> El 26/08/15 a las 17:15, Amos Jeffries escribió:
>>>
>>> On 27/08/2015 7:53 a.m., Sebastián Goicochea wrote:
>>>
>>> After I sent you my previous email, I continued investigating the
>>> subject .. I made a change in the source code as follows:
>>>
>>> File: /src/http.cc
>>>
>>> HttpStateData::haveParsedReplyHeaders()
>>> {
>>> .
>>> .
>>> ##### THIS IS NEW STUFF ###########
>>> if (rep->header.has(HDR_VARY)) {
>>> rep->header.delById(HDR_VARY);
>>> debugs(11,3, "Vary detected. Hack Cleaning it up");
>>> }
>>> ##### END OF NEW STUFF ###########
>>>
>>> #if X_ACCELERATOR_VARY
>>> if (rep->header.has(HDR_X_ACCELERATOR_VARY)) {
>>> rep->header.delById(HDR_X_ACCELERATOR_VARY);
>>> debugs(11,3, "HDR_X_ACCELERATOR_VARY Vary detected. Hack Cleaning it
>>> up");
>>> }
>>> #endif
>>> .
>>> .
>>>
>>>
>>> Deleting Vary from the header at this point gives me hits in every
>>> object I test (that previously didn't hit) .. web browser never receives
>>> the Vary in the response header.
>>> Now I read your answer and you say that this is a critical validity
>>> check and that worries me. Taking away the vary altogether at this point
>>> could lead to the problems that you described? If that is the case .. I
>>> have to investigate other alternatives.
>>>
>>> I'll have to look into that function when I'm back at the code later to
>>> confirm this. But IIRC that function is acting directly on a freshly
>>> received reply message. You are not removing the validity check, you are
>>> removing Squids ability to see that it is a Vary object at all. So it is
>>> never even cached as one.
>>>
>>> The side effect of that is that clients asking for non-gzip can get the
>>> cached gzip copy, etc. but at least its the same URL. So the security
>>> risks are gone. But the user experience is not always good either way.
>>>
>>> Amos
>>>
>>> _______________________________________________
>>> squid-users mailing list
>>> squid-users at lists.squid-cache.org
>>> http://lists.squid-cache.org/listinfo/squid-users
>>>
>>>
>>>
>>>
>>> _______________________________________________
>>> squid-users mailing list
>>> squid-users at lists.squid-cache.org
>>> http://lists.squid-cache.org/listinfo/squid-users
>>>
>
>
>
>
> _______________________________________________
> squid-users mailing list
> squid-users at lists.squid-cache.org
> http://lists.squid-cache.org/listinfo/squid-users
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20150914/8058292f/attachment-0001.html>
More information about the squid-users
mailing list