[ZODB-Dev] BTrees q [Fwd: [Zope-dev] More Transience weirdness in 2.7.1b1]

[Chris McDonough]

I recently got the below message from a user of Zope sessioning.  Zope
sessioning makes use of ZODB and BTrees, and Steve reports a somewhat
odd (well, odd to me, at least) error.

-----Forwarded Message-----
> From: Steve Jibson <stevej at parlant.com>
> To: zope-dev at zope.org
> Subject: [Zope-dev] More Transience weirdness in 2.7.1b1
> Date: Wed, 02 Jun 2004 13:39:59 -0600
> 
> It seems that there may still be some strangeness with Transience. 
> We're running Zope-2.7.1b1 (Python 2.3.3, Fedora Core 1) and after using 
> the system for a day or two, it got the following error on a page that 
> accesses the SESSION:
> 
>    Traceback (innermost last):
>      Module ZPublisher.Publish, line 101, in publish
>      Module ZPublisher.mapply, line 88, in mapply
>      Module ZPublisher.Publish, line 39, in call_object
>      Module OFS.DTMLDocument, line 128, in __call__
>       - <DTMLDocument instance at 9e684350>
>       -URL: http://george/login/root/ChooseAccount/chooseAccount/manage_main
>       - Physical Path: /login/root/ChooseAccount/chooseAccount
>      Module DocumentTemplate.DT_String, line 474, in __call__
>      Module DocumentTemplate.DT_With, line 76, in render
>      Module DocumentTemplate.DT_In, line 703, in renderwob
>      Module DocumentTemplate.DT_Let, line 76, in render
>      Module DocumentTemplate.DT_Util, line 198, in eval
>       - __traceback_info__: value
>      Module <string>, line 1, in <expression>
>    NameError: name 'SESSION' is not defined
> 
> 
> It doesn't appear to be a problem accessing a variable in the SESSION, 
> but finding "SESSION" itself.
> 
> So, I hook-up to the ZMI and click on *temp_folder*, then click on    	
> *session_data (Session Data Container)* and I get the following error:
> 
>    Traceback (innermost last):
>      Module ZPublisher.Publish, line 101, in publish
>      Module ZPublisher.mapply, line 88, in mapply
>      Module ZPublisher.Publish, line 39, in call_object
>      Module App.special_dtml, line 62, in __call__
>      Module DocumentTemplate.DT_String, line 474, in __call__
>      Module Products.Transience.Transience, line 709, in nudge
>      Module Products.Transience.Transience, line 555, in _gc
>    RuntimeError: the bucket being iterated changed size
> 
> 
> The same thing happened yesterday and re-starting Zope seemed to get 
> things working again.  After the problem yesterday, I changed my temp 
> database to use filestorage to see if that would help.  No luck, the 
> problem showed up again today.

I am wondering how the "RuntimeError:  bucket being iterated over" error
could get raised given that the code from which the RuntimeError
emanates is:

    def _gc(self, now=None):
        if not self._timeout_slices:
            return # dont do gc if there is no timeout

        if now is None:
            now = getCurrentTimeslice(self._period) # for unit tests
        max_ts = now  - (self._period * (self._timeout_slices + 1))

        to_notify = []

        DEBUG and TLOG('_gc: now is %s' % now)
        DEBUG and TLOG('_gc: max_ts is %s' % max_ts)

        for key in list(self._data.keys(None, max_ts)):
            assert(key <= max_ts)
            STRICT and _assert(self._data.has_key(key))

            for v in self._data[key].values():
                to_notify.append(v)
                self._length.change(-1)

            DEBUG and TLOG('deleting %s from _data' % key)
            del self._data[key]

        for v in to_notify:
            self.notifyDel(v)

Line 555 is the line:

   "for key in list(self._data.keys(None, max_ts)):"

It doesn't appear that I am mutating the state of the _data btree when
iterating over its keys, values or items.  If I'm wrong, I trust you'll
let me know. ;-)

Guesses:  Could the BTreeItems_seek code raise this error if the data
structure was being accessed by another thread via a different database
connection simultaneously?  Could a suppressed conflict error at a past
transaction commit time leave the database in such a state where a
subsequent run through this code could wind up in this state?

FWIW, I have a high-concurrency test rig that exercises this code which
I have run for 24+ hours without bumping in to the same issue, so I'm
flying a bit blind here.

- C