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@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: