Logging HTTP Requests & Jersey
For the record, I've been very impressed with Jersey. We recently unplugged a RESTful framework from our application, which I designed and wrote a couple of years ago and slotting Jersey in was simple and straightforward and it's good to be using a JSR rather than something proprietary. I'm happy with the annotation approach and the ease at which it integrates nicely with Spring and JAXB – I was also pleased to discover that support for WADL is out of the box. I've always liked WADL and was always full of intention to add support for WADL to my home-grown REST framework but now I don't need to bother J
One thing I miss from my old framework though is the verbose logging of the HTTP requests and execution time, which when you are working on system integration and other developers are consuming your services, this level of debugging is very very useful. Unfortunately I lost this behaviour when I implemented Jersey and have been keen to get it back. So in a moment of frustration when trying to resolve an issue one of my customers had and finding it very difficult to understand the exact request she had sent in I decided to put logging back in.
I didn't want to start extending the Spring/Jersey Servlet so I decided to knock up a HTTP Servlet Filter to do the job for me. I'd not written one of these before and so with a little Google Coding have developed this class which does the trick for me. It's not specific to Jersey in any way, but seems to work for me. Under the Java code I've also put the web.xml definition which hooks this into the Jersey servlet:
package com.talis.soa.jersey;
import java.io.BufferedReader;
import java.io.ByteArrayInputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.InputStream;
import java.io.InputStreamReader;
import java.util.Enumeration;
import java.util.HashMap;
import java.util.Map;
import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletInputStream;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletRequestWrapper;
import javax.servlet.http.HttpServletResponse;
import org.apache.log4j.Logger;
/**
* Jersey doesn't log it's requests/responses and so this filter intercepts
* Jersey to provide this behaviour.
*
* In order to log the request body this class also caches the input stream of the request
* so that the bytes are available to the next process in the filter chain.
*
* @author Andy Latham
* @date 25th February 2009
*/
public class JerseyServletLoggingFilter implements Filter {
private static final Logger logger = Logger.getLogger(JerseyServletLoggingFilter.class);
@Override
public void init(FilterConfig filterConfig) throws ServletException {
// This is doing simple logging and so doesn't need to
// use or keep a reference to the filter config...
}
@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse,
FilterChain chain) throws IOException, ServletException
{
HttpServletRequest httpServletRequest = (HttpServletRequest)servletRequest;
HttpServletResponse httpServletResponse = (HttpServletResponse)servletResponse;
long startTime = System.currentTimeMillis();
Map<String, String> requestMap = this.getTypesafeRequestMap(httpServletRequest);
BufferedRequestWrapper bufferedReqest = new BufferedRequestWrapper(httpServletRequest);
final String logMessage = new StringBuilder("REST Request - ")
.append("[HTTP METHOD:")
.append(httpServletRequest.getMethod())
.append("] [PATH INFO:")
.append(httpServletRequest.getPathInfo())
.append("] [REQUEST PARAMETERS:")
.append(requestMap)
.append("] [REQUEST BODY:")
.append(bufferedReqest.getRequestBody())
.append("] [REMOTE ADDRESS:")
.append(httpServletRequest.getRemoteAddr())
.append("]")
.toString();
StringBuilder initLogMessage = new StringBuilder(logMessage).append(" - is being processed... ");
logger.info(initLogMessage);
chain.doFilter (bufferedReqest, httpServletResponse);
long endTime = System.currentTimeMillis();
double totalTime = endTime - startTime;
StringBuilder successLogMessage = new StringBuilder(logMessage).append(" - processed succesfully in ").append(totalTime).append("ms ");
logger.info(successLogMessage);
}
private Map<String, String> getTypesafeRequestMap(HttpServletRequest request) {
Map<String, String> typesafeRequestMap = new HashMap<String, String>();
Enumeration<?> requestParamNames = request.getParameterNames();
while (requestParamNames.hasMoreElements()) {
String requestParamName = (String)requestParamNames.nextElement();
String requestParamValue = request.getParameter(requestParamName);
typesafeRequestMap.put(requestParamName, requestParamValue);
}
return typesafeRequestMap;
}
@Override
public void destroy() {
logger.info("REST Web Services Servlet Filter is now shutting down due to container shutdown.");
}
private static final class BufferedRequestWrapper extends HttpServletRequestWrapper {
private ByteArrayInputStream bais = null;
private ByteArrayOutputStream baos = null;
private BufferedServletInputStream bsis = null;
private byte[] buffer = null;
public BufferedRequestWrapper(HttpServletRequest req)
throws IOException {
super(req);
// Read InputStream and store its content in a buffer.
InputStream is = req.getInputStream();
this.baos = new ByteArrayOutputStream();
byte buf[] = new byte[1024];
int letti;
while ((letti = is.read(buf)) > 0)
{
this.baos.write(buf, 0, letti);
}
this.buffer = this.baos.toByteArray();
}
@Override
public ServletInputStream getInputStream()
{
// Generate a new InputStream by stored buffer
this.bais = new ByteArrayInputStream(this.buffer);
// Istantiate a subclass of ServletInputStream
// (Only ServletInputStream or subclasses of it are accepted by
// the servlet engine!)
this.bsis = new BufferedServletInputStream(this.bais);
return this.bsis;
}
String getRequestBody() throws IOException
{
BufferedReader reader = new BufferedReader(new InputStreamReader(this.getInputStream()));
String line = null;
StringBuilder inputBuffer = new StringBuilder();
do {
line = reader.readLine();
if (null != line) {
inputBuffer.append(line.trim());
}
} while (line != null);
reader.close();
return inputBuffer.toString().trim();
}
}
/*
* Subclass of ServletInputStream needed by the servlet engine. All
* inputStream methods are wrapped and are delegated to the
* ByteArrayInputStream (obtained as constructor parameter)!
*/
private static final class BufferedServletInputStream extends ServletInputStream {
private ByteArrayInputStream bais;
public BufferedServletInputStream(ByteArrayInputStream bais) {
this.bais = bais;
}
@Override
public int available() {
return this.bais.available();
}
@Override
public int read() {
return this.bais.read();
}
@Override
public int read(byte[] buf, int off, int len) {
return this.bais.read(buf, off, len);
}
}
}
And the web.xml snippet:
<filter>
<filter-name>JerseyServletLoggingFilter</filter-name>
<filter-class>com.talis.soa.jersey.JerseyServletLoggingFilter</filter-class>
</filter>
<filter-mapping>
<filter-name>JerseyServletLoggingFilter</filter-name>
<url-pattern>/*</url-pattern>
</filter-mapping>
<servlet>
<servlet-name>Jersey Spring Web Application</servlet-name>
<servlet-class>
com.sun.jersey.spi.spring.container.servlet.SpringServlet
</servlet-class>
<load-on-startup>10</load-on-startup>
</servlet>
<servlet-mapping>
<servlet-name>Jersey Spring Web Application</servlet-name>
<url-pattern>/*</url-pattern>
</servlet-mapping>
posted by Andy Latham at 12:12 PM
2 comments
