Thursday, 21 November 2013

When running a webapplication in production you need the ability to retrace all actions an user has done.
Especially is this interesting when an error/exception occured. In this article you will learn to add the session-id and the username of the logged in user to every single line logged into the logfile.

Log4j's MDC (Mapped Diagnostic Context)

Log4j offers a Thread-local Key-Value-Store to store information for the lifetime of a request. It is called MDC (Mapped Diagnostic Context) (see
http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/MDC.html).Values stored in this context can be referenced over their key in a log4j-configuration to be used in the output format.

Store Session-ID and username using a Servlet-Filter

A webapp filter has access to the request and the related session. We implement a filter to retrieve the session-id and store the value in the MDC:
com.pairoo.frontend.webapp.filter

import java.io.IOException;

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 javax.servlet.http.HttpSession;

import org.slf4j.MDC;

public class LogSessionIdFilter implements Filter {
  @Override
  public void destroy() {
  }

  @Override
  public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException,
    ServletException {
    HttpServletRequest httpRequest = (HttpServletRequest) request;
    HttpSession session = httpRequest.getSession();
    if (session != null) {
      MDC.put("sessionID", session.getId());
    }
    chain.doFilter(request, response);
  }

  @Override
  public void init(FilterConfig arg0) throws ServletException {
  }
}
As long as there is no session, the MDC will have "sessionID" not set. The output (reference to the sessionID-value) in the log-line will be emtpy.
The same way other informations (like the username) can be retrieved in the "doFilter" method and be stored under a key. As this is specific for every webapp, you should debug into the session to find out how to get more session-specific objects (like the authenticated user and his username).

Register the filter in the web.xml

Add this filter and his mapping to your web.xml (note: if it depends on other filters, locate it after them to be sure that they are executed before):
<filter>
  <filter-name>logSessionIdFilter</filter-name>
  <filter-class>com.pairoo.frontend.webapp.filter.LogSessionIdFilter</filter-class>
</filter>
...
<filter-mapping>
  <filter-name>logSessionIdFilter</filter-name>
  <url-pattern>/*</url-pattern>
</filter-mapping>
    
<filter-mapping>
  <filter-name>wicketfilter</filter-name>
  <url-pattern>/*</url-pattern>
</filter-mapping> 

Add Session-ID value to Log-Format

You can reference MDC values by their key (e.g. "sessionID") with "%X{key}" (e.g. "%X{sessionID}") and insert at any location inside the ConversionPattern:
<appender name="FILE" class="org.apache.log4j.rolling.RollingFileAppender">
  ...
  <layout class="org.apache.log4j.PatternLayout">
    <param name="ConversionPattern" value="[%d{ISO8601}] %5p [%X{sessionID}] [%t][%x] %c.%M - %m%n" />
  </layout>
</appender>
If you just want to show let's say the first 5 characters of the session-Id you can shorten it like this (using "%.5", see article about logging here):
...
    <param name="ConversionPattern" value="[%d{ISO8601} %-5p] [%X{username} / %.5X{sessionID}...] %-25c{1} (%-8t) > %m%n"/>
...
The example additionally added an example for logging the current username (that certainly has to be set in the MDC before).

Example-Output

The above ConversionPattern logs the session-id after the logging level (here: INFO) in brackets. It is not only logged in webapp-layer, but in all log outputs of all layers. So it is easy (using grep for one session id) to find out, what happened for one user. If you log out the username (like we did) you get one line that links the username to the session-id:
[2013-11-21 21:59:03,068]  INFO [jk4n0ulydj7a1onb4lig7fe8a] [9413464@qtp-9651822-0][] com.pairoo.business.services.impl.UserAccountServiceImpl.login - tries to login: username = adam
[2013-11-21 21:59:03,095]  INFO [jk4n0ulydj7a1onb4lig7fe8a] [9413464@qtp-9651822-0][] com.pairoo.frontend.webapp.wicket.WicketWebSession.login - user 'adam' logged in
That's it!

5 comments:

  1. Can it log multiple users logging in at same time? Can mdc handle multiple threads st and time?

    ReplyDelete
  2. Mulltiple sessions sharing the same latest session number right? how to handle this issue?

    ReplyDelete
  3. every session has a different id. it is stored per thread / request. the session number is individual for every session / no sharing.

    ReplyDelete
  4. This comment has been removed by the author.

    ReplyDelete
  5. If there are multiple threads after login thread.Will this detail be accessible in those thread also??
    Thank you.

    ReplyDelete