[ZODB-Dev] POSKeyError with Zope 2.7.2, suddenly appeared, thendisappeared...

[Dieter Maurer]

Hi Florent,

Florent Guillaume wrote at 2005-2-21 16:46 +0100:
>Dieter Maurer  <dieter at handshake.de> wrote:
>> >I can't agree that info level was inappropriate here, at least not without a
>> >lot more thought than I can give to it now.  A problem with ZEO is that
>> >people normally want a way to tell that ZEO is still _alive_ in info-level
>> >logs.  Logging info about transaction-lock activity is one natural way to do
>> >that (if you're doing transactions over ZEO, but not seeing those msgs, you
>> >can deduce that ZEO is dead or deadlocked or something; and looking then at
>> >the last lock activity logged can be a good clue about how things got
>> >hosed).
>> 
>> I changed this (in our private copy) and now
>> explicitly log when a transaction needs to wait for the
>> transaction lock (and what (user and description) is holding
>> this lock) and when it is restarted.
>
>Could you point me to where you added these logs? I'm trying to find the
>reason for a deadlock we have here...

I did not read your message carefully enough.
Therefore, in a previous message, I have sent you a log to
"DB.DB.open" (which is useful as well but apparently
not what you were asking for).

Almost surely, you are interested in the ZEO logging.
Here come the details. All logs are in "ZEO.StorageServer.py".
Look for "DM 2005-01-19" to locate the changes.

    def notifyDisconnected(self):
        # When this storage closes, we must ensure that it aborts
        # any pending transaction.
        if self.transaction is not None:
            # DM 2005-01-19: replace "str" by "_getBlockingTransactionInfo"
            #  for consistency and to get more information
            self.log("disconnected during transaction %s"
                     % self._getBlockingTransactionInfo(self.transaction)
                     )
            self._abort()
        else:
            self.log("disconnected")
    ....


    def register(self, storage_id, read_only):
        ...
        self.setup_delegation()
        self.timeout, self.stats = self.server.register_connection(storage_id,
                                                                   self)
        # DM 2005-01-19: extend log info by storage id
        self.log_label += '(%s)' % storage_id
	


    def _wait(self, thunk):
        # Wait for the storage lock to be acquired.
        self._thunk = thunk
        if self.storage._transaction:
            d = Delay()
            self.storage._waiting.append((d, self))
            # DM 2005-01-19: added blocking transaction info
            self.log("Transaction blocked waiting for storage. "
                     "Clients waiting: %d."
                     " Blocking transaction: %s"
                     % (len(self.storage._waiting),
                        self._getBlockingTransactionInfo(),
                        )
                     )
            return d

    def _handle_waiting(self):
        # Restart any client waiting for the storage lock.
        while self.storage._waiting:
            delay, zeo_storage = self.storage._waiting.pop(0)
            if self._restart_other(zeo_storage, delay):
                # DM 2005-01-19: ATT: this code can be affected by
                #  race conditions as we may not be executed in the main
                #  thread.
                if self.storage._waiting:
                    n = len(self.storage._waiting)
                    # DM 2005-01-19: added blocking transaction info
                    self.log("Blocked transaction restarted.  "
                             "Clients waiting: %d"
                             " Blocking transaction: %s"
                             % (n, self._getBlockingTransactionInfo(), )
                             )
                else:
                    self.log("Blocked transaction restarted.")
                return

    # DM 2005-01-19: added
    def _getBlockingTransactionInfo(self, transaction=None):
        # due to race conditions we may not be able to determine
        # the blocking transaction!
        t = transaction
        if t is None: t = self.storage._transaction
        if t is None:
            # race condition
            info = '*** could not be determined (race condition) ***'
        else:
            info = "id='%s' user='%s' description='%s'" % (
                b2a_hex(t.id), t.user, t.description
                )
        return info


-- 
Dieter