Open GoogleCodeExporter opened 8 years ago
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:
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
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
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
gah, just use this diff. :)
Original comment by adrian.c...@gmail.com
on 29 Jun 2010 at 11:05
Attachments:
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
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
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
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
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
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
Original issue reported on code.google.com by
pyroma...@gmail.com
on 12 Apr 2010 at 9:44