Showing posts with label xmlrpc. Show all posts
Showing posts with label xmlrpc. Show all posts

Thursday, October 21, 2010

A Custom Drupal XMLRPC Service

I have written earlier about using Drupal as an XMLRPC client - via a custom module that hooks into the persistence lifecycle of a Drupal node in order to send XMLRPC requests out to an external publishing system containing an embedded XMLRPC server. Drupal can also act as an XMLRPC server, receiving and acting on XMLRPC requests from external clients.

We have been using one of the built-in services (the comment.save from Comment Services Module). However, we recently decided to build an external Comment Moderation tool, since we have outgrown the rather rudimentary comment moderation form available in Drupal, and that needs services exposed on Drupal to publish, unpublish and delete a comment, which are not available from the comment services module.

My initial explorations on Google pointed me to the this post on the Riff Blog, and thence to the XMLRPC hook, available in core Drupal. However, the results were not too satisfying (it didn't show up on the Services page at /admin/build/services) so I quickly abandoned this path and went looking for something better.

I found my answer in the source code for the Comment Services Module - it implemented hook_service(), so that pointed me to the Services Module, which in turn led me to the Services Handbook, and buried in the links on the right navigation toolbar on this page, some information that I could actually use.

Interestingly, not only does Drupal allow you to build/install custom services, it also allows for custom servers (such as JSON or SOAP). However, since I already had an XMLRPC server installed for the pre-installed services, I did not explore this option. There is more information about this on Deja Augustine's post here, along with some skeletal code for a simple service.

My example is a bit more involved, but uses the same ideas as Deja's post. Build a custom module that is in the "Services - services" package and depends on the services package (to the best of my knowledge, these are required, when I tried putting it under a different package, it would not show up on the Services page). Therefore, although I physically put the code under the sites/all/modules/custom/cmxs directory, the package name is "Services - services". Here is the .info file for my module.

1
2
3
4
5
name = cmxs
description = Comment Moderation XMLRPC Services
package = Services - services
dependencies[] = services
core = 6.x

The module code is also quite simple. The hook_service() declares the methods that the service makes available, along with name, input and output parameter name and types, and the names of callback functions each method must call. You can install the module immediately after your hook_service() declarations are done (along with stubs for the callback functions) by going to the Modules (admin/build/modules) page and enabling the new module. The new services will show up on the Services (admin/build/services) page, along with forms to manually test the services.

Here is the complete code for my services module:

  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
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
<?php

define('CMXS_SUCCESS', 0);
define('CMXS_COMMENT_PUBLISHED', 0);
define('CMXS_COMMENT_NOT_PUBLISHED', 1);

/**
 * Implementation of hook_service().
 * Describes the methods that are exposed by this service module.
 */
function cmxs_service() {
  return array (
    // comment_publish
    array (
      '#method' => 'cmxs.comment_publish',
      '#callback' => 'cmxs_comment_publish',
      '#access callback' => 'cmxs_user_access',
      '#args' => array (
        array (
          '#name' => 'cids',
          '#type' => 'string',
          '#description' => t('Comma-separated list of Comment IDs, eg. $cid1,$cid2,...')
        )
      ),
      '#return' => 'int',
      '#help' => t('Publishes the specified comment.')
    ),
    // comment_unpublish
    array (
      '#method' => 'cmxs.comment_unpublish',
      '#callback' => 'cmxs_comment_unpublish',
      '#access callback' => 'cmxs_user_access',
      '#args' => array (
        array (
          '#name' => 'cids',
          '#type' => 'string',
          '#description' => t('Comma-separated list of Comment IDs, eg. $cid1,$cid2,...')
        )
      ),
      '#return' => 'int',
      '#help' => t('Unpublishes the specified comment.')
    ),
    // comment_delete
    array (
      '#method' => 'cmxs.comment_delete',
      '#callback' => 'cmxs_comment_delete',
      '#access callback' => 'cmxs_user_access',
      '#args' => array (
        array (
          '#name' => 'cids',
          '#type' => 'string',
          '#description' => t('Comma-separated list of Comment IDs, eg. $cid1,$cid2,...')
        )
      ),
      '#return' => 'int',
      '#help' => t('Deletes the specified comment.')
    ),
  );
}

/**
 * Implementation of hook_disable().
 * Actions that need to happen when this module is disabled.
 */
function cmxs_disable() {
  cache_clear_all('services:methods', 'cache');
}

/**
 * Implementation of hook_enable().
 * Actions that need to happen when this module is enabled.
 */
function cmxs_enable() {
  cache_clear_all('services:methods', 'cache');
}

/**
 * Custom user access function to short circuit user_access() since
 * we want to bypass Drupal's authentication, since the tool will
 * always send authenticated requests.
 */
function cmxs_user_access() {
  return TRUE;
}

/**
 * Finds the comments corresponding to the cids specified that are in
 * state NOT_PUBLISHED and updates their status to PUBLISHED, then saves 
 * them.
 */
function cmxs_comment_publish($cids) {
  watchdog('cmxs', 'cmxs_comment_publish(cids=' . $cids . ')');
  $comments = _cmxs_find_comments($cids, CMXS_COMMENT_NOT_PUBLISHED);
  foreach ($comments as $comment) {
    $comment->status = CMXS_COMMENT_PUBLISHED;
    comment_save((array) $comment);
    watchdog('cmxs', 'Comment (cid=' . $comment->cid . ') published');
  }
  return CMXS_SUCCESS;
}

/**
 * Finds the comments corresponding to the cids specified that are in
 * state PUBLISHED and updates their status to PUBLISHED, then saves them.
 */
function cmxs_comment_unpublish($cids) {
  watchdog('cmxs', 'cmxs_comment_unpublish(cids=' . $cids . ')');
  $comments = _cmxs_find_comments($cids, CMXS_COMMENT_PUBLISHED);
  foreach ($comments as $comment) {
    $comment->status = CMXS_COMMENT_NOT_PUBLISHED;
    comment_save((array) $comment);
    watchdog('cmxs', 'Comment (cid=' . $comment->cid . ') unpublished');
  }
  return CMXS_SUCCESS;
}

/**
 * Since deleting a comment requires administrator privileges, we cannot
 * call comment_delete($cid) directly (since our service has no privileges).
 * So we unpublish first, and then delete using a direct SQL call.
 */
function cmxs_comment_delete($cids) {
  watchdog('cmxs', 'cmxs_comment_delete(cids=' . $cids . ')');
  $comments = _cmxs_find_comments($cids);
  foreach ($comments as $comment) {
    $comment->status = CMXS_COMMENT_NOT_PUBLISHED;
    comment_save((array) $comment); // UDXI unpublished called here
    _cmxs_delete_comment($comment->cid);
    watchdog('cmxs', 'Comment (cid=' . $comment->cid . ') deleted');
  }
  return CMXS_SUCCESS;
}

/**
 * Given a comma-separated list of CIDs, return a list of comments that
 * correspond to these CIDs. CIDs that don't correspond to a Comment in
 * Drupal are silently ignored. If the optional parameter status is provided
 * only comments with the specified status are returned.
 */
function _cmxs_find_comments($cids, $status = NULL) {
  $comments = array();
  $cid_array = explode(',', $cids);
  if ($cid_array == FALSE) {
    return $comments;
  } else {
    foreach ($cid_array as $cid) {
      $comment = _comment_load($cid);
      if ($comment != NULL) {
        if ($status != NULL) {
          if ($comment->status != $status) {
            continue;
          }
        }
        $comments[] = $comment;
      }
    }
  }
  return $comments;
}

/**
 * Deletes a comment corresponding to the specified cid from the Drupal
 * database. There is no authorization check.
 */
function _cmxs_delete_comment($cid)  {
  $db_result = db_query('DELETE FROM {comments} WHERE cid = %d', $cid);
}

As you can see, the hook_service() is purely declarative. I also have hook_enable() and hook_disable() implementations to make it a bit quicker to develop (changes in method signature only needs a module disable followed by a module enable, no update.php run required).

I also have a custom user_access() function which does nothing. Because I am using non-authenticated XMLRPC requests, and the Drupal comment API for saving the updated comment object, I figured that Drupal would insist (as it should) on an authorized user to do the updates. So the cmxs_user_access() function is there to bypass Drupal's authentication.

I have mentioned before about how impressed I am by Drupal's overall design, and the Services module is no exception. Like the rest of Drupal, it follows the convention over configuration philosophy, and once you understand the convention, building a custom service is really quite simple.

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.

Saturday, March 20, 2010

HTTP Debug Proxy with Twisted

Motivation

Recently, I've been building a few distributed components for an upcoming project. The components talk to each other over XMLRPC. So far, the connectivity is PHP-Java, Java-PHP and Java-Java. On the Java side, I use Apache XMLRPC library to build the clients and servers. The PHP side is basically Drupal's XMLRPC service.

Apache XMLRPC provides Java abstractions at both the client and the server ends, so a programmer only needs to work with Java objects. The library takes care of the generation and parsing of the XML request and response - while this is mostly very convenient, sometimes it is helpful for debugging to see the actual XML request and response. This is what initially prompted me to look for this kind of script, and ultimately build one.

Background

I initially tried netcat with tee, but couldn't make it work the way I wanted it to across both my CentOS and Mac OSX machines. To be honest, I didn't try too hard, because the nc/tee combination outputs to two separate files, and I wanted it in one single output.

There are actually two Python scripts which do about the same thing as the one I built. The HTTP/XMLRPC Debug proxy from myelin came closest to what I wanted, but I would have to hack it a bit to accomodate arbitary source ports. Another proxy was Xavier Defrang's HTTP Debugging Proxy which looked promising, but its HTTP only, and I wanted to use it (in the future) for protocols other than HTTP.

One nice (but non-free) tool in this space is Charles. This would be a good model for someone looking to build an Eclipse plugin :-).

