10:01 a.m.
Administrator Administrator [http://community.jboss.org/people/admin] modified the
document:
"Logging Contextual Information"
To view the document, visit: http://community.jboss.org/docs/DOC-12847
--------------------------------------------------------------
h4. 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.
h4. 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
http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/MDC.html 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!
h4. 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.
--------------------------------------------------------------
Comment by going to Community
[http://community.jboss.org/docs/DOC-12847]
Create a new document in EJB3 at Community
[http://community.jboss.org/choose-container!input.jspa?contentType=102&am...]