Re: [squid-users] assertion failed: cbdata.cc:130: "cookie == ((long)this ^ Cookie)"

Hi,

I have tried squid-3.2.0.17-20120611-r11586 and it still crash shortly
after starting.

So looking through the chnagelog for 3.2.0.17, the most likely culprit
seemed squid-3.2-11549.patch:

http://www.squid-cache.org/Versions/v3/3.2/changesets/squid-3.2-11549.patch

So I reversed that patch and now squid-3.2.0.17-20120611-r11586 has been
running stable for 5 hours.

John

-- 
John Hay -- jhay_at_meraka.csir.co.za / jhay_at_FreeBSD.org
On Wed, Jun 06, 2012 at 02:05:59PM +0200, John Hay wrote:
> Hi,
> 
> When upgrading from 3.2.0.16 to 3.2.0.17 I ran into this:
> 2012/06/06 12:19:56 kid1| assertion failed: cbdata.cc:130: "cookie == ((long)this ^ Cookie)"
> 
> I have also tried squid-3.2.0.17-20120527-r11561, but see the same problem.
> I'll include my squid.conf, a piece of cache.log and the backtrace. This
> happen somewhere from a few seconds after starting squid to a few minutes
> later.
> 
> The machine is running FreeBSD 8.2-STABLE and up to now, I have not had
> such a problem with squid. I have been running the 3.2 branch for a while
> because I need the IPv6 -> IPv4 failover. The machine has 2 interfaces
> with one side having global IPv4 and IPv6 addresses and the other side
> have some private addresses. It also do transparent IPv4 proxying for
> those that did not configure a proxy.
> 
> Has anybody seen something like this? Can it be something in my config
> that is now catching up with me? I have not changed that in a while.
> 
> John
> -- 
> John Hay -- jhay_at_meraka.csir.co.za / jhay_at_FreeBSD.org
> acl local-servers dstdomain .csir.co.za
> acl local-servers dstdomain .fmfi.org.za
> acl to_ipv6 dst ipv6
> acl localnet src 10.0.0.0/8	# RFC1918 possible internal network
> acl localnet src 146.64.0.0/16
> acl localnet src 2001:4200:7000::/48
> acl localnet src fd9c:6829:597c::/48
> acl localdst dst 146.64.0.0/16
> acl localdst dst 10.0.0.0/8
> acl badsrc src 146.64.8.10
> acl SSL_ports port 443
> acl SSL_ports port 563
> acl SSL_ports port 7002		# 
> acl SSL_ports port 9001		# 
> acl Safe_ports port 80		# http
> acl Safe_ports port 21		# ftp
> acl Safe_ports port 443		# https
> acl Safe_ports port 70		# gopher
> acl Safe_ports port 210		# wais
> acl Safe_ports port 1025-65535	# unregistered ports
> acl Safe_ports port 280		# http-mgmt
> acl Safe_ports port 488		# gss-http
> acl Safe_ports port 591		# filemaker
> acl Safe_ports port 777		# multiling http
> acl Safe_ports port 800		# 
> acl CONNECT method CONNECT
> http_access allow manager localhost
> http_access deny manager
> http_access deny badsrc
> http_access deny !Safe_ports
> http_access deny CONNECT !SSL_ports
> http_access allow localnet
> http_access deny all
> icp_access allow localnet
> icp_access deny all
> htcp_access allow localnet
> htcp_access deny all
> http_port 146.64.8.8:3128
> http_port 127.0.0.1:3000 transparent
> http_port 3128
> icp_port 3130
> connect_timeout 5 seconds
> connect_retries 2
> hierarchy_stoplist cgi-bin ?
> cache_log /home/squid/logs/cache.log
> access_log /home/squid/logs/access.log squid
> refresh_pattern ^ftp:		1440	20%	10080
> refresh_pattern ^gopher:	1440	0%	1440
> refresh_pattern -i (/cgi-bin/|\?) 0	0%	0
> refresh_pattern .		0	20%	4320
> cache_mgr jhay_at_meraka.org.za
> cache_effective_user squid
> cache_effective_group squid
> visible_hostname crypton.cids.org.za
> cache_mem 96 MB
> dns_defnames on
> coredump_dir /home/squid
> 2012/06/06 11:38:48 kid1| Starting Squid Cache version 3.2.0.17-20120527-r11561 for amd64-portbld-freebsd8.2...
> 2012/06/06 11:38:48 kid1| Process ID 34071
> 2012/06/06 11:38:48 kid1| Process Roles: worker
> 2012/06/06 11:38:48 kid1| With 11095 file descriptors available
> 2012/06/06 11:38:48 kid1| Initializing IP Cache...
> 2012/06/06 11:38:48 kid1| DNS Socket created at [::], FD 7
> 2012/06/06 11:38:48 kid1| DNS Socket created at 0.0.0.0, FD 8
> 2012/06/06 11:38:48 kid1| Adding domain meraka.csir.co.za from /etc/resolv.conf
> 2012/06/06 11:38:48 kid1| Adding domain cids.org.za from /etc/resolv.conf
> 2012/06/06 11:38:48 kid1| Adding nameserver 127.0.0.1 from /etc/resolv.conf
> 2012/06/06 11:38:48 kid1| Adding nameserver ::1 from /etc/resolv.conf
> 2012/06/06 11:38:48 kid1| Logfile: opening log /home/squid/logs/access.log
> 2012/06/06 11:38:48 kid1| WARNING: log parameters now start with a module name. Use 'stdio:/home/squid/logs/access.log'
> 2012/06/06 11:38:48 kid1| Store logging disabled
> 2012/06/06 11:38:48 kid1| Swap maxSize 0 + 98304 KB, estimated 7561 objects
> 2012/06/06 11:38:48 kid1| Target number of buckets: 378
> 2012/06/06 11:38:48 kid1| Using 8192 Store buckets
> 2012/06/06 11:38:48 kid1| Max Mem  size: 98304 KB
> 2012/06/06 11:38:48 kid1| Max Swap size: 0 KB
> 2012/06/06 11:38:48 kid1| Using Least Load store dir selection
> 2012/06/06 11:38:48 kid1| Set Current Directory to /home/squid
> 2012/06/06 11:38:48 kid1| Loaded Icons.
> 2012/06/06 11:38:48 kid1| HTCP Disabled.
> 2012/06/06 11:38:48 kid1| Accepting HTTP Socket connections at local=146.64.8.8:3128 remote=[::] FD 10 flags=9
> 2012/06/06 11:38:48 kid1| Accepting NAT intercepted HTTP Socket connections at local=127.0.0.1:3000 remote=[::] FD 11 flags=41
> 2012/06/06 11:38:48 kid1| Accepting HTTP Socket connections at local=[::]:3128 remote=[::] FD 12 flags=9
> 2012/06/06 11:38:48 kid1| Accepting ICP messages on [::]:3130
> 2012/06/06 11:38:48 kid1| Sending ICP messages from [::]:3130
> 2012/06/06 11:38:49 kid1| storeLateRelease: released 0 objects
> 2012/06/06 11:39:16 kid1| assertion failed: cbdata.cc:130: "cookie == ((long)this ^ Cookie)"
> 
> 
> 2012/06/06 12:05:04 kid1| Starting Squid Cache version 3.2.0.17-20120527-r11561 for amd64-portbld-freebsd8.2...
> 2012/06/06 12:05:04 kid1| Process ID 89811
> 2012/06/06 12:05:04 kid1| Process Roles: worker
> 2012/06/06 12:05:04 kid1| With 11095 file descriptors available
> 2012/06/06 12:05:04 kid1| Initializing IP Cache...
> 2012/06/06 12:05:04 kid1| DNS Socket created at [::], FD 7
> 2012/06/06 12:05:04 kid1| DNS Socket created at 0.0.0.0, FD 8
> 2012/06/06 12:05:04 kid1| Adding domain meraka.csir.co.za from /etc/resolv.conf
> 2012/06/06 12:05:04 kid1| Adding domain cids.org.za from /etc/resolv.conf
> 2012/06/06 12:05:04 kid1| Adding nameserver 127.0.0.1 from /etc/resolv.conf
> 2012/06/06 12:05:04 kid1| Adding nameserver ::1 from /etc/resolv.conf
> 2012/06/06 12:05:04 kid1| Logfile: opening log /home/squid/logs/access.log
> 2012/06/06 12:05:04 kid1| WARNING: log parameters now start with a module name. Use 'stdio:/home/squid/logs/access.log'
> 2012/06/06 12:05:04 kid1| Store logging disabled
> 2012/06/06 12:05:04 kid1| Swap maxSize 0 + 98304 KB, estimated 7561 objects
> 2012/06/06 12:05:04 kid1| Target number of buckets: 378
> 2012/06/06 12:05:04 kid1| Using 8192 Store buckets
> 2012/06/06 12:05:04 kid1| Max Mem  size: 98304 KB
> 2012/06/06 12:05:04 kid1| Max Swap size: 0 KB
> 2012/06/06 12:05:04 kid1| Using Least Load store dir selection
> 2012/06/06 12:05:04 kid1| Set Current Directory to /home/squid
> 2012/06/06 12:05:04 kid1| Loaded Icons.
> 2012/06/06 12:05:04 kid1| HTCP Disabled.
> 2012/06/06 12:05:04 kid1| Accepting HTTP Socket connections at local=146.64.8.8:3128 remote=[::] FD 10 flags=9
> 2012/06/06 12:05:04 kid1| Accepting NAT intercepted HTTP Socket connections at local=127.0.0.1:3000 remote=[::] FD 11 flags=41
> 2012/06/06 12:05:04 kid1| Accepting HTTP Socket connections at local=[::]:3128 remote=[::] FD 12 flags=9
> 2012/06/06 12:05:04 kid1| Accepting ICP messages on [::]:3130
> 2012/06/06 12:05:04 kid1| Sending ICP messages from [::]:3130
> 2012/06/06 12:05:05 kid1| storeLateRelease: released 0 objects
> 2012/06/06 12:08:33 kid1| Failed to select source for 'http://asection.washingtonpost.com/wp-dyn/rss/print/asection/new/index.xml'
> 2012/06/06 12:08:33 kid1|   always_direct = 0
> 2012/06/06 12:08:33 kid1|    never_direct = 0
> 2012/06/06 12:08:33 kid1|        timedout = 0
> 2012/06/06 12:19:56 kid1| assertion failed: cbdata.cc:130: "cookie == ((long)this ^ Cookie)"
> 
> crypton# gdb ./squid /home/squid/squid.core
> GNU gdb 6.1.1 [FreeBSD]
> Copyright 2004 Free Software Foundation, Inc.
> GDB is free software, covered by the GNU General Public License, and you are
> welcome to change it and/or distribute copies of it under certain conditions.
> Type "show copying" to see the conditions.
> There is absolutely no warranty for GDB.  Type "show warranty" for details.
> This GDB was configured as "amd64-marcel-freebsd"...
> Core was generated by `squid'.
> Program terminated with signal 6, Aborted.
> Reading symbols from /usr/lib/librt.so.1...done.
> Loaded symbols for /usr/lib/librt.so.1
> Reading symbols from /usr/lib/libgssapi.so.10...done.
> Loaded symbols for /usr/lib/libgssapi.so.10
> Reading symbols from /usr/lib/libheimntlm.so.10...done.
> Loaded symbols for /usr/lib/libheimntlm.so.10
> Reading symbols from /usr/lib/libkrb5.so.10...done.
> Loaded symbols for /usr/lib/libkrb5.so.10
> Reading symbols from /usr/lib/libhx509.so.10...done.
> Loaded symbols for /usr/lib/libhx509.so.10
> Reading symbols from /usr/lib/libcom_err.so.5...done.
> Loaded symbols for /usr/lib/libcom_err.so.5
> Reading symbols from /lib/libcrypto.so.6...done.
> Loaded symbols for /lib/libcrypto.so.6
> Reading symbols from /usr/lib/libasn1.so.10...done.
> Loaded symbols for /usr/lib/libasn1.so.10
> Reading symbols from /usr/lib/libroken.so.10...done.
> Loaded symbols for /usr/lib/libroken.so.10
> Reading symbols from /lib/libcrypt.so.5...done.
> Loaded symbols for /lib/libcrypt.so.5
> Reading symbols from /usr/lib/libstdc++.so.6...done.
> Loaded symbols for /usr/lib/libstdc++.so.6
> Reading symbols from /lib/libm.so.5...done.
> Loaded symbols for /lib/libm.so.5
> Reading symbols from /lib/libgcc_s.so.1...done.
> Loaded symbols for /lib/libgcc_s.so.1
> Reading symbols from /lib/libthr.so.3...done.
> Loaded symbols for /lib/libthr.so.3
> Reading symbols from /lib/libc.so.7...done.
> Loaded symbols for /lib/libc.so.7
> Reading symbols from /libexec/ld-elf.so.1...done.
> Loaded symbols for /libexec/ld-elf.so.1
> #0  0x0000000801c1f8cc in kill () from /lib/libc.so.7
> [New Thread 801e041c0 (LWP 100861/initial thread)]
> (gdb) bt
> #0  0x0000000801c1f8cc in kill () from /lib/libc.so.7
> #1  0x0000000801c1e6cb in abort () from /lib/libc.so.7
> #2  0x0000000000459012 in xassert (
>     msg=0x61b778 "cookie == ((long)this ^ Cookie)", file=0x61b769 "cbdata.cc", 
>     line=130) at debug.cc:567
> #3  0x000000000042715e in cbdata::check (this=0x802a38cd8, aLine=420)
>     at cbdata.cc:130
> #4  0x0000000000426cb4 in cbdataInternalLock (p=0x802a38cf0) at cbdata.cc:420
> #5  0x000000000046846d in ev_entry (this=0x801ed5c70, 
>     aName=0x662598 "Comm::ConnOpener::DelayedConnectRetry", 
>     aFunction=0x5e4ae0 <Comm::ConnOpener::DelayedConnectRetry(void*)>, 
>     aArgument=0x802a38cf0, evWhen=1338977996.4006131, aWeight=0, 
>     haveArgument=true) at event.cc:116
> #6  0x000000000046854f in EventScheduler::schedule (this=0x7fe8e0, 
>     name=0x662598 "Comm::ConnOpener::DelayedConnectRetry", 
>     func=0x5e4ae0 <Comm::ConnOpener::DelayedConnectRetry(void*)>, 
>     arg=0x802a38cf0, when=0.050000000000000003, weight=0, cbdata=true)
>     at event.cc:341
> #7  0x00000000004686fe in eventAdd (
>     name=0x662598 "Comm::ConnOpener::DelayedConnectRetry", 
>     func=0x5e4ae0 <Comm::ConnOpener::DelayedConnectRetry(void*)>, 
>     arg=0x802a38cf0, when=0.050000000000000003, weight=0, cbdata=true)
>     at event.cc:129
> ---Type <return> to continue, or q <return> to quit---
> #8  0x00000000005e6466 in Comm::ConnOpener::connect (this=0x802c6a858)
>     at ConnOpener.cc:264
> #9  0x00000000005e8362 in NullaryMemFunT<Comm::ConnOpener>::doDial (
>     this=0x802a9cd90) at AsyncJobCalls.h:101
> #10 0x00000000005e86ee in JobDialer<Comm::ConnOpener>::dial (this=0x802a9cd90, 
>     call=@0x802a9cd60) at AsyncJobCalls.h:175
> #11 0x00000000005e887d in AsyncCallT<NullaryMemFunT<Comm::ConnOpener> >::fire (
>     this=0x802a9cd60) at AsyncCall.h:142
> #12 0x00000000005864ff in AsyncCall::make (this=0x802a9cd60) at AsyncCall.cc:36
> #13 0x00000000005899c9 in AsyncCallQueue::fireNext (this=0x802a382e0)
>     at AsyncCallQueue.cc:54
> #14 0x0000000000589a9f in AsyncCallQueue::fire (this=0x802a382e0)
>     at AsyncCallQueue.cc:40
> #15 0x0000000000469769 in EventLoop::dispatchCalls (this=0x7fffffffe910)
>     at EventLoop.cc:154
> #16 0x0000000000469a62 in EventLoop::runOnce (this=0x7fffffffe910)
>     at EventLoop.cc:131
> #17 0x0000000000469b4e in EventLoop::run (this=0x7fffffffe910)
>     at EventLoop.cc:95
> #18 0x00000000004d0d4d in SquidMain (argc=3, argv=0x7fffffffeaa8)
>     at main.cc:1503
> #19 0x00000000004d0e8c in SquidMainSafe (argc=3, argv=0x7fffffffeaa8)
>     at main.cc:1218
> ---Type <return> to continue, or q <return> to quit---
> #20 0x00000000004d0fbb in main (argc=3, argv=0x7fffffffeaa8) at main.cc:1210
> (gdb) 
>