Organize Your Logs With a Cool Java EE 6 Trick

Picture this -- it's 9:00 Friday night, and you've just gotten a phone call asking why the hell a key part of your system is down... after verifying that something's definitely busted, you open up the only resource you have -- your system logs... it doesn't take you long to find some exceptions, but they don't tell you much of the story... pretty soon, you realize there are 5 or 6 different errors being thrown, plus messages from areas of the system that appear to be working fine... to boot, it's the middle of your busiest time of the year, which means that you may have a few thousand users on the system at this very moment... yikes -- how the heck do you make heads or tails of this mess?

Logging -- no longer an afterthought

Ok, so four or five days later, when you finally sort out your issue, it's time to make things better before that happens again... it's time to actually put some thought behind your logging practices... first stop -- learn how to log, and put some standards in place! I'm not going to elaborate on the details of that article, because I think the author does a fine job... frankly, I was hooked when he defined the logs as a 'secondary interface' of your system -- your support staff (i.e. -- you) can't see what your customers are looking at in their browsers, so you need to make damn sure that you're providing enough information in your logs for you to understand what's going on!

Let's be real, though -- the traffic on your system hasn't gone down any since that fateful Friday (luckily), and you don't have the time to rework all of the logging in your system... there has to be a way to put some incremental improvements in here that will make your life easier the next time things catch fire, even if that's tomorrow...

Adding the Context without the Pain -- or a single change to your core code

Ultimately, you were able to make some sense out of that catastrophe by realizing your logging framework was providing you with a subtle piece of context -- the thread name... seems innocuous, but in most Servlet containers, it's enough to identify that each line in the log belonged to a particular thread -- or request... It's not perfect though -- you didn't have any messages in your logs that stated "Starting GET request for /shoppingcart/buySomething.html", so you couldn't tell exactly where each request started and ended... luckily, with Java EE 6 and a good logging framework, it's not hard to get there...

Before I dig in, though, let's get acquainted with the Mapped Diagnostics Context, or MDC -- hopefully, your logging system supports it (log4j does, so most folks will be covered)... MDC provides the ability to attach pieces of context to the thread of execution you're in, and allows for you to add this info on all log messages...

The following example shows a piece of code that uses the MDC in SLF4J -- a logging framework much like the Apache Commons Logging framework that can provide a single interface to multiple logging run-times -- excellent for building libraries when you don't want to impose a logging system on your users... Anyway, on to the show:

public class RequestLoggingContext implements Filter {
  private static final String SESSION_CONTEXT = "session-context";

  ...

  @Override
  public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException {
      if(req instanceof HttpServletRequest) {
          HttpServletRequest httpRequest = (HttpServletRequest)req;
          session = httpRequest.getSession(false);
 
          if(session != null)
              MDC.put(SESSION_CONTEXT, session.getId());
      }

      chain.doFilter(req, resp);

      if(session != null) {
          MDC.remove(SESSION_CONTEXT);
      }
  }
}

Pretty simple -- two static methods on the 'MDC' class -- 'put' and 'remove'... while I'm not a particular fan of the static API, this is about as simple as it gets (incidentaly, this is the only 'unfortunate' use of static methods that I have seen in SLF4J -- they use the standard method of having static factory classes, but that at least makes sense, and has precedent)... so what the heck did this do? Well, we now have the ability to refer to that "session-context" as a part of our logging 'Pattern', using the "%X{session-context}" flag -- like so:

<configuration>

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
  <pattern>%d{HH:mm:ss.SSS} [session-context=%X{session-context}][%thread] %-5level %logger{36} - %msg%n</pattern>
</layout>
</appender>

<root level="debug">
<appender-ref ref="STDOUT">
</root>
</configuration>

BTW, that is not a log4j config file -- it's a Logback config... Logback is the 'native' implementation of the SLF4J library that's written by the same folks who brought you Log4J -- kind of a 'take two', if you will... anyway, it should be obvious that it's driven heavily from Log4J's configuration :)

So we have now added context to our logging system -- and all without disturbing a single line of code in our existing system... but wait, there's more!

The Trick

One of the interesting additions to Java EE 6 is the combination of Servlet Annotations, and web fragments -- this allows library authors to self configure the use of their library, where previously the end user would need to make additions to the web.xml... a great use of Convention Over Configuration, and very powerful, indeed!

So let's take the above code sample and expand it to include a randomly generated context id for each HttpRequest, and some basic log messages to delineate the start and end of every request:

@WebFilter("/*")
@WebListener
public class RequestLoggingContext implements Filter, HttpSessionListener {
  private static final String REQUEST_CONTEXT = "request-context";
  private static final String SESSION_CONTEXT = "session-context";

  private Logger log = LoggerFactory.getLogger(RequestLoggingContext.class);

