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? -- Paul Winkler http://www.slinkp.com
+-------[ Paul Winkler ]---------------------- | Been doing web services (XML-RPC) stuff lately. | What suggestions do people have for troubleshooting a zope-based | XML-RPC application? When debugging; o Raise an exception from python scripts, you can include some info in it. o Use FireFox and use the JavaScript Console to see the traceback returned. o Don't forget to check /error_log in your Zope instance. -- Andrew Milton akm@theinternet.com.au
On Wed, Sep 13, 2006 at 02:39:14AM +1000, Andrew Milton wrote:
+-------[ Paul Winkler ]---------------------- | Been doing web services (XML-RPC) stuff lately. | What suggestions do people have for troubleshooting a zope-based | XML-RPC application?
When debugging; o Raise an exception from python scripts, you can include some info in it.
OK, but when we're dealing with a production system, I can't raise random exceptions just to gather information.
o Use FireFox and use the JavaScript Console to see the traceback returned.
This is a web service. It's not designed to interact with browsers.
o Don't forget to check /error_log in your Zope instance.
Of course. Thanks for the suggestions. I'll probably have to just bite the bullet and do more manual logging. Unless somebody has any more ideas... fwiw, I've also used tcpwatch (http://hathawaymix.org/Software/TCPWatch) which is really great for inspecting the actual data on the wire, but again that's not something i can do in production. -- Paul Winkler http://www.slinkp.com
+-------[ Paul Winkler ]---------------------- | On Wed, Sep 13, 2006 at 02:39:14AM +1000, Andrew Milton wrote: | > +-------[ Paul Winkler ]---------------------- | > | Been doing web services (XML-RPC) stuff lately. | > | What suggestions do people have for troubleshooting a zope-based | > | XML-RPC application? | > | > When debugging; | > o Raise an exception from python scripts, you can include some info in it. | | OK, but when we're dealing with a production system, I can't raise | random exceptions just to gather information. That's why you have a development instance right? d8) -- Andrew Milton akm@theinternet.com.au
On Wed, Sep 13, 2006 at 03:04:48AM +1000, Andrew Milton wrote:
+-------[ Paul Winkler ]---------------------- | On Wed, Sep 13, 2006 at 02:39:14AM +1000, Andrew Milton wrote: | > +-------[ Paul Winkler ]---------------------- | > | Been doing web services (XML-RPC) stuff lately. | > | What suggestions do people have for troubleshooting a zope-based | > | XML-RPC application? | > | > When debugging; | > o Raise an exception from python scripts, you can include some info in it. | | OK, but when we're dealing with a production system, I can't raise | random exceptions just to gather information.
That's why you have a development instance right? d8)
Yes. But in real life you sometimes have an "oh s**t" moment on production. That isn't the case for me today, but I'm trying to plan ahead :) -- Paul Winkler http://www.slinkp.com
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:
On Tue, Sep 12, 2006 at 06:58:36PM +0200, Willi Langenberger wrote:
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).
(snip) Thanks! I may give this a try. FWIW, I've been toying with adding a @log decorator to my methods, along the lines of the logger example at http://soiland.no/software/decorator but i'm having some pain - will report back if i get it working. -- Paul Winkler http://www.slinkp.com
--On 12. September 2006 12:34:38 -0400 Paul Winkler <pw_lists@slinkp.com> wrote:
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.
Ethereal aka Wireshark how it is called now works perfectly for any kind of network analysis like that. It has a functionality "Follow TCP stream" and is able to decode nearly every protocol. -aj
On Tue, Sep 12, 2006 at 07:40:15PM +0200, Andreas Jung wrote:
Ethereal aka Wireshark how it is called now works perfectly for any kind of network analysis like that. It has a functionality "Follow TCP stream" and is able to decode nearly every protocol.
Oooh, that looks really really useful. Thanks! Found it at http://www.wireshark.org/faq.html Unlike tcpdump, it doesn't require pointing clients to a different port (or running on the server and restarting the server on a different port). -- Paul Winkler http://www.slinkp.com
Paul Winkler wrote:
On Tue, Sep 12, 2006 at 07:40:15PM +0200, Andreas Jung wrote:
Ethereal aka Wireshark how it is called now works perfectly for any kind of network analysis like that. It has a functionality "Follow TCP stream" and is able to decode nearly every protocol.
Oooh, that looks really really useful. Thanks! Found it at http://www.wireshark.org/faq.html
Unlike tcpdump, it doesn't require pointing clients to a different port (or running on the server and restarting the server on a different port).
Doing a lot web services developoment lately, I find tcpflow¹ very usefull (and much easier to use then ethereal), e.g.: `tcpflow -c -i eth0 port 8080` will sniff on port 8080 (interface eth0) in interactive mode, so you'll see the data fly by, already decoded and ready to be copy&pasted into SOAPUI² :) ¹: http://www.circlemud.org/~jelson/software/tcpflow/ ²: http://www.soapui.org/ HTH, Igor
On Wed, Sep 13, 2006 at 10:02:56AM +0200, Igor Stroh wrote:
Doing a lot web services developoment lately, I find tcpflow? very usefull (and much easier to use then ethereal), e.g.: `tcpflow -c -i eth0 port 8080` will sniff on port 8080 (interface eth0) in interactive mode, so you'll see the data fly by, already decoded and ready to be copy&pasted into SOAPUI? :)
?: http://www.circlemud.org/~jelson/software/tcpflow/ ?: http://www.soapui.org/
Nice! tcpflow is simple and handy. Anybody know of something like soapui that supports xml-rpc? Bonus points for json-rpc. -- Paul Winkler http://www.slinkp.com
participants (5)
-
Andreas Jung -
Andrew Milton -
Igor Stroh -
Paul Winkler -
Willi Langenberger