[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")