Debugging XML with Apache XMLRPC

Its been quite insane the last couple of months at work, which is why I haven't been posting as frequently as I would like. I usually do the work I write about on my commute to and from work, and I've either been too mentally exhausted to do anything, or too busy debugging work related problems in my head. To those who have been kind enough to comment, I apologize for not getting back sooner, but I hope you understand - I will get to them as soon as I can.

As you know, I have been trying to interface a Java based publishing system with the Drupal CMS - the interface is over XMLRPC. I have a custom module which traps publish/unpublish events for various content types, and sends over a map of name value pairs for the Java publishing system to persist, where it is used by the web front end. On the Java side, I use Apache XMLRPC in server mode. There are also a few cases where I call Drupal's XMLRPC service using an Apache XMLRPC client.

One thing that struck me early on is the opacity of the Apache XMLRPC library (I find Drupal almost equally opaque, but that is probably because of a combination of my relative inexperience with Drupal and the dynamic nature of PHP). I mean, I am using a library for generating and parsing XMLRPC because I am either lazy or smart (depending on your point of view), not because reading (or writing) XML makes my head hurt. In fact, because all my transactions involve a (almost) black box (Drupal) at one end or the other, being able to see the XML request and response can help me develop and debug the other end that much faster.

I looked up the web for solutions to this problem, but I could not find what I was looking for - namely, some sort of switch to turn XMLRPC logging on and off in Apache XMLRPC. I did find some advice to proxy the request through a logging tool such as netcat, which leads me to believe that the feature I am looking for does not exist, and that the Apache XMLRPC team feels that such a feature is not important/useful enough to implement. I could be wrong, though - would appreciate corrections and pointers.

I've been getting by so far with a dummy handler on the server which just spits out the request XML in the server logs - obviously the request would actually "fail" because the handler cannot respond, because by the time the handlers have a chance to get at the request, its already been consumed. I've been meaning to do something nicer and more elegant, but just didn't have the time.

A few days ago, things came to a head when a really simple XMLRPC request to Drupal (user.login) resulted in the following exception from my client. Notice how completely useless it is.

1 2 3 4 5 6 7 8

[junit] Testcase: testLogin took 0.499 sec [junit] Caused an ERROR [junit] Failed to parse server's response: The markup in the document follow ing the root element must be well-formed. [junit] org.apache.xmlrpc.client.XmlRpcClientException: Failed to parse serv er's response: The markup in the document following the root element must be wel l-formed. [junit] ...

That's when I decided that I really needed to stop wasting cycles trying to figure out these kind of issues, and spend some time instrumenting the code to really see whats going on with the XML. My approach involves extending Apache XMLRPC to do this. I describe the results of my efforts in this post. I've been using this for about 3 days now and find it incredibly useful. Hopefully you will too.

Client Side

A typical Java XMLRPC client in my codebase looks like this. Its basically copied straight off the Apache XMLRPC Documentation.

1 2 3 4 5 6 7 8 9

XmlRpcClientConfigImpl config = new XmlRpcClientConfigImpl(); config.setServerURL(new URL("http://localhost/services/xmlrpc")); XmlRpcClient client = new XmlRpcClient(); client.setTransportFactory(new XmlRpcCommonsTransportFactory(client)); client.setConfig(config); Map<String,Object> data = new HashMap<String,Object>(); // populate the map... Object ret = client.execute("methodName", new Object[] {data}); // check the return value...

In order to get the actual XML requests and response, I subclass the XmlRpcCommonsTransportFactory, and in my factory, return a subclass of XmlRpcCommonsTransport, which logs the request and response. To use this, all we need to do is to change this line in the above code:

1	client.setTransportFactory(new CustomXmlRpcCommonsTransportFactory(client));

In fact, because the logging is triggered by the setting in the log4j.properties file, you can just switch out the XmlRpcCommonsTransportFactory with my custom version - if your logging is turned off for this class, then it behaves exactly like the original factory. Here's the code - the actual transport is modeled as an inner class within the factory, since it is only ever called from the factory.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61

