Saturday, May 01, 2010

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.

6 comments (moderated to prevent spam):

Anonymous said...

Hello, just wanting to say "Thank you!". Your code really helped me in debugging a weird methodResponse.

Alessandro

Sujit Pal said...

Thanks Alessandro, glad it helped.

David Mail said...

Thank you Sujit. I needed some XMLRPC logging at the client side for a Java app and your code is great for that.

While the response logging works great, for the requests the line
logger.debug( method.getRequestEntity());
prints something like: org.apache.xmlrpc.client.XmlRpcCommonsTransport$1@5b0a8e87

Any idea why?

Thanks again for sharing your code,
David

Sujit Pal said...

Thanks David, you are welcome. Regarding your question, I suspect that RequestEntity does not have a toString() method defined on it, so it is using Object.toString().

Anonymous said...

I assume this only works for the specific transport class you are using? Because when I try to subclass the one we're using, I get an error on "method" as there is no such field.

I'm currently searching for a more generic way to do it.

Sujit Pal said...

I guess so... I am extending the XmlRpcCommonsTransport class. I am using the method.getRequestEntity() to get the request object so the logger can write out a copy of it to the log files. In your transport class, there must be some way to get the request, if you use that instead I think the rest of the code should work as-is (or almost as-is).