Valid document was not found in the cache and "only-if-cached" directive was specified. Sibling issues

GoogleCodeExporter commented 9 years ago

I have 8 sibling caches with single upstream squid.
Those siblings talk over multicast ICP. Also i have one "away" sibling over
unicast. Also i have parent for specific content, i guess not important for
this case.

I start to receive complaints that users getting error on random content:
"Valid document was not found in the cache and "only-if-cached" directive
was specified."

As i understand, one of caches returning ICP HIT, but in fact doesn't have
this document in cache.

Here is debug info. HTTP request, reply. If i request data over squidclient
- those "faulty" sibling will not return HIT. No idea why...
10.0.1.36 "faulty", 10.0.1.34 - just unit which receive request from me.
I notice that hosts getting HIT from each other in random fashion. It is
really something weird.

Here is related part of config:

mcast_groups    224.9.9.9
cache_peer      224.9.9.9               multicast       8080 3130 ttl=8
cache_peer      10.0.1.34               sibling         8080 3130
multicast-responder proxy-only
cache_peer      10.0.1.35               sibling         8080 3130
multicast-responder proxy-only
cache_peer      10.0.1.37               sibling         8080 3130
multicast-responder proxy-only
cache_peer      10.0.1.39               sibling         8080 3130
multicast-responder proxy-only
cache_peer      10.0.1.40               sibling         8080 3130
multicast-responder proxy-only
cache_peer      10.0.1.41               sibling         8080 3130
multicast-responder proxy-only
cache_peer      10.0.1.42               sibling         8080 3130
multicast-responder proxy-only
cache_peer      194.146.153.28          sibling         8080 3130 proxy-only

cache_peer 194.146.153.12 parent 8080 3130 proxy-only no-query weight=10
cache_peer 10.0.1.38 parent 8080    3130 no-query weight=1

T 192.168.0.176:51391 -> 10.0.1.34:8080 [AP]
  POST http://disqus.com/comments/register/ HTTP/1.1..Host:
disqus.com..User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.2.3)
Gecko/20100406 Gentoo Firefox/3.6.3..A
  ccept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8..Accept-Language
:
en,ru;q=0.7,en-us;q=0.3..Accept-Encoding: gzip,deflate..Accept-Charset:
ISO-8859-1,
  utf-8;q=0.7,*;q=0.7..Keep-Alive: 115..Proxy-Connection:
keep-alive..Referer: http://disqus.com/comments/register/..Cookie:
__qca=P0-1812485800-1271168987352; __utma=1138694
  58.355764790.1272628467.1272628467.1272628467.1;
__utmb=113869458.5.10.1272628467;
__utmz=113869458.1272628467.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
__utmc=113
  869458..Content-Type: application/x-www-form-urlencoded..Content-Length:
67....website=&name=&url=&username=&password=&email=&auth_choice=register 

#                                                                         

T 10.0.1.34:8080 -> 192.168.0.176:51391 [AP]                              

  HTTP/1.1 504 Gateway Time-out..Server: Lusca..Date: Fri, 30 Apr 2010
12:21:04 GMT..Content-Type: text/html..Content-Length: 2986..X-Squid-Error:
ERR_ONLY_IF_CACHED_MISS 0..
  X-Cache: MISS from Cache-10.0.1.36.visp.net.lb..X-Cache: MISS from
Cache-10.0.1.34.visp.net.lb..Via: 1.0 Cache-10.0.1.36.visp.net.lb:8080
(Lusca), 1.1 Cache-10.0.1.34.visp.
  net.lb:8080 (Lusca)..Connection: close....                              

#                                                          

mrtg ~ # squidclient -h 10.0.1.34 -p 8080 -m POST
http://disqus.com/comments/register/                                      

HTTP/1.1 500 Internal Server Error
Date: Fri, 30 Apr 2010 12:21:53 GMT
Server: Apache/2.2.11 (Ubuntu) mod_python/3.3.1 Python/2.6.2
PHP/5.2.6-3ubuntu4.4 with Suhosin-Patch mod_wsgi/3.1
Vary: Cookie                                                              

Content-Length: 1767                                                      

Content-Type: text/html; charset=utf-8                                    

X-Cache: MISS from Cache-Parent.visp.net.lb                               

X-Cache: MISS from Cache-10.0.1.34.visp.net.lb                            

Via: 1.1 Cache-Parent.visp.net.lb:8080 (Lusca), 1.1
Cache-10.0.1.34.visp.net.lb:8080 (Lusca)                     
Connection: close                                                         

<!DOCTYPE HTML PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml">                               

        <head>                                 

