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.