[Zodb-checkins] CVS: StandaloneZODB/ZEO - ClientStorage.py:1.38.2.2 StorageServer.py:1.34.2.2 smac.py:1.14.2.2 zrpc.py:1.21.2.2

Jeremy Hylton jeremy@zope.com
Fri, 15 Mar 2002 01:47:53 -0500


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

Modified Files:
      Tag: zeo-1_0-debug-branch
	ClientStorage.py StorageServer.py smac.py zrpc.py 
Log Message:
Revised logging that is performed.

Try to use log levels consistently.  The lowest level, TRACE, is used
to prints per-message dumps and nothing else.  The next level, DEBUG,
is use to print method calls and responses, plus some other cruft.

Add status() call to client and server.  The status() implementation
lives in the StorageServer instance.  It prints a log message with a
list of all storages and all connections.




=== StandaloneZODB/ZEO/ClientStorage.py 1.38.2.1 => 1.38.2.2 ===
 __version__='$Revision$'[11:-2]
 
-import struct, time, os, socket, string, Sync, zrpc, ClientCache
-import tempfile, Invalidator, ExtensionClass, thread
-import ThreadedAsync
-
-now=time.time
+import struct, time, os, socket, string
+import tempfile, thread
 from struct import pack, unpack
+from types import TupleType
+
+import Invalidator, ExtensionClass
+import ThreadedAsync, Sync, zrpc, ClientCache
+
 from ZODB import POSException, BaseStorage
 from ZODB.TimeStamp import TimeStamp
-from zLOG import LOG, PROBLEM, INFO
 
-try: from ZODB.ConflictResolution import ResolvedSerial
-except: ResolvedSerial='rs'
+from ZEO.logger import zLogger
+
+log = zLogger("ZEO Client")
 
-TupleType=type(())
+try:
+    from ZODB.ConflictResolution import ResolvedSerial
+except:
+    ResolvedSerial='rs'
 
 class ClientStorageError(POSException.StorageError):
     """An error occured in the ZEO Client Storage"""
@@ -62,8 +67,12 @@
         self._info={'length': 0, 'size': 0, 'name': 'ZEO Client',
                     'supportsUndo':0, 'supportsVersions': 0,
                     }
