[ZODB-Dev] More exciting ZODB errors ;-)

[Tim Peters]

[Chris Withers]
> We recently upgraded to Zope 2.8.4 and have been seeing some different
> and special errors every so often (why does this always and only ever
> happen to me? ;-)

I don't know, but if I were you I'd try running for a while on entirely
different hardware.

> Nothing noticeably bad appears to result from these, but, as always, I
> loose hair over them and would like ot know what's going on :-S
>
> Any clues?
>
> Chris
>
> 08:55 - Traceback (most recent call last):
> "lib/python/transaction/_transaction.py", line 422, in _commitResources
>      rm.tpc_begin(self)
>    File "lib/python/ZODB/Connection.py", line 446, in tpc_begin
>      self._normal_storage.tpc_begin(transaction)
>    File "lib/python/ZEO/ClientStorage.py", line 914, in tpc_begin
>      txn._extension, tid, status)
>    File "lib/python/ZEO/ServerStub.py", line 232, in tpc_begin
>      return self.rpc.call('tpc_begin', id, user, descr, ext, tid, status)
>    File "lib/python/ZEO/zrpc/connection.py", line 536, in call
>      raise inst # error raised by server
> StorageTransactionError: Multiple simultaneous tpc_begin requests from one
client.

Found only one previous report of this, against Zope 2.6.1, some ZODB 3.0.1
beta (unclear exactly which), and Berkeley DB:

    http://mail.zope.org/pipermail/zodb-dev/2003-May/005195.html

Jeremy made some suggestions a few msgs down, but there was no followup from
the OP and no resolution.

> 10:05 - Couldn't load state for 0x013872b7: Traceback (most recent call
last):
>    File "lib/python/ZODB/Connection.py", line 704, in setstate
>      self._setstate(obj)
>    File "lib/python/ZODB/Connection.py", line 757, in _setstate
>      self._load_before_or_conflict(obj)
>    File "lib/python/ZODB/Connection.py", line 765, in
_load_before_or_conflict
>      if not (self._mvcc and self._setstate_noncurrent(obj)):
>    File "lib/python/ZODB/Connection.py", line 788, in _setstate_noncurrent
>      assert end is not None
> AssertionError
>
> 10:05 - Error viewing a method on an object:
>    File "lib/python/Products/PluginIndexes/DateIndex/DateIndex.py", line
135, in index_object
>      oldConvertedDate = self._unindex.get( documentId, _marker )
>    File "lib/python/ZODB/Connection.py", line 704, in setstate
>      self._setstate(obj)
>    File "lib/python/ZODB/Connection.py", line 757, in _setstate
>      self._load_before_or_conflict(obj)
>    File "lib/python/ZODB/Connection.py", line 765, in
load_before_or_conflict
>      if not (self._mvcc and self._setstate_noncurrent(obj)):
>    File "lib/python/ZODB/Connection.py", line 788, in _setstate_noncurrent
>      assert end is not None
> AssertionError

Haven't seen a report of this before.  It's trying to load state for a ghost
object, but the oid has been invalidated, so (because of MVCC) it's trying
to load state that _was_ current at the time the transaction began.  The
assertion is griping because the non-current state it loaded doesn't appear
to have a sane validity range (that `end` is None is claiming that the old
state is still valid, but that can't be true if the oid has in fact been
invalidated).

Smells like an internal MVCC bug to me.

Jeremy, the code at the start of _setstate() looks fishy:  any idea what the
intent was?:

        # There is a harmless data race with self._invalidated.  A
        # dict update could go on in another thread, but we don't care
        # because we have to check again after the load anyway.

        if (obj._p_oid in self._invalidated
            and not myhasattr(obj, "_p_independent")
            and not self._invalidated
            ):
            # If the object has _p_independent(), we will handle it below.
            self._load_before_or_conflict(obj)
            return

Specifically, how could:

    obj._p_oid in self._invalidated

and:

    not self._invalidated

be true at the same time?  The latter says _invalidated is empty, but the
former can't be true if _invalidated is empty.  Offhand, then, unless we're
_counting_ on a thread race here ;-), it looks impossible that the body of
this `if` could execute.

I don't have a reason to believe it's directly relevant to Chris's problem,
it's just that I got baffled by the first thing I looked at ;-)