[ZODB-Dev] instrumenting zeo for forensic analysis
hazmat
hazmat at objectrealms.net
Wed May 7 22:43:19 EDT 2003
hi folks,
i'm trying to debug a hanging zeo/zope cluster. the app runs fine on a
single non zeo node with a similiar load, but in the cluster it hangs.
based on other investigative work i'm fairly sure that the problem lies
in either zeo or sessions (sessions are served as a mounted db from the
zeo server). in an effort to debug the problem further i tried to write
a wrapper around the ClientStorage to log all methods called and most
arguments to a log file, in attempt to try and write an isolated script
that can reproduce the hang problem. unfortunately my wrapper refuses to
properly connect to the zeo server, and i'm not sure why.. perhaps
something simple.. i dunno. i've attached the wrapper class (ZCSLog.py),
the zeo_server log (all logging enabled) and the log from the wrapper.
if anyone can take a look and offer some insight, i'd be grateful. the
code used was from zeo/zodb3 and zope cvs as of today.
thanks
-haz
-------------- next part --------------
"""
Foresenic Client Storage
- ZEO Client Storage + logging instrumentation
this would be alot more fun w/ 2.2 and a metaclass :-)
author: hazmat at objectrealms.net
"""
import os
from ZEO.ClientStorage import ClientStorage
from logging import getLogger
from logging.config import fileConfig
def initializeLog(filename):
filename = os.path.expanduser( os.path.expandvars(filename) )
fileConfig(filename)
initializeLog('~/.zcs_log.ini')
log = getLogger('zcs')
log.info('Forensic Log Begin')
## class ZCSLog:
## def __init__(self, *args, **kw):
## self._storage = ClientStorage(*args, **kw)
## def __getattr__(self, name):
## log.info('%s', name)
## return getattr(self._storage, name)
class ZCSLog(ClientStorage):
def __init__(self, *args, **kw):
log.info('__init__')
ClientStorage.__init__(self, *args, **kw)
def _wait(self):
log.info('wait')
return ClientStorage._wait(self)
def _wait_sync(self):
log.info('wait_sync')
return ClientStorage._wait_sync(self)
def close(self):
log.info('close')
return ClientStorage.close(self)
def registerDB(self):
log.info('registerDB')
return ClientStorage.registerDB(self)
def is_connected(self):
log.info('is_connected')
return ClientStorage.is_connected(self)
def sync(self):
log.info('sync')
return ClientStorage.sync(self)
def testConnection(self, conn):
log.info('testConnection %s', conn)
return ClientStorage.testConnection(self, conn)
def notifyConnected(self, conn):
log.info('notifyConnected %s', conn)
return ClientStorage.notifyConnected(self, conn)
def set_server_addr(self, addr):
log.info('set_server_address %s', addr)
return ClientStorage.set_server_address(self, addr)
def sortKey(self):
log.info('sortKey')
return ClientStorage.sortKey(self)
def verify_cache(self, server):
log.info('verify_cache %s', server)
return ClientStorage.verify_cache(self, server)
def notifyDisconnected(self):
log.info('notifyDisconnected')
return ClientStorage.notifyDisconnected(self)
def __len__(self):
log.info('__len__')
return ClientStorage.__len__(self)
def getName(self):
log.info('getName')
return ClientStorage.getName(self)
def getSize(self):
log.info('getSize')
return ClientStorage.getSize(self)
def getExtensionMethods(self):
log.info('getExtensionMethods')
return ClientStorage.getExtensionMethods(self)
def supportsUndo(self):
log.info('supportsUndo')
return ClientStorage.supportsUndo(self)
def supportsVersions(self):
log.info('supportsVersions')
return ClientStorage.supportsVersions(self)
def supportsTransactionalUndo(self):
log.info('supportsTransactionalUndo')
return ClientStorage.supportsTransactionalUndo(self)
def isReadOnly(self):
log.info('isReadOnly')
return ClientStorage.isReadOnly(self)
def _check_trans(self, trans):
log.info('_check_trans %s', trans)
return ClientStorage._check_trans(self, trans)
def abortVersion(self, version, transaction):
log.info('abortVersion %s, %s', version, transaction)
return ClientStorage.abortVersion(self, version, transaction)
def commitVersion(self, source, destination, transaction):
log.info('commitVersion %s, %s, %s', source, destination, transaction)
return ClientStorage.commitVersion(self, source, destination, transaction)
def history(self, oid, version, length=1):
log.info('history %s, %s, %s', oid, version, length)
return ClientStorage.history(self, oid, version, length)
def __getattr__(self, name):
log.info('getattr hook %s', name)
return ClientStorage.__getattr__(self, name)
def loadSerial(self, oid, serial):
log.info('loadSerial %s, %s', oid, serial)
return ClientStorage.loadSerial(self, oid, serial)
def load(self, oid, version):
log.info('load %s, %s', oid, version)
return ClientStorage.load(self, oid, version)
def modifiedInVersion(self, oid):
log.info('modifiedInVersion %s', oid)
return ClientStorage.modifiedInVersion(self, oid)
def new_oid(self):
log.info('new_oid')
return ClientStorage.new_oid(self)
def pack(self, t=None, referencesf=None, wait=1, days=0):
log.info('pack %s, %s, %s, %s', t, referencesf, wait, days)
return ClientStorage.pack(self, t, referencesf, wait, days)
def _check_serials(self):
log.info('_check_serials')
return ClientStorage._check_serials(self)
def store(self, oid, serial, data, version, transaction):
log.info('store %s, %s, %s, %s', oid, serial, version, transaction)
return ClientStorage.store(self, oid, serial, data, version, transaction)
def tpc_vote(self, transaction):
log.info('tpc_vote %s', transaction)
return ClientStorage.tpc_vote(self, transaction)
def tpc_begin(self, txn, tid=None, status=' '):
log.info('tpc_begin %s %s %s', txn, tid, status)
return ClientStorage.tpc_begin(self, txn, tid, status)
def end_transaction(self):
"""Internal helper to end a transaction."""
log.info('end_transaction')
return ClientStorage.end_transaction(self)
def lastTransaction(self):
log.info('lastTransaction')
return ClientStorage.lastTransaction(self)
def tpc_abort(self, transaction):
log.info('tpc_abort %s', transaction)
return ClientStorage.tpc_abort(self, transaction)
def tpc_finish(self, transaction, f=None):
log.info('tpc_finish %s %s', transaction, f)
return ClientStorage.tpc_finish(self, transaction, f)
def _update_cache(self):
log.info('_update_cache')
return ClientStorage._update_cache(self)
def transactionalUndo(self, trans_id, trans):
log.info('transactionalUndo %s, %s', trans_id, trans)
return ClientStorage.transactionalUndo(self, trans_id, trans)
def undo(self, transaction_id):
log.info('undo %s', transaction_id)
return ClientStorage.undo(self, transaction_id)
def undoInfo(self, first=0, last=-20, specification=None):
log.info('undoInfo %s %s %s', first, last, specification)
return ClientStorage.undoInfo(self, first, last, specification)
def undoLog(self, first=0, last=-20, filter=None):
log.info('undoLog %s, %s, %s', first, last, filter)
return ClientStorage.undoLog(self, first, last, filter)
def versionEmpty(self, version):
log.info('versionEmpty %s', version)
return ClientStorage.versionEmpty(self, version)
def versions(self, max=None):
log.info('versions %s', max)
return ClientStorage.versions(self, max)
# Below are methods invoked by the StorageServer
def serialnos(self, args):
log.info('serialnos %s', args)
return ClientStorage.serialnos(self, args)
def info(self, dict):
log.info('info %s', dict)
return ClientStorage.info(self, dict)
def invalidateVerify(self, args):
log.info('invalidateVerify %s', args)
return ClientStorage.invalidteVerify(self, args)
def _process_invalidations(self, invs):
log.info('_process_invalidation %s', invs)
return ClientStorage._process_invalidation(self, invs)
def endVerify(self):
log.info('endVerify')
return ClientStorage.endVerify(self)
def invalidateTransaction(self, tid, args):
log.info('invalidateTransaction %s %s', tid, args)
return ClientStorage.invalidateTransaction(self, tid, args)
# The following are for compatibility with protocol version 2.0.0
def invalidateTrans(self, args):
return self.invalidateTransaction(None, args)
invalidate = invalidateVerify
end = endVerify
Invalidate = invalidateTrans
-------------- next part --------------
------
2003-05-07T18:40:13 INFO(0) RUNSVR opening storage '1' using FileStorage
------
2003-05-07T18:40:13 INFO(0) ZSS:11701 StorageServer created RW with storages: 1:RW:/home/hazmat/servers/zeotests/zeo2server/var/Data.fs
------
2003-05-07T18:40:13 INFO(0) zrpc:11701 listening on ('', 9999)
------
2003-05-07T18:40:21 TRACE(-300) zrpc:11701 message_output 4 bytes: 'Z201'
------
2003-05-07T18:40:21 INFO(0) ZSS:11701 new connection ('127.0.0.1', 50287): <ManagedServerConnection ('127.0.0.1', 50287)>
------
2003-05-07T18:40:21 BLATHER(-100) zrpc:11701 connect from ('127.0.0.1', 50287): <ManagedServerConnection ('127.0.0.1', 50287)>
------
2003-05-07T18:40:21 INFO(0) zrpc-conn:127.0.0.1:50287 received handshake 'Z201'
------
2003-05-07T18:40:21 TRACE(-300) zrpc-conn:127.0.0.1:50287 recv msg: 0, 0, register, ('1', 0)
------
2003-05-07T18:40:21 DEBUG(-200) zrpc-conn:127.0.0.1:50287 calling register('1', 0)
------
2003-05-07T18:40:21 DEBUG(-200) zrpc-conn:127.0.0.1:50287 register returns None
------
2003-05-07T18:40:21 TRACE(-300) zrpc:11701 message_output 16 bytes: '(K\x00K\x00U\x06.replyNt.'
------
2003-05-07T18:40:21 TRACE(-300) zrpc-conn:127.0.0.1:50287 poll(), async=1
------
2003-05-07T18:40:21 INFO(0) ZSS:11701/127.0.0.1:50287 disconnected
-------------- next part --------------
2003-05-07 18:40:21,105 INFO Forensic Log Begin
2003-05-07 18:40:21,106 INFO __init__
2003-05-07 18:40:21,108 INFO wait
2003-05-07 18:40:21,115 INFO testConnection <ManagedConnection ('127.0.0.1', 9999)>
2003-05-07 18:40:21,125 INFO notifyConnected <ManagedConnection ('127.0.0.1', 9999)>
2003-05-07 18:40:21,126 INFO set_server_address ('127.0.0.1', 9999)
2003-05-07 18:40:26,131 INFO testConnection <ManagedConnection ('127.0.0.1', 9999)>
2003-05-07 18:40:26,144 INFO notifyConnected <ManagedConnection ('127.0.0.1', 9999)>
2003-05-07 18:40:26,145 INFO set_server_address ('127.0.0.1', 9999)
More information about the ZODB-Dev
mailing list