[Zope] POST sucks.

[Willi Langenberger]

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: