[Zope3-checkins] CVS: Zope3/lib/python/ZEO/zrpc - client.py:1.8 connection.py:1.9 log.py:1.4 marshal.py:1.4 server.py:1.7 smac.py:1.3

Tim Peters tim.one@comcast.net
Thu, 19 Dec 2002 15:33:01 -0500


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

Modified Files:
	client.py connection.py log.py marshal.py server.py smac.py 
Log Message:
Enough interconnected logging edits so that the ZEO tests pass again.


=== Zope3/lib/python/ZEO/zrpc/client.py 1.7 => 1.8 ===
--- Zope3/lib/python/ZEO/zrpc/client.py:1.7	Thu Dec  5 13:25:37 2002
+++ Zope3/lib/python/ZEO/zrpc/client.py	Thu Dec 19 15:33:00 2002
@@ -20,11 +20,10 @@
 import types
 
 import ThreadedAsync
-import zLOG
 
 from ZODB.POSException import ReadOnlyError
 
-from ZEO.zrpc.log import log
+from ZEO.zrpc import log
 from ZEO.zrpc.trigger import trigger
 from ZEO.zrpc.connection import ManagedConnection
 
@@ -93,12 +92,11 @@
         finally:
             self.cond.release()
         if t is not None:
-            log("CM.close(): stopping and joining thread")
+            log.info("CM.close(): stopping and joining thread")
             t.stop()
             t.join(30)
             if t.isAlive():
-                log("CM.close(): self.thread.join() timed out",
-                    level=zLOG.WARNING)
+                log.error("CM.close(): self.thread.join() timed out")
         if conn is not None:
             # This will call close_conn() below which clears self.connection
             conn.close()
@@ -119,9 +117,9 @@
 
         # XXX need each connection started with async==0 to have a
         # callback
-        log("CM.set_async(%s)" % repr(map))
+        log.info("CM.set_async(%s)" % repr(map))
         if not self.closed and self.trigger is None:
-            log("CM.set_async(): first call")
+            log.info("CM.set_async(): first call")
             self.trigger = trigger()
             self.thr_async = 1 # XXX needs to be set on the Connection
 
@@ -168,7 +166,7 @@
                 return
             t = self.thread
             if t is None:
-                log("CM.connect(): starting ConnectThread")
+                log.info("CM.connect(): starting ConnectThread")
                 self.thread = t = ConnectThread(self, self.client,
                                                 self.addrlist,
                                                 self.tmin, self.tmax)
@@ -178,7 +176,7 @@
                 while self.connection is None:
                     self.cond.wait(30)
                     if self.connection is None:
-                        log("CM.connect(sync=1): still waiting...")
+                        log.info("CM.connect(sync=1): still waiting...")
         finally:
             self.cond.release()
         if sync:
@@ -186,7 +184,7 @@
 
     def connect_done(self, conn, preferred):
         # Called by ConnectWrapper.notify_client() after notifying the client
-        log("CM.connect_done(preferred=%s)" % preferred)
+        log.info("CM.connect_done(preferred=%s)", preferred)
         self.cond.acquire()
         try:
             self.connection = conn
@@ -202,9 +200,9 @@
         try:
             if conn is not self.connection:
                 # Closing a non-current connection
-                log("CM.close_conn() non-current", level=zLOG.BLATHER)
+                log.info("CM.close_conn() non-current")
                 return
-            log("CM.close_conn()")
+            log.info("CM.close_conn()")
             self.connection = None
         finally:
             self.cond.release()
@@ -295,7 +293,7 @@
                 break
             time.sleep(delay)
             delay = min(delay*2, self.tmax)
-        log("CT: exiting thread: %s" % self.getName())
+        log.info("CT: exiting thread: %s", self.getName())
 
     def try_connecting(self, timeout):
         """Try connecting to all self.addrlist addresses.
@@ -306,7 +304,7 @@
 
         If no connection is found within timeout seconds, return 0.
         """
-        log("CT: attempting to connect on %d sockets" % len(self.addrlist))
+        log.info("CT: attempting to connect on %d sockets", len(self.addrlist))
         deadline = time.time() + timeout
         wrappers = self._create_wrappers()
         for wrap in wrappers.keys():
@@ -365,14 +363,14 @@
                 break
             try:
                 r, w, x = select.select([], connecting, connecting, 1.0)
