[squid-users] Lots of "Vary object loop!"

[Amos Jeffries]

On 15/09/2015 9:16 a.m., Sebastián Goicochea wrote:
> 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
> 

That script is not doing what you think it is.

The requests are being made in series with the first one finishing
before the second starts. Your access.log timing confirms that with a
whole 18ms between the two requests.

So I dont think this script is actually triggering the collapsed
forwarding behaviour. Or it should not be if it is.


Also, look closely for the "\r\n" between headers.

[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]


> 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!
> 

> 
> What do you think? Is this the expected behaviour?
> 

There is something slightly odd. I'm not sure if its wrong exactly, but
definitely odd.


Its not clear if the cache.log output is from the first or second
request. I assume (big IF) that above cache.log is the first one finding
some prior Firefox entry, then the second one finding the first ones entry.

Its very weird that the second one gets "Not a Vary match". The lookups
should have been the same regardless of your script breakage.

Amos