<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0 Transitional//EN">
<html>
<body link="#355491" alink="#4262a1" vlink="#355491" style="background: #e2e2e2; margin: 0; padding: 20px;">
<div>
<table cellpadding="0" bgcolor="#FFFFFF" border="0" cellspacing="0" style="border: 1px solid #dadada; margin-bottom: 30px; width: 100%; -moz-border-radius: 6px; -webkit-border-radius: 6px;">
<tbody>
<tr>
<td>
<table border="0" cellpadding="0" cellspacing="0" bgcolor="#FFFFFF" style="border: solid 2px #ccc; background: #dadada; width: 100%; -moz-border-radius: 6px; -webkit-border-radius: 6px;">
<tbody>
<tr>
<td bgcolor="#000000" valign="middle" height="58px" style="border-bottom: 1px solid #ccc; padding: 20px; -moz-border-radius-topleft: 3px; -moz-border-radius-topright: 3px; -webkit-border-top-right-radius: 5px; -webkit-border-top-left-radius: 5px;">
<h1 style="color: #333333; font: bold 22px Arial, Helvetica, sans-serif; margin: 0; display: block !important;">
<!-- To have a header image/logo replace the name below with your img tag -->
<!-- Email clients will render the images when the message is read so any image -->
<!-- must be made available on a public server, so that all recipients can load the image. -->
<a href="http://community.jboss.org/index.jspa" style="text-decoration: none; color: #E1E1E1">JBoss Community</a></h1>
</td>
</tr>
<tr>
<td bgcolor="#FFFFFF" style="font: normal 12px Arial, Helvetica, sans-serif; color:#333333; padding: 20px; -moz-border-radius-bottomleft: 4px; -moz-border-radius-bottomright: 4px; -webkit-border-bottom-right-radius: 5px; -webkit-border-bottom-left-radius: 5px;"><h3 style="margin: 10px 0 5px; font-size: 17px; font-weight: normal;">
Logging Contextual Information
</h3>
<span style="margin-bottom: 10px;">
modified by <a href="http://community.jboss.org/people/admin">Administrator Administrator</a> in <i>EJB3</i> - <a href="http://community.jboss.org/docs/DOC-12847">View the full document</a>
</span>
<hr style="margin: 20px 0; border: none; background-color: #dadada; height: 1px;">
<div class="jive-rendered-content"><h4>Introduction</h4><p>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.</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><p>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.</p><h4>Contextual Logging with Log4J</h4><p>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:</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><pre class="jive-pre"><code class="jive-code jive-java">UserTransaction utx = (UserTransaction) <font color="navy"><b>new</b></font> InitialContext().lookup(<font color="red">"java:/UserTransaction"</font>);
log.debug(utx.toString());
</code></pre><p>But what about container managed transactions?  What if we don't want to pollute our business code with endless logging details?</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><p>Log4J includes a very useful feature called Mapped Diagnostic Contexts, or <a class="jive-link-external-small" href="http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/MDC.html">MDC</a> 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.</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><p>We can manage information in the MDC like such:</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><pre class="jive-pre"><code class="jive-code jive-java">MDC.put(<font color="red">"name"</font>, <font color="red">"value"</font>);
...
log.debug(<font color="red">"Hello!"</font>);
...
MDC.remove(<font color="red">"name"</font>);
</code></pre><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><p>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.</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><pre class="jive-pre"><code class="jive-code jive-xml"><span class="jive-xml-tag"><layout class="org.apache.log4j.PatternLayout"></span>
     <span class="jive-xml-tag"><param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%X{name}] [%c{1}] %m%n"/></span>