-                log("CT: select() %d, %d, %d" % tuple(map(len, (r,w,x))))
+                log.info("CT: select() %d, %d, %d" % tuple(map(len, (r,w,x))))
             except select.error, msg:
-                log("CT: select failed; msg=%s" % str(msg),
-                    level=zLOG.WARNING) # XXX Is this the right level?
+                # XXX Is error the right level?
+                log.error("CT: select failed; msg=%s", msg)
                 continue
             # Exceptable wrappers are in trouble; close these suckers
             for wrap in x:
-                log("CT: closing troubled socket %s" % str(wrap.addr))
+                log.info("CT: closing troubled socket %s", str(wrap.addr))
                 del wrappers[wrap]
                 wrap.close()
             # Writable sockets are connected
@@ -402,7 +400,7 @@
                     return -1
             assert wrap.state == "closed"
             del wrappers[wrap]
-        
+
 
 class ConnectWrapper:
     """An object that handles the connection procedure for one socket.
@@ -427,12 +425,11 @@
         self.sock = None
         self.conn = None
         self.preferred = 0
-        log("CW: attempt to connect to %s" % repr(addr))
+        log.info("CW: attempt to connect to %s", repr(addr))
         try:
             self.sock = socket.socket(domain, socket.SOCK_STREAM)
         except socket.error, err:
-            log("CW: can't create socket, domain=%s: %s" % (domain, err),
-                level=zLOG.ERROR)
+            log.error("CW: can't create socket, domain=%s: %s", domain, err)
             self.close()
             return
         self.sock.setblocking(0)
@@ -444,19 +441,17 @@
             try:
                 err = self.sock.connect_ex(self.addr)
             except socket.error, msg:
-                log("CW: connect_ex(%r) failed: %s" % (self.addr, msg),
-                    level=zLOG.ERROR)
+                log.error("CW: connect_ex(%r) failed: %s", self.addr, msg)
                 self.close()
                 return
-            log("CW: connect_ex(%s) returned %s" %
-                (self.addr, errno.errorcode.get(err) or str(err)))
+            log.info("CW: connect_ex(%s) returned %s", self.addr,
+                     errno.errorcode.get(err) or str(err))
             if err in _CONNECT_IN_PROGRESS:
                 self.state = "connecting"
                 return
             if err not in _CONNECT_OK:
-                log("CW: error connecting to %s: %s" %
-                    (self.addr, errno.errorcode.get(err) or str(err)),
-                    level=zLOG.WARNING)
+                log.error("CW: error connecting to %s: %s", self.addr,
+                          errno.errorcode.get(err) or str(err))
                 self.close()
                 return
             self.state = "connected"
@@ -476,12 +471,13 @@
             self.preferred = self.client.testConnection(self.conn)
             self.state = "tested"
         except ReadOnlyError:
-            log("CW: ReadOnlyError in testConnection (%s)" % repr(self.addr))
+            log.info("CW: ReadOnlyError in testConnection (%s)",
+                      repr(self.addr))
             self.close()
             return
         except:
-            log("CW: error in testConnection (%s)" % repr(self.addr),
-                level=zLOG.ERROR, error=sys.exc_info())
+            log.error("CW: error in testConnection (%s)", repr(self.addr),
+                      exc_info=True)
             self.close()
             return
         if self.preferred:
@@ -499,8 +495,8 @@
         try:
             self.client.notifyConnected(self.conn)
         except:
-            log("CW: error in notifyConnected (%s)" % repr(self.addr),
-                level=zLOG.ERROR, error=sys.exc_info())
+            log.error("CW: error in notifyConnected (%s)", repr(self.addr),
+                      exc_info=True)
             self.close()
             return
         self.state = "notified"


=== Zope3/lib/python/ZEO/zrpc/connection.py 1.8 => 1.9 ===
--- Zope3/lib/python/ZEO/zrpc/connection.py:1.8	Thu Dec 19 12:43:19 2002
+++ Zope3/lib/python/ZEO/zrpc/connection.py	Thu Dec 19 15:33:00 2002
@@ -17,14 +17,14 @@
 import sys
 import threading
 import types
+import logging
 
 import ThreadedAsync
 from ZEO.zrpc import smac
 from ZEO.zrpc.error import ZRPCError, DisconnectedError
-from ZEO.zrpc.log import log, short_repr
+from ZEO.zrpc import log
 from ZEO.zrpc.marshal import Marshaller
 from ZEO.zrpc.trigger import trigger
-import zLOG
 from ZODB import POSException
 
 REPLY = ".reply" # message name used for replies
@@ -47,7 +47,7 @@
         self.send_reply(self.msgid, obj)
 
     def error(self, exc_info):
-        log("Error raised in delayed method", zLOG.ERROR, error=exc_info)
+        log.error("Error raised in delayed method", exc_info=True)
         self.return_error(self.msgid, 0, *exc_info[:2])
 
 class MTDelay(Delay):
@@ -151,9 +151,6 @@
 
     __str__ = __repr__ # Defeat asyncore's dreaded __getattr__
 
-    def log(self, message, level=zLOG.BLATHER, error=None):
-        zLOG.LOG(self.log_label, level, message, error=error)
-
     def close(self):
         if self.closed:
             return
@@ -189,8 +186,9 @@
         if message == self.protocol_version:
             self.message_input = self._message_input
         else:
-            self.log("recv_handshake: bad handshake %s" % short_repr(message),
-                     level=zLOG.ERROR)
+            log.error("%s: recv_handshake: bad handshake %s",
+                      self.log_label,
+                      log.short_repr(message))
         # otherwise do something else...
 
     def message_input(self, message):
@@ -202,9 +200,9 @@
         msgid, flags, name, args = self.marshal.decode(message)
 
         if __debug__:
-            self.log("recv msg: %s, %s, %s, %s" % (msgid, flags, name,
-                                                   short_repr(args)),
-                     level=zLOG.TRACE)
+            log.debug("%s: recv msg: %s, %s, %s, %s",
+                      self.log_label, msgid, flags, name,
+                      log.short_repr(args))
         if name == REPLY:
             self.handle_reply(msgid, flags, args)
         else:
@@ -212,8 +210,8 @@
 
     def handle_reply(self, msgid, flags, args):
         if __debug__:
-            self.log("recv reply: %s, %s, %s"
-                     % (msgid, flags, short_repr(args)), level=zLOG.DEBUG)
+            log.debug("%s: recv reply: %s, %s, %s",
+                      self.log_label, msgid, flags, log.short_repr(args))
         self.replies_cond.acquire()
         try:
             self.replies[msgid] = flags, args
@@ -226,8 +224,8 @@
             msg = "Invalid method name: %s on %s" % (name, repr(self.obj))
             raise ZRPCError(msg)
         if __debug__:
-            self.log("calling %s%s" % (name, short_repr(args)),
-                     level=zLOG.BLATHER)
+            log.info("%s: calling %s%s", self.log_label, name,
+                     log.short_repr(args))
 
         meth = getattr(self.obj, name)
         try:
@@ -236,18 +234,19 @@
             raise
         except Exception, msg:
             error = sys.exc_info()
-            self.log("%s() raised exception: %s" % (name, msg), zLOG.INFO,
-                     error=error)
+            log.info("%s: %s() raised exception: %s", self.log_label,
+                     name, msg, exc_info=True)
             error = error[:2]
             return self.return_error(msgid, flags, *error)
 
         if flags & ASYNC:
             if ret is not None:
                 raise ZRPCError("async method %s returned value %s" %
-                                (name, short_repr(ret)))
+                                (name, log.short_repr(ret)))
         else:
             if __debug__:
-                self.log("%s returns %s" % (name, short_repr(ret)), zLOG.DEBUG)
+                log.debug("%s: %s returns %s", self.log_label, name,
+                          log.short_repr(ret))
             if isinstance(ret, Delay):
                 ret.set_sender(msgid, self.send_reply, self.return_error)
             else:
@@ -260,7 +259,7 @@
         self.close()
 
     def log_error(self, msg="No error message supplied"):
-        self.log(msg, zLOG.ERROR, error=sys.exc_info())
+        log.error("%s: %s", self.log_label, msg, exc_info=True)
 
     def check_method(self, name):
         # XXX Is this sufficient "security" for now?
@@ -273,7 +272,7 @@
             msg = self.marshal.encode(msgid, 0, REPLY, ret)
         except self.marshal.errors:
             try:
-                r = short_repr(ret)
+                r = log.short_repr(ret)
             except:
                 r = "<unreprable>"
             err = ZRPCError("Couldn't pickle return %.100s" % r)
@@ -292,7 +291,7 @@
             msg = self.marshal.encode(msgid, 0, REPLY, (err_type, err_value))
         except self.marshal.errors:
             try:
-                r = short_repr(err_value)
+                r = log.short_repr(err_value)
             except:
                 r = "<unreprable>"
             err = ZRPCError("Couldn't pickle error %.100s" % r)
@@ -312,8 +311,8 @@
         finally:
             self.msgid_lock.release()
         if __debug__:
-            self.log("send msg: %d, %d, %s, ..." % (msgid, flags, method),
-                     zLOG.TRACE)
+            log.debug("%s: send msg: %d, %d, %s, ...", self.log_label,
+                      msgid, flags, method)
         buf = self.marshal.encode(msgid, flags, method, args)
         self.message_output(buf)
         return msgid
@@ -368,8 +367,8 @@
     def wait(self, msgid):
         """Invoke asyncore mainloop and wait for reply."""
         if __debug__:
-            self.log("wait(%d), async=%d" % (msgid, self.is_async()),
-                     level=zLOG.TRACE)
+            log.debug("%s: wait(%d), async=%d", self.log_label, msgid,
+                      self.is_async())
         if self.is_async():
             self._pull_trigger()
 
@@ -386,8 +385,8 @@
                 if reply is not None:
                     del self.replies[msgid]
                     if __debug__:
-                        self.log("wait(%d): reply=%s" %
-                                 (msgid, short_repr(reply)), level=zLOG.DEBUG)
+                        log.debug("%s: wait(%d): reply=%s", self.log_label,
+                                  msgid, log.short_repr(reply))
                     return reply
                 if self.is_async():
                     self.replies_cond.wait(10.0)
@@ -396,14 +395,15 @@
                     try:
                         try:
                             if __debug__:
-                                self.log("wait(%d): asyncore.poll(%s)" %
-                                         (msgid, delay), level=zLOG.TRACE)
+                                log.debug("%s: wait(%d): asyncore.poll(%s)",
+                                          self.log_label, msgid, delay)
                             asyncore.poll(delay, self._map)
                             if delay < 1.0:
                                 delay += delay
                         except select.error, err:
-                            self.log("Closing.  asyncore.poll() raised %s."
-                                     % err, level=zLOG.BLATHER)
+                            log.info("%s: Closing.  "
+                                     "asyncore.poll() raised %s.",
+                                     self.log_label, err)
                             self.close()
                     finally:
                         self.replies_cond.acquire()
@@ -413,7 +413,7 @@
     def poll(self):
         """Invoke asyncore mainloop to get pending message out."""
         if __debug__:
-            self.log("poll(), async=%d" % self.is_async(), level=zLOG.TRACE)
+            log.debug("poll(), async=%d", self.is_async())
         if self.is_async():
             self._pull_trigger()
         else:
@@ -422,7 +422,8 @@
     def pending(self):
         """Invoke mainloop until any pending messages are handled."""
         if __debug__:
-            self.log("pending(), async=%d" % self.is_async(), level=zLOG.TRACE)
+            log.debug("%s: pending(), async=%d", self.log_label,
+                      self.is_async())
         if self.is_async():
             return
         # Inline the asyncore poll() function to know whether any input


=== Zope3/lib/python/ZEO/zrpc/log.py 1.3 => 1.4 ===
--- Zope3/lib/python/ZEO/zrpc/log.py:1.3	Fri Nov 22 16:24:53 2002
+++ Zope3/lib/python/ZEO/zrpc/log.py	Thu Dec 19 15:33:00 2002
@@ -13,22 +13,44 @@
 ##############################################################################
 import os
 import types
-import zLOG
 import threading
+import logging
 
 LOG_THREAD_ID = 0 # Set this to 1 during heavy debugging
 
 _label = "zrpc:%s" % os.getpid()
 
-def new_label():
-    global _label
-    _label = "zrpc:%s" % os.getpid()
+# The code duplication here is for speed (save a layer of function call).
 
-def log(message, level=zLOG.BLATHER, label=None, error=None):
-    label = label or _label
+def critical(msg, *args, **kw):
+    label = _label
     if LOG_THREAD_ID:
         label = "%s:%s" % (label, threading.currentThread().getName())
-    zLOG.LOG(label, level, message, error=error)
+    logging.critical("%s: "+msg, label, *args, **kw)
+
+def error(msg, *args, **kw):
+    label = _label
+    if LOG_THREAD_ID:
+        label = "%s:%s" % (label, threading.currentThread().getName())
+    logging.error("%s: "+msg, label, *args, **kw)
+
+def warn(msg, *args, **kw):
+    label = _label
+    if LOG_THREAD_ID:
+        label = "%s:%s" % (label, threading.currentThread().getName())
+    logging.warn("%s: "+msg, label, *args, **kw)
+
+def info(msg, *args, **kw):
+    label = _label
+    if LOG_THREAD_ID:
+        label = "%s:%s" % (label, threading.currentThread().getName())
+    logging.info("%s: "+msg, label, *args, **kw)
+
+def debug(msg, *args, **kw):
+    label = _label
+    if LOG_THREAD_ID:
+        label = "%s:%s" % (label, threading.currentThread().getName())
+    logging.debug("%s: "+msg, label, *args, **kw)
 
 REPR_LIMIT = 40
 


=== Zope3/lib/python/ZEO/zrpc/marshal.py 1.3 => 1.4 ===
--- Zope3/lib/python/ZEO/zrpc/marshal.py:1.3	Fri Nov 22 16:24:53 2002
+++ Zope3/lib/python/ZEO/zrpc/marshal.py	Thu Dec 19 15:33:00 2002
@@ -15,10 +15,8 @@
 from cStringIO import StringIO
 import types
 
-import zLOG
-
 from ZEO.zrpc.error import ZRPCError
-from ZEO.zrpc.log import log, short_repr
+from ZEO.zrpc import log
 
 class Marshaller:
     """Marshal requests and replies to second across network"""
@@ -38,7 +36,7 @@
         try:
             return unpickler.load() # msgid, flags, name, args
         except:
-            log("can't decode message: %s" % short_repr(msg), level=zLOG.ERROR)
+            log.error("can't decode message: %s", log.short_repr(msg))
             raise
 
 _globals = globals()


=== Zope3/lib/python/ZEO/zrpc/server.py 1.6 => 1.7 ===
--- Zope3/lib/python/ZEO/zrpc/server.py:1.6	Mon Dec 16 16:18:02 2002
+++ Zope3/lib/python/ZEO/zrpc/server.py	Thu Dec 19 15:33:00 2002
@@ -16,8 +16,7 @@
 import types
 
 from ZEO.zrpc.connection import Connection, Delay
-from ZEO.zrpc.log import log
-import zLOG
+from ZEO.zrpc import log
 import ThreadedAsync
 
 # Export the main asyncore loop
@@ -44,7 +43,7 @@
         else:
             self.create_socket(socket.AF_UNIX, socket.SOCK_STREAM)
         self.set_reuse_addr()
-        log("listening on %s" % str(self.addr), zLOG.INFO)
+        log.info("listening on %s", str(self.addr))
         self.bind(self.addr)
         self.listen(5)
 
@@ -58,8 +57,8 @@
         try:
             sock, addr = self.accept()
         except socket.error, msg:
-            log("accepted failed: %s" % msg)
+            log.info("accepted failed: %s", msg)
             return
         c = self.factory(sock, addr)
-        log("connect from %s: %s" % (repr(addr), c))
+        log.info("connect from %s: %s", repr(addr), c)
         self.clients.append(c)


=== Zope3/lib/python/ZEO/zrpc/smac.py 1.2 => 1.3 ===
--- Zope3/lib/python/ZEO/zrpc/smac.py:1.2	Thu Dec 12 11:58:14 2002
+++ Zope3/lib/python/ZEO/zrpc/smac.py	Thu Dec 19 15:33:00 2002
@@ -15,13 +15,11 @@
 
 import asyncore, struct
 import threading
-from ZEO.Exceptions import Disconnected
-import zLOG
+import socket, errno
 from types import StringType
 
-from ZEO.zrpc.log import log, short_repr
-
-import socket, errno
+from ZEO.Exceptions import Disconnected
+from ZEO.zrpc import log
 
 # Use the dictionary to make sure we get the minimum number of errno
 # entries.   We expect that EWOULDBLOCK == EAGAIN on most systems --
@@ -204,9 +202,8 @@
     def message_output(self, message):
         if __debug__:
             if self._debug:
-                log('message_output %d bytes: %s' %
-                    (len(message), short_repr(message)),
-                    level=zLOG.TRACE)
+                log.debug('message_output %d bytes: %s',
+                          len(message), log.short_repr(message))
 
         if self.__closed:
             raise Disconnected("Action is temporarily unavailable")