<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" 
  "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">

<html xmlns="http://www.w3.org/1999/xhtml">
  <head>
    <meta http-equiv="content-type" content="text/html; charset=iso-8859-1" />
    <title>SLF4J extensions</title>
    
    <link rel="stylesheet" type="text/css" media="screen" href="css/site.css" />
    <link rel="stylesheet" type="text/css" href="css/prettify.css" />
  </head>
  <body onload="prettyPrint()">
    <script type="text/javascript">prefix='';</script>
    <script type="text/javascript" src="js/prettify.js"></script>
    <script src="templates/header.js" type="text/javascript"></script>
    <div id="left">
      <script src="templates/left.js" type="text/javascript"></script>
    </div>
    <div id="content">

    <h1>SLF4J extensions</h1>

    <p>SLF4J extensions are packaged within <em>slf4j-ext.jar</em>
    which ships with SLF4J.  </p>

    
    <ul>
      <li><a href="#profiler">Profiler</a></li>
      <li><a href="#extended_logger">Extended logger</a></li>
      <li><a href="#event_logger">Event Logging</a></li>
      <li><a href="#javaagent">Logging added with Java agent (requires Java 5)</a></li>
    </ul>

		<h2><a name="profiler"></a>Profilers</h2>

		<h3>What is a profiler?</h3>
    
    <p>According to wikipedia, <a
    href="http://en.wikipedia.org/wiki/Profiler_%28computer_science%29">profiling</a>
    is the investigation of a program's behavior using information
    gathered as the program runs, i.e. it is a form of dynamic program
    analysis, as opposed to static code analysis. The usual goal of
    performance analysis is to determine which parts of a program to
    optimize for speed or memory usage.
    </p>

    <p>SLF4J profilers, a.k.a. poor man's profilers, will help the
    developer gather performance data. Essentially, a profiler
    consists of one or more stopwatches. Stopwatches are driven
    (started/stopped) by statements in the <em>source code</em>. An
    example should make the point clearer.
    </p>

    <h3>Basic example</h3>


    <em>Example: Using the profiler: <a
    href="xref-test/org/slf4j/profiler/BasicProfilerDemo.html">BasicProfilerDemo</a></em>

    <pre class="prettyprint source">[omitted]
32  public class BasicProfilerDemo {
33  
34    public static void main(String[] args) {
35      // create a profiler called "BASIC"
36      <b>Profiler profiler = new Profiler("BASIC");</b>
37      <b>profiler.start("A");</b>
38      doA();
39  
40      <b>profiler.start("B");</b>
41      doB();
42      
43      <b>profiler.start("OTHER");</b>
44      doOther();
45      <b>profiler.stop().print();</b>
46    }
[omitted]</pre>


  <p>Running the above example will output the following output.</p>

    <p class="source">+ Profiler [BASIC]
|-- elapsed time                      [A]   220.487 milliseconds.
|-- elapsed time                      [B]  2499.866 milliseconds.
|-- elapsed time                  [OTHER]  3300.745 milliseconds.
|-- Total                         [BASIC]  6022.568 milliseconds.</p>
  
   <p>Instantiating a profiler starts a global stopwatch. Each call to
   the start() method starts a new and named stopwatch. In addition to
   starting a named stopwatch, the start() method also causes the
   previous stopwatch to stop. Thus, the call to
   <code>profiler.start("A")</code> starts a stopwatch named "A". The
   subsequent call to <code>profiler.start("B")</code> starts
   stopwatch "B" and simultaneously stops the stopwatch named
   "A". Invoking the <code>stop()</code> on a profiler stops the last
   stopwatch as well as the global stopwatch which was started when
   the profiler was instantiated.
   </p>


   <h3>Profiler nesting</h3>
   
   <p>Profilers can also be nested. By nesting profilers, it is
   possible to measure a task which itself has subtasks that need to
   be timed and measured.
   </p>

   <p>Starting a nested profiler will stop any previously started
   stopwatch or nested profiler associated with the parent profiler.
   </p>
   
   <p>Often times, the subtask is implemented by a different class as
   the class hosting the parent profiler. Using the
   <code>ProfilerRegistry</code> is a convenient way of passing a
   nested profiler to an object outside the current object. Each
   thread has its own profiler registry which can be retrieved by
   invoking the <code>getThreadContextInstance()</code> method.
   </p>

   <em>Example: <a
   href="xref-test/org/slf4j/profiler/NestedProfilerDemo.html">NestedProfilerDemo</a>
   </em>

   <pre class="prettyprint source">33  public class NestedProfilerDemo {
34    
35    public static void main(String[] args) {
36      // create a profiler called "DEMO"
37      Profiler profiler = new Profiler("DEMO");
38      
39      // register this profiler in the thread context's profiler registry
40      <b>ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();</b>
41      <b>profiler.registerWith(profilerRegistry);</b>
42      
43      // start a stopwatch called "RANDOM"
44      profiler.start("RANDOM");
45      RandomIntegerArrayGenerator riaGenerator = new RandomIntegerArrayGenerator();
46      int n = 1000*1000;
47      int[] randomArray = riaGenerator.generate(n);
48      
49      // create and start a nested profiler called "SORT_AND_PRUNE"
50      // By virtue of its parent-child relationship with the "DEMO"
51      // profiler, and the previous registration of the parent profiler, 
52      // this nested profiler will be automatically registered
53      // with the thread context's profiler registry
54      <b>profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME);</b>
55      
56      SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray);
57      pruner.sortAndPruneComposites();
58      
59      // stop and print the "DEMO" printer
60      profiler.stop().print();
61    }
62  }</pre>

   <p>Here is the relevant excerpt from the <a
   href="xref-test/org/slf4j/profiler/SortAndPruneComposites.html">SortAndPruneComposites</a>
   class.
   </p>

   <pre class="prettyprint source">[omitted]
6   public class SortAndPruneComposites {
7   
8     static String NESTED_PROFILER_NAME = "SORT_AND_PRUNE";
9     
10    final int[] originalArray;
11    final int originalArrayLength;
12    
13    public SortAndPruneComposites(int[] randomArray) {
14      this.originalArray = randomArray;
15      this.originalArrayLength = randomArray.length;
16     
17    }
18    
19    public int[] sortAndPruneComposites() {
20      // retrieve previously registered profiler named "SORT_AND_PRUNE"
21      ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
22      <b>Profiler sortProfiler = profilerRegistry.get(NESTED_PROFILER_NAME);</b>
23  
24      // start a new stopwatch called SORT
25      sortProfiler.start("SORT");
26      int[] sortedArray = sort();
27      // start a new stopwatch called PRUNE_COMPOSITES
28      sortProfiler.start("PRUNE_COMPOSITES");
29      int result[] = pruneComposites(sortedArray);
30      
31      return result;
32    }
[omitted] </pre>
   

  <p>On a Dual-Core Intel CPU clocked at 3.2 GHz, running the
  <code>ProfilerDemo</code> application yields the following output:</p>
  
  <p class="source">+ Profiler [DEMO]
|-- elapsed time                 [RANDOM]    70.524 milliseconds.
|---+ Profiler [SORT_AND_PRUNE]
    |-- elapsed time                   [SORT]   665.281 milliseconds.
    |-- elapsed time       [PRUNE_COMPOSITES]  5695.515 milliseconds.
    |-- Subtotal             [SORT_AND_PRUNE]  6360.866 milliseconds.
|-- elapsed time         [SORT_AND_PRUNE]  6360.866 milliseconds.
|-- Total                          [DEMO]  6433.922 milliseconds.</p>

  <p>From the above, we learn that generating 1'000'000 random
  integers takes 70 ms, sorting them 665 ms, and pruning the composite
  (non-prime) integers 5695 ms, for a grand total of 6433 ms. Given
  that pruning composites takes most of the CPU effort, any future
  optimizations efforts would be directed at the pruning part.
  </p>

  <p>With just a few well-placed profiler calls we were able to
  identify hot-spots in our application. Also note that passing a
  profiler to a target class could be achieved by registering it in a
  profiler registry and then retrieving it in the target class.
  </p>

  <h3>Printing using a logger</h3>

  <p> Invoking <code>profiler.print</code> will always print the
  output on the console. If you wish to leave the profiler code in
  production, then you probably need more control over the output
  destination. This can be accomplished by associating a logger of
  your choice with a profiler.
  </p>
  
  <p>After you have associated a logger with a profiler, you would
  invoke the <code>log()</code> method instead of <code>print()</code>
  previously, as the next example illustrates.
  </p>

  <em>Profiler with a logger: <a
  href="xref-test/org/slf4j/profiler/NestedProfilerDemo2.html">NestedProfilerDemo2</a>
   </em>

   <pre class="prettyprint source">[omitted]
17  public class NestedProfilerDemo2 {
18  
19    static Logger logger = LoggerFactory.getLogger(NestedProfilerDemo2.class);
20    
21    public static void main(String[] args) {
22      Profiler profiler = new Profiler("DEMO");
23      // associate a logger with the profiler
24      <b>profiler.setLogger(logger);</b>
25      
26      ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
27      profiler.registerWith(profilerRegistry);
28      
29      profiler.start("RANDOM");
30      RandomIntegerArrayGenerator riaGenerator = new RandomIntegerArrayGenerator();
31      int n = 10*1000;
32      int[] randomArray = riaGenerator.generate(n);
33      
34      profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME);
35      
36      SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray);
37      pruner.sortAndPruneComposites();
38      
39      // stop and log
40      profiler.stop().<b>log()</b>;
41    }
42  } </pre>
  
  <p>The output generated by this example will depend on the logging
  environment, but should be very similar to the output generated by
  the previous <code>NestedProfilerDemo</code> example. 
  </p>

  <p>The log() method logs at level DEBUG using a marker named
  "PROFILER".</p>

  <p>If your logging system supports markers, e.g. logback, you could
  specifically enable or disable output generated by SLF4J
  profilers. Here is logback configuration file disabling output for
  any logging event bearing the "PROFILER" marker, even if the logger
  used by the profiler is enabled for the debug level.
  </p>


  <em>logback configuration disabling logging from profilers, and only
  profilers</em>

  <pre class="prettyprint source">&lt;configuration>

  <b>&lt;turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    &lt;Marker>PROFILER&lt;/Marker>
    &lt;OnMatch>DENY&lt;/OnMatch>
  &lt;/turboFilter></b>
    
  &lt;appender name="STDOUT"
    class="ch.qos.logback.core.ConsoleAppender">
    &lt;layout class="ch.qos.logback.classic.PatternLayout">
      &lt;Pattern>%-5level %logger{36} - %msg%n&lt;/Pattern>
    &lt;/layout>
  &lt;/appender>

  &lt;root>
    &lt;level value="DEBUG" />
    &lt;appender-ref ref="STDOUT" />
  &lt;/root>
