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
_______________________________________________
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/
ZODB-Dev mailing list - ZODB-Dev@zope.org
https://mail.zope.org/mailman/listinfo/zodb-dev