I started out building something with Python sockets based on Gordon McMillans's Python Socket Programming HOWTO, but gave up when I started having problems with blocking in send() and recv() - my knowledge of socket programming wasn't enough to follow him down the rabbit hole of select() calls.

I ultimately settled on using Twisted, based on a rather lively discussion which pointed me to Twisted in the first place. What I liked about Twisted is that its very object oriented and feels almost like Java. A Twisted network component (client or server) is built using a protocol and a factory class, plus an optional "business logic" class. The components are not started directly, they are injected into the Twisted reactor object (similar to a IoC container) and the reactor started.

Twisted does have a steep learning curve, but Twisted Matrix Labs provides excellent documentation. There is also the O'Reilly book by Abe Fettig, which I tried to get but couldn't find at my local Borders bookstore. But the online documentation and tutorial is quite good, you can actually figure Twisted out from there.

Architecture

What I wanted was something that will hook in between the client and the server, and print out the request and response on the console, as shown in the figure below. The dotted blue and red lines represent the normal request and response flows respectively. The idea is to repoint the client at the HTTP proxy, and have the proxy forward the request over to the server application.

As you can see, the HTTP proxy is actually a pipeline of a server component and a client component. The server just listens on the port, spawning off a new client-server pair per each incoming connection. Once the server gets the data, it starts a client that sends the data over to the target (server application), gets back the response, and hands it back to the server, which sends it back to the source (client application) and terminates the connection.