&lt;/configuration>  </pre>


<!-- .............................................................. -->

   <h2><a name="mdcStrLookup"></a>MDCStrLookup</h2>

   <p>StrLookup is a class defined in Apache Commons Lang. It is used
   in conjunction with the StrSubstitutor class to allow Strings to
   have tokens in the Strings dynamically replaced at run time. There
   are many cases where it is desirable to merge the values for keys
   in the SLF4J MDC into Strings. MDCStrLookup makes this possible.
   </p>
   <p>
   Apache Commons Configuration provides a ConfigurationInterpolator
   class. This class allows new StrLookups to be registered and the
   values can then be used to merge with both the configuration of
   Commons Configuration as well as the configuration files it manages.
   </p>
   <p>
   StrLookup obviously has a dependency on Commons Lang. The Maven
   pom.xml for slf4j-ext lists this dependency as optional so
   that those wishing to use other extensions are not required to
   unnecessarily package the commons lang jar. Therefore, when using
   MDCStrLookup the dependency for commons-lang must be explicitly
   declared along with slf4j-ext.    
   </p>

<!-- .............................................................. -->

   <h2><a name="extended_logger"></a>Extended Logger</h2>

   <p>The <a
   href="apidocs/org/slf4j/ext/XLogger.html"><code>XLogger</code></a>
   class provides a few extra logging methods that are quite useful
   for following the execution path of applications. These methods
   generate logging events that can be filtered separately from other
   debug logging. Liberal use of these methods is encouraged as the
   output has been found to
   </p>
   
   <ul> 
     <li>aid in problem diagnosis in development without requiring a
     debug session</li>

     <li>aid in problem diagnosis in production where no debugging is
     possible</li> 
     
     <li>help educate new developers in learning the application.</li>
   </ul>
   

   <p>The two most used methods are the <code>entry()</code> and
   <code>exit()</code> methods. <code>entry()</code> should be placed
   at the beginning of methods, except perhaps for simple getters and
   setters. <code>entry()</code> can be called passing from 0 to 4
   parameters. Typically these will be parameters passed to the
   method.  The <code>entry()</code> method logs with a level of TRACE
   and uses a <code>Marker</code> with a name of "ENTER" which is also
   a "FLOW" Marker.
   </p>
   
   <p>The <code>exit()</code> method should be placed before any
   return statement or as the last statement of methods without a
   return. <code>exit()</code> can be called with or without a
   parameter. Typically, methods that return void will use
   <code>exit()</code> while methods that return an Object will use
   exit(Object obj).  The <code>entry()</code> method logs with a
   level of TRACE and uses a Marker with a name of "EXIT" which is
   also a "FLOW" Marker.
   </p>
   
   <p>The throwing() method can be used by an application when it is
   throwing an exception that is unlikely to be handled, such as a
   RuntimeException. This will insure that proper diagnostics are
   available if needed. The logging event generated will have a level
   of ERROR and will have an associated Marker with a name of
   "THROWING" which is also an "EXCEPTION" Marker.
   </p>

   <p>The catching() method can be used by an application when it
   catches an Exception that it is not going to rethrow, either
   explicitly or attached to another Exception. The logging event
   generated will have a level of ERROR and will have an associated
   Marker with a name of "CATCHING" which is also an "EXCEPTION"
   Marker.
   </p>
   
   <p>By using these extended methods applications that standardize on
   SLF4J can be assured that they will be able to perform diagnostic
   logging in a standardized manner.
   </p>

   <p>Note that XLogger instances are obtained to through the 
   <a
   href="apidocs/org/slf4j/ext/XLoggerFactory.html"><code>XLoggerFactory</code></a>
   utility class.</p>

   <p>The following example shows a simple application using these
   methods in a fairly typical manner. The <code>throwing()</code>
   method is not present since no Exceptions are explicitly thrown and
   not handled.
   </p>

   <pre class="prettyprint source">package com.test;

import org.slf4j.ext.XLogger;
import org.slf4j.ext.XLoggerFactory;

import java.util.Random;

public class TestService {
  private XLogger logger = XLoggerFactory.getXLogger(TestService.class
      .getName());

  private String[] messages = new String[] { "Hello, World",
      "Goodbye Cruel World", "You had me at hello" };

  private Random rand = new Random(1);

  public String retrieveMessage() {
    logger.entry();

    String testMsg = getMessage(getKey());

    logger.exit(testMsg);
    return testMsg;
  }

  public void exampleException() {
    logger.entry();
    try {
      String msg = messages[messages.length];
      logger.error("An exception should have been thrown");
    } catch (Exception ex) {
      logger.catching(ex);
    }
    logger.exit();
  }

  public String getMessage(int key) {
    logger.entry(key);

    String value = messages[key];

    logger.exit(value);
    return value;
  }

  private int getKey() {
    logger.entry();
    int key = rand.nextInt(messages.length);
    logger.exit(key);
    return key;
  }
}</pre>

   <p>This test application uses the preceding service to generate
   logging events.
   </p>

   <pre class="prettyprint source">package com.test;

public class App {
  public static void main( String[] args )    {
    TestService service = new TestService();
    service.retrieveMessage();
    service.retrieveMessage();
    service.exampleException();
  }
} </pre>
  
   <p>The configuration below will cause all output to be routed to
   target/test.log. The pattern for the FileAppender includes the
   class name, line number and method name. Including these in the
   pattern are critical for the log to be of value.
   </p>

   <pre class="prettyprint source">&lt;?xml version='1.0' encoding='UTF-8'?>
&lt;configuration&gt;
  &lt;appender name="console" class="ch.qos.logback.core.ConsoleAppender"&gt;
    &lt;filter class="ch.qos.logback.classic.filter.LevelFilter"&gt;
      &lt;level&gt;ERROR&lt;/level&gt;
      &lt;onMatch&gt;ACCEPT&lt;/onMatch&gt;
      &lt;onMismatch&gt;DENY&lt;/onMismatch&gt;
    &lt;/filter&gt;
    &lt;layout class="ch.qos.logback.classic.PatternLayout"&gt;
      &lt;Pattern&gt;%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n&lt;/Pattern&gt;
    &lt;/layout&gt;
  &lt;/appender&gt;
  &lt;appender name="log" class="ch.qos.logback.core.FileAppender"&gt;
    &lt;File&gt;target/test.log&lt;/File&gt;
    &lt;Append&gt;false&lt;/Append&gt;
    &lt;layout class="ch.qos.logback.classic.PatternLayout"&gt;
      &lt;Pattern&gt;%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n&lt;/Pattern&gt;
    &lt;/layout&gt;
  &lt;/appender&gt;

  &lt;root&gt;
    &lt;level value="trace" /&gt;
    &lt;appender-ref ref="log" /&gt;
  &lt;/root&gt;
&lt;/configuration&gt;
</pre>
   <p>
   Here is the output that results from the Java classes and configuration above.     
   </p>
<p class="source">00:07:57.725 TRACE com.test.TestService:22 retrieveMessage - entry
00:07:57.738 TRACE com.test.TestService:57 getKey - entry
00:07:57.739 TRACE com.test.TestService:59 getKey - exit with (0)
00:07:57.741 TRACE com.test.TestService:47 getMessage - entry with (0)
00:07:57.741 TRACE com.test.TestService:51 getMessage - exit with (Hello, World)
00:07:57.742 TRACE com.test.TestService:26 retrieveMessage - exit with (Hello, World)
00:07:57.742 TRACE com.test.TestService:22 retrieveMessage - entry
00:07:57.742 TRACE com.test.TestService:57 getKey - entry
00:07:57.743 TRACE com.test.TestService:59 getKey - exit with (1)
00:07:57.745 TRACE com.test.TestService:47 getMessage - entry with (1)
00:07:57.745 TRACE com.test.TestService:51 getMessage - exit with (Goodbye Cruel World)
00:07:57.746 TRACE com.test.TestService:26 retrieveMessage - exit with (Goodbye Cruel World)
00:07:57.746 TRACE com.test.TestService:32 exampleException - entry
00:07:57.750 ERROR com.test.TestService:40 exampleException - catching
java.lang.ArrayIndexOutOfBoundsException: 3
  at com.test.TestService.exampleException(TestService.java:35)
  at com.test.AppTest.testApp(AppTest.java:39)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
  at java.lang.reflect.Method.invoke(Method.java:585)
  at junit.framework.TestCase.runTest(TestCase.java:154)
  at junit.framework.TestCase.runBare(TestCase.java:127)
  at junit.framework.TestResult$1.protect(TestResult.java:106)
  at junit.framework.TestResult.runProtected(TestResult.java:124)
  at junit.framework.TestResult.run(TestResult.java:109)
  at junit.framework.TestCase.run(TestCase.java:118)
  at junit.framework.TestSuite.runTest(TestSuite.java:208)
  at junit.framework.TestSuite.run(TestSuite.java:203)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
  at java.lang.reflect.Method.invoke(Method.java:585)
  at org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:213)
  at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
  at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
  at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
  at java.lang.reflect.Method.invoke(Method.java:585)
  at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338)
  at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)
00:07:57.750 TRACE com.test.TestService:42 exampleException - exit</p>

   <p>Simply changing the root logger level to DEBUG in the example
   above will reduce the output considerably.
   </p>
   <p class="source">00:28:06.004 ERROR com.test.TestService:40 exampleException - catching
