Search squid archive

Re: Lots of "Vary object loop!"

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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@xxxxxxxxxxxxxxxx> 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@xxxxxxxxxxxxxxxxxxxxx
http://lists.squid-cache.org/listinfo/squid-users




_______________________________________________
squid-users mailing list
squid-users@xxxxxxxxxxxxxxxxxxxxx
http://lists.squid-cache.org/listinfo/squid-users





_______________________________________________
squid-users mailing list
squid-users@xxxxxxxxxxxxxxxxxxxxx
http://lists.squid-cache.org/listinfo/squid-users


_______________________________________________
squid-users mailing list
squid-users@xxxxxxxxxxxxxxxxxxxxx
http://lists.squid-cache.org/listinfo/squid-users

[Index of Archives]     [Linux Audio Users]     [Samba]     [Big List of Linux Books]     [Linux USB]     [Yosemite News]

  Powered by Linux