storeLocateVary: Not our vary marker object

[GoogleCodeExporter]

What steps will reproduce the problem?
1. Unknown
2.
3.

What is the expected output? What do you see instead?
No error in cache log. 

What version of the product are you using? On what operating system?
LUSCA_HEAD-r14535 Debian 5.0.1

Please provide any additional information below.

The error always mentions accept-encoding="gzip,deflate so I'm wondering 
if its related to Gzip compression. It happends very frequently with 400 
users on the proxy. 

2010/04/12 21:37:14| storeLocateVary: Not our vary marker object, 
7642FF1728147A73DA9064A2C33837ED 
= 'http://an.tacoda.net/an/cda1.js', 'accept-encoding="gzip,%
20deflate"'/'gzip, deflate'
2010/04/12 21:37:14| storeLocateVary: Not our vary marker object, 
A734F7F48C13B221F0A44E8AD841DA0D 
= 'http://an.tacoda.net/an/tpp.html', 'accept-encoding="gzip,%
20deflate"'/'gzip, deflate'
2010/04/12 21:37:15| storeLocateVary: Not our vary marker object, 
E80B968A159BB3AC276995C5C6C452B6 
= 'http://an.tacoda.net/an/tpp3.js', 'accept-encoding="gzip,%
20deflate"'/'gzip, deflate'
2010/04/12 21:37:23| storeLocateVary: Not our vary marker object, 
F6E05E2A9971D86A87E7100BCE85CB3D 
= 'http://s7.addthis.com/js/250/addthis_widget.js', 'accept-
encoding="gzip,deflate,sdch"'/'gzip,deflate,sdch'
2010/04/12 21:38:06| idnsReadTcp: Short response from nameserver 1 for 
afv.pplive.com.
2010/04/12 21:38:09| storeLocateVary: Not our vary marker object, 
BF1F675396CC7206A74B9FE5C1FA172A 
= 'http://static.ak.fbcdn.net/rsrc.php/zBCZC/hash/6iwl7nqi.css', 'accept-
encoding="gzip,%20deflate"'/'gzip, deflate'
2010/04/12 21:38:21| storeLocateVary: Not our vary marker object, 
38A7AB8DA5F761ADE6E77A62CEB908B6 
= 'http://static.ak.fbcdn.net/rsrc.php/z70NZ/hash/cqp62s8o.js', 'accept-
encoding="gzip,%20deflate"'/'gzip, deflate'
2010/04/12 21:38:22| storeLocateVary: Not our vary marker object, 
1E739F7CA9D4E9AE1CCE98CC4994C539 
= 'http://static.ak.fbcdn.net/rsrc.php/z2KLB/hash/68rhih7w.css', 'accept-
encoding="gzip,%20deflate"'/'gzip, deflate'
2010/04/12 21:38:22| storeLocateVary: Not our vary marker object, 
10E345FBE0F121942E59FBFF9CE4606F 
= 'http://static.ak.fbcdn.net/rsrc.php/z5DUA/hash/d2f1n3c0.js', 'accept-
encoding="gzip,%20deflate"'/'gzip, deflate'
2010/04/12 21:38:22| storeLocateVary: Not our vary marker object, 
38A7AB8DA5F761ADE6E77A62CEB908B6 
= 'http://static.ak.fbcdn.net/rsrc.php/z70NZ/hash/cqp62s8o.js', 'accept-
encoding="gzip,%20deflate"'/'gzip, deflate'
2010/04/12 21:38:22| storeLocateVary: Not our vary marker object, 
BA7716649EC1EAB1EDC2BEB786B59ADC 
= 'http://static.ak.fbcdn.net/rsrc.php/z7LZY/hash/5vjds43u.js', 'accept-
encoding="gzip,%20deflate"'/'gzip, deflate'
2010/04/12 21:38:23| storeLocateVary: Not our vary marker object, 
180BB5BF6F1311E8A95356186A410F19 
= 'http://static.ak.fbcdn.net/rsrc.php/z6F6I/hash/bxdm2bja.js', 'accept-
encoding="gzip,%20deflate"'/'gzip, deflate'

Original issue reported on code.google.com by pyroma...@gmail.com on 12 Apr 2010 at 9:44

[GoogleCodeExporter]

Hi,

Please apply the attached patch and get back to me. I'm trying to understand 
exactly what conditions occur for this to happen.

This patch logs the vary marker header which it's comparing against. I really 
would like to see what it thinks the content-type is.

Original comment by adrian.c...@gmail.com on 22 Jun 2010 at 9:24

Attachments:

• store-vary.1.diff

[GoogleCodeExporter]

After applying the patch Squid started to restart frequently after 10 ~ 20 
minutes 

inspecting the cache.log i got 
2010/06/26 17:39:38| clientTryParseRequest: FD 321 (81.25.139.16:38143) Invalid 
Request
2010/06/26 17:39:38| clientTryParseRequest: FD 197 (81.25.139.16:38142) Invalid 
Request
2010/06/26 17:40:40| clientTryParseRequest: FD 166 (81.25.139.16:19099) Invalid 
Request
2010/06/26 17:41:07| clientTryParseRequest: FD 329 (81.25.139.16:4113) Invalid 
Request
2010/06/26 17:41:07| clientTryParseRequest: FD 126 (81.25.139.16:4114) Invalid 
Request
2010/06/26 17:41:11| clientTryParseRequest: FD 222 (81.25.139.16:19102) Invalid 
Request
2010/06/26 17:41:14| storeLocateVary: Not our vary marker object, 
5628A2D8E10D67485240C2363E98EB9E = 
'http://static.ak.fbcdn.net/rsrc.php/z3J8R/hash/en6wnfcw.css', 
vary_data='accept-encoding="gzip,deflate,sdch"' ; 
accept_encoding='gzip,deflate,sdch'
2010/06/26 17:41:14| storeLocateVary: local content type: 'FATAL: Received 
Segment Violation...dying.
2010/06/26 17:41:14| storeDirWriteCleanLogs: Starting...
2010/06/26 17:41:14| WARNING: Closing open FD  101
2010/06/26 17:41:14| commSetEvents: epoll_ctl(EPOLL_CTL_DEL): failed on fd=101: 
(1) Operation not permitted
2010/06/26 17:41:14|     65536 entries written so far.
2010/06/26 17:41:14|    131072 entries written so far.
2010/06/26 17:41:14|    196608 entries written so far.
2010/06/26 17:41:14|    262144 entries written so far.
2010/06/26 17:41:14|    327680 entries written so far.
2010/06/26 17:41:14|    393216 entries written so far.
- Show quoted text -

Original comment by degreane@gmail.com on 26 Jun 2010 at 5:18

[GoogleCodeExporter]

Yeah that patch is broken. Try this:

Index: src/store_vary.c
===================================================================
--- src/store_vary.c    (revision 14716)
+++ src/store_vary.c    (working copy)
@@ -585,10 +585,18 @@
     state->seen_offset = offset;
     if (!strLen2(e->mem_obj->reply->content_type) || strCmp(e->mem_obj->reply->content_type, "x-squid-internal/vary") != 0) {
        /* This is not our Vary marker object. Bail out. */
-       debug(33, 1) ("storeLocateVary: Not our vary marker object, %s = '%s', 
'%s'/'%.*s'\n",
+       debug(33, 1) ("storeLocateVary: Not our vary marker object, %s = '%s', 
vary_data='%s' ; accept_encoding='%.*s'\n",
            storeKeyText(e->hash.key), e->mem_obj->url, vary_data,
            strLen2(accept_encoding) ? strLen2(accept_encoding) : 1,
            strBuf2(accept_encoding) ? strBuf2(accept_encoding) : "-");
+
+       if (strLen2(e->mem_obj->reply->content_type))
+               debug(33, 1) ("storeLocateVary: local content type: '%.*s'\n",
+                   strLen2(e->mem_obj->reply->content_type),
+                   strBuf2(e->mem_obj->reply->content_type));
+       else
+               debug(33, 1) ("storeLocateVary: reply->content_type length is 
0, why!?\n");
+
        storeLocateVaryCallback(state);
        return;
     }

Original comment by adrian.c...@gmail.com on 29 Jun 2010 at 4:47

• Added labels: Version-Head
• Removed labels: Version-1.0

[GoogleCodeExporter]

I have tried your new patch look what it gives when patching.

patch -p0 <patch.diff 
patching file src/store_vary.c
Hunk #1 FAILED at 585.
1 out of 1 hunk FAILED -- saving rejects to file src/store_vary.c.rej

and src/store_vary.c.rej contains
***************
*** 585,594 ****
      state->seen_offset = offset;
      if (!strLen2(e->mem_obj->reply->content_type) || strCmp(e->mem_obj->reply->content_type, "x-squid-internal/vary") != 0) {
         /* This is not our Vary marker object. Bail out. */
-        debug(33, 1) ("storeLocateVary: Not our vary marker object, %s = '%s', 
'%s'/'%.*s'\n",
             storeKeyText(e->hash.key), e->mem_obj->url, vary_data,
             strLen2(accept_encoding) ? strLen2(accept_encoding) : 1,
             strBuf2(accept_encoding) ? strBuf2(accept_encoding) : "-");
         storeLocateVaryCallback(state);
         return;
      }
--- 585,602 ----
      state->seen_offset = offset;
      if (!strLen2(e->mem_obj->reply->content_type) || strCmp(e->mem_obj->reply->content_type, "x-squid-internal/vary") != 0) {
         /* This is not our Vary marker object. Bail out. */
+        debug(33, 1) ("storeLocateVary: Not our vary marker object, %s = '%s', 
vary_data='%s' ; accept_encoding='%.*s'\n",
             storeKeyText(e->hash.key), e->mem_obj->url, vary_data,
             strLen2(accept_encoding) ? strLen2(accept_encoding) : 1,
             strBuf2(accept_encoding) ? strBuf2(accept_encoding) : "-");
+ 
+        if (strLen2(e->mem_obj->reply->content_type))
+                debug(33, 1) ("storeLocateVary: local content type: '%.*s'\n",
+                    strLen2(e->mem_obj->reply->content_type),
+                    strBuf2(e->mem_obj->reply->content_type));
+        else
+                debug(33, 1) ("storeLocateVary: reply->content_type length is 
0, why!?\n");
+ 
         storeLocateVaryCallback(state);
         return;
      }

Original comment by degreane@gmail.com on 29 Jun 2010 at 10:39

[GoogleCodeExporter]

gah, just use this diff. :)

Original comment by adrian.c...@gmail.com on 29 Jun 2010 at 11:05

Attachments:

• t

[GoogleCodeExporter]

Have you had any further luck? I'm still trying to understand the exact set of 
circumstances which is giving rise to this behaviour. I can take a stab at the 
dark and say it's a potentially bad use of Vary, but it'd be complete 
conjecture.

Original comment by adrian.c...@gmail.com on 6 Aug 2010 at 6:42

[GoogleCodeExporter]

I take it there is currently no solution to this?
I have noticed that I have started receiving these messages in my cache.log 
also.
I'm running CentOS 5.5 Final 2.6.18-194.17.1.el5 i686 and Squid Cache: Version 
2.6.STABLE21
configure options:  '--build=i686-redhat-linux-gnu' 
'--host=i686-redhat-linux-gnu' '--target=i386-redhat-linux-gnu' 
'--program-prefix=' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' 
'--sbindir=/usr/sbin' '--sysconfdir=/etc' '--includedir=/usr/include' 
'--libdir=/usr/lib' '--libexecdir=/usr/libexec' '--sharedstatedir=/usr/com' 
'--mandir=/usr/share/man' '--infodir=/usr/share/info' '--exec_prefix=/usr' 
'--bindir=/usr/sbin' '--libexecdir=/usr/lib/squid' '--localstatedir=/var' 
'--datadir=/usr/share' '--sysconfdir=/etc/squid' '--enable-arp-acl' 
'--enable-epoll' '--enable-snmp' '--enable-removal-policies=heap,lru' 
'--enable-storeio=aufs,coss,diskd,null,ufs' '--enable-ssl' 
'--with-openssl=/usr/kerberos' '--enable-delay-pools' 
'--enable-linux-netfilter' '--with-pthreads' 
'--enable-ntlm-auth-helpers=SMB,fakeauth' 
'--enable-external-acl-helpers=ip_user,ldap_group,unix_group,wbinfo_group' 
'--enable-auth=basic,digest,ntlm,negotiate' 
'--enable-negotiate-auth-helpers=squid_kerb_auth' 
'--enable-digest-auth-helpers=password' '--with-winbind-auth-challenge' 
'--enable-useragent-log' '--enable-referer-log' '--disable-dependency-tracking' 
'--enable-cachemgr-hostname=localhost' '--enable-underscores' 
'--enable-basic-auth-helpers=LDAP,MSNT,NCSA,PAM,SMB,YP,getpwnam,multi-domain-NTL
M,SASL' '--enable-cache-digests' '--enable-ident-lookups' '--with-large-files' 
'--enable-follow-x-forwarded-for' '--enable-wccpv2' '--enable-fd-config' 
'--with-maxfd=16384' 'build_alias=i686-redhat-linux-gnu' 
'host_alias=i686-redhat-linux-gnu' 'target_alias=i386-redhat-linux-gnu' 
'CFLAGS=-D_FORTIFY_SOURCE=2 -fPIE -Os -g -pipe -fsigned-char' 'LDFLAGS=-pie'

gzip version 1.3.5

Excerpt from cache.log

2010/10/15 03:16:20| storeLocateVary: Not our vary marker object, 
F617F5402D4FB09D207D95EA71AF9978 = 
'http://static.ak.fbcdn.net/connect.php/css/share-button-css', 
'accept-encoding'/'-'
2010/10/15 03:17:01| storeLocateVary: Not our vary marker object, 
F617F5402D4FB09D207D95EA71AF9978 = 
'http://static.ak.fbcdn.net/connect.php/css/share-button-css', 
'accept-encoding'/'-'
2010/10/15 03:19:01| storeLocateVary: Not our vary marker object, 
F617F5402D4FB09D207D95EA71AF9978 = 
'http://static.ak.fbcdn.net/connect.php/css/share-button-css', 
'accept-encoding'/'-'
2010/10/15 03:19:24| storeLocateVary: Not our vary marker object, 
F617F5402D4FB09D207D95EA71AF9978 = 
'http://static.ak.fbcdn.net/connect.php/css/share-button-css', 
'accept-encoding'/'-'
2010/10/15 03:20:10| storeLocateVary: Not our vary marker object, 
F617F5402D4FB09D207D95EA71AF9978 = 
'http://static.ak.fbcdn.net/connect.php/css/share-button-css', 
'accept-encoding'/'-'
2010/10/15 03:37:15| storeLocateVary: Not our vary marker object, 
C7E5FE01CD93D02622687D5F8ED67C4F = 'http://platform.twitter.com/widgets.js', 
'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 04:26:36| storeLocateVary: Not our vary marker object, 
8D56CEAEF25E728F8DBBC9D4F7B85B1E = 
'http://static.ak.connect.facebook.com/js/api_lib/v0.4/FeatureLoader.js.php/en_U
S', 'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 04:26:38| storeLocateVary: Not our vary marker object, 
924FD6FE07BB3A5EB4342EBD122CDF7B = 
'http://resources.news.com.au/cs/adelaidenow/images/favicon.ico', 
'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 05:04:39| storeLocateVary: Not our vary marker object, 
C7E5FE01CD93D02622687D5F8ED67C4F = 'http://platform.twitter.com/widgets.js', 
'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 05:56:27| storeLocateVary: Not our vary marker object, 
36093CE3F455EC98D9F33558B062F9F9 = 
'http://static.ak.connect.facebook.com/connect.php/en_US/js/Api/CanvasUtil/Conne
ct/XFBML', 'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 06:02:31| storeLocateVary: Not our vary marker object, 
E9B6EC80EC2E797A97973C73E335A8A1 = 
'http://resources.news.com.au/cs/adelaidenow/css/modules.css', 
'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 06:07:09| storeLocateVary: Not our vary marker object, 
E915700F5073F851AA7A1F34A83A5FD1 = 
'http://resources.news.com.au/cs/network/css/layout-2plus1.css', 
'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 06:10:54| storeLocateVary: Not our vary marker object, 
190497AD5FE079088A245F5052B825E6 = 'http://www.dailymail.co.uk/dwr/engine.js', 
'accept-encoding'/'-'
2010/10/15 06:13:10| storeLocateVary: Not our vary marker object, 
190497AD5FE079088A245F5052B825E6 = 'http://www.dailymail.co.uk/dwr/engine.js', 
'accept-encoding'/'-'
2010/10/15 06:20:22| storeLocateVary: Not our vary marker object, 
190497AD5FE079088A245F5052B825E6 = 'http://www.dailymail.co.uk/dwr/engine.js', 
'accept-encoding'/'-'
2010/10/15 06:23:06| storeLocateVary: Not our vary marker object, 
190497AD5FE079088A245F5052B825E6 = 'http://www.dailymail.co.uk/dwr/engine.js', 
'accept-encoding'/'-'
2010/10/15 06:32:04| storeLocateVary: Not our vary marker object, 
DF0F45A5DEEC7BB16A9CCA5D0BC37C12 = 
'http://images.icnetwork.co.uk/js/r2/preDisplay.js', 'accept-encoding'/'-'
2010/10/15 06:40:12| storeLocateVary: Not our vary marker object, 
DF0F45A5DEEC7BB16A9CCA5D0BC37C12 = 
'http://images.icnetwork.co.uk/js/r2/preDisplay.js', 'accept-encoding'/'-'
2010/10/15 06:41:52| storeLocateVary: Not our vary marker object, 
7458B85087DAAAD5ABA866BF72728114 = 
'http://images.icnetwork.co.uk/css/icnetwork/tmKytemasterhome.css', 
'accept-encoding'/'-'
2010/10/15 06:44:30| storeLocateVary: Not our vary marker object, 
190497AD5FE079088A245F5052B825E6 = 'http://www.dailymail.co.uk/dwr/engine.js', 
'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 06:56:23| storeLocateVary: Not our vary marker object, 
E915700F5073F851AA7A1F34A83A5FD1 = 
'http://resources.news.com.au/cs/network/css/layout-2plus1.css', 
'accept-encoding="gzip,deflate,sdch"'/'-'
2010/10/15 07:11:02| storeLocateVary: Not our vary marker object, 
71E204C8F694DAEF97A848FDEEEF9AD7 = 
'http://resources1.news.com.au/cs/js/site-adelaidenow-min.js', 
'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 07:11:02| storeLocateVary: Not our vary marker object, 
E915700F5073F851AA7A1F34A83A5FD1 = 
'http://resources.news.com.au/cs/network/css/layout-2plus1.css', 
'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 07:11:03| storeLocateVary: Not our vary marker object, 
E9B6EC80EC2E797A97973C73E335A8A1 = 
'http://resources.news.com.au/cs/adelaidenow/css/modules.css', 
'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 07:11:10| storeLocateVary: Not our vary marker object, 
8D56CEAEF25E728F8DBBC9D4F7B85B1E = 
'http://static.ak.connect.facebook.com/js/api_lib/v0.4/FeatureLoader.js.php/en_U
S', 'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 07:11:10| storeLocateVary: Not our vary marker object, 
36093CE3F455EC98D9F33558B062F9F9 = 
'http://static.ak.connect.facebook.com/connect.php/en_US/js/Api/CanvasUtil/Conne
ct/XFBML', 'accept-encoding="gzip,%20deflate"'/'-'
2010/10/15 07:14:56| storeLocateVary: Not our vary marker object, 
E915700F5073F851AA7A1F34A83A5FD1 = 
'http://resources.news.com.au/cs/network/css/layout-2plus1.css', 
'accept-encoding="gzip,%20deflate"'/'-'

I have cleared the cache but to no avail. 

Original comment by david.bu...@gmail.com on 14 Oct 2010 at 9:50

[GoogleCodeExporter]

David, I need to know exactly what's going on in order to fix it. I don't have 
a way of reproducing it at home. It seems to require many more real users 
through the proxy.

What it -looks- like is that some requests include the Vary: stuff, and so the 
cache stores a Vary: object for that particular URL and then sub-objects under 
that; some requests don't and that particular URL gets a raw object stored. 
Whatever order this is occuring with is creeping out Squid/Lusca.

I'd love to know precisely how to replicate it. :)

Original comment by adrian.c...@gmail.com on 19 Oct 2010 at 2:14

[GoogleCodeExporter]

Added further debugging for this in r14806. Please update to this and report!

Original comment by adrian.c...@gmail.com on 19 Oct 2010 at 2:22

• Changed state: Started

[GoogleCodeExporter]

Here's an example - turns out I added the debugging and forgot, so content-type 
is doubled up:

2010/10/19 10:21:59| storeLocateVary: Not our vary marker object, 
0040D0DC31D99EF71C3CA4D1226EEC62 = 
'http://www.xinhuanet.com/english2010/static/css.css', 
vary_data='accept-encoding="gzip,%20deflate"' ; content-type: 'text/css' ; 
accept_encoding='-'
2010/10/19 10:21:59| storeLocateVary: local content type: 'text/css'
2010/10/19 10:21:59| storeLocateVary: Not our vary marker object, 
2C3AB28DD1F6C14868083A861F54E857 = 
'http://www.xinhuanet.com/english2010/static/xilan.css', 
vary_data='accept-encoding="gzip,%20deflate"' ; content-type: 'text/css' ; 
accept_encoding='-'
2010/10/19 10:21:59| storeLocateVary: local content type: 'text/css'
2010/10/19 10:21:59| storeLocateVary: Not our vary marker object, 
5AA2A61D55392004AB27E3F0ED4CA053 = 
'http://www.xinhuanet.com/english2010/static/dp.js', 
vary_data='accept-encoding="gzip,%20deflate"' ; content-type: 
'application/x-javascript' ; accept_encoding='-'
2010/10/19 10:21:59| storeLocateVary: local content type: 
'application/x-javascript'
2010/10/19 10:21:59| storeLocateVary: Not our vary marker object, 
C307762E3D32F224E610329EB6401B0C = 
'http://www.xinhuanet.com/english2010/static/check.js', 
vary_data='accept-encoding="gzip,%20deflate"' ; content-type: 
'application/x-javascript' ; accept_encoding='-'
2010/10/19 10:21:59| storeLocateVary: local content type: 
'application/x-javascript'
2010/10/19 10:22:00| storeLocateVary: Not our vary marker object, 
0040D0DC31D99EF71C3CA4D1226EEC62 = 
'http://www.xinhuanet.com/english2010/static/css.css', 
vary_data='accept-encoding="gzip,%20deflate"' ; content-type: 'text/css' ; 
accept_encoding='-'
2010/10/19 10:22:00| storeLocateVary: local content type: 'text/css'

See? The reply content-type of the object is a non-vary object - so something's 
replied to this object with a non-Vary reply and the cache has stored that. A 
subsequent request is for a Vary object .. but as I said, an earlier reply 
didn't indicate it was a Vary response.

So, it's harmless. I now know why; but it's harmless.

Original comment by adrian.c...@gmail.com on 19 Oct 2010 at 2:28

[GoogleCodeExporter]

I try to this patch ti my LUSCA_HEAD-r14809, but not worked

root@proxy:/home/LUSCA_HEAD-r14809
can't find file to patch at input line 5
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|Index: store_vary.c
|===================================================================
|--- store_vary.c       (revision 14718)
|+++ store_vary.c       (working copy)
--------------------------
File to patch: src/store_vary.c
patching file src/store_vary.c
Hunk #1 FAILED at 589.
1 out of 1 hunk FAILED -- saving rejects to file src/store_vary.c.rej

Original comment by nael.lilik on 11 May 2012 at 3:59