java.lang.ArrayIndexOutOfBoundsException: 3
  at com.test.TestService.exampleException(TestService.java:35)
  at com.test.AppTest.testApp(AppTest.java:39)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
  at java.lang.reflect.Method.invoke(Method.java:585)
  at junit.framework.TestCase.runTest(TestCase.java:154)
  at junit.framework.TestCase.runBare(TestCase.java:127)
  at junit.framework.TestResult$1.protect(TestResult.java:106)
  at junit.framework.TestResult.runProtected(TestResult.java:124)
  at junit.framework.TestResult.run(TestResult.java:109)
  at junit.framework.TestCase.run(TestCase.java:118)
  at junit.framework.TestSuite.runTest(TestSuite.java:208)
  at junit.framework.TestSuite.run(TestSuite.java:203)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
  at java.lang.reflect.Method.invoke(Method.java:585)
  at org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:213)
  at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
  at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
  at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
  at java.lang.reflect.Method.invoke(Method.java:585)
  at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338)
  at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)    </p>

  <!-- .............................................................. -->

  <h2><a name="event_logger"></a>Event Logging</h2>

  <p>The EventLogger class provides a simple mechanism for logging events that occur in an application.
  While the EventLogger is useful as a way of initiating events that should be processed by an audit
  Logging system, it does not implement any of the features an audit logging system would require
  such as guaranteed delivery.</p>

  <p>The recommended way of using the EventLogger in a typical web application is to populate
  the SLF4J MDC with data that is related to the entire lifespan of the request such as the user's id,
  the user's ip address, the product name, etc. This can easily be done in a servlet filter where
  the MDC can also be cleared at the end of the request. When an event that needs to be recorded
  occurs an EventData object should be created and populated. Then call EventLogger.logEvent(data)
  where data is a reference to the EventData object.</p>

  <pre class="prettyprint source">import org.slf4j.MDC;
import org.apache.commons.lang.time.DateUtils;

import javax.servlet.Filter;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.FilterChain;
import javax.servlet.http.HttpSession;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.Cookie;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.TimeZone;

public class RequestFilter implements Filter
{
  private FilterConfig filterConfig;
  private static String TZ_NAME = "timezoneOffset";

  public void init(FilterConfig filterConfig) throws ServletException {
    this.filterConfig = filterConfig;
  }

  /**
   * Sample filter that populates the MDC on every request.
   */
  public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse,
                       FilterChain filterChain) throws IOException, ServletException {
    HttpServletRequest request = (HttpServletRequest)servletRequest;
    HttpServletResponse response = (HttpServletResponse)servletResponse;
    MDC.put("ipAddress", request.getRemoteAddr());
    HttpSession session = request.getSession(false);
    TimeZone timeZone = null;
    if (session != null) {
      // Something should set this after authentication completes
      String loginId = (String)session.getAttribute("LoginId");
      if (loginId != null) {
        MDC.put("loginId", loginId);
      }
      // This assumes there is some javascript on the user's page to create the cookie.
      if (session.getAttribute(TZ_NAME) == null) {
        if (request.getCookies() != null) {
          for (Cookie cookie : request.getCookies()) {
            if (TZ_NAME.equals(cookie.getName())) {
              int tzOffsetMinutes = Integer.parseInt(cookie.getValue());
              timeZone = TimeZone.getTimeZone("GMT");
              timeZone.setRawOffset((int)(tzOffsetMinutes * DateUtils.MILLIS_PER_MINUTE));
              request.getSession().setAttribute(TZ_NAME, tzOffsetMinutes);
              cookie.setMaxAge(0);
              response.addCookie(cookie);
            }
          }
        }
      }
    }
    MDC.put("hostname", servletRequest.getServerName());
    MDC.put("productName", filterConfig.getInitParameter("ProductName"));
    MDC.put("locale", servletRequest.getLocale().getDisplayName());
    if (timeZone == null) {
      timeZone = TimeZone.getDefault();
    }
    MDC.put("timezone", timeZone.getDisplayName());
    filterChain.doFilter(servletRequest, servletResponse);
    MDC.clear();
  }

  public void destroy() {
  }
} </pre>
 
  <p>Sample class that uses EventLogger.</p>
  <pre class="prettyprint source">import org.slf4j.ext.EventData;