// Source: src/main/java/com/mycompany/myapp/xmlrpc/CustomXmlRpcCommonsTransportFactory.java package com.mycompany.myapp.xmlrpc; import java.io.ByteArrayInputStream; import java.io.InputStream; import org.apache.xmlrpc.XmlRpcException; import org.apache.xmlrpc.client.XmlRpcClient; import org.apache.xmlrpc.client.XmlRpcCommonsTransport; import org.apache.xmlrpc.client.XmlRpcCommonsTransportFactory; import org.apache.xmlrpc.client.XmlRpcTransport; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class CustomXmlRpcCommonsTransportFactory extends XmlRpcCommonsTransportFactory { private final Logger logger = LoggerFactory.getLogger(getClass()); public CustomXmlRpcCommonsTransportFactory(XmlRpcClient pClient) { super(pClient); } @Override public XmlRpcTransport getTransport() { return new LoggingTransport(this); } private class LoggingTransport extends XmlRpcCommonsTransport { public LoggingTransport(CustomXmlRpcCommonsTransportFactory pFactory) { super(pFactory); } /** * Logs the request content in addition to the actual work. */ @Override protected void writeRequest(final ReqWriter pWriter) throws XmlRpcException { super.writeRequest(pWriter); if (logger.isDebugEnabled()) { CustomLoggingUtils.logRequest(logger, method.getRequestEntity()); } } /** * Logs the response from the server, and returns the contents of * the response as a ByteArrayInputStream. */ @Override protected InputStream getInputStream() throws XmlRpcException { InputStream istream = super.getInputStream(); if (logger.isDebugEnabled()) { return new ByteArrayInputStream( CustomLoggingUtils.logResponse(logger, istream).getBytes()); } else { return istream; } } } }

Since I used a similar approach to log XML requests and responses on the server side as well, I decided to move my logging code (which includes prettifying the XML for readability) into a common utilities class. Here is the Logging utilities class. Included in the class is a method to prettify the XML request and response - Drupal sends out a nicely formatted XML chunk, but Apache XMLRPC sends it out in one long line (for performance I think) - I found a nice way to do this here using just the standard Java libraries.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87

// Source: src/main/java/com/mycompany/myapp/xmlrpc/CustomLoggingUtils.java package com.mycompany.myapp.xmlrpc; import java.io.BufferedReader; import java.io.ByteArrayOutputStream; import java.io.IOException; import java.io.InputStream; import java.io.InputStreamReader; import java.io.StringReader; import java.io.StringWriter; import javax.xml.transform.OutputKeys; import javax.xml.transform.Transformer; import javax.xml.transform.TransformerFactory; import javax.xml.transform.stream.StreamResult; import javax.xml.transform.stream.StreamSource; import org.apache.commons.httpclient.methods.RequestEntity; import org.apache.commons.io.IOUtils; import org.apache.xmlrpc.XmlRpcException; import org.slf4j.Logger; public class CustomLoggingUtils { public static void logRequest(Logger logger, RequestEntity requestEntity) throws XmlRpcException { ByteArrayOutputStream bos = null; try { logger.debug("---- Request ----"); bos = new ByteArrayOutputStream(); requestEntity.writeRequest(bos); logger.debug(toPrettyXml(logger, bos.toString())); } catch (IOException e) { throw new XmlRpcException(e.getMessage(), e); } finally { IOUtils.closeQuietly(bos); } } public static void logRequest(Logger logger, String content) { logger.debug("---- Request ----"); logger.debug(toPrettyXml(logger, content)); } public static String logResponse(Logger logger, InputStream istream) throws XmlRpcException { BufferedReader reader = null; try { reader = new BufferedReader(new InputStreamReader(istream)); String line = null; StringBuilder respBuf = new StringBuilder(); while ((line = reader.readLine()) != null) { respBuf.append(line); } String response = respBuf.toString(); logger.debug("---- Response ----"); logger.debug(toPrettyXml(logger, respBuf.toString())); return response; } catch (IOException e) { throw new XmlRpcException(e.getMessage(), e); } finally { IOUtils.closeQuietly(reader); } } public static void logResponse(Logger logger, String content) { logger.debug("---- Response ----"); logger.debug(toPrettyXml(logger, content)); } private static String toPrettyXml(Logger logger, String xml) { try { Transformer transformer = TransformerFactory.newInstance().newTransformer(); transformer.setOutputProperty(OutputKeys.INDENT, "yes"); transformer.setOutputProperty( "{http://xml.apache.org/xslt}indent-amount", "2"); StreamResult result = new StreamResult(new StringWriter()); StreamSource source = new StreamSource(new StringReader(xml)); transformer.transform(source, result); return result.getWriter().toString(); } catch (Exception e) { logger.warn("Can't parse XML"); return xml; } } }

Server Side

On the server side, I use a similar approach (ie, subclassing) as on the client side. In my code, I use the XmlRpcServletServer embedded inside a Spring controller, like this:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17

@PostConstruct protected void init() throws Exception { XmlRpcServerConfigImpl config = new XmlRpcServerConfigImpl(); config.setBasicEncoding(encoding); config.setEnabledForExceptions(enabledForExceptions); config.setEnabledForExtensions(enabledForExtensions); service = new XmlRpcServletServer(); service.setConfig(config); ... } @RequestMapping(value="/someMethod", method=RequestMethod.POST) public void publish(HttpServletRequest request, HttpServletResponse response) throws Exception { service.execute(request, response); }

