[Zope-Checkins] CVS: Zope3/src/ZEO - ClientStorage.py:1.122 StorageServer.py:1.110 monitor.py:1.6 runzeo.py:1.24

Gintautas Miliauskas gintas at pov.lt
Sun Apr 25 07:34:49 EDT 2004


Update of /cvs-repository/Zope3/src/ZEO
In directory cvs.zope.org:/tmp/cvs-serv23562

Modified Files:
	ClientStorage.py StorageServer.py monitor.py runzeo.py 
Log Message:
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.


=== Zope3/src/ZEO/ClientStorage.py 1.121 => 1.122 ===
--- Zope3/src/ZEO/ClientStorage.py:1.121	Thu Feb 26 19:31:51 2004
+++ Zope3/src/ZEO/ClientStorage.py	Sun Apr 25 07:34:15 2004
@@ -25,6 +25,7 @@
 import threading
 import time
 import types
+import logging
 
 from ZEO import ServerStub
 from ZEO.cache import ClientCache
@@ -34,11 +35,15 @@
 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 @@
         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 @@
               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 @@
     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 @@
                 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 @@
             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 @@
 
         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 @@
         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 @@
         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 @@
         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 @@
             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 @@
         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 @@
         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 @@
             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 @@
         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 @@
         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


=== Zope3/src/ZEO/StorageServer.py 1.109 => 1.110 ===
--- Zope3/src/ZEO/StorageServer.py:1.109	Wed Mar 31 22:56:59 2004
+++ Zope3/src/ZEO/StorageServer.py	Sun Apr 25 07:34:15 2004
@@ -26,6 +26,7 @@
 import sys
 import threading
 import time
+import logging
 
 import transaction
 
@@ -37,23 +38,30 @@
 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 @@
         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 @@
             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 @@
             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 @@
             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 @@
             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 @@
                 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 @@
                 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 @@
                      "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 @@
         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 @@
             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 @@
             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):


=== Zope3/src/ZEO/monitor.py 1.5 => 1.6 ===
--- Zope3/src/ZEO/monitor.py:1.5	Fri Nov 28 11:44:47 2003
+++ Zope3/src/ZEO/monitor.py	Sun Apr 25 07:34:15 2004
@@ -20,9 +20,9 @@
 import socket
 import time
 import types
+import logging
 
 import ZEO
-import zLOG
 
 class StorageStats:
     """Per-storage usage statistics."""
@@ -129,7 +129,8 @@
         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)
 


=== Zope3/src/ZEO/runzeo.py 1.23 => 1.24 ===
--- Zope3/src/ZEO/runzeo.py:1.23	Thu Apr 22 14:45:52 2004
+++ Zope3/src/ZEO/runzeo.py	Sun Apr 25 07:34:15 2004
@@ -36,17 +36,27 @@
 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 @@
         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 @@
     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 @@
         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
@@ -255,43 +262,6 @@
             continue
         if k_startswith("SIG") and not k_startswith("SIG_"):
             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




More information about the Zope-Checkins mailing list