assert failure: cbdata.c:207: "c->locks > 0"

From: Andres Kroonmaa <andre@dont-contact.us>
Date: Tue Jul 29 13:15:56 2003

 Hi,

 I've been chasing assertion failure: cbdata.c:207: "c->locks > 0" and
 occasional SEGVs in 2.2PRE2. Is this known?
 It happens pretty rarely, (although my current test box has very little load).
 Knowing too little of latest squid internals, it is pretty hard for me to
 find a cause. Below is a sample of log with debug some enabled from which
 I can see that assert failed because all locks where unlocked but cbdata
 was still marked as valid.

 in cbdataUnlock(),
    if (c->valid || c->locks)
        return;
    cbdataReallyFree(c);
 }
 This allows for "valid" data with zero locks to exist.

 While in cbdataValid(),
    assert(c != NULL);
    assert(c->locks > 0);
    return c->valid;
 does not allow "valid" cbdata without locks to exist.
 The only place where "valid" is reset is in cbdataFree()

 Could anyone clarify:
  1) Do we miss a cbdataFree() somewhere?
  2) Do we miss a cbdataLock() somewhere?
  3) Do we have excess cbdataUnlock() somewhere?
  4) Should cbdataValid() allow for unlocked but valid cbdata?
  5) Should cbdataUnlock call cbdataFree if locks == 0?

 How do you chase such bug? Increasing debug level creates tons
 of logs while the bug appears pretty rarely...

------- Forwarded Message Follows -------
Date sent: Tue, 9 Feb 1999 09:14:37 +0200 (EET)

debug_options ALL,2 45,3 72,3 71,3 33,3 61,3 5,3 44,3 38,3 6,3 14,3 17,3

1999/02/09 08:17:50| fwdComplete: http://cache.uninet.ee/squid-internal-periodic/store_digest
        status 404