15:23:14.717711 IP 10.0.1.36.icpv2 > 10.0.1.34.icpv2: UDP, length 57
        0x0000:  4500 0055 0000 4000 4011 2453 0a00 0124  E..U..@.@.$S...$
        0x0010:  0a00 0122 0c3a 0c3a 0041 1189 0202 0039  ...".:.:.A.....9
        0x0020:  011c c703 0000 0000 0000 0000 0000 0000  ................
        0x0030:  6874 7470 3a2f 2f64 6973 7175 732e 636f  http://disqus.co
        0x0040:  6d2f 636f 6d6d 656e 7473 2f72 6567 6973  m/comments/regis
        0x0050:  7465 722f 00                             ter/.

15:25:25.458981 IP 10.0.1.34.icpv2 > 224.9.9.9.icpv2: UDP, length 61
        0x0000:  4500 0059 0000 4000 0811 7e60 0a00 0122  E..Y..@...~`..."
        0x0010:  e009 0909 0c3a 0c3a 0045 cf4f 0102 003d  .....:.:.E.O...=
        0x0020:  011d 2c41 0000 0000 0000 0000 0000 0000  ..,A............
        0x0030:  0000 0000 6874 7470 3a2f 2f64 6973 7175  ....http://disqu
        0x0040:  732e 636f 6d2f 636f 6d6d 656e 7473 2f72  s.com/comments/r
        0x0050:  6567 6973 7465 722f 00                   egister/.

I did also lookup for cache objects over cachemgr

on 10.0.1.34
KEY 46CC18810EE7F14973A40199283225B8
        GET http://disqus.com/comments/register/
        STORE_OK      IN_MEMORY     SWAPOUT_DONE PING_DONE
        CACHABLE,DISPATCHED,VALIDATED
        LV:1272628840 LU:1272628842 LM:-1        EX:-1
        0 locks, 0 clients, 1 refs
        Swap Dir 0, File 0X166AF7
        inmem_lo: 0
        inmem_hi: 8167
        swapout: 8167 bytes queued

on 10.0.1.36
KEY 64B4AC6388D800EE5C719847735724D8
        GET http://disqus.com/comments/register/
        STORE_OK      IN_MEMORY     SWAPOUT_DONE PING_NONE
        CACHABLE,VALIDATED
        LV:1272629189 LU:1272630029 LM:-1        EX:1272729189
        0 locks, 0 clients, 4 refs
        Swap Dir 0, File 0X11DAEE
        inmem_lo: 0
        inmem_hi: 2376
        swapout: 2376 bytes queued

Original issue reported on code.google.com by nuclear...@gmail.com on 30 Apr 2010 at 12:48

GoogleCodeExporter commented 9 years ago

Wait. So the object is there, and ICP_HIT is returned, but the fetch fails?
Is that right?

Original comment by adrian.c...@gmail.com on 30 May 2010 at 11:01

Added labels: ****
Removed labels: ****

GoogleCodeExporter commented 9 years ago

Seems so, it is appearing after running LUSCA for long time on heavy load (this
cluster receive up to 80k simultaneuous connections at peak time) without 
restart
(usually i am restarting each night).
So it is actually very difficult to trigger it, now also i have less complaints 
about
it. I will make sure at monday, if there is still any and probably will make
something to report instantly to me about such issues.

Original comment by nuclear...@gmail.com on 30 May 2010 at 11:33

Added labels: ****
Removed labels: ****

GoogleCodeExporter commented 9 years ago

Probably it is related to issue 114 (memory corruption)?

Original comment by nuclear...@gmail.com on 30 May 2010 at 11:41

Added labels: ****
Removed labels: ****

GoogleCodeExporter commented 9 years ago

Which version are you running?

Original comment by adrian.c...@gmail.com on 30 May 2010 at 12:19

Added labels: ****
Removed labels: ****

GoogleCodeExporter commented 9 years ago

It is some HEAD, but no idea which revision (those one i dont touch, because 
current
HEAD have some issues and i cannot push them to production servers till i will 
be
able to make bugreport).
Maybe it is possible to include revision tag in squid -v ?
The only i know it is looks like fetched before 28 Apr.

Original comment by nuclear...@gmail.com on 30 May 2010 at 12:26

Added labels: ****
Removed labels: ****

GoogleCodeExporter commented 9 years ago

I've begun including the svn revision in the reported version for the source 
tarballs
found in the download section. I don't recall when I began doing this but it's 
very
recently (in the last month or two.)

Sorry. :(

Original comment by adrian.c...@gmail.com on 30 May 2010 at 2:15

Added labels: ****
Removed labels: ****

GoogleCodeExporter commented 9 years ago

Squid Cache: Version LUSCA_HEAD-r14674 with this issue

I did automated report, it happens mostly on POST requests.
Possible it is somehow related with recent memory corruption.
I will try to test revision that is marked as stable in memory corruption issue.

Original comment by nuclear...@gmail.com on 7 Jun 2010 at 10:09

Added labels: ****
Removed labels: ****

agusneos / lusca-cache

Valid document was not found in the cache and "only-if-cached" directive was specified. Sibling issues #111