Here's the script to do this all.

  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
#!/usr/local/bin/python
# $Id$
# $Source$
import getopt
import string
import sys

from twisted.internet import protocol
from twisted.internet import reactor

class ConsoleWriter():
  """ Write request (on source port) and response (from target host:port) """
  """ to console. Also holds on to the "latest" data received for output  """
  """ into the proxy server's response stream.                            """

  def write(self, data, type):
    if (data):
      lines = data.split("\n")
      prefix = "<" if type == "request" else ">"
      for line in lines:
        sys.stdout.write("%s %s\n" % (prefix, line))
    else:
      sys.stdout.write("No response from server\n")


class DebugHttpClientProtocol(protocol.Protocol):
  """ Client protocol. Writes out the request to the target HTTP server."""
  """ Response is written to stdout on receipt, and back to the server's"""
  """ transport when the client connection is lost.                     """

  def __init__(self, serverTransport):
    self.serverTransport = serverTransport

  def sendMessage(self, data):
    self.transport.write(data)
  
  def dataReceived(self, data):
    self.data = data
    ConsoleWriter().write(data, "response")
    self.transport.loseConnection()

  def connectionLost(self, reason):
    self.serverTransport.write(self.data)
    self.serverTransport.loseConnection()


class DebugHttpServerProtocol(protocol.Protocol):
  """ Server Protocol. Handles data received from client application.   """
  """ Writes the data to console, then creates a proxy client component """
  """ and sends the data through, then terminates the client and server """
  """ connections.                                                      """

  def dataReceived(self, data):
    self.data = data
    ConsoleWriter().write(self.data, "request")
    client = protocol.ClientCreator(reactor, DebugHttpClientProtocol, self.transport)
    d = client.connectTCP(self.factory.targetHost, self.factory.targetPort)
    d.addCallback(self.forwardToClient, client)

  def forwardToClient(self, client, data):
    client.sendMessage(self.data)


class DebugHttpServerFactory(protocol.ServerFactory):
  """ Server Factory. A holder for the protocol and for user-supplied args """

  protocol = DebugHttpServerProtocol

  def __init__(self, targetHost, targetPort):
    self.targetHost = targetHost
    self.targetPort = targetPort


def usage():
  sys.stdout.write("Usage: %s --help|--source port --target host:port\n"
    % (sys.argv[0]))
  sys.stdout.write("-h|--help: Show this message\n")
  sys.stdout.write("-s|--source: The port on the local host on which this \n")
  sys.stdout.write("             proxy listens\n")
  sys.stdout.write("-t|--target: The host:port which this proxy talks to\n")
  sys.stdout.write("Both -s and -t must be specified. There are no defaults.\n")
  sys.stdout.write("To use this proxy between client app A and server app B,\n")
  sys.stdout.write("point A at this proxy's source port, and point this\n")
  sys.stdout.write("proxy's target host:port at B. The request and response\n")
  sys.stdout.write("data flowing through A and B will be written to stdout for\n")
  sys.stdout.write("your visual pleasure.\n")
  sys.stdout.write("To stop the proxy, press CTRL+C\n")
  sys.exit(2)


