This should be the last nail in zLOG's coffin. grep reveals no more references

to zLOG other than a few comments.

This definitely broke the log analyzers pretty bad.

src/ZEO/ClientStorage.py

@@ -25,6 +25,7 @@ import tempfile
 import threading
 import time
 import types
+import logging
 
 from ZEO import ServerStub
 from ZEO.cache import ClientCache
@@ -34,11 +35,15 @@ from ZEO.auth import get_module
 from ZEO.zrpc.client import ConnectionManager
 
 from ZODB import POSException
+from ZODB.loglevels import BLATHER
 from persistent.TimeStamp import TimeStamp
-from zLOG import LOG, PROBLEM, INFO, BLATHER, ERROR
 
-def log2(type, msg, subsys="ZCS:%d" % os.getpid()):
-    LOG(subsys, type, msg)
+logger = logging.getLogger('ZEO.ClientStorage')
+_pid = str(os.getpid())
+
+def log2(msg, level=logging.INFO, subsys=_pid, exc_info=False):
+    message = "(%s) %s" % (subsys, msg)
+    logger.log(level, message, exc_info=exc_info)
 
 try:
     from ZODB.ConflictResolution import ResolvedSerial
@@ -177,7 +182,7 @@ class ClientStorage(object):
         testConnection() and doAuth() for details).
         """
 
-        log2(INFO, "%s (pid=%d) created %s/%s for storage: %r" %
+        log2("%s (pid=%d) created %s/%s for storage: %r" %
              (self.__class__.__name__,
               os.getpid(),
               read_only and "RO" or "RW",
@@ -185,18 +190,17 @@ class ClientStorage(object):
               storage))
 
         if debug:
-            log2(INFO, "ClientStorage(): debug argument is no longer used")
+            log2("ClientStorage(): debug argument is no longer used")
 
         # wait defaults to True, but wait_for_server_on_startup overrides
         # if not None
         if wait_for_server_on_startup is not None:
             if wait is not None and wait != wait_for_server_on_startup:
-                log2(PROBLEM,
-                     "ClientStorage(): conflicting values for wait and "
-                     "wait_for_server_on_startup; wait prevails")
+                log2("ClientStorage(): conflicting values for wait and "
+                     "wait_for_server_on_startup; wait prevails",
+                     level=logging.WARNING)
             else:
-                log2(INFO,
-                     "ClientStorage(): wait_for_server_on_startup "
+                log2("ClientStorage(): wait_for_server_on_startup "
                      "is deprecated; please use wait instead")
                 wait = wait_for_server_on_startup
         elif wait is None:
@@ -325,7 +329,7 @@ class ClientStorage(object):
     def _wait(self, timeout=None):
         if timeout is not None:
             deadline = time.time() + timeout
-            log2(BLATHER, "Setting deadline to %f" % deadline)
+            log2("Setting deadline to %f" % deadline, level=BLATHER)
         else:
             deadline = None
         # Wait for a connection to be established.
@@ -341,9 +345,10 @@ class ClientStorage(object):
                 if self._ready.isSet():
                     break
                 if timeout and time.time() > deadline:
-                    log2(PROBLEM, "Timed out waiting for connection")
+                    log2("Timed out waiting for connection",
+                         level=logging.WARNING)
                     break
-                log2(INFO, "Waiting for cache verification to finish")
+                log2("Waiting for cache verification to finish")
         else:
             self._wait_sync(deadline)
 
@@ -354,9 +359,9 @@ class ClientStorage(object):
             if self._ready.isSet():
                 break
             if deadline and time.time() > deadline:
-                log2(PROBLEM, "Timed out waiting for connection")
+                log2("Timed out waiting for connection", level=logging.WARNING)
                 break
-            log2(INFO, "Waiting for cache verification to finish")
+            log2("Waiting for cache verification to finish")
             if self._connection is None:
                 # If the connection was closed while we were
                 # waiting for it to become ready, start over.
@@ -408,16 +413,15 @@ class ClientStorage(object):
 
         module = get_module(protocol)
         if not module:
-            log2(PROBLEM, "%s: no such an auth protocol: %s" %
-                 (self.__class__.__name__, protocol))
+            log2("%s: no such an auth protocol: %s" %
+                 (self.__class__.__name__, protocol), level=logging.WARNING)
             return
 
         storage_class, client, db_class = module
 
         if not client:
-            log2(PROBLEM,
-                 "%s: %s isn't a valid protocol, must have a Client class" %
-                 (self.__class__.__name__, protocol))
+            log2("%s: %s isn't a valid protocol, must have a Client class" %
+                 (self.__class__.__name__, protocol), level=logging.WARNING)
             raise AuthError, "invalid protocol"
 
         c = client(stub)
@@ -446,20 +450,20 @@ class ClientStorage(object):
         succeeding register() call is deemed an optimal match, and any
         exception raised by register() is passed through.
         """
