[ZODB-Dev] transaction timeouts raise no exceptions and cause strange errors on clients

[Chris Withers]

Hi All,

I have a ZODB 3.9.6 ZEO storage server configured with a transaction 
time of 20 seconds.

On one zeo client I saw the following:

------
2010-11-04T10:40:50 INFO ZEO.ClientStorage unpackedstorage Disconnected 
from storage: "('xx', 6000)"
------
2010-11-04T10:40:50 INFO ZEO.ClientStorage unpackedstorage Testing 
connection <ManagedClientConnection ('xx', 6000)>
------
2010-11-04T10:40:50 INFO ZEO.zrpc.Connection(C) (xx:6000) received 
handshake 'Z309'
------
2010-11-04T10:40:50 ERROR ZODB.Connection Couldn't load state for 0x15ef67
Traceback (most recent call last):
   File "ZODB3-3.9.6-py2.6-linux-i686.egg/ZODB/Connection.py", line 847, 
in setstate
     self._setstate(obj)
   File "ZODB3-3.9.6-py2.6-linux-i686.egg/ZODB/Connection.py", line 897, 
in _setstate
     p, serial = self._storage.load(obj._p_oid, '')
   File "ZODB3-3.9.6-py2.6-linux-i686.egg/ZODB/Connection.py", line 
1282, in load
     return self._storage.load(oid, '')
   File "ZODB3-3.9.6-py2.6-linux-i686.egg/ZEO/ClientStorage.py", line 
813, in load
     data, tid = self._server.loadEx(oid)
   File "ZODB3-3.9.6-py2.6-linux-i686.egg/ZEO/ClientStorage.py", line 
88, in __getattr__
     raise ClientDisconnected()
ClientDisconnected
------
2010-11-04T10:40:51 INFO ZEO.ClientStorage unpackedstorage Server 
authentication protocol None
------
2010-11-04T10:40:51 INFO ZEO.ClientStorage unpackedstorage Connected to 
storage: ('xx', 6000)
------
2010-11-04T10:40:51 INFO ZEO.ClientStorage unpackedstorage No 
verification necessary (last_inval_tid up-to-date)
------
2010-11-04T10:40:51 ERROR Zope.SiteErrorLog 1288867251.890.173783627248 
https://xx
Traceback (innermost last):
...
   Module ZODB.Connection, line 847, in setstate
   Module ZODB.Connection, line 897, in _setstate
   Module ZODB.Connection, line 1282, in load
   Module ZEO.ClientStorage, line 813, in load
   Module ZEO.ClientStorage, line 88, in __getattr__
ClientDisconnected
------
2010-11-04T10:40:54 CRITICAL txn.-1271567456 A storage error occurred 
during the second phase of the two-phase commit.  Resources may be in an 
inconsistent state.
------
2010-11-04T10:40:55 ERROR Zope.SiteErrorLog 1288867255.090.422928174987 
https://xx
Traceback (innermost last):
   Module ZPublisher.Publish, line 135, in publish
   Module Zope2.App.startup, line 291, in commit
   Module transaction._manager, line 89, in commit
   Module transaction._transaction, line 329, in commit
   Module transaction._transaction, line 431, in _commitResources
   Module ZODB.Connection, line 794, in tpc_finish
   Module ZEO.ClientStorage, line 1148, in tpc_finish
ClientDisconnected: Calling tpc_finish() on a disconnected transaction

This was all pretty alarming, especially as I could see no errors logged 
anywhere else.

Eevntually, in the storage server logs, I found:

2010-11-04T10:40:50 INFO ZEO.StorageServer (7008/xx) Transaction timeout 
after 20 seconds
------
2010-11-04T10:40:50 INFO ZEO.StorageServer (7008/xx) disconnected during 
transaction <transaction._transaction.Transaction object at 0x9b4106c>
------
2010-11-04T10:40:50 INFO ZEO.StorageServer (7008) new connection ('xx', 
34996): <ManagedServerConnection ('xx', 34996)>
------
2010-11-04T10:40:50 INFO ZEO.zrpc.Connection(S) (xx) received handshake 
'Z309'
------
2010-11-04T10:40:55 WARNING ZEO.StorageServer (7008/xx) no current 
transaction: tpc_abort()
------

I'm curious:

- Why is the timeout not logged at ERROR or even CRITICAL?

- Is the "inconsistent state" warning genuine here? I restarted the
   client to be on the safe side, but it'd be good to know for sure.

- If that warning is genuine, is there any way the timeout could not
   leave the client in an inconsistent state?

cheers,

Chris

-- 
Simplistix - Content Management, Batch Processing & Python Consulting
            - http://www.simplistix.co.uk