Log4j diagnostic contexts

You have a cool web application with a lot of logging information. Each action the user performed logs a suitable amount of traces in the way of DEBUG, INFO, ERROR, etc.. But there are a lot of concurrent users performing the same actions and their logs messages are interleaved witch each other.

Of course you have the thread name in order to track down one specific user, but threads are poolled and so the names are. Multiple users may, at one time or another, pick the same thread and so the mess will continue.

If you are using Log4j there are two useful features called nested diagnostic contexts and mapped diagnostic contexts. In esence, Log4j allows you to insert arbitrary context information at some point in the thread execution and all subsequent logging instructions will retrieve and print that information.
In this link there are more info about thase two features.

In order to apply this in your application, one possible option would be to declare a Servlet Filter which populate the context. A useful context information could be:

• A unique identifier
• The user name, if any.
• The user IP

For example, this is my ContextInfoLogFilter (I used the OncePerRequestFilter of Spring):

import java.io.IOException;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.apache.log4j.MDC;
import org.springframework.security.core.context.SecurityContextHolder;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;

@Component("log4ContextFilter")
public class ContextInfoLogFilter extends OncePerRequestFilter {

 @Override
 protected boolean shouldNotFilter(HttpServletRequest request) throws ServletException {
  return request.getServletPath().startsWith("/resources/");   
 }
 
 @Override
 protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
  try {
   MDC.put("key", System.currentTimeMillis());
   MDC.put("usuario", getUsuario(request));
   MDC.put("ip", getIP(request));     
   filterChain.doFilter(request, response);
  }
  finally {
   MDC.clear();
  }
 }
 
 private String getUsuario(HttpServletRequest request) {
  if (SecurityContextHolder.getContext() != null 
    && SecurityContextHolder.getContext().getAuthentication() != null) {
   return SecurityContextHolder.getContext().getAuthentication().getName();
  }
  else if (request.getUserPrincipal() != null) {
   return request.getUserPrincipal().getName();
  }
  return "ANONYMOUS";
 }

 private String getIP(HttpServletRequest request) {
  final String ipAddress = request.getHeader("X-FORWARDED-FOR");
  if (ipAddress == null) {
      return request.getRemoteAddr();
  }
  return ipAddress;
 }
}

Remember to declare this filter after Spring Security Filter Chain, in order to have the security context.

(... Other Filters ...)
<filter>
 <filter-name>log4jContext</filter-name>
 <filter-class>org.springframework.web.filter.DelegatingFilterProxy</filter-class>
 <init-param>
  <param-name>targetBeanName</param-name>
  <param-value>log4ContextFilter</param-value>
 </init-param>
</filter>

<filter-mapping>
 <filter-name>log4jContext</filter-name>
 <url-pattern>/*</url-pattern>
</filter-mapping>

Finally, in your log config file you must configure the log pattern with the %X{property} conversion character. In my case I used "[%X{key}: %X{usuario} - %X{ip}]", which will extract the "key", "usuario" and "ip" properties from the mapped context.
You can check all conversio characters in htps://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html.

Fo example, this would be  my log4j.xml file:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

 <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
  <layout class="org.apache.log4j.PatternLayout">
   <param name="ConversionPattern" value="%d{ISO8601} %-5p [%c] (%t) [%X{key}: %X{usuario} - %X{ip}] %m%n" />
  </layout>
 </appender>

 <appender name="LOG" class="org.apache.log4j.RollingFileAppender">
  <param name="File" value="${jboss.server.log.dir}/seguridad-presentacion.log" />
  <param name="MaxFileSize" value="10MB" />
  <param name="MaxBackupIndex" value="10" />
  <layout class="org.apache.log4j.PatternLayout">
   <param name="ConversionPattern" value="%d{ISO8601} %-5p [%c] (%t) [%X{key}: %X{usuario} - %X{ip}] %m%n" />
  </layout>
 </appender>

 (... Other log stuff ...)

 <root>
  <level value="INFO" />
  <appender-ref ref="CONSOLE" />
  <appender-ref ref="LOG" />
 </root>

</log4j:configuration>

Also, you need to keep in mind that a web application may has multiple entry points, not just a common HTTP request message. For example:

• If the entry point is a web service you can use an interceptor to create the log context. In CXF you have this.
• If the entry point is a EJB you can also use an interceptor as this or simply receive some information as a method parameter.