-        log2(INFO, "Testing connection %r" % conn)
+        log2("Testing connection %r" % conn)
         # XXX Check the protocol version here?
         self._conn_is_read_only = 0
         stub = self.StorageServerStubClass(conn)
 
         auth = stub.getAuthProtocol()
-        log2(INFO, "Server authentication protocol %r" % auth)
+        log2("Server authentication protocol %r" % auth)
         if auth:
             skey = self.doAuth(auth, stub)
             if skey:
-                log2(INFO, "Client authentication successful")
+                log2("Client authentication successful")
                 conn.setSessionKey(skey)
             else:
-                log2(ERROR, "Authentication failed")
+                log2("Authentication failed")
                 raise AuthError, "Authentication failed"
 
         try:
@@ -468,7 +472,7 @@ class ClientStorage(object):
         except POSException.ReadOnlyError:
             if not self._read_only_fallback:
                 raise
-            log2(INFO, "Got ReadOnlyError; trying again with read_only=1")
+            log2("Got ReadOnlyError; trying again with read_only=1")
             stub.register(str(self._storage), read_only=1)
             self._conn_is_read_only = 1
             return 0
@@ -499,16 +503,16 @@ class ClientStorage(object):
         self._connection = conn
 
         if reconnect:
-            log2(INFO, "Reconnected to storage: %s" % self._server_addr)
+            log2("Reconnected to storage: %s" % self._server_addr)
         else:
-            log2(INFO, "Connected to storage: %s" % self._server_addr)
+            log2("Connected to storage: %s" % self._server_addr)
 
         stub = self.StorageServerStubClass(conn)
         self._oids = []
         self._info.update(stub.get_info())
         self.verify_cache(stub)
         if not conn.is_async():
-            log2(INFO, "Waiting for cache verification to finish")
+            log2("Waiting for cache verification to finish")
             self._wait_sync()
         self._handle_extensions()
 
@@ -532,7 +536,8 @@ class ClientStorage(object):
             try:
                 canonical, aliases, addrs = socket.gethostbyaddr(host)
             except socket.error, err:
-                log2(BLATHER, "Error resolving host: %s (%s)" % (host, err))
+                log2("Error resolving host: %s (%s)" % (host, err),
+                     level=BLATHER)
                 canonical = host
             self._server_addr = str((canonical, addr[1]))
 
@@ -559,27 +564,26 @@ class ClientStorage(object):
         if last_inval_tid is not None:
             ltid = server.lastTransaction()
             if ltid == last_inval_tid:
-                log2(INFO, "No verification necessary "
-                     "(last_inval_tid up-to-date)")
+                log2("No verification necessary (last_inval_tid up-to-date)")
                 self._server = server
                 self._ready.set()
                 return "no verification"
 
             # log some hints about last transaction