I extend the XmlRpcServletServer and override its execute() method to look at the log4j setting and optionally log its request and response XML to the server logs. This is done inline with the code, a request comes in, is logged to server logs, then acted upon by the execute method which generates the response. Before being sent back to the client, the response is logged on the server logs.

This is slightly more involved. It involves wrapping the request and response parameters in request and response wrapper objects, which in turn return subclasses of ServletInputStream and ServletOutputStream, where the actual magic happens.

The custom ServletInputStream writes the real InputStream that it wraps into a ByteArrayInputStream on construction and logs the request contents. In the overriden read() method, it returns bytes from the ByteArrayInputStream instead of the real InputStream. The custom ServletOutputStream wraps the real OutputStream and has an overriden write() method which copies the bytes into a StringBuilder buffer as they come in. On close(), the response is logged from the StringBuilder and the real OutputStream is closed. The idea is derived from this page. Here is the code.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138

// Source: src/main/java/com/mycompany/myapp/xmlrpc/CustomXmlRpcServletServer.java package com.mycompany.myapp.xmlrpc; import java.io.BufferedReader; import java.io.ByteArrayInputStream; import java.io.ByteArrayOutputStream; import java.io.IOException; import java.io.InputStreamReader; import java.io.OutputStreamWriter; import java.io.PrintWriter; import javax.servlet.ServletException; import javax.servlet.ServletInputStream; import javax.servlet.ServletOutputStream; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletRequestWrapper; import javax.servlet.http.HttpServletResponse; import javax.servlet.http.HttpServletResponseWrapper; import org.apache.xmlrpc.webserver.XmlRpcServletServer; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class CustomXmlRpcServletServer extends XmlRpcServletServer { private final Logger logger = LoggerFactory.getLogger(getClass()); @Override public void execute(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException { if (logger.isDebugEnabled()) { super.execute(new LoggingRequestWrapper(request), new LoggingResponseWrapper(response)); } else { super.execute(request, response); } } private class LoggingRequestWrapper extends HttpServletRequestWrapper { private HttpServletRequest originalRequest; private LoggingServletInputStream loggingInputStream = null; public LoggingRequestWrapper(HttpServletRequest request) { super(request); this.originalRequest = request; } @Override public ServletInputStream getInputStream() throws IOException { loggingInputStream = new LoggingServletInputStream( originalRequest.getInputStream()); return loggingInputStream; } @Override public BufferedReader getReader() throws IOException { return new BufferedReader(new InputStreamReader(getInputStream())); } } private class LoggingServletInputStream extends ServletInputStream { private ServletInputStream istream; private ByteArrayInputStream standinInputStream; public LoggingServletInputStream(ServletInputStream istream) throws IOException { this.istream = istream; ByteArrayOutputStream bos = new ByteArrayOutputStream(); byte[] buf = new byte[4096]; int n = 0; while (true) { n = istream.read(buf); if (n == -1) { break; } bos.write(buf, 0, n); } this.standinInputStream = new ByteArrayInputStream(bos.toByteArray()); CustomLoggingUtils.logRequest(logger, new String(bos.toByteArray())); } @Override public int read() throws IOException { int c = standinInputStream.read(); return c; } } private class LoggingResponseWrapper extends HttpServletResponseWrapper { private HttpServletResponse originalResponse; private LoggingServletOutputStream loggingOutputStream = null; public LoggingResponseWrapper(HttpServletResponse response) { super(response); this.originalResponse = response; } @Override public ServletOutputStream getOutputStream() throws IOException { this.loggingOutputStream = new LoggingServletOutputStream( originalResponse.getOutputStream()); return loggingOutputStream; } @Override public PrintWriter getWriter() throws IOException { return new PrintWriter(new OutputStreamWriter(getOutputStream())); } } private class LoggingServletOutputStream extends ServletOutputStream { private ServletOutputStream ostream; private StringBuilder buf; public LoggingServletOutputStream(ServletOutputStream ostream) { this.ostream = ostream; this.buf = new StringBuilder(); } @Override public void write(int b) throws IOException { buf.append((char) b); ostream.write(b); } @Override public void close() throws IOException { if (buf.length() > 0) { CustomLoggingUtils.logResponse(logger, buf.toString()); } ostream.close(); } } }

To turn logging on and off, you will need to tweak your log4j.properties file. Basically, if the logging for either of these is set to DEBUG, then it will log, otherwise it will not.

Oh, and by the way, remember the malformed XML exception that started this off in the first place? Turns out that I had the Devel module turned on in my Drupal installation, so the trace of the SQLs that were being executed were also being echoed back after the closing <methodResponse> tag in the response.