[Zope] POST sucks.
Willi Langenberger
wlang at wu-wien.ac.at
Tue Sep 12 12:58:36 EDT 2006
According to Paul Winkler:
> Been doing web services (XML-RPC) stuff lately.
> What suggestions do people have for troubleshooting a zope-based
> XML-RPC application?
>
> Access and trace logs are totally useless, since even the method name is
> hidden in the POST payload, so I feel like I'm flying blind; when a
> client developer tells me he gets occasional hangs, I have no idea what
> kind of request triggers the hang.
>
> I may end up sprinkling my code with a lot more logging calls than I'm used
> to. Any other suggestions?
I found it very useful to log every xml-rpc call (call and return
value). For this we have patched ZPublisher/xmlrpc.py (and one line in
ZPublisher/HTTPRequest.py). See attachment (tested against 2.9.3).
The log entries look like that:
Sep 10 06:58:40 bach-s10 xmlrpc id=-177841652, client=137.208.89.23, \
user=stupl, inst=bach-s10.wu-wien.ac.at:10082, path=/bach/stupl/RPC, \
call=get_adreptl3(2002,)
Sep 10 06:58:40 bach-s10 xmlrpc id=-177841652, client=137.208.89.23, \
user=stupl, inst=bach-s10.wu-wien.ac.at:10082, time=88.27ms, out-ok, \
ret=[('E', 19007, None, 7066351, 1, None), ('E', 19010, None, ...
\wlang{}
--
Willi.Langenberger at wu-wien.ac.at Fax: +43/1/31336/9207
Zentrum fuer Informatikdienste, Wirtschaftsuniversitaet Wien, Austria
-----included file follows-----
--- xmlrpc.py.ori 2006-05-12 13:53:45.000000000 +0200
+++ xmlrpc.py 2006-09-12 18:52:39.094041280 +0200
@@ -21,11 +21,56 @@
import re
import sys, types
+import time
from HTTPResponse import HTTPResponse
import xmlrpclib
+import logging
+logger = logging.getLogger('event.xmlrpc')
+logger.setLevel(logging.INFO)
+hdlr = logging.handlers.SysLogHandler('/dev/log')
+logger.addHandler(hdlr)
from zExceptions import Unauthorized
+def log_before(request, method, response):
+ # PATH_INFO, or PATH_TRANSLATED ???
+ #url = request.base + request.environ['PATH_INFO']
+ path = request.environ.get('PATH_INFO')
+ host_port = request.environ.get('HTTP_HOST')
+ user = request._authUserPW() # returns (user,pw) tuple or None
+ if user:
+ user = user[0]
+ response.xmlrpc_timestamp = time.time()
+ idstring = 'xmlrpc id=%u, client=%s, user=%s, inst=%s' % (
+ id(response), request._client_addr, user, host_port)
+ args = '%s' % (request.args,)
+ if len(args) > 200: # syslog line limit: 1024
+ sargs = []
+ # XXX
+ logger.info(
+ "%s, path=%s, call=%s%s" %
+ (idstring, path, method, request.args))
+ response.xmlrpc_idstring = idstring
+
+def get_xmlrpc_info(response):
+ ts = getattr(response, 'xmlrpc_timestamp', None)
+ if ts:
+ t = '%.2fms' % ((time.time() - ts) * 1000,)
+ else:
+ t = '-'
+ idstring = (getattr(response, 'xmlrpc_idstring', None) or
+ 'xmlrpc %u' % (id(response),))
+ return idstring,t
+
+def log_ok(response, ret):
+ idstring, t = get_xmlrpc_info(response)
+ logger.info("%s, time=%s, out-ok, ret=%s" % (idstring, t, ret))
+
+def log_exception(response, errortext):
+ idstring, t = get_xmlrpc_info(response)
+ logger.info(
+ "%s, time=%s, out-error, exception=%s" % (idstring, t, errortext))
+
def parse_input(data):
"""Parse input data and return a method path and argument tuple
@@ -97,8 +142,11 @@
def setBody(self, body, title='', is_error=0, bogus_str_search=None):
if isinstance(body, xmlrpclib.Fault):
+ txt = str(body)
+ log_exception(self, txt)
# Convert Fault object to XML-RPC response.
- body=xmlrpclib.dumps(body, methodresponse=1, allow_none=True)
+ body=xmlrpclib.dumps(body, methodresponse=1, allow_none=True,
+ encoding='iso-8859-1')
else:
if type(body) == types.InstanceType:
# Avoid disclosing private members. Private members are
@@ -117,8 +165,13 @@
# was a Python None. This is now patched in xmlrpclib to
# allow Nones nested inside data structures too.
try:
+ ret = '%s' % (body,)
+ if len(ret) > 80:
+ ret = ret[:80] + '...'
body = xmlrpclib.dumps(
- (body,), methodresponse=1, allow_none=True)
+ (body,), methodresponse=1, allow_none=True,
+ encoding='iso-8859-1')
+ log_ok(self, ret)
except:
self.exception()
return
@@ -141,6 +194,9 @@
isinstance(t, types.ClassType) and issubclass(t, Unauthorized)
):
+ txt = '%s: %s' % (t, v)
+ log_exception(self, txt)
+
return self._real.exception(fatal=fatal, info=info)
# Create an appropriate Fault object. Containing error information
--- HTTPRequest.py.orig 2006-05-12 13:53:45.000000000 +0200
+++ HTTPRequest.py 2006-06-01 10:23:57.272282896 +0200
@@ -394,6 +394,7 @@
if xmlrpc is None: import xmlrpc
meth, self.args = xmlrpc.parse_input(fs.value)
response=xmlrpc.response(response)
+ xmlrpc.log_before(self, meth, response)
other['RESPONSE']=self.response=response
self.maybe_webdav_client = 0
else:
More information about the Zope
mailing list