-            log2(INFO, "last inval tid: %r %s\n"
+            log2("last inval tid: %r %s\n"
                  % (last_inval_tid, tid2time(last_inval_tid)))
-            log2(INFO, "last transaction: %r %s" %
+            log2("last transaction: %r %s" %
                  (ltid, ltid and tid2time(ltid)))
 
             pair = server.getInvalidations(last_inval_tid)
             if pair is not None:
-                log2(INFO, "Recovering %d invalidations" % len(pair[1]))
+                log2("Recovering %d invalidations" % len(pair[1]))
                 self.invalidateTransaction(*pair)
                 self._server = server
                 self._ready.set()
                 return "quick verification"
 
-        log2(INFO, "Verifying cache")
+        log2("Verifying cache")
         # setup tempfile to hold zeoVerify results
         self._tfile = tempfile.TemporaryFile(suffix=".inv")
         self._pickler = cPickle.Pickler(self._tfile, 1)
@@ -607,7 +611,7 @@ class ClientStorage(object):
         This is called by ConnectionManager when the connection is
         closed or when certain problems with the connection occur.
         """
-        log2(INFO, "Disconnected from storage: %s" % repr(self._server_addr))
+        log2("Disconnected from storage: %s" % repr(self._server_addr))
         self._connection = None
         self._ready.clear()
         self._server = disconnected_stub
@@ -934,7 +938,8 @@ class ClientStorage(object):
             try:
                 self._server.tpc_abort(id(txn))
             except ClientDisconnected:
-                log2(BLATHER, 'ClientDisconnected in tpc_abort() ignored')
+                log2("ClientDisconnected in tpc_abort() ignored",
+                     level=BLATHER)
         finally:
             self._tbuf.clear()
             self._seriald.clear()
@@ -1088,11 +1093,11 @@ class ClientStorage(object):
         self._process_invalidations(InvalidationLogIterator(f))
         f.close()
 
-        log2(INFO, "endVerify finishing")
+        log2("endVerify finishing")
         self._server = self._pending_server
         self._ready.set()
         self._pending_conn = None
-        log2(INFO, "endVerify finished")
+        log2("endVerify finished")
 
     def invalidateTransaction(self, tid, args):
         """Invalidate objects modified by tid."""
@@ -1102,8 +1107,8 @@ class ClientStorage(object):
         finally:
             self._lock.release()
         if self._pickler is not None:
-            log2(BLATHER,
-                 "Transactional invalidation during cache verification")
+            log2("Transactional invalidation during cache verification",
+                 level=BLATHER)
             for t in args:
                 self._pickler.dump(t)
             return

src/ZEO/StorageServer.py

@@ -26,6 +26,7 @@ import os
 import sys
 import threading
 import time
+import logging
 
 import transaction
 
@@ -37,23 +38,30 @@ from ZEO.zrpc.connection import ManagedServerConnection, Delay, MTDelay
 from ZEO.zrpc.trigger import trigger
 from ZEO.Exceptions import AuthError
 
-import zLOG
 from ZODB.ConflictResolution import ResolvedSerial
 from ZODB.POSException import StorageError, StorageTransactionError
 from ZODB.POSException import TransactionError, ReadOnlyError, ConflictError
 from ZODB.serialize import referencesf
 from ZODB.utils import u64, oid_repr
+from ZODB.loglevels import BLATHER
 
-_label = "ZSS" # Default label used for logging.
+logger = logging.getLogger('ZEO.StorageServer')
+
+# XXX This used to say "ZSS", which is now implied in the logger name, can this
+#     be either set to str(os.getpid()) (if that makes sense) or removed?
+_label = "" # default label used for logging.
 
 def set_label():
     """Internal helper to reset the logging label (e.g. after fork())."""
     global _label
-    _label = "ZSS:%s" % os.getpid()
+    _label = "%s" % os.getpid()
 
-def log(message, level=zLOG.INFO, label=None, error=None):
-    """Internal helper to log a message using zLOG."""
-    zLOG.LOG(label or _label, level, message, error=error)
+def log(message, level=logging.INFO, label=None, exc_info=False):
+    """Internal helper to log a message."""
+    label = label or _label
+    if label:
+        message = "(%s) %s" % (label, message)
+    logger.log(level, message, exc_info=exc_info)
 
 class StorageServerError(StorageError):
     """Error reported when an unpickleable exception is raised."""
@@ -131,8 +139,8 @@ class ZEOStorage:
         name = self.__class__.__name__
         return "<%s %X trans=%s s_trans=%s>" % (name, id(self), tid, stid)
 
-    def log(self, msg, level=zLOG.INFO, error=None):
-        zLOG.LOG(self.log_label, level, msg, error=error)
+    def log(self, msg, level=logging.INFO, exc_info=False):
+        log(msg, level=level, label=self.log_label, exc_info=exc_info)
 
     def setup_delegation(self):
         """Delegate several methods to the storage"""
@@ -164,7 +172,8 @@ class ZEOStorage:
             raise ReadOnlyError()
         if self.transaction is None:
             caller = sys._getframe().f_back.f_code.co_name
-            self.log("no current transaction: %s()" % caller, zLOG.PROBLEM)
+            self.log("no current transaction: %s()" % caller,
+                     level=logging.WARNING)
             if exc is not None:
                 raise exc(None, tid)
             else:
@@ -173,7 +182,7 @@ class ZEOStorage:
             caller = sys._getframe().f_back.f_code.co_name
             self.log("%s(%s) invalid; current transaction = %s" %
                      (caller, repr(tid), repr(self.transaction.id)),
-                     zLOG.PROBLEM)
+                     logging.WARNING)
             if exc is not None:
                 raise exc(self.transaction.id, tid)
             else:
@@ -412,7 +421,7 @@ class ZEOStorage:
             self.locked = 0
             self.timeout.end(self)
             self.stats.lock_time = None
-            self.log("Transaction released storage lock", zLOG.BLATHER)
+            self.log("Transaction released storage lock", BLATHER)
             # _handle_waiting() can start another transaction (by
             # restarting a waiting one) so must be done last
             self._handle_waiting()
@@ -494,13 +503,11 @@ class ZEOStorage:
             if isinstance(err, ConflictError):
                 self.stats.conflicts += 1
                 self.log("conflict error oid=%s msg=%s" %
-                         (oid_repr(oid), str(err)), zLOG.BLATHER)
+                         (oid_repr(oid), str(err)), BLATHER)
             if not isinstance(err, TransactionError):
                 # Unexpected errors are logged and passed to the client
-                exc_info = sys.exc_info()
-                self.log("store error: %s, %s" % exc_info[:2],
-                         zLOG.ERROR, error=exc_info)
-                del exc_info
+                self.log("store error: %s, %s" % sys.exc_info()[:2],
+                         logging.ERROR, exc_info=True)
             # Try to pickle the exception.  If it can't be pickled,
             # the RPC response would fail, so use something else.
             pickler = cPickle.Pickler()
@@ -509,7 +516,7 @@ class ZEOStorage:
                 pickler.dump(err, 1)
             except:
                 msg = "Couldn't pickle storage exception: %s" % repr(err)
-                self.log(msg, zLOG.ERROR)
+                self.log(msg, logging.ERROR)
                 err = StorageServerError(msg)
             # The exception is reported back as newserial for this oid
             newserial = err
@@ -518,7 +525,7 @@ class ZEOStorage:
                 self.invalidated.append((oid, version))
         if newserial == ResolvedSerial:
             self.stats.conflicts_resolved += 1
-            self.log("conflict resolved oid=%s" % oid_repr(oid), zLOG.BLATHER)
+            self.log("conflict resolved oid=%s" % oid_repr(oid), BLATHER)
         self.serials.append((oid, newserial))
         return err is None
 
@@ -572,7 +579,7 @@ class ZEOStorage:
                      "Clients waiting: %d." % len(self.storage._waiting))
             return d
         else:
-            self.log("Transaction acquired storage lock.", zLOG.BLATHER)
+            self.log("Transaction acquired storage lock.", BLATHER)
             return self._restart()
 
     def _restart(self, delay=None):
@@ -582,7 +589,7 @@ class ZEOStorage:
         else:
             template = "Preparing to commit transaction: %d objects, %d bytes"
         self.log(template % (self.txnlog.stores, self.txnlog.size()),
-                 level=zLOG.BLATHER)
+                 level=BLATHER)
         self._tpc_begin(self.transaction, self.tid, self.status)
         loads, loader = self.txnlog.get_loader()
         for i in range(loads):
@@ -615,7 +622,7 @@ class ZEOStorage:
             zeo_storage._restart(delay)
         except:
             self.log("Unexpected error handling waiting transaction",
-                     level=zLOG.WARNING, error=sys.exc_info())
+                     level=logging.WARNING, exc_info=True)
             zeo_storage.connection.close()
             return 0
         else:
@@ -794,7 +801,7 @@ class StorageServer:
             zstorage = self.ZEOStorageClass(self, self.read_only)
 
         c = self.ManagedServerConnectionClass(sock, addr, zstorage, self)
-        log("new connection %s: %s" % (addr, `c`))
+        log("new connection %s: %s" % (addr, repr(c)))
         return c
 
     def register_connection(self, storage_id, conn):

src/ZEO/monitor.py

@@ -13,16 +13,16 @@
 ##############################################################################
 """Monitor behavior of ZEO server and record statistics.
 
-$Id: monitor.py,v 1.5 2003/11/28 16:44:47 jim Exp $
+$Id: monitor.py,v 1.6 2004/04/25 11:34:15 gintautasm Exp $
 """
 
 import asyncore
 import socket
 import time
 import types
+import logging
 
 import ZEO
-import zLOG
 
 class StorageStats:
     """Per-storage usage statistics."""
@@ -129,7 +129,8 @@ class StatsServer(asyncore.dispatcher):
         else:
             self.create_socket(socket.AF_UNIX, socket.SOCK_STREAM)
         self.set_reuse_addr()
-        zLOG.LOG("ZSM", zLOG.INFO, "monitor listening on %s" % repr(self.addr))
+        logger = logging.getLogger('ZEO.monitor')
+        logger.info("listening on %s", repr(self.addr))
         self.bind(self.addr)
         self.listen(5)
 

src/ZEO/runzeo.py

@@ -36,17 +36,27 @@ import os
 import sys
 import signal
 import socket
+import logging
 
 import ZConfig, ZConfig.datatypes
-import zLOG
 import ZEO
 from zdaemon.zdoptions import ZDOptions
 
+logger = logging.getLogger('ZEO.runzeo')
+_pid = str(os.getpid())
+
+def log(msg, level=logging.INFO, exc_info=False):
+    """Internal: generic logging function."""
+    message = "(%s) %s" % (_pid, msg)
+    logger.log(level, message, exc_info=exc_info)
+
+
 def parse_address(arg):
     # XXX Not part of the official ZConfig API
     obj = ZConfig.datatypes.SocketAddress(arg)
     return obj.family, obj.address
 
+
 class ZEOOptionsMixin:
 
     storages = None
@@ -129,7 +139,6 @@ class ZEOServer:
         if self.options.config_logger is not None:
             return
         # No log file is configured; default to stderr.
-        import logging
         logger = logging.getLogger()
         handler = logging.StreamHandler()
         handler.setLevel(logging.INFO)
@@ -160,7 +169,7 @@ class ZEOServer:
     def open_storages(self):
         self.storages = {}
         for opener in self.options.storages:
-            info("opening storage %r using %s"
+            log("opening storage %r using %s"
                 % (opener.name, opener.__class__.__name__))
             self.storages[opener.name] = opener.open()
 
@@ -202,33 +211,31 @@ class ZEOServer:
         ThreadedAsync.LoopCallback.loop()
 
     def handle_sigterm(self):
-        info("terminated by SIGTERM")
+        log("terminated by SIGTERM")
         sys.exit(0)
 
     def handle_sigint(self):
-        info("terminated by SIGINT")
+        log("terminated by SIGINT")
         sys.exit(0)
 
     def handle_sighup(self):
-        info("restarted by SIGHUP")
+        log("restarted by SIGHUP")
         sys.exit(1)
 
     def handle_sigusr2(self):
-        # This requires a modern zLOG (from Zope 2.6 or later); older
-        # zLOG packages don't have the initialize() method
-        info("reinitializing zLOG")
-        # XXX Shouldn't this be below with _log()?
-        import zLOG
-        zLOG.initialize()
-        info("reinitialized zLOG")
+        # XXX this used to reinitialize zLOG. How do I achieve
+        #     the same effect with Python's logging package?
+        #     Should we restart as with SIGHUP?
+        log("received SIGUSR2, but it was not handled!", level=logging.WARNING)
 
     def close_storages(self):
         for name, storage in self.storages.items():
-            info("closing storage %r" % name)
+            log("closing storage %r" % name)
             try:
                 storage.close()
             except: # Keep going
-                exception("failed to close storage %r" % name)
+                log("failed to close storage %r" % name,
+                    level=logging.EXCEPTION, exc_info=True)
 
 
 # Signal names
@@ -257,43 +264,6 @@ def init_signames():
             signames[sig] = name
 
 
-# Log messages with various severities.
-# This uses zLOG, but the API is a simplified version of PEP 282
-
-def critical(msg):
-    """Log a critical message."""
-    _log(msg, zLOG.PANIC)
-
-def error(msg):
-    """Log an error message."""
-    _log(msg, zLOG.ERROR)
-
-def exception(msg):
-    """Log an exception (an error message with a traceback attached)."""
-    _log(msg, zLOG.ERROR, error=sys.exc_info())
-
-def warn(msg):
-    """Log a warning message."""
-    _log(msg, zLOG.PROBLEM)
-
-def info(msg):
-    """Log an informational message."""
-    _log(msg, zLOG.INFO)
-
-def debug(msg):
-    """Log a debugging message."""
-    _log(msg, zLOG.DEBUG)
-
-# XXX It would be nice if a program that extended this one (like
-# runzrs) could change the label.
-
-_label = "RUNZEO:%d" % os.getpid()
-
-def _log(msg, severity=zLOG.INFO, error=None):
-    """Internal: generic logging function."""
-    zLOG.LOG(_label, severity, msg, "", error)
-
-
 # Main program
 
 def main(args=None):

src/ZEO/tests/ConnectionTests.py

@@ -19,8 +19,7 @@ import random
 import asyncore
 import tempfile
 import threading
-
-import zLOG
+import logging
 
 import ZEO.ServerStub
 from ZEO.ClientStorage import ClientStorage
@@ -38,6 +37,8 @@ from ZODB.tests.StorageTestBase \
 import transaction
 from transaction import Transaction
 
+logger = logging.getLogger('ZEO.tests.ConnectionTests')
+
 ZERO = '\0'*8
 
 class TestServerStub(ZEO.ServerStub.StorageServer):
@@ -91,7 +92,7 @@ class CommonSetupTearDown(StorageTestBase):
         for i in 1, 2, ...
         """
         self.__super_setUp()
-        zLOG.LOG("testZEO", zLOG.INFO, "setUp() %s" % self.id())
+        logging.info("setUp() %s", self.id())
         self.file = tempfile.mktemp()
         self.addr = []
         self._pids = []
@@ -103,13 +104,13 @@ class CommonSetupTearDown(StorageTestBase):
 
     def tearDown(self):
         """Try to cause the tests to halt"""
-        zLOG.LOG("testZEO", zLOG.INFO, "tearDown() %s" % self.id())
+        logging.info("tearDown() %s" % self.id())
         for p in self.conf_paths:
             os.remove(p)
         if getattr(self, '_storage', None) is not None:
             self._storage.close()
             if hasattr(self._storage, 'cleanup'):
-                zLOG.LOG("testZEO", zLOG.DEBUG, "cleanup storage %s" %
+                logging.debug("cleanup storage %s" %
                          self._storage.__name__)
                 self._storage.cleanup()
         for adminaddr in self._servers:
@@ -191,8 +192,7 @@ class CommonSetupTearDown(StorageTestBase):
 
     def startServer(self, create=1, index=0, read_only=0, ro_svr=0, keep=None):
         addr = self.addr[index]
-        zLOG.LOG("testZEO", zLOG.INFO,
-                 "startServer(create=%d, index=%d, read_only=%d) @ %s" %
+        logging.info("startServer(create=%d, index=%d, read_only=%d) @ %s" %
                      (create, index, read_only, addr))
         path = "%s.%d" % (self.file, index)
         sconf = self.getConfig(path, create, read_only)
@@ -206,7 +206,7 @@ class CommonSetupTearDown(StorageTestBase):
         self._servers.append(adminaddr)
 
     def shutdownServer(self, index=0):
-        zLOG.LOG("testZEO", zLOG.INFO, "shutdownServer(index=%d) @ %s" %
+        logging.info("shutdownServer(index=%d) @ %s" %
                      (index, self._servers[index]))
         adminaddr = self._servers[index]
         if adminaddr is not None:
@@ -450,11 +450,9 @@ class ConnectionTests(CommonSetupTearDown):
         oid = self._storage.new_oid()
         obj = MinPO(12)
         self._dostore(oid, data=obj)
-        zLOG.LOG("checkReconnection", zLOG.INFO,
-                 "About to shutdown server")
+        logging.info("checkReconnection(): About to shutdown server")
         self.shutdownServer()
-        zLOG.LOG("checkReconnection", zLOG.INFO,
-                 "About to restart server")
+        logging.info("checkReconnection(): About to restart server")
         self.startServer(create=0)
         oid = self._storage.new_oid()
         obj = MinPO(12)
@@ -464,13 +462,12 @@ class ConnectionTests(CommonSetupTearDown):
                 break
             except ClientDisconnected:
                 # Maybe the exception mess is better now
-                zLOG.LOG("checkReconnection", zLOG.INFO,
-                         "Error after server restart; retrying.",
-                         error=sys.exc_info())
+                logging.info("checkReconnection(): Error after"
+                             " server restart; retrying.", exc_info=True)
                 transaction.abort()
             # Give the other thread a chance to run.
             time.sleep(0.1)
-        zLOG.LOG("checkReconnection", zLOG.INFO, "finished")
+        logging.info("checkReconnection(): finished")
         self._storage.close()
 
     def checkBadMessage1(self):
@@ -832,7 +829,7 @@ class ReconnectionTests(CommonSetupTearDown):
         self.pollDown()
         self._storage.verify_result = None
         perstorage.verify_result = None
-        zLOG.LOG("testZEO", zLOG.INFO, '2ALLBEEF')
+        logging.info('2ALLBEEF')
         self.startServer(create=0, keep=0)
         self.pollUp()
         self.pollUp(storage=perstorage)

src/ZEO/tests/forker.py

@@ -21,8 +21,9 @@ import socket
 import logging
 import StringIO
 import tempfile
+import logging
 
-import zLOG
+logger = logging.getLogger('ZEO.tests.forker')
 
 class ZEOConfig:
     """Class to generate ZEO configuration file. """
@@ -143,19 +144,19 @@ def start_zeo_server(storage_conf, zeo_conf, port, keep=0):
     for i in range(120):
         time.sleep(0.25)
         try:
-            zLOG.LOG('forker', zLOG.DEBUG, 'connect %s' % i)
+            logger.debug('connect %s', i)
             s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
             s.connect(adminaddr)
             ack = s.recv(1024)
             s.close()
-            zLOG.LOG('forker', zLOG.DEBUG, 'acked: %s' % ack)
+            logging.debug('acked: %s' % ack)
             break
         except socket.error, e:
             if e[0] not in (errno.ECONNREFUSED, errno.ECONNRESET):
                 raise
             s.close()
     else:
-        zLOG.LOG('forker', zLOG.DEBUG, 'boo hoo')
+        logging.debug('boo hoo')
         raise
     return ('localhost', port), adminaddr, pid, tmpfile
 
@@ -187,5 +188,5 @@ def shutdown_zeo_server(adminaddr):
             if e[0] == errno.ECONNRESET:
                 raise
             ack = 'no ack received'
-        zLOG.LOG('shutdownServer', zLOG.DEBUG, 'acked: %s' % ack)
+        logger.debug('shutdown_zeo_server(): acked: %s' % ack)
         s.close()

src/ZEO/tests/testZEO.py

@@ -20,16 +20,13 @@ import socket
 import asyncore
 import tempfile
 import unittest
-
-# Zope/ZODB3 imports
-import zLOG
+import logging
 
 # ZODB test support
 import ZODB
 from ZODB.tests.MinPO import MinPO
 from ZODB.tests.StorageTestBase import zodb_unpickle
 
-
 # ZODB test mixin classes
 from ZODB.tests import StorageTestBase, BasicStorage, VersionStorage, \
      TransactionalUndoStorage, TransactionalUndoVersionStorage, \
@@ -39,6 +36,8 @@ from ZODB.tests import StorageTestBase, BasicStorage, VersionStorage, \
 from ZEO.ClientStorage import ClientStorage
 from ZEO.tests import forker, Cache, CommitLockTests, ThreadTests
 
+logger = logging.getLogger('ZEO.tests.testZEO')
+
 class DummyDB:
     def invalidate(self, *args):
         pass
@@ -113,7 +112,7 @@ class GenericTests(
     """Combine tests from various origins in one class."""
 
     def setUp(self):
-        zLOG.LOG("testZEO", zLOG.INFO, "setUp() %s" % self.id())
+        logger.info("setUp() %s", self.id()) # XXX is this really needed?
         port = get_port()
         zconf = forker.ZEOConfig(('', port))
         zport, adminaddr, pid, path = forker.start_zeo_server(self.getConfig(),

src/ZEO/tests/zeoserver.py

@@ -22,9 +22,10 @@ import socket
 import signal
 import asyncore
 import threading
+import logging
+
 import ThreadedAsync.LoopCallback
 
-import zLOG
 from ZEO.StorageServer import StorageServer
 from ZEO.runzeo import ZEOOptions
 
@@ -38,9 +39,11 @@ def cleanup(storage):
     except AttributeError:
         pass
 
+logger = logging.getLogger('ZEO.tests.zeoserver')
 
 def log(label, msg, *args):
-    zLOG.LOG(label, zLOG.DEBUG, msg % args)
+    message = "(%s) %s" % (label, msg)
+    logger.debug(message, args)
 
 
 class ZEOTestServer(asyncore.dispatcher):
@@ -67,8 +70,7 @@ class ZEOTestServer(asyncore.dispatcher):
         self._keep = keep
         # Count down to zero, the number of connects
         self._count = 1
-        # For zLOG
-        self._label ='zeoserver:%d @ %s' % (os.getpid(), addr)
+        self._label ='%d @ %s' % (os.getpid(), addr)
         self.create_socket(socket.AF_INET, socket.SOCK_STREAM)
         # Some ZEO tests attempt a quick start of the server using the same
         # port so we have to set the reuse flag.
@@ -126,7 +128,7 @@ class Suicide(threading.Thread):
         # as long as 300 seconds.  Set this timeout to 330 to minimize
         # chance that the server gives up before the clients.
         time.sleep(330)
-        log("zeoserver", "suicide thread invoking shutdown")
+        log(str(os.getpid()), "suicide thread invoking shutdown")
 
         # If the server hasn't shut down yet, the client may not be
         # able to connect to it.  If so, try to kill the process to
@@ -146,8 +148,8 @@ class Suicide(threading.Thread):
 def main():
     global pid
     pid = os.getpid()
-    label = 'zeoserver:%d' % pid
-    log(label, 'starting')
+    label = str(pid)
+    log(label, "starting")
 
     # We don't do much sanity checking of the arguments, since if we get it
     # wrong, it's a bug in the test suite.