<span class="jive-xml-tag"></layout></span>
</code></pre><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><p>In this example, the [%X{name}] token will result in a log line similar to this:</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><pre class="jive-pre"><code class="jive-code">15:33:59,694 DEBUG  [value] [MyClass] Hello!</code></pre><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><h4>Logging Transaction ID for EJB3 Calls</h4><p>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:</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><pre class="jive-pre"><code class="jive-code jive-java"><font color="navy"><b>public</b></font> <font color="navy"><b>class</b></font> LogContextInterceptor <font color="navy">{</font>
    <font color="navy"><b>private</b></font> <font color="navy"><b>static</b></font> <font color="navy"><b>final</b></font> String TX_UID_KEY = <font color="red">"txid"</font>;
    @Resource(mappedName=<font color="red">"java:/TransactionManager"</font>) <font color="navy"><b>private</b></font> TransactionManager tm;   
    @AroundInvoke
    <font color="navy"><b>public</b></font> Object intercept(InvocationContext ctx) <font color="navy"><b>throws</b></font> Exception <font color="navy">{</font>
        TransactionImple tx = (TransactionImple) tm.getTransaction();
        MDC.put(TX_UID_KEY, tx.get_uid());
        <font color="navy"><b>try</b></font> <font color="navy">{</font>
            <font color="navy"><b>return</b></font> ctx.proceed();
        <font color="navy">}</font> <font color="navy"><b>finally</b></font> <font color="navy">{</font>
            MDC.remove(TX_UID_KEY);
        <font color="navy">}</font>
    <font color="navy">}</font>
<font color="navy">}</font>
</code></pre><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><p>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:</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><pre class="jive-pre"><code class="jive-code jive-xml"><span class="jive-xml-tag"><?xml version="1.0" encoding="UTF-8"?></span>
<span class="jive-xml-tag"><span><ejb-jar version="3.0" xmlns="</span><a class="jive-link-external-small" href="http://java.sun.com/xml/ns/javaee" target="_blank">http://java.sun.com/xml/ns/javaee</a><span>"
    xmlns:xsi="</span><a class="jive-link-external-small" href="http://www.w3.org/2001/XMLSchema-instance" target="_blank">http://www.w3.org/2001/XMLSchema-instance</a><span>"
    xsi:schemaLocation="</span><a class="jive-link-external-small" href="http://java.sun.com/xml/ns/javaee" target="_blank">http://java.sun.com/xml/ns/javaee</a><span> </span><a class="jive-link-external-small" href="http://java.sun.com/xml/ns/javaee/ejb-jar_3_0.xsd" target="_blank">http://java.sun.com/xml/ns/javaee/ejb-jar_3_0.xsd</a><span>"></span></span>
    <span class="jive-xml-tag"><assembly-descriptor></span>
        <span class="jive-xml-tag"><interceptor-binding></span>
            <span class="jive-xml-tag"><ejb-name></span>*<span class="jive-xml-tag"></ejb-name></span>
            <span class="jive-xml-tag"><interceptor-class></span>org.jboss.example.logging.LogContextInterceptor<span class="jive-xml-tag"></interceptor-class></span>
        <span class="jive-xml-tag"></interceptor-binding></span>
    <span class="jive-xml-tag"></assembly-descriptor></span>
<span class="jive-xml-tag"></ejb-jar></span>
</code></pre><p>Don't forget to add the "txid" token to Log4J's ConversionPattern:</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><pre class="jive-pre"><code class="jive-code jive-xml"><span class="jive-xml-tag"><layout class="org.apache.log4j.PatternLayout"></span>
     <span class="jive-xml-tag"><param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%X{txid}] [%c{1}] %m%n"/></span>
<span class="jive-xml-tag"></layout></span></code></pre><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><p>Now let's look at the output from a basic SLSB invocation:</p><p style="min-height: 8pt; height: 8pt; padding: 0px;"> </p><pre class="jive-pre"><code class="jive-code">16:39:10,184 INFO  [7f000001:c958:48fe3ca7:124] [TransactionalServiceBean] Echoing string Hello World!
</code></pre><p><br/>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.</p></div>
<div style="background-color: #f4f4f4; padding: 10px; margin-top: 20px;">
<p style="margin: 0;">Comment by <a href="http://community.jboss.org/docs/DOC-12847">going to Community</a></p>
<p style="margin: 0;">Create a new document in EJB3 at <a href="http://community.jboss.org/choose-container!input.jspa?contentType=102&containerType=14&container=2029">Community</a></p>
</div></td>
</tr>
</tbody>
</table>
</td>
</tr>
</tbody>
</table>
</div>
</body>
</html>