[Zodb-checkins] CVS: StandaloneZODB/ZEO - StorageServer.py:1.34.2.6 smac.py:1.14.2.3

Jeremy Hylton jeremy@zope.com
Tue, 26 Mar 2002 00:59:10 -0500


Update of /cvs-repository/StandaloneZODB/ZEO
In directory cvs.zope.org:/tmp/cvs-serv22457

Modified Files:
      Tag: zeo-1_0-debug-branch
	StorageServer.py smac.py 
Log Message:
Add per-method logging for some methods at blather level.

This logging is less verbose than the debug level logging, but still
notes all transactions boundaries, loads, and stores.

Format oids and txnids using ZODB.utils.U64 for easier reading.

XXX There seems to be an intermittent error in this branch w/ python
-O!  Perhaps once every four test runs I see the
checkCommitLockOnAbort test fail with a release unlocked lock error
raised on the server side.  

The terse asyncore exception points to message_input() line 201.  Not
sure if this is on the client side or the server side.  Assume it must
be the client, since the server doesn't get returns.

The client-side traceback is in a tpc_finish() / __call__() of zrpc
with the std "see server log for real traceback" method.  But the
server log doesn't have anything!


=== StandaloneZODB/ZEO/StorageServer.py 1.34.2.5 => 1.34.2.6 ===
 from ZODB.Transaction import Transaction
 from ZODB.referencesf import referencesf
+from ZODB.utils import U64
 
 from ZEO import trigger
 from ZEO import asyncwrap
@@ -190,7 +191,8 @@
             self._ncalls = 0
             
         SizedMessageAsyncConnection.__init__(self, sock, addr, debug=debug)
-        log.info('Connect %s %s' % (id(self), `addr`))
+        self.logaddr = repr(addr) # form of addr suitable for logging
+        log.info('Connect %s %s' % (id(self), self.logaddr))
 
     def stats(self):
         # This method is called via the status() command.  The stats
@@ -250,8 +252,8 @@
 
         if self.__storage is None:
             if __debug__:
-                log.debug("register connection to %s from %s" % (message,
-                                                                 self.addr))
+                log.blather("register connection to %s from %s" % (message,
+                                                                self.logaddr))
             # This is the first communication from the client
             self.__storage, self.__storage_id = (
                 self.__server.register_connection(self, message))
@@ -272,7 +274,7 @@
                 self._last_method = name
                 self._ncalls = self._ncalls + 1
                 log.debug("call %s%s from %s" % (name, format_msg(args),
-                                                 self.addr))
+                                                 self.logaddr))
                 
             if not storage_method(name):
                 log.warning("Invalid method name: %s" % name)
@@ -285,12 +287,12 @@
                 r=apply(getattr(self.__storage, name), args)
             if r is _noreturn:
                 if __debug__:
-                    log.debug("no return to %s" % `self.addr`)
+                    log.debug("no return to %s" % self.logaddr)
                     self._t_end = time.time()
                 return
         except (UndoError, VersionCommitError), err:
             if __debug__:
-                log.debug("return error %s to %s" % (err, self.addr))
+                log.debug("return error %s to %s" % (err, self.logaddr))
                 self._t_end = time.time()
             # These are normal usage errors. No need to log them.
             self.return_error(sys.exc_info()[0], sys.exc_info()[1])
@@ -303,7 +305,7 @@
             return
 
         if __debug__:
-            log.debug("return %s to %s" % (format_msg(r), self.addr))
+            log.debug("return %s to %s" % (format_msg(r), self.logaddr))
             self._t_end = time.time()
             
         r=dump(r,1)            
@@ -350,6 +352,8 @@
             }
 
     def zeoLoad(self, oid):
+        if __debug__:
+            log.blather("zeoLoad(%s) %s" % (U64(oid), self.logaddr))
         storage=self.__storage
         v=storage.modifiedInVersion(oid)
         if v: pv, sv = storage.load(oid, v)
@@ -366,6 +370,8 @@
             
 
     def beginZeoVerify(self):
+        if __debug__:
+            log.blather("beginZeoVerify() %s" % self.logaddr)
         self.message_output('bN.')            
         return _noreturn
 
@@ -382,6 +388,8 @@
         return _noreturn
 
     def endZeoVerify(self):
+        if __debug__:
+            log.blather("endZeoVerify() %s" % self.logaddr)
         self.message_output('eN.')
         return _noreturn
 
@@ -439,6 +447,9 @@
 
     def storea(self, oid, serial, data, version, id,
                dump=dump):
+        if __debug__:
+            log.blather("storea(%s, [%d], %s) %s" % (U64(oid), len(data),
+                                                   U64(id), self.logaddr))
         try:
             t=self._transaction
             if t is None or id != t.id:
@@ -478,12 +489,17 @@
         return self.__storage.tpc_vote(t)
 
     def transactionalUndo(self, trans_id, id):
+        if __debug__:
+            log.blather("transactionalUndo(%s, %s) %s" % (trans_id,
+                                                        U64(id), self.logaddr))
         t=self._transaction
         if t is None or id != t.id:
             raise POSException.StorageTransactionError(self, id)
         return self.__storage.transactionalUndo(trans_id, self._transaction)
         
     def undo(self, transaction_id):
+        if __debug__:
+            log.blather("undo(%s) %s" % (transaction_id, self.logaddr))
         oids=self.__storage.undo(transaction_id)
         if oids:
             self.__server.invalidate(
@@ -539,6 +555,12 @@
                 onerror()
 
     def tpc_abort(self, id):
+        if __debug__:
+            try:
+                log.blather("tpc_abort(%s) %s" % (U64(id), self.logaddr))
+            except:
+                print repr(id)
+                raise
         t = self._transaction
         if t is None or id != t.id:
             return
@@ -554,6 +576,8 @@
         self.message_output('UN.')
 
     def tpc_begin(self, id, user, description, ext):
+        if __debug__:
+            log.blather("tpc_begin(%s) %s" % (U64(id), self.logaddr))
         t = self._transaction
         if t is not None:
             if id == t.id:
@@ -567,7 +591,8 @@
         if storage._transaction is not None:
             self.commitlock_suspend(self.unlock, (), self.close)
             return 1 # Return a flag indicating a lock condition.
-            
+
+        assert id != 't'
         self._transaction=t=Transaction()
         t.id=id
         t.user=user
@@ -604,6 +629,8 @@
         return 1
 
     def tpc_finish(self, id, user, description, ext):
+        if __debug__:
+            log.blather("tpc_finish(%s) %s" % (U64(id), self.logaddr))
         t = self._transaction
         if id != t.id:
             return


=== StandaloneZODB/ZEO/smac.py 1.14.2.2 => 1.14.2.3 ===
             '__init__')(self, sock, map)
         self.addr=addr
-        if debug is not None:
+        if debug is None and __debug__:
+            self._debug = zLogger("smac")
+        else:
             self._debug = debug
-        elif not hasattr(self, '_debug'):
-            self._debug = __debug__ and zLogger("smac")
         self.__state=None
         self.__inp=None
         self.__inpl=0