-        
-        self._call=zrpc.asyncRPC(connection, debug=debug,
+
+        if debug:
+            debug_log = log
+        else:
+            debug_log = None
+        self._call=zrpc.asyncRPC(connection, debug=debug_log,
                                  tmin=min_disconnect_poll,
                                  tmax=max_disconnect_poll)
 
@@ -132,7 +141,7 @@
             # If we can't connect right away, go ahead and open the cache
             # and start a separate thread to try and reconnect.
 
-            LOG("ClientStorage", PROBLEM, "Failed to connect to storage")
+            log.problem("Failed to connect to storage")
             self._cache.open()
             thread.start_new_thread(self._call.connect,(0,))
 
@@ -140,7 +149,7 @@
             # notifyConnected
 
     def notifyConnected(self, s):
-        LOG("ClientStorage", INFO, "Connected to storage")
+        log.info("Connected to storage")
         self._lock_acquire()
         try:
             
@@ -197,7 +206,7 @@
     ### responsible for starting the thread that makes the connection.
 
     def notifyDisconnected(self, ignored):
-        LOG("ClientStorage", PROBLEM, "Disconnected from storage")
+        log.problem("Disconnected from storage")
         self._connected=0
         self._transaction=None
         thread.start_new_thread(self._call.connect,(0,))
@@ -233,7 +242,7 @@
     def close(self):
         self._lock_acquire()
         try:
-            LOG("ClientStorage", INFO, "close")
+            log.info("close")
             self._call.closeIntensionally()
             try:
                 self._tfile.close()
@@ -549,6 +558,9 @@
         finally: self._lock_release()
 
     def sync(self): self._call.sync()
+
+    def status(self):
+        self._call.sendMessage('status')
 
 def getWakeup(_w=[]):
     if _w: return _w[0]


=== StandaloneZODB/ZEO/StorageServer.py 1.34.2.1 => 1.34.2.2 ===
 
 import asyncore, socket, string, sys, os
-from smac import SizedMessageAsyncConnection
-from ZODB import POSException
 import cPickle
 from cPickle import Unpickler
+from cStringIO import StringIO
+from thread import start_new_thread
+from types import StringType
+
+from ZODB import POSException
 from ZODB.POSException import TransactionError, UndoError, VersionCommitError
 from ZODB.Transaction import Transaction
-import traceback
-from zLOG import LOG, INFO, ERROR, TRACE, BLATHER
 from ZODB.referencesf import referencesf
-from thread import start_new_thread
-from cStringIO import StringIO
+
 from ZEO import trigger
 from ZEO import asyncwrap
-from ZEO.smac import Disconnected
-from types import StringType
-
-class StorageServerError(POSException.StorageError): pass
-
-max_blather=120
-def blather(*args):
-    accum = []
-    total_len = 0
-    for arg in args:
-        if not isinstance(arg, StringType):
-            arg = str(arg)
-        accum.append(arg)
-        total_len = total_len + len(arg)
-        if total_len >= max_blather:
-            break
-    m = string.join(accum)
-    if len(m) > max_blather: m = m[:max_blather] + ' ...'
-    LOG('ZEO Server', TRACE, m)
+from ZEO.smac import Disconnected, SizedMessageAsyncConnection
+from ZEO.logger import zLogger, format_msg
 
+class StorageServerError(POSException.StorageError):
+    pass
 
 # We create a special fast pickler! This allows us
 # to create slightly more efficient pickles and
@@ -56,6 +41,8 @@
 pickler.fast=1 # Don't use the memo
 dump=pickler.dump
 
+log = zLogger("ZEO Server")
+
 class StorageServer(asyncore.dispatcher):
 
     def __init__(self, connection, storages):
@@ -80,14 +67,14 @@
             self.create_socket(socket.AF_INET, socket.SOCK_STREAM)
             self.set_reuse_addr()
 
-        LOG('ZEO Server', INFO, 'Listening on %s' % repr(connection))
+        log.info('Listening on %s' % repr(connection))
         self.bind(connection)
         self.listen(5)
 
     def register_connection(self, connection, storage_id):
         storage=self.__storages.get(storage_id, None)
         if storage is None:
-            LOG('ZEO Server', ERROR, "Unknown storage_id: %s" % storage_id)
+            log.error("Unknown storage_id: %s" % storage_id)
             connection.close()
             return None, None
         
@@ -132,12 +119,17 @@
         else:
             ZEOConnection(self, sock, addr)
 
-    def log_info(self, message, type='info'):
-        if type=='error': type=ERROR
-        else: type=INFO
-        LOG('ZEO Server', type, message)
+    def status(self):
+        """Log status information about connections and storages"""
 
-    log=log_info
+        lines = []
+        for storage_id, connections in self.__connections.items():
+            s = "Storage %s has %d connections" % (storage_id,
+                                                   len(connections))
+            lines.append(s)
+            for c in connections:
+                lines.append(str(c))
+        log.info(string.join(lines, "\n"))
 
 storage_methods={}
 for n in (
@@ -148,6 +140,7 @@
     'tpc_finish', 'undo', 'undoLog', 'undoInfo', 'versionEmpty', 'versions',
     'transactionalUndo',
     'vote', 'zeoLoad', 'zeoVerify', 'beginZeoVerify', 'endZeoVerify',
+    'status'
     ):
     storage_methods[n]=1
 storage_method=storage_methods.has_key
@@ -159,7 +152,8 @@
         raise StorageServerError, (
             "Couldn\'t import global module %s" % module)
 
-    try: r=getattr(m, name)
+    try:
+        r=getattr(m, name)
     except:
         raise StorageServerError, (
             "Couldn\'t find global %s in module %s" % (name, module))
@@ -177,12 +171,21 @@
 
     def __init__(self, server, sock, addr):
         self.__server=server
+        self.status = server.status
         self.__invalidated=[]
         self.__closed=None
-        if __debug__: debug='ZEO Server'
-        else: debug=0
+        if __debug__:
+            debug = log
+        else:
+            debug = None
         SizedMessageAsyncConnection.__init__(self, sock, addr, debug=debug)
-        LOG('ZEO Server', INFO, 'Connect %s %s' % (id(self), `addr`))
+        log.info('Connect %s %s' % (id(self), `addr`))
+
+    def __repr__(self):
+        return "<ZEOConnection %s%s" % (`self.addr`,
+                         # sort of messy way to add tag 'closed' to
+                         # connections that are closed
+                         (self.__closed is None and '>' or 'closed>'))
 
     def close(self):
         t=self._transaction
@@ -196,17 +199,17 @@
         self.__server.unregister_connection(self, self.__storage_id)
         self.__closed=1
         SizedMessageAsyncConnection.close(self)
-        LOG('ZEO Server', INFO, 'Close %s' % id(self))
+        log.info('Close %s' % id(self))
 
     def message_input(self, message,
                       dump=dump, Unpickler=Unpickler, StringIO=StringIO,
                       None=None):
         if __debug__:
-            if len(message) > max_blather:
-                tmp = `message[:max_blather]`
+            if len(message) > 120: # XXX need constant from logger
+                tmp = `message[:120]`
             else:
                 tmp = `message`
-            blather('message_input', id(self), tmp)
+            log.trace("message_input %s" % tmp)
 
         if self.__storage is None:
             # This is the first communication from the client
@@ -226,27 +229,31 @@
             
             name, args = args[0], args[1:]
             if __debug__:
-                apply(blather,
-                      ("call", id(self), ":", name,) + args)
+                log.debug("call %s%s from %s" % (name, format_msg(args),
+                                                 self.addr))
                 
             if not storage_method(name):
+                log.warning("Invalid method name: %s" % name)
                 raise 'Invalid Method Name', name
             if hasattr(self, name):
                 r=apply(getattr(self, name), args)
             else:
                 r=apply(getattr(self.__storage, name), args)
-            if r is _noreturn: return
+            if r is _noreturn:
+                if __debug__:
+                    log.trace("no return to %s" % `self.addr`)
+                return
         except (UndoError, VersionCommitError):
             # These are normal usage errors. No need to leg them
             self.return_error(sys.exc_info()[0], sys.exc_info()[1])
             return
         except:
-            LOG('ZEO Server', ERROR, 'error', error=sys.exc_info())
+            log.error("error", error=sys.exc_info())
             self.return_error(sys.exc_info()[0], sys.exc_info()[1])
             return
 
         if __debug__:
-            blather("%s R: %s" % (id(self), `r`))
+            log.trace("return %s to %s" % (`r`, self.addr))
             
         r=dump(r,1)            
         self.message_output('R'+r)
@@ -256,7 +263,7 @@
             err_value = err_type, err_value
 
         if __debug__:
-            blather("%s E: %s" % (id(self), `err_value`))
+            log.trace("%s E: %s" % (id(self), `err_value`))
                     
         try: r=dump(err_value, 1)
         except:
@@ -340,11 +347,11 @@
 
     def _pack(self, t, wait=0):
         try:
-            LOG('ZEO Server', BLATHER, 'pack begin')
+            log.blather('pack begin')
             self.__storage.pack(t, referencesf)
-            LOG('ZEO Server', BLATHER, 'pack end')
+            log.blather('pack end')
         except:
-            LOG('ZEO Server', ERROR,
+            log.error(
                 'Pack failed for %s' % self.__storage_id,
                 error=sys.exc_info())
             if wait:
@@ -396,7 +403,7 @@
             # all errors need to be serialized to prevent unexpected
             # returns, which would screw up the return handling.
             # IOW, Anything that ends up here is evil enough to be logged.
-            LOG('ZEO Server', ERROR, 'store error', error=sys.exc_info())
+            log.error('store error', error=sys.exc_info())
             newserial=sys.exc_info()[1]
         else:
             if serial != '\0\0\0\0\0\0\0\0':
@@ -471,7 +478,7 @@
                 # disconnect will have generated its own log event.
                 onerror()
             except:
-                LOG('ZEO Server', ERROR,
+                log.error(
                     "Unexpected error handling queued tpc_begin()",
                     error=sys.exc_info())
                 onerror()
@@ -564,7 +571,7 @@
 if __name__=='__main__':
     import ZODB.FileStorage
     name, port = sys.argv[1:3]
-    blather(name, port)
+    log.trace(format_msg(name, port))
     try:
         port='', int(port)
     except:


=== StandaloneZODB/ZEO/smac.py 1.14.2.1 => 1.14.2.2 ===
 import asyncore, string, struct, zLOG, sys, Acquisition
 import socket, errno
-from zLOG import LOG, TRACE, ERROR, INFO
+from logger import zLogger
 
 # Use the dictionary to make sure we get the minimum number of errno
 # entries.   We expect that EWOULDBLOCK == EAGAIN on most systems --
@@ -49,9 +49,9 @@
             '__init__')(self, sock, map)
         self.addr=addr
         if debug is not None:
-            self._debug=debug
+            self._debug = debug
         elif not hasattr(self, '_debug'):
-            self._debug=__debug__ and 'smac'
+            self._debug = __debug__ and zLogger("smac")
         self.__state=None
         self.__inp=None
         self.__inpl=0
@@ -132,23 +132,18 @@
 
     def message_output(self, message,
                        pack=struct.pack, len=len):
-        if self._debug:
-            if len(message) > 40: m=message[:40]+' ...'
-            else: m=message
-            LOG(self._debug, TRACE, 'message_output %s' % `m`)
+        if self._debug is not None:
+            if len(message) > 40:
+                m = message[:40]+' ...'
+            else:
+                m = message
+            self._debug.trace('message_output %s' % `m`)
 
         append=self.__append
         if append is None:
             raise Disconnected("This action is temporarily unavailable.<p>")
         
         append(pack(">i",len(message))+message)
-
-    def log_info(self, message, type='info'):
-        if type=='error': type=ERROR
-        else: type=INFO
-        LOG('ZEO', type, message)
-
-    log=log_info
 
     def close(self):
         if self.__append is not None:


=== StandaloneZODB/ZEO/zrpc.py 1.21.2.1 => 1.21.2.2 ===
         self.__call_lr=l.release
 
-    def connect(self, tryonce=1, log_type='client'):
+    def connect(self, tryonce=1):
         t=self._tmin
         connection = self._connection
         debug=self._debug
         while self.__closed == 0:
-            if log_type: LOG(log_type, INFO,
-                             'Trying to connect to server: %s' % `connection`)
+            LOG("client", INFO,
+                'Trying to connect to server: %s' % `connection`)
             try:
                 if type(connection) is type(''):
                     s=socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
@@ -75,15 +75,15 @@
                     s=socket.socket(socket.AF_INET, socket.SOCK_STREAM)
                 s.connect(connection)    
             except Exception, err:
-                if debug:
-                    LOG(debug, DEBUG, "Failed to connect to server: %s" % err)
+                if debug is not None:
+                    debug.blather("Failed to connect to server: %s" % err)
                 if tryonce: return 0
                 time.sleep(t)
                 t=t*2
                 if t > self._tmax: t=self._tmax
             else:
-                if debug:
-                    LOG(debug, DEBUG, "Connected to server")
+                if debug is not None:
+                    debug.blather("Connected to server")
                     
                 # Make sure the result lock is set, se we don't
                 # get an old result (e.g. the exception that
@@ -199,12 +199,12 @@
         self._outOfBand=f
 
     def message_input(self, m):
-        if self._debug:
+        if self._debug is not None:
             if len(m) > 60:
                 md = repr(m[:60]) + ' ...'
             else:
                 md = repr(m)
-            LOG(self._debug, TRACE, 'message_input %s' % md)
+            self._debug.trace('message_input %s' % md)
 
         c=m[:1]
         if c in 'RE':