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/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,8 +169,8 @@ class ZEOServer:
     def open_storages(self):
         self.storages = {}
         for opener in self.options.storages:
-            info("opening storage %r using %s"
-                 % (opener.name, opener.__class__.__name__))
+            log("opening storage %r using %s"
+                % (opener.name, opener.__class__.__name__))
             self.storages[opener.name] = opener.open()
 
     def setup_signals(self):
@@ -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,9 +192,8 @@ 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" %
-                 (create, index, read_only, addr))
+        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)
         zconf = self.getServerConfig(addr, ro_svr)
@@ -206,8 +206,8 @@ class CommonSetupTearDown(StorageTestBase):
         self._servers.append(adminaddr)
 
     def shutdownServer(self, index=0):
-        zLOG.LOG("testZEO", zLOG.INFO, "shutdownServer(index=%d) @ %s" %
-                 (index, self._servers[index]))
+        logging.info("shutdownServer(index=%d) @ %s" %
+                     (index, self._servers[index]))
         adminaddr = self._servers[index]
         if adminaddr is not None:
             forker.shutdown_zeo_server(adminaddr)
@@ -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.