import org.slf4j.ext.EventLogger;

import java.util.Date;
import java.util.UUID;

public class MyApp {

  public String doFundsTransfer(Account toAccount, Account fromAccount, long amount) {
    toAccount.deposit(amount);
    fromAccount.withdraw(amount);
    EventData data = new EventData();
    data.setEventDateTime(new Date());
    data.setEventType("transfer");
    String confirm = UUID.randomUUID().toString();
    data.setEventId(confirm);
    data.put("toAccount", toAccount);
    data.put("fromAccount", fromAccount);
    data.put("amount", amount);
    EventLogger.logEvent(data);
    return confirm;
  }
}  </pre>
 
  <p>The EventLogger class uses a Logger named "EventLogger". EventLogger uses a logging level
  of INFO. The following shows a configuration using Logback.</p>
  <pre class="prettyprint source">&lt;configuration&gt;
  &lt;appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"&gt;
    &lt;layout class="ch.qos.logback.classic.PatternLayout"&gt;
      &lt;Pattern&gt;%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n&lt;/Pattern&gt;
    &lt;/layout&gt;
  &lt;/appender&gt;

  &lt;appender name="events" class="ch.qos.logback.core.ConsoleAppender"&gt;
    &lt;layout class="ch.qos.logback.classic.PatternLayout"&gt;
      &lt;Pattern&gt;%d{HH:mm:ss.SSS} %X - %msg%n&lt;/Pattern&gt;
    &lt;/layout&gt;
  &lt;/appender&gt;

  &lt;logger name="EventLogger" additivity="false"&gt;
    &lt;level value="INFO"/&gt;
    &lt;appender appender-ref="events"/&gt;
  &lt;/logger&gt;

  &lt;root level="DEBUG"&gt;
    &lt;appender-ref ref="STDOUT" /&gt;
  &lt;/root&gt;

&lt;/configuration&gt;  </pre>

  <!-- .............................................................. -->

  <h2><a name="javaagent"></a>Adding logging with Java agent</h2>

  <p><b>NOTE:  BETA RELEASE, NOT PRODUCTION QUALITY</b>  </p>

  <p>Quickstart for the impatient:</p>

  <ol>
    <li>Use Java 5 or later.</li>
    <li>Download slf4j-ext-${project.version}.jar and javassist.jar, and put them
    both in the same directory.</li>
    <li>Ensure your application is properly configured with
    slf4j-api-${project.version}.jar and a suitable backend.</li>

    <li>Instead of "java ..." use "java --javaagent:PATH/slf4j-ext-${project.version}.jar=time,verbose,level=info ..."
    <br/>
    (replace PATH with the path to the jar)
    </li>
    <li>That's it!</li>
  </ol>

  <p>In some applications logging is used to trace the actual
  execution of the application as opposed to log an occasional event.
  One approach is using the <a href="#extended_logger">extended
  logger</a> to add statements as appropriately, but another is to use
  a tool which modifies compiled bytecode to add these statements!
  Many exist, and the one included in slf4j-ext is not intended to
  compete with these, but merely provide a quick way to get very basic
  trace information from a given application.
  </p>

  <p>Java 5 added the Java Instrumentation mechanism, which allows you
  to provide "Java agents" that can inspect and modify the byte code
  of the classes as they are loaded.  This allows the original class
  files to remain unchanged, and the transformations done on the byte
  codes depend on the needs at launch time.
  </p>

  <p>Given the well-known "Hello World" example:</p>

  <pre class="prettyprint source">public class HelloWorld {
  public static void main(String args[]) {
    System.out.println("Hello World");
  }
}</pre>

  <p>a typical transformation would be similar to: (imports omitted)</p>

  <pre class="prettyprint source">public class LoggingHelloWorld {
  final static Logger _log = LoggerFactory.getLogger(LoggingHelloWorld.class.getName());

  public static void main(String args[]) {
    if (_log.isInfoEnabled()) {
      _log.info("> main(args=" + Arrays.asList(args) + ")");
    }
    System.out.println("Hello World");
    if (_log.isInfoEnabled()) {
      _log.info("&lt; main()");
    }
  }
}</pre>

  <p>which in turn produces the following result when run similar to
  "java LoggingHelloWorld 1 2 3 4":
  </p>

  <p class="source">1 [main] INFO LoggingHelloWorld - > main(args=[1, 2, 3, 4])
