Introduction

Informative, granular log statements are essential to any server-side application.  JBoss relies on the popular Log4J framework to bring this capability to users.  However, typical logging statments may not always contain enough information to truly understand what's happening.

Almost everything that happens within the scope of a Java EE service invocation -- whether it be Servlet, EJB or anything else -- has interesting context that can be useful to someone reading the log file.  We might like to know the JTA Transaction ID during an EJB invocation or the name of the current user during a Servlet request.  This is quite simple using Log4J, but in a busy application, you might end up with hundreds of log lines every second and have no way to correlate one flow through the application from another.

Contextual Logging with Log4J

Logging something trivial from an EJB such as the number of rows returned by a query may be useful, but it would be far better if we knew what context it happened in.  Most EJBs execute in within a JTA Transaction so why not add that to the log?  It's relatively easy to log Transaction information at the beginning of a method:

UserTransaction utx = (UserTransaction) new InitialContext().lookup("java:/UserTransaction");
log.debug(utx.toString());

But what about container managed transactions?  What if we don't want to pollute our business code with endless logging details?

Log4J includes a very useful feature called Mapped Diagnostic Contexts, or MDC for short.  MDC gives us a way to add contextual information orthogonally to the code that's actually logging information.  The MDC class contains static methods used to put and remove key/value pairs which can then be accessed by the Appender through named tokens.

We can manage information in the MDC like such:

MDC.put("name", "value");
...
log.debug("Hello!");
...
MDC.remove("name");

In the above snippet, we have the option to output the value of the "name" information in the logs.  To do this, we modify our conversion pattern using the %X token, specifying "name" as a parameter.  By default, the Log4J configuration file resides in $JBOSS_HOME/server/<config>/conf/jboss-log4j.xml.

<layout class="org.apache.log4j.PatternLayout">
     <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%X{name}] [%c{1}] %m%n"/>
</layout>

In this example, the [%X{name}] token will result in a log line similar to this:

15:33:59,694 DEBUG  [value] [MyClass] Hello!

Logging Transaction ID for EJB3 Calls

Now let's do something useful with this.  I mentioned earlier that it would be interesting to log the JTA Transaction ID for EJB calls.  I also showed that we can do this orthogonally to our business code so as not to pollute every method with nasty references to transaction APIs.  What we need now is a place to add the Transaction ID to the MDC before a call begins and remove it after it returns.  For this we'll use a standard EJB3 Interceptor.  Here's an example implementation:

public class LogContextInterceptor {
    private static final String TX_UID_KEY = "txid";
    @Resource(mappedName="java:/TransactionManager") private TransactionManager tm;    
    @AroundInvoke
    public Object intercept(InvocationContext ctx) throws Exception {
        TransactionImple tx = (TransactionImple) tm.getTransaction();
        MDC.put(TX_UID_KEY, tx.get_uid());
        try {
            return ctx.proceed();
        } finally {
            MDC.remove(TX_UID_KEY);
        }
    }
}

Note that this implementation uses the JBoss specific Arjuna TransactionImple so is isn't portable.  This class can be compiled and shipped as part of your EJB Jar.  By itself, however, it won't intercept anything!  Next we need a deployment descriptor that specifies that this Interceptor be appled to every method.  Here's an example ejb-jar.xml:

<?xml version="1.0" encoding="UTF-8"?>
<ejb-jar version="3.0" xmlns="http://java.sun.com/xml/ns/javaee"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/ejb-jar_3_0.xsd">
    <assembly-descriptor>
        <interceptor-binding>
            <ejb-name>*</ejb-name>
            <interceptor-class>org.jboss.example.logging.LogContextInterceptor</interceptor-class>
        </interceptor-binding>
    </assembly-descriptor>
</ejb-jar>

Don't forget to add the "txid" token to Log4J's ConversionPattern:

<layout class="org.apache.log4j.PatternLayout">
     <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%X{txid}] [%c{1}] %m%n"/>
</layout>

Now let's look at the output from a basic SLSB invocation:

16:39:10,184 INFO  [7f000001:c958:48fe3ca7:124] [TransactionalServiceBean] Echoing string Hello World!

That's it!  Now you've got something to tie log lines to or use as a grep token.  This general pattern can be used to output anything imaginable.