Tracing Servlet Requests
Tracing through Servlet-based web application log files isn't always as convenient as one may hope. Sure, when using Tomcat, we may rely on the thread names (such as http-8080-2
), but sometimes they seem to bleed into each other resulting in a difficult structure to grep
. Compounding this, an observer of the log requires an understanding of the application's flow of execution. For quite a few years, and with great success, I have been using a simple solution combining a Servlet Filter and MDC. The source follows.
package ca.burnison.commons.web.filter;
import java.io.IOException;
import java.util.concurrent.atomic.AtomicInteger;
import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
/**
* A simple Filter that maps an atomicly increasing "request ID" to the
* logging provider's Mapped Diagnostic Context.
* <br />
* This filter assumes the incoming ServletRequest is an instance of
* HttpServletRequest.
* <br />
* While this filter can be used across multiple nodes, the request ID will
* be duplicated on each node. If this is not acceptable, it is possible to
* override/refactor {@link #getNextRequestId()} to generate a UUID or pull
* a value from a shared data source.
*
* @author Richard Burnison
*/
public class MdcRequestIdFilter implements Filter
{
private static final Logger logger = LoggerFactory.getLogger(MdcRequestIdFilter.class);
private static final String KEY_REQUEST_ID = "requestId";
private final AtomicInteger volatileRequestId = new AtomicInteger(1);
@Override
public void init(final FilterConfig config)
{
}
@Override
public void destroy()
{
}
@Override
public void doFilter(final ServletRequest request, final ServletResponse response, final FilterChain chain) throws IOException, ServletException
{
final HttpServletRequest httpRequest = (HttpServletRequest)request;
final String requestId = this.getNextRequestId();
final String requestedUri = httpRequest.getRequestURI();
final String requestingIp = httpRequest.getRemoteAddr();
try{
MDC.put(KEY_REQUEST_ID, requestId);
logger.info("Beginning request {} for {}. Requested URI is {}.", new Object[]{requestId, requestingIp, requestedUri});
chain.doFilter(request, response);
} finally {
logger.info("Completing request {}.", requestId);
MDC.remove(KEY_REQUEST_ID);
}
}
protected String getNextRequestId()
{
final int currentId = volatileRequestId.getAndIncrement()
return Integer.toString(currentId);
}
}
Assuming you are using a logging implementation that supports MDC and you have correctly configured your appender to print it, the results will be similar to the following.
INFO com.example.MdcRequestIdFilter{{requestId,1}} - Beginning request 1 for 10.2.2.100. Requested URI is /foo.
INFO com.example.Stuff{{requestId,1}} - Doing stuff.
INFO com.example.MoreStuff{{requestId,1}} - Doing more stuff.
INFO com.example.MdcRequestIdFilter{{requestId,1}} - Completing request 1.
Coupled with an MDC-binding of a session identifier, log tracing becomes much easier.