Tracing Servlet Requests

2012-03-25 20:24UTC

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.