[Zodb-checkins] CVS: Zope3/lib/python/ZEO - StorageServer.py:1.46

Guido van Rossum guido@python.org
Thu, 19 Dec 2002 15:22:44 -0500


Update of /cvs-repository/Zope3/lib/python/ZEO
In directory cvs.zope.org:/tmp/cvs-serv25580

Modified Files:
	StorageServer.py 
Log Message:
Convert to using the logging module, using the sublogger machinery.


=== Zope3/lib/python/ZEO/StorageServer.py 1.45 => 1.46 ===
--- Zope3/lib/python/ZEO/StorageServer.py:1.45	Thu Dec 19 14:38:05 2002
+++ Zope3/lib/python/ZEO/StorageServer.py	Thu Dec 19 15:22:43 2002
@@ -26,6 +26,7 @@
 import sys
 import threading
 import time
+import logging
 
 from ZEO import ClientStub
 from ZEO.CommitLog import CommitLog
@@ -33,21 +34,9 @@
 from ZEO.zrpc.connection import ManagedServerConnection, Delay, MTDelay
 
 from Transaction.Transaction import Transaction
-import zLOG
 from ZODB.POSException import StorageError, StorageTransactionError
 from ZODB.POSException import TransactionError, ReadOnlyError
 
-_label = "ZSS" # 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()
-
-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)
-
 class StorageServerError(StorageError):
     """Error reported when an unpickleable exception is raised."""
 
@@ -99,12 +88,14 @@
 
         self.addr = addr
         self.storages = storages
-        set_label()
+        self.logger = logging.getLogger("ZSS.%s" % os.getpid())
         msg = ", ".join(
             ["%s:%s" % (name, storage.isReadOnly() and "RO" or "RW")
              for name, storage in storages.items()])
-        log("%s created %s with storages: %s" %
-            (self.__class__.__name__, read_only and "RO" or "RW", msg))
+        self.logger.warn("%s created %s with storages: %s",
+                         self.__class__.__name__,
+                         read_only and "RO" or "RW",
+                         msg)
         for s in storages.values():
             s._waiting = []
         self.read_only = read_only
@@ -122,7 +113,7 @@
         """
         z = self.ZEOStorageClass(self, self.read_only)
         c = self.ManagedServerConnectionClass(sock, addr, z, self)
-        log("new connection %s: %s" % (addr, `c`))
+        self.logger.warn("new connection %s: %s", addr, `c`)
         return c
 
     def register_connection(self, storage_id, conn):
@@ -211,27 +202,28 @@
         self.storage_id = "uninitialized"
         self.transaction = None
         self.read_only = read_only
-        self.log_label = _label
+        self.logger = logging.getLogger("ZSS.%d.ZEO" % os.getpid())
+        self.log_label = ""
 
     def notifyConnected(self, conn):
         self.connection = conn # For restart_other() below
         self.client = self.ClientStorageStubClass(conn)
         addr = conn.addr
         if isinstance(addr, type("")):
-            label = addr
+            self.log_label = addr
         else:
             host, port = addr
-            label = str(host) + ":" + str(port)
-        self.log_label = _label + "/" + label
+            self.log_label = str(host) + ":" + str(port)
 
     def notifyDisconnected(self):
         # When this storage closes, we must ensure that it aborts
         # any pending transaction.
         if self.transaction is not None:
-            self.log("disconnected during transaction %s" % self.transaction)
+            self.logger.warn("%s: disconnected during transaction %s",
+                             self.log_label, self.transaction)
             self.abort()
         else:
-            self.log("disconnected")
+            self.logger.warn("%s: disconnected", self.log_label)
 
     def __repr__(self):
         tid = self.transaction and repr(self.transaction.id)
@@ -243,9 +235,6 @@
         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 setup_delegation(self):
         """Delegate several methods to the storage"""
         self.versionEmpty = self.storage.versionEmpty
@@ -272,15 +261,16 @@
             raise ReadOnlyError()
         caller = sys._getframe().f_back.f_code.co_name
         if self.transaction is None:
-            self.log("no current transaction: %s()" % caller, zLOG.PROBLEM)
+            self.logger.error("%s: no current transaction: %s()",
+                              self.log_label, caller)
             if exc is not None:
                 raise exc(None, tid)
             else:
                 return 0
         if self.transaction.id != tid:
-            self.log("%s(%s) invalid; current transaction = %s" %
-                     (caller, repr(tid), repr(self.transaction.id)),
-                     zLOG.PROBLEM)
+            self.logger.error("%s: %s(%s) invalid; current transaction = %s",
+                              self.log_label,
+                              caller, repr(tid), repr(self.transaction.id))
             if exc is not None:
                 raise exc(self.transaction.id, tid)
             else:
@@ -293,11 +283,12 @@
         This method must be the first one called by the client.
         """
         if self.storage is not None:
-            self.log("duplicate register() call")
+            self.logger.warn("%s: duplicate register() call", self.log_label)
             raise ValueError, "duplicate register() call"
         storage = self.server.storages.get(storage_id)
         if storage is None:
-            self.log("unknown storage_id: %s" % storage_id)
+            self.logger.warn("%s: unknown storage_id: %s",
+                             self.log_label, storage_id)
             raise ValueError, "unknown storage: %s" % storage_id
 
         if not read_only and (self.read_only or storage.isReadOnly()):
@@ -389,9 +380,9 @@
             return None
 
     def pack_impl(self, time):
-        self.log("pack(time=%s) started..." % repr(time))
+        self.logger.warn("%s: pack(time=%r) started...", self.log_label, time)
         self.storage.pack(time)
-        self.log("pack(time=%s) complete" % repr(time))
+        self.logger.warn("%s: pack(time=%r) complete", self.log_label, time)
         # Broadcast new size statistics
         self.server.invalidate(0, self.storage_id, ())
 
@@ -426,7 +417,8 @@
             raise ReadOnlyError()
         if self.transaction is not None:
             if self.transaction.id == id:
-                self.log("duplicate tpc_begin(%s)" % repr(id))
+                self.logger.warn("%s: duplicate tpc_begin(%r)",
+                                 self.log_label, id)
                 return
             else:
                 raise StorageTransactionError("Multiple simultaneous tpc_begin"
@@ -507,8 +499,9 @@
         if self.storage._transaction:
             d = Delay()
             self.storage._waiting.append((d, self))
-            self.log("Transaction blocked waiting for storage. "
-                     "Clients waiting: %d." % len(self.storage._waiting))
+            self.logger.warn("%s: Transaction blocked waiting for storage. "
+                             "Clients waiting: %d.",
+                             self.log_label, len(self.storage._waiting))
             return d
         else:
             return self.restart()
@@ -522,10 +515,11 @@
             if self.restart_other(zeo_storage, delay):
                 if self.storage._waiting:
                     n = len(self.storage._waiting)
-                    self.log("Blocked transaction restarted.  "
-                             "Clients waiting: %d" % n)
+                    self.logger.warn("%s: Blocked transaction restarted.  "
+                                     "Clients waiting: %d", self.log_label, n)
                 else:
-                    self.log("Blocked transaction restarted.")
+                    self.logger.warn("%s: Blocked transaction restarted.",
+                                     self.log_label)
                 return
 
     def restart_other(self, zeo_storage, delay):
@@ -534,8 +528,9 @@
         try:
             zeo_storage.restart(delay)
         except:
-            self.log("Unexpected error handling waiting transaction",
-                     level=zLOG.WARNING, error=sys.exc_info())
+            self.logger.error("%s: Unexpected error "
+                              "handling waiting transaction",
+                              self.log_label, exc_info=True)
             zeo_storage.connection.close()
             return 0
         else:
@@ -546,7 +541,8 @@
         assert isinstance(old_strategy, DelayedCommitStrategy)
         self.strategy = ImmediateCommitStrategy(self.storage,
                                                 self.client,
-                                                self.log)
+                                                self.logger,
+                                                self.log_label)
         resp = old_strategy.restart(self.strategy)
         if delay is not None:
             delay.reply(resp)
@@ -602,12 +598,13 @@
 class ImmediateCommitStrategy:
     """The storage is available so do a normal commit."""
 
-    def __init__(self, storage, client, logmethod):
+    def __init__(self, storage, client, logger, log_label):
         self.storage = storage
         self.client = client
         self.invalidated = []
         self.serials = []
-        self.log = logmethod
+        self.logger = logger
+        self.log_label = log_label
 
     def tpc_begin(self, txn, tid, status):
         self.txn = txn
@@ -634,10 +631,9 @@
         except Exception, err:
             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
+                t, v = sys.exc_info()[:2]
+                self.logger.error("%s: store error: %s, %s",
+                                  self.log_label, t, v, 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()
@@ -646,7 +642,7 @@
                 pickler.dump(err, 1)
             except:
                 msg = "Couldn't pickle storage exception: %s" % repr(err)
-                self.log(msg, zLOG.ERROR)
+                self.error(msg)
                 err = StorageServerError(msg)
             # The exception is reported back as newserial for this oid
             newserial = err