  @Inject
  private ContextGenerator contextGenerator;

  @Override
  public void init(FilterConfig fc) throws ServletException {
  }

  @Override
  public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException {
      MDC.put(REQUEST_CONTEXT, contextGenerator.generateContextId());
    
      StringBuilder msg = new StringBuilder();
      if(req instanceof HttpServletRequest) {
          HttpServletRequest httpRequest = (HttpServletRequest)req;
          HttpSession session = httpRequest.getSession(false);

          if(session != null)
              MDC.put(SESSION_CONTEXT, session.getId());

          //Build Detailed Message
          msg.append("Starting ");
          msg.append(httpRequest.getMethod());
          msg.append(" request for URL '");
          msg.append(httpRequest.getRequestURL());
          if(httpRequest.getMethod().equalsIgnoreCase("get") && httpRequest.getQueryString() != null) {
              msg.append('?');
              msg.append(httpRequest.getQueryString());
          }
          msg.append("'.");
      }

      if(msg.length() == 0) {
          msg.append("Starting new request for Server '");
          msg.append(req.getScheme());
          msg.append(":\\");
          msg.append(req.getServerName());
          msg.append(':');
          msg.append(req.getServerPort());
          msg.append('/');
      }

      log.info(msg.toString());
      long startTime = System.currentTimeMillis();
    
      chain.doFilter(req, resp);

      msg.setLength(0);
      msg.append("Request processing complete.  Time Elapsed -- ");
      msg.append(System.currentTimeMillis() - startTime);
      msg.append(" ms.");
      log.info(msg.toString());

      if(((HttpServletRequest)req).getSession(false) != null) {
          MDC.remove(SESSION_CONTEXT);
      }
      MDC.remove(REQUEST_CONTEXT);
  }

  @Override
  public void destroy() {
  }

  @Override
  public void sessionCreated(HttpSessionEvent hse) {
      MDC.put(SESSION_CONTEXT, hse.getSession().getId());
  }

  @Override
  public void sessionDestroyed(HttpSessionEvent hse) {      
  }
}

All that's left is to literally throw that in its' own .jar file, put it in your WEB-INF/lib folder, and add either or both of the 'context' keys to your logging config and presto -- you have logging context! (I have omitted the definition of the ContextGenerator class for brevity -- it just generates a random string) Now your logs will look something like this:

INFO: 00:02:11.140 [request-context=sonqc52zbqia][http-thread-pool-8080-(1)] INFO  c.m.l.support.RequestLoggingContext - Starting GET request for URL 'http://localhost:8080/Test/'.
INFO: 00:02:12.156 [request-context=sonqc52zbqia][http-thread-pool-8080-(1)] INFO  c.m.l.i.TimingLogInterceptor - Executing com.test.facade.LoadHomeFacade.loadData
INFO: 00:02:12.156 [request-context=sonqc52zbqia][http-thread-pool-8080-(1)] INFO  c.m.l.i.TimingLogInterceptor - Doing something interesting.
INFO: 00:10:36.250 [request-context=sonqc52zbqia][http-thread-pool-8080-(1)] INFO  c.m.l.support.RequestLoggingContext - Request processing complete.  Time Elapsed -- 719 ms.

So now, without touching a single line of existing code or modifying a single class, we can now clearly associate any logging message in our system with other messages generated on that request, and we have clear delineation of where each request begins and ends, and how long it took to execute... pretty damn sweet! So now when your system blows up next Friday night, you'll be a bit more prepared to sort things out before the weekend is over! (just don't throw out those scripts that sort based on 'request-context'!)

Final Word

Final word? I guess that means there's more -- three things, actually... first -- there is absolutely nothing preventing you from putting the above in place if you're on an earlier version of the Java EE spec (and let's face it -- that's pretty much all of us!)... The only thing you lose is the self configuration, so you'll need to add the appropriate <filter> and <filter-mapping> elements to your web.xml

Second, if you're on Java EE 6 (wow, that was fast!), and your application already makes use of Servlet Filters, whether they're 'self configured' or not, you may need to do some configuration in your web.xml to provide an explicit ordering -- note that this is not strictly required, although it is probably a good idea :)...

And finally, I mentioned above that Log4J users were in luck when it came to supporting MDC... unfortunately, the JDK Logging API doesn't support MDC (come on! Why not! Am I the only one who seems to think they haven't advanced this API in the last five years!?) -- those users aren't entirely out of luck, though... there is a way to 'subclass' the JDK Logger and add logging info to the front or end of any logging message, although it's tricky -- unfortunately, I don't have this code handy anymore, but perhaps I'll sit down and figure it out again if I'm so inclined one day (of course, if I get feedback to do this, it might make me more inclined :) )

Now don't forget to get back and add better logging messages to your code!

M