Hello World
1 [main] INFO LoggingHelloWorld - &lt; main()</p>

  <p>The same effect could have been had by using this command (with
  the relative path to javassist.jar and
  slf4j-ext-${project.version}.jar being ../jars):</p>

  <p class="source">java -javaagent:../jars/slf4j-ext-${project.version}.jar HelloWorld 1 2 3 4</p>

  <p></p>


  <h3>How to use</h3>
  <p>The javaagent may take one or more options separated by comma.  The following options
  are currently supported:</p>

  <dl>
    <dt><b>level</b>=X</dt>
    <dd>The log level to use for the generated log statements. X is
    one of "info", "debug" or "trace". Default is "info".</dd>
    
    <dt><b>time</b></dt>
    <dd>Print out the current date at program start, and again when
    the program ends plus the execution time in milliseconds.</dd>
    
    <dt><b>verbose</b></dt>
    <dd>Print out when a class is processed as part of being loaded</dd>

    <dt><b>ignore</b>=X:Y:...</dt>
    <dd>(Advanced) Provide full list of colon separated prefixes of
    class names NOT to add logging to.  The default list is 
    "org/slf4j/:ch/qos/logback/:org/apache/log4j/".  This does not override the fact that a class must be able to access the 
    slf4j-api classes in order to do logging, so if these classes are  not visible to a given class it is not instrumented. 
    </dd>
  </dl>


    <p>Some classes may misbehave when being rendered with "object.toString()" so they may be explicitly disabled 
    in the logback configuration file permanently.  For instance the ToStringBuilder in the Apache Jakarta commons lang 
    package is a prime candidate for this.  For logback add this snippet to logback.xml:
    <pre>&lt;logger name="org.apache.commons.lang.builder" level="OFF" /&gt;</pre>
    </p>
    

  <p>Note: These are not finalized yet, and may change.</p>

  <h3>Locations of jar files</h3>

  <p>The javassist library is used for the actual byte code
  manipulation and must be available to be able to add any logging
  statements.  slf4j-ext-${project.version} has been configured to
  look for the following:
  </p>

  <ul>
    <li>"javassist-3.4.GA.jar" relatively to
    slf4j-ext-${project.version}.jar as would be if Maven had downloaded
    both from the repository and slf4j-ext-${project.version}.jar was
    referenced directly in the Maven repository in the
    "-javaagent"-argument.</li>
    <li>"javassist-3.4.GA.jar" in the same directory as slf4j-ext</li>
    <li>"javassist.jar" in the same directory as slf4j-ext</li>
  </ul>

  <p>A warning message is printed if the javassist library was not
  found by the agent, and options requiring byte code transformations will not work.
  </p>


  <h3>Misc notes</h3>

  <ul>
    <li>A java agent is not invoked on any classes already loaded by the
    class loader.</li>
    <li>Exceptions in the java agent that would normally have been
    printed, may be silently swallowed by the JVM.</li>
    <li>The javaagent only logs to System.err.</li>
    <li>The name of the logger variable is fixed (to a value unlikely to be used) so if that
    name is already used, a failure occurs.  This should be changed to determine
    an unused name and use that instead.</li>
    <li>Empty methods are not instrumented (an incorrect check for an interface).  They should be</li>
    
  </ul>

  <p>(The agent is an adaption of the java.util.logging version
  described in <a
  href="http://today.java.net/pub/a/today/2008/04/24/add-logging-at-class-load-time-with-instrumentation.html"
  >http://today.java.net/pub/a/today/2008/04/24/add-logging-at-class-load-time-with-instrumentation.html</a>)
  </p>

  <script  src="templates/footer.js" type="text/javascript"></script> 
</div>
</body>
</html>