1999/02/09 08:17:50| fwdReforward: http://cache.uninet.ee/squid-internal-periodic/store_digest?
1999/02/09 08:17:50| fwdReforward: No forward-servers left
1999/02/09 08:17:50| fwdComplete: not re-forwarding status 404
1999/02/09 08:17:50| cbdataLock: 87df398
1999/02/09 08:17:50| cbdataValid: 89a3af0
1999/02/09 08:17:50| cbdataValid: 82101b0
1999/02/09 08:17:50| cbdataValid: 8210070
1999/02/09 08:17:50| cbdataValid: 8210070
1999/02/09 08:17:50| peerDigestFetchReply: cache.uninet.ee status: 404, expires: 918541069 (-1)
1999/02/09 08:17:50| peerDigestFetchAbort: peer cache.uninet.ee, reason: Not Found
1999/02/09 08:17:50| cbdataLock: 82101b0
1999/02/09 08:17:50| peerDigestSetCheck: will check peer cache.uninet.ee in 19200 secs
1999/02/09 08:17:50| peerDigestFetchFinish: recv 1375 bytes in 1 secs
1999/02/09 08:17:50| peerDigestFetchFinish: expires: 918541129 (+59), lmt: -1 (-918541071)
1999/02/09 08:17:50| temporary disabling (Not Found) digest from cache.uninet.ee
1999/02/09 08:17:50| cbdataUnlock: 82101b0
1999/02/09 08:17:50| peerDigestFetchFinish: deleting old entry
1999/02/09 08:17:50| cbdataFree: 89a5478
1999/02/09 08:17:50| cbdataReallyFree: Freeing 89a5478
1999/02/09 08:17:50| cbdataFree: 87df398
1999/02/09 08:17:50| cbdataFree: 87df398 has 1 locks, not freeing
1999/02/09 08:17:50| cbdataUnlock: 89a3af0
1999/02/09 08:17:50| cbdataFree: 89a3af0
1999/02/09 08:17:50| cbdataReallyFree: Freeing 89a3af0
1999/02/09 08:17:50| cbdataUnlock: 87df398
1999/02/09 08:17:50| cbdataReallyFree: Freeing 87df398
1999/02/09 08:17:50| cbdataValid: 8ad5cc0
1999/02/09 08:17:50| cbdataFree: 8ad5cc0
1999/02/09 08:17:50| cbdataFree: 8ad5cc0 has 1 locks, not freeing
1999/02/09 08:17:50| cbdataUnlock: 8ad5cc0
1999/02/09 08:17:50| cbdataReallyFree: Freeing 8ad5cc0
1999/02/09 08:17:50| cbdataValid: 89c2998
1999/02/09 08:17:50| fwdServerClosed: FD 16 http://cache.uninet.ee/squid-internal-periodic/store_digest
1999/02/09 08:17:50| fwdStateFree: 89c2998
1999/02/09 08:17:50| cbdataFree: 89c2998
1999/02/09 08:17:50| cbdataFree: 89c2998 has 1 locks, not freeing
1999/02/09 08:17:50| cbdataUnlock: 89c2998
1999/02/09 08:17:50| cbdataReallyFree: Freeing 89c2998
1999/02/09 08:18:48| cbdataValid: 8210660
1999/02/09 08:18:48| cbdataUnlock: 8210660
1999/02/09 08:18:48| cbdataValid: 8210520
1999/02/09 08:18:48| peerDigestCheck: peer cache.estnet.ee:3128
1999/02/09 08:18:48| peerDigestCheck: time: 918541128, last received: 918531528 (+9600)
1999/02/09 08:18:48| peerDigestCheck: cache.estnet.ee, avoiding close requests (59 < 60 secs).
1999/02/09 08:18:48| cbdataLock: 8210660
1999/02/09 08:18:48| peerDigestSetCheck: will check peer cache.estnet.ee in 1 secs
1999/02/09 08:18:49| cbdataValid: 8210660
1999/02/09 08:18:49| cbdataUnlock: 8210660
1999/02/09 08:18:49| cbdataValid: 8210520
1999/02/09 08:18:49| peerDigestCheck: peer cache.estnet.ee:3128
1999/02/09 08:18:49| peerDigestCheck: time: 918541129, last received: 918531528 (+9601)
1999/02/09 08:18:49| peerDigestRequest: http://cache.estnet.ee:3128/squid-internal-periodic/store_digest key: 2317A7FA087FF45297DD291013A2EE93
1999/02/09 08:18:49| cbdataAdd: 89a3af0
1999/02/09 08:18:49| cbdataAdd: 87df398
1999/02/09 08:18:49| cbdataAdd: 89a5478
1999/02/09 08:18:49| peerDigestRequest: forwarding to fwdStart...
1999/02/09 08:18:49| fwdStart: 'http://cache.estnet.ee:3128/squid-internal-periodic/store_digest'
1999/02/09 08:18:49| cbdataAdd: 89c2998
1999/02/09 08:18:49| peerSelect: http://cache.estnet.ee:3128/squid-internal-periodic/store_digest
1999/02/09 08:18:49| cbdataAdd: 83b7a40
1999/02/09 08:18:49| cbdataLock: 89c2998
1999/02/09 08:18:49| peerSelectFoo: 'GET cache.estnet.ee'
1999/02/09 08:18:49| cbdataAdd: 8826c28
1999/02/09 08:18:49| cbdataLock: 8218e50
1999/02/09 08:18:49| cbdataLock: 83b7a40
1999/02/09 08:18:49| cbdataValid: 8218e50
1999/02/09 08:18:49| cbdataUnlock: 8218e50
1999/02/09 08:18:49| cbdataValid: 83b7a40
1999/02/09 08:18:49| peerCheckAlwaysDirectDone: 1
1999/02/09 08:18:49| peerSelectFoo: 'GET cache.estnet.ee'
1999/02/09 08:18:49| peerSelectFoo: direct = DIRECT_YES
1999/02/09 08:18:49| peerGetSomeParent: GET cache.estnet.ee
1999/02/09 08:18:49| peerSelectCallback: http://cache.estnet.ee:3128/squid-internal-periodic/store_digest
1999/02/09 08:18:49| cbdataValid: 89c2998
1999/02/09 08:18:49| fwdStartComplete: http://cache.estnet.ee:3128/squid-internal-periodic/store_digest
1999/02/09 08:18:49| fwdConnectStart: http://cache.estnet.ee:3128/squid-internal-periodic/store_digest
1999/02/09 08:18:49| cbdataLock: 89c2998
1999/02/09 08:18:49| commSetTimeout: FD 16 timeout 120
1999/02/09 08:18:49| commConnectStart: FD 16, cache.estnet.ee:3128
1999/02/09 08:18:49| cbdataAdd: 87a9e40
1999/02/09 08:18:49| cbdataLock: 89c2998
1999/02/09 08:18:49| cbdataLock: 87a9e40
1999/02/09 08:18:49| cbdataLock: 87a9e40
1999/02/09 08:18:49| cbdataValid: 87a9e40
1999/02/09 08:18:49| ipcacheCycleAddr: cache.estnet.ee now at 192.98.49.1
1999/02/09 08:18:49| cbdataUnlock: 87a9e40
1999/02/09 08:18:49| cbdataUnlock: 89c2998
1999/02/09 08:18:49| cbdataFree: 83b7a40
1999/02/09 08:18:49| cbdataFree: 83b7a40 has 1 locks, not freeing
1999/02/09 08:18:49| cbdataUnlock: 83b7a40
1999/02/09 08:18:49| cbdataReallyFree: Freeing 83b7a40
1999/02/09 08:18:49| cbdataFree: 8826c28
1999/02/09 08:18:49| cbdataReallyFree: Freeing 8826c28
1999/02/09 08:18:49| cbdataLock: 89a3af0
1999/02/09 08:18:49| cbdataLock: 8210660
1999/02/09 08:18:49| cbdataUnlock: 87a9e40
1999/02/09 08:18:49| commSetTimeout: FD 16 timeout -1
1999/02/09 08:18:49| commConnectFree: FD 16
1999/02/09 08:18:49| cbdataFree: 87a9e40
1999/02/09 08:18:49| cbdataReallyFree: Freeing 87a9e40
1999/02/09 08:18:49| cbdataValid: 89c2998
1999/02/09 08:18:49| fwdConnectDone: FD 16: 'http://cache.estnet.ee:3128/squid-internal-periodic/store_digest'
1999/02/09 08:18:49| fwdDispatch: FD -1: Fetching 'GET http://cache.estnet.ee:3128/squid-internal-periodic/store_digest'
1999/02/09 08:18:49| cbdataAdd: 880de90
1999/02/09 08:18:49| cbdataLock: 880de90
1999/02/09 08:18:49| cbdataLock: 880de90
1999/02/09 08:18:49| cbdataValid: 880de90
1999/02/09 08:18:49| cbdataUnlock: 880de90
1999/02/09 08:18:49| netdbSendPing: pinging cache.estnet.ee
1999/02/09 08:18:49| cbdataFree: 880de90
1999/02/09 08:18:49| cbdataFree: 880de90 has 1 locks, not freeing
1999/02/09 08:18:49| cbdataUnlock: 880de90
1999/02/09 08:18:49| cbdataReallyFree: Freeing 880de90
1999/02/09 08:18:49| cbdataAdd: 8ad5cc0
1999/02/09 08:18:49| cbdataLock: 8ad5cc0
1999/02/09 08:18:49| commSetTimeout: FD 16 timeout 900
1999/02/09 08:18:49| cbdataUnlock: 89c2998
1999/02/09 08:18:49| cbdataLock: 8ad5cc0
1999/02/09 08:18:49| cbdataValid: 8ad5cc0
1999/02/09 08:18:49| cbdataUnlock: 8ad5cc0
1999/02/09 08:18:49| pingerLog: 918541129.590227 192.98.49.1 8 Echo 0ms 0 hops
1999/02/09 08:18:49| pingerLog: 918541129.617930 192.98.49.1 0 Echo Reply 27ms 6 hops
1999/02/09 08:18:49| netdbHandlePingReply: from 192.98.49.1
1999/02/09 08:18:49| netdbHandlePingReply: 192.98.49.0; rtt= 18.7 hops= 6.0
1999/02/09 08:18:49| commSetTimeout: FD 16 timeout 900
1999/02/09 08:18:49| commSetTimeout: FD 16 timeout 900
1999/02/09 08:18:49| fwdComplete: http://cache.estnet.ee:3128/squid-internal-periodic/store_digest
        status 400