def main():
  (opts, args) = getopt.getopt(sys.argv[1:], "s:t:h",
    ["source=", "target=", "help"])
  sourcePort, targetHost, targetPort = None, None, None
  for option, argval in opts:
    if (option in ("-h", "--help")):
      usage()
    if (option in ("-s", "--source")):
      sourcePort = int(argval)
    if (option in ("-t", "--target")):
      (targetHost, targetPort) = string.split(argval, ":")
  # remember no defaults?
  if (not(sourcePort and targetHost and targetPort)):
    usage()
  # start twisted reactor
  reactor.listenTCP(sourcePort,
    DebugHttpServerFactory(targetHost, int(targetPort)))
  reactor.run()


if __name__ == "__main__":
  main()

The server is defined using the DebugHttpServerProtocol and DebugHttpServerFactory, and the client is defined using the DebugHttpClientProtocol. The ConsoleWriter just writes a formatted request and response data to the console.

When a request comes in from the client application, it is sent to DebugHttpServerProtocol.dataReceived, where the data is first written out to the console. A client object is then created using ClientCreator, which takes the DebugHttpClientProtocol and a reference to the server's transport object. The client then connects to the target host and port, and a callback added for the client to relay the request over to the target server once the client connects.

Once the client connects, the callback is triggered, which relays the request across to the target host. The response from the target host is captured by DebugHttpClientProtocol.dataReceived(), which writes the data to the console, then loses the connection. The connection lost event is captured by the connectionLost() method, which writes the response back to the caller and closes the connection.

Testing/Usage

To test the proxy, I started up the proxy to listen to port 1234 and forward to my test Drupal instance running on port 80. I then repointed the service URL in my JUnit test from http://localhost/services/xmlrpc to http://localhost:1234/services/xmlrpc. The JUnit test sends a comment to Drupal's XMLRPC comment.save service.

1
sujit@cyclone:network$ ./httpspy.py -s 1234 -t localhost:80

I then run my JUnit test from another console. On the console where I started httpspy.py, I see the following (the "< " and "> " signifies request and response).

 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
< POST /services/xmlrpc HTTP/1.1
< Content-Type: text/xml
< User-Agent: Apache XML RPC 3.0 (Jakarta Commons httpclient Transport)
< Host: localhost:1234
< Content-Length: 604
< 
< <?xml version="1.0" encoding="UTF-8"?><methodCall><methodName>comment.save
</methodName><params><param><value><struct><member><name>mail</name><value>f
oo@bar.com</value></member><member><name>subject</name><value>my stupid subj
ect (1269113982563)</value></member><member><name>nid</name><value><i4>8</i4
></value></member><member><name>name</name><value>godzilla</value></member><
member><name>comment</name><value>a test comment entry at 1269113982563 ms s
ince epoch</value></member><member><name>homepage</name><value>http://homesw
eethome.us</value></member></struct></value></param></params></methodCall>
<
<
> HTTP/1.1 200 OK
> Date: Sat, 20 Mar 2010 19:39:42 GMT
> Server: Apache/2.0.63 (Unix) PHP/5.2.11 DAV/2
> X-Powered-By: PHP/5.2.11
> Set-Cookie: SESS421aa90e079fa326b6494f812ad13e79=da32e0283f634a62937761a01c
0fb91d; expires=Mon, 12-Apr-2010 23:13:02 GMT; path=/
> Expires: Sun, 19 Nov 1978 05:00:00 GMT
> Last-Modified: Sat, 20 Mar 2010 19:39:42 GMT
> Cache-Control: store, no-cache, must-revalidate
> Cache-Control: post-check=0, pre-check=0
> Connection: close
> Content-Length: 142
> Content-Type: text/xml
> 
> <?xml version="1.0"?>
> 
> <methodResponse>
>   <params>
>   <param>
>     <value><string>10</string></value>
>   </param>
>   </params>
> </methodResponse>
> 
> 

As you can see, there is still a bit of work needed to beautify the raw request if its XML (probably by parsing out the Content-Type header), but the script is usable right now, so that will be something I will do in the future.

Another use case I have tried is to put it between a client HTTP GET call and a Drupal webpage. I still need to test this stuff extensively through various use-cases - if I find bugs in the code, I will update it here. Meanwhile, if you find bugs or strange behavior (or even better, bugs with fixes :-)), would really appreciate knowing.

Update 2010-04-04: The code here breaks down when (a) the request/response payload is large and/or (b) servers are slow. I am trying to fix the code, will post the updated code when done.

Update 2010-12: Because of its unreliability, I basically abandoned the script in favor of this less general solution. Mikedominice was kind enough to prod me into looking at this again. As a result, I ended up rewriting most of the script, and it seems to work quite well now. The updated code is posted above.