Issue 107 in lusca-cache: storeLocateVary: Not our vary marker object
codesite...@google.com
Owner: ----
Labels: Type-Defect Priority-Medium Version-1.0
New issue 107 by pyromania: storeLocateVary: Not our vary marker object
http://code.google.com/p/lusca-cache/issues/detail?id=107
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'
--
You received this message because you are listed in the owner
or CC fields of this issue, or because you starred this issue.
You may adjust your issue notification preferences at:
http://code.google.com/hosting/settings
codesite...@google.com
Comment #1 on issue 107 by adrian.chadd: storeLocateVary: Not our vary
marker object
http://code.google.com/p/lusca-cache/issues/detail?id=107
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.
Attachments:
store-vary.1.diff 1.1 KB
codesite...@google.com
Comment #2 on issue 107 by degreane: storeLocateVary: Not our vary marker
object
http://code.google.com/p/lusca-cache/issues/detail?id=107
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 -
codesite...@google.com
Labels: -Version-1.0 Version-Head
Comment #3 on issue 107 by adrian.chadd: storeLocateVary: Not our vary
marker object
http://code.google.com/p/lusca-cache/issues/detail?id=107
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;
}
codesite...@google.com
Comment #4 on issue 107 by degreane: storeLocateVary: Not our vary marker
object
http://code.google.com/p/lusca-cache/issues/detail?id=107
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. */
codesite...@google.com
Comment #5 on issue 107 by adrian.chadd: storeLocateVary: Not our vary
marker object
http://code.google.com/p/lusca-cache/issues/detail?id=107
gah, just use this diff. :)
Attachments:
t 715 bytes
codesite...@google.com
Comment #6 on issue 107 by adrian.chadd: storeLocateVary: Not our vary
marker object
http://code.google.com/p/lusca-cache/issues/detail?id=107
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.
codesite...@google.com
Comment #7 on issue 107 by david.bull.01: storeLocateVary: Not our vary
marker object
http://code.google.com/p/lusca-cache/issues/detail?id=107
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-NTLM,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_US', '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/Connect/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_US', '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/Connect/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.
codesite...@google.com
Comment #8 on issue 107 by adrian.chadd: storeLocateVary: Not our vary
marker object
http://code.google.com/p/lusca-cache/issues/detail?id=107
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. :)
codesite...@google.com
Status: Started
Comment #9 on issue 107 by adrian.chadd: storeLocateVary: Not our vary
marker object
http://code.google.com/p/lusca-cache/issues/detail?id=107
Added further debugging for this in r14806. Please update to this and
report!
codesite...@google.com
Comment #10 on issue 107 by adrian.chadd: storeLocateVary: Not our vary
marker object
http://code.google.com/p/lusca-cache/issues/detail?id=107
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.
codesite...@google.com
Comment #11 on issue 107 by nael.li...@gmail.com: storeLocateVary: Not our
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.