1999/02/09 08:18:49| fwdReforward: http://cache.estnet.ee:3128/squid-internal-periodic/store_digest?
1999/02/09 08:18:49| fwdReforward: No forward-servers left
1999/02/09 08:18:49| fwdComplete: not re-forwarding status 400
1999/02/09 08:18:49| cbdataLock: 89a5478
1999/02/09 08:18:49| cbdataValid: 89a3af0
1999/02/09 08:18:49| cbdataValid: 8210660
1999/02/09 08:18:49| cbdataValid: 8210520
1999/02/09 08:18:49| cbdataValid: 8210520
1999/02/09 08:18:49| peerDigestFetchReply: cache.estnet.ee status: 400, expires: -1 (-918541130)
1999/02/09 08:18:49| peerDigestFetchAbort: peer cache.estnet.ee, reason: Bad Request
1999/02/09 08:18:49| cbdataLock: 8210660
1999/02/09 08:18:49| peerDigestSetCheck: will check peer cache.estnet.ee in 19200 secs
1999/02/09 08:18:49| peerDigestFetchFinish: recv 614 bytes in 0 secs
1999/02/09 08:18:49| peerDigestFetchFinish: expires: 918541189 (+60), lmt: -1 (-918541130)
1999/02/09 08:18:49| temporary disabling (Bad Request) digest from cache.estnet.ee
1999/02/09 08:18:49| cbdataUnlock: 8210660
1999/02/09 08:18:49| peerDigestFetchFinish: deleting old entry
1999/02/09 08:18:49| cbdataFree: 87df398
1999/02/09 08:18:49| cbdataReallyFree: Freeing 87df398
1999/02/09 08:18:49| cbdataFree: 89a5478
1999/02/09 08:18:49| cbdataFree: 89a5478 has 1 locks, not freeing
1999/02/09 08:18:49| cbdataUnlock: 89a3af0
1999/02/09 08:18:49| cbdataFree: 89a3af0
1999/02/09 08:18:49| cbdataReallyFree: Freeing 89a3af0
1999/02/09 08:18:49| cbdataUnlock: 89a5478
1999/02/09 08:18:49| cbdataReallyFree: Freeing 89a5478
1999/02/09 08:18:49| cbdataValid: 8ad5cc0
1999/02/09 08:18:49| cbdataFree: 8ad5cc0
1999/02/09 08:18:49| cbdataFree: 8ad5cc0 has 1 locks, not freeing
1999/02/09 08:18:49| cbdataUnlock: 8ad5cc0
1999/02/09 08:18:49| cbdataReallyFree: Freeing 8ad5cc0
1999/02/09 08:18:49| cbdataValid: 89c2998
1999/02/09 08:18:49| fwdServerClosed: FD 16 http://cache.estnet.ee:3128/squid-internal-periodic/store_digest
1999/02/09 08:18:49| fwdStateFree: 89c2998
1999/02/09 08:18:49| cbdataFree: 89c2998
1999/02/09 08:18:49| cbdataFree: 89c2998 has 1 locks, not freeing
1999/02/09 08:18:49| cbdataUnlock: 89c2998
1999/02/09 08:18:49| cbdataReallyFree: Freeing 89c2998
1999/02/09 08:19:49| cbdataValid: 82108b8
1999/02/09 08:19:49| cbdataUnlock: 82108b8
1999/02/09 08:19:49| cbdataValid: 8210778
1999/02/09 08:19:49| assertion failed: cbdata.c:207: "c->locks > 0"
1999/02/09 08:19:49| Pinger exiting.
1999/02/09 08:19:54| Starting Squid Cache version 2.2.PRE2 for i386-pc-solaris2.7...
1999/02/09 08:19:54| Process ID 5238

egrep "8210778|assert" cache.log:

1999/02/09 03:00:06| cbdataLock: 8210778
1999/02/09 03:00:07| cbdataValid: 8210778
1999/02/09 03:00:07| cbdataLock: 8210778
1999/02/09 03:00:07| cbdataUnlock: 8210778
1999/02/09 03:00:27| cbdataValid: 8210778
1999/02/09 03:00:27| cbdataUnlock: 8210778
1999/02/09 03:00:27| cbdataLock: 8210778
1999/02/09 03:00:27| cbdataValid: 8210778
1999/02/09 03:00:27| cbdataUnlock: 8210778
1999/02/09 03:00:43| cbdataValid: 8210778
1999/02/09 03:01:44| cbdataValid: 8210778
1999/02/09 03:02:43| cbdataValid: 8210778
1999/02/09 03:03:43| cbdataValid: 8210778
1999/02/09 03:04:43| cbdataValid: 8210778
1999/02/09 03:04:43| cbdataValid: 8210778
1999/02/09 03:04:43| cbdataValid: 8210778
1999/02/09 03:09:43| cbdataValid: 8210778
1999/02/09 03:09:44| cbdataValid: 8210778
1999/02/09 03:09:44| cbdataValid: 8210778
1999/02/09 03:09:44| cbdataValid: 8210778
1999/02/09 03:19:44| cbdataValid: 8210778
1999/02/09 03:19:45| cbdataValid: 8210778
1999/02/09 03:19:45| cbdataValid: 8210778
1999/02/09 03:19:45| cbdataValid: 8210778
1999/02/09 03:39:45| cbdataValid: 8210778
1999/02/09 03:39:46| cbdataValid: 8210778
1999/02/09 03:39:46| cbdataValid: 8210778
1999/02/09 03:39:46| cbdataValid: 8210778
1999/02/09 04:13:44| cbdataLock: 8210778
1999/02/09 04:13:44| cbdataValid: 8210778
1999/02/09 04:13:44| cbdataLock: 8210778
1999/02/09 04:13:44| cbdataUnlock: 8210778
1999/02/09 04:14:07| cbdataValid: 8210778
1999/02/09 04:14:07| cbdataUnlock: 8210778
1999/02/09 04:14:07| cbdataLock: 8210778
1999/02/09 04:14:07| cbdataValid: 8210778
1999/02/09 04:14:07| cbdataUnlock: 8210778
1999/02/09 04:19:46| cbdataValid: 8210778
1999/02/09 04:19:48| cbdataValid: 8210778
1999/02/09 04:19:49| cbdataValid: 8210778
1999/02/09 04:19:49| cbdataValid: 8210778
1999/02/09 05:39:49| cbdataValid: 8210778
1999/02/09 05:39:49| cbdataValid: 8210778
1999/02/09 05:39:49| cbdataValid: 8210778
1999/02/09 05:40:53| cbdataLock: 8210778
1999/02/09 05:40:53| cbdataValid: 8210778
1999/02/09 05:40:53| cbdataLock: 8210778
1999/02/09 05:40:53| cbdataUnlock: 8210778
1999/02/09 05:41:22| cbdataValid: 8210778
1999/02/09 05:41:22| cbdataUnlock: 8210778
1999/02/09 05:41:22| cbdataLock: 8210778
1999/02/09 05:41:22| cbdataValid: 8210778
1999/02/09 05:41:22| cbdataUnlock: 8210778
1999/02/09 07:01:26| cbdataLock: 8210778
1999/02/09 07:01:26| cbdataValid: 8210778
1999/02/09 07:01:26| cbdataLock: 8210778
1999/02/09 07:01:26| cbdataUnlock: 8210778
1999/02/09 07:01:26| cbdataUnlock: 8210778
1999/02/09 07:01:53| cbdataValid: 8210778
1999/02/09 07:01:53| cbdataUnlock: 8210778
1999/02/09 07:01:53| cbdataLock: 8210778
1999/02/09 07:01:53| cbdataValid: 8210778
1999/02/09 07:01:53| cbdataUnlock: 8210778
1999/02/09 08:19:49| cbdataValid: 8210778
1999/02/09 08:19:49| assertion failed: cbdata.c:207: "c->locks > 0"

 ----------------------------------------------------------------------
  Andres Kroonmaa mail: andre@online.ee
  Network Manager
  Organization: MicroLink Online Tel: 6308 909
  Tallinn, Sakala 19 Pho: +372 6308 909
  Estonia, EE0001 http://www.online.ee Fax: +372 6308 901
 ----------------------------------------------------------------------
Received on Tue Jul 29 2003 - 13:15:56 MDT

This archive was generated by hypermail pre-2.1.9 : Tue Dec 09 2003 - 16:12:04 MST