1<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" 2 "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd"> 3 4<html xmlns="http://www.w3.org/1999/xhtml"> 5 <head> 6 <meta http-equiv="content-type" content="text/html; charset=iso-8859-1" /> 7 <title>SLF4J extensions</title> 8 9 <link rel="stylesheet" type="text/css" media="screen" href="css/site.css" /> 10 <link rel="stylesheet" type="text/css" href="css/prettify.css" /> 11 </head> 12 <body onload="prettyPrint()"> 13 <script type="text/javascript">prefix='';</script> 14 <script type="text/javascript" src="js/prettify.js"></script> 15 <script src="templates/header.js" type="text/javascript"></script> 16 <div id="left"> 17 <script src="templates/left.js" type="text/javascript"></script> 18 </div> 19 <div id="content"> 20 21 <h1>SLF4J extensions</h1> 22 23 <p>SLF4J extensions are packaged within <em>slf4j-ext.jar</em> 24 which ships with SLF4J. </p> 25 26 27 <ul> 28 <li><a href="#profiler">Profiler</a></li> 29 <li><a href="#extended_logger">Extended logger</a></li> 30 <li><a href="#event_logger">Event Logging</a></li> 31 <li><a href="#javaagent">Logging added with Java agent (requires Java 5)</a></li> 32 </ul> 33 34 <h2><a name="profiler"></a>Profilers</h2> 35 36 <h3>What is a profiler?</h3> 37 38 <p>According to wikipedia, <a 39 href="http://en.wikipedia.org/wiki/Profiler_%28computer_science%29">profiling</a> 40 is the investigation of a program's behavior using information 41 gathered as the program runs, i.e. it is a form of dynamic program 42 analysis, as opposed to static code analysis. The usual goal of 43 performance analysis is to determine which parts of a program to 44 optimize for speed or memory usage. 45 </p> 46 47 <p>SLF4J profilers, a.k.a. poor man's profilers, will help the 48 developer gather performance data. Essentially, a profiler 49 consists of one or more stopwatches. Stopwatches are driven 50 (started/stopped) by statements in the <em>source code</em>. An 51 example should make the point clearer. 52 </p> 53 54 <h3>Basic example</h3> 55 56 57 <em>Example: Using the profiler: <a 58 href="xref-test/org/slf4j/profiler/BasicProfilerDemo.html">BasicProfilerDemo</a></em> 59 60 <pre class="prettyprint source">[omitted] 6132 public class BasicProfilerDemo { 6233 6334 public static void main(String[] args) { 6435 // create a profiler called "BASIC" 6536 <b>Profiler profiler = new Profiler("BASIC");</b> 6637 <b>profiler.start("A");</b> 6738 doA(); 6839 6940 <b>profiler.start("B");</b> 7041 doB(); 7142 7243 <b>profiler.start("OTHER");</b> 7344 doOther(); 7445 <b>profiler.stop().print();</b> 7546 } 76[omitted]</pre> 77 78 79 <p>Running the above example will output the following output.</p> 80 81 <p class="source">+ Profiler [BASIC] 82|-- elapsed time [A] 220.487 milliseconds. 83|-- elapsed time [B] 2499.866 milliseconds. 84|-- elapsed time [OTHER] 3300.745 milliseconds. 85|-- Total [BASIC] 6022.568 milliseconds.</p> 86 87 <p>Instantiating a profiler starts a global stopwatch. Each call to 88 the start() method starts a new and named stopwatch. In addition to 89 starting a named stopwatch, the start() method also causes the 90 previous stopwatch to stop. Thus, the call to 91 <code>profiler.start("A")</code> starts a stopwatch named "A". The 92 subsequent call to <code>profiler.start("B")</code> starts 93 stopwatch "B" and simultaneously stops the stopwatch named 94 "A". Invoking the <code>stop()</code> on a profiler stops the last 95 stopwatch as well as the global stopwatch which was started when 96 the profiler was instantiated. 97 </p> 98 99 100 <h3>Profiler nesting</h3> 101 102 <p>Profilers can also be nested. By nesting profilers, it is 103 possible to measure a task which itself has subtasks that need to 104 be timed and measured. 105 </p> 106 107 <p>Starting a nested profiler will stop any previously started 108 stopwatch or nested profiler associated with the parent profiler. 109 </p> 110 111 <p>Often times, the subtask is implemented by a different class as 112 the class hosting the parent profiler. Using the 113 <code>ProfilerRegistry</code> is a convenient way of passing a 114 nested profiler to an object outside the current object. Each 115 thread has its own profiler registry which can be retrieved by 116 invoking the <code>getThreadContextInstance()</code> method. 117 </p> 118 119 <em>Example: <a 120 href="xref-test/org/slf4j/profiler/NestedProfilerDemo.html">NestedProfilerDemo</a> 121 </em> 122 123 <pre class="prettyprint source">33 public class NestedProfilerDemo { 12434 12535 public static void main(String[] args) { 12636 // create a profiler called "DEMO" 12737 Profiler profiler = new Profiler("DEMO"); 12838 12939 // register this profiler in the thread context's profiler registry 13040 <b>ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();</b> 13141 <b>profiler.registerWith(profilerRegistry);</b> 13242 13343 // start a stopwatch called "RANDOM" 13444 profiler.start("RANDOM"); 13545 RandomIntegerArrayGenerator riaGenerator = new RandomIntegerArrayGenerator(); 13646 int n = 1000*1000; 13747 int[] randomArray = riaGenerator.generate(n); 13848 13949 // create and start a nested profiler called "SORT_AND_PRUNE" 14050 // By virtue of its parent-child relationship with the "DEMO" 14151 // profiler, and the previous registration of the parent profiler, 14252 // this nested profiler will be automatically registered 14353 // with the thread context's profiler registry 14454 <b>profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME);</b> 14555 14656 SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray); 14757 pruner.sortAndPruneComposites(); 14858 14959 // stop and print the "DEMO" printer 15060 profiler.stop().print(); 15161 } 15262 }</pre> 153 154 <p>Here is the relevant excerpt from the <a 155 href="xref-test/org/slf4j/profiler/SortAndPruneComposites.html">SortAndPruneComposites</a> 156 class. 157 </p> 158 159 <pre class="prettyprint source">[omitted] 1606 public class SortAndPruneComposites { 1617 1628 static String NESTED_PROFILER_NAME = "SORT_AND_PRUNE"; 1639 16410 final int[] originalArray; 16511 final int originalArrayLength; 16612 16713 public SortAndPruneComposites(int[] randomArray) { 16814 this.originalArray = randomArray; 16915 this.originalArrayLength = randomArray.length; 17016 17117 } 17218 17319 public int[] sortAndPruneComposites() { 17420 // retrieve previously registered profiler named "SORT_AND_PRUNE" 17521 ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance(); 17622 <b>Profiler sortProfiler = profilerRegistry.get(NESTED_PROFILER_NAME);</b> 17723 17824 // start a new stopwatch called SORT 17925 sortProfiler.start("SORT"); 18026 int[] sortedArray = sort(); 18127 // start a new stopwatch called PRUNE_COMPOSITES 18228 sortProfiler.start("PRUNE_COMPOSITES"); 18329 int result[] = pruneComposites(sortedArray); 18430 18531 return result; 18632 } 187[omitted] </pre> 188 189 190 <p>On a Dual-Core Intel CPU clocked at 3.2 GHz, running the 191 <code>ProfilerDemo</code> application yields the following output:</p> 192 193 <p class="source">+ Profiler [DEMO] 194|-- elapsed time [RANDOM] 70.524 milliseconds. 195|---+ Profiler [SORT_AND_PRUNE] 196 |-- elapsed time [SORT] 665.281 milliseconds. 197 |-- elapsed time [PRUNE_COMPOSITES] 5695.515 milliseconds. 198 |-- Subtotal [SORT_AND_PRUNE] 6360.866 milliseconds. 199|-- elapsed time [SORT_AND_PRUNE] 6360.866 milliseconds. 200|-- Total [DEMO] 6433.922 milliseconds.</p> 201 202 <p>From the above, we learn that generating 1'000'000 random 203 integers takes 70 ms, sorting them 665 ms, and pruning the composite 204 (non-prime) integers 5695 ms, for a grand total of 6433 ms. Given 205 that pruning composites takes most of the CPU effort, any future 206 optimizations efforts would be directed at the pruning part. 207 </p> 208 209 <p>With just a few well-placed profiler calls we were able to 210 identify hot-spots in our application. Also note that passing a 211 profiler to a target class could be achieved by registering it in a 212 profiler registry and then retrieving it in the target class. 213 </p> 214 215 <h3>Printing using a logger</h3> 216 217 <p> Invoking <code>profiler.print</code> will always print the 218 output on the console. If you wish to leave the profiler code in 219 production, then you probably need more control over the output 220 destination. This can be accomplished by associating a logger of 221 your choice with a profiler. 222 </p> 223 224 <p>After you have associated a logger with a profiler, you would 225 invoke the <code>log()</code> method instead of <code>print()</code> 226 previously, as the next example illustrates. 227 </p> 228 229 <em>Profiler with a logger: <a 230 href="xref-test/org/slf4j/profiler/NestedProfilerDemo2.html">NestedProfilerDemo2</a> 231 </em> 232 233 <pre class="prettyprint source">[omitted] 23417 public class NestedProfilerDemo2 { 23518 23619 static Logger logger = LoggerFactory.getLogger(NestedProfilerDemo2.class); 23720 23821 public static void main(String[] args) { 23922 Profiler profiler = new Profiler("DEMO"); 24023 // associate a logger with the profiler 24124 <b>profiler.setLogger(logger);</b> 24225 24326 ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance(); 24427 profiler.registerWith(profilerRegistry); 24528 24629 profiler.start("RANDOM"); 24730 RandomIntegerArrayGenerator riaGenerator = new RandomIntegerArrayGenerator(); 24831 int n = 10*1000; 24932 int[] randomArray = riaGenerator.generate(n); 25033 25134 profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME); 25235 25336 SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray); 25437 pruner.sortAndPruneComposites(); 25538 25639 // stop and log 25740 profiler.stop().<b>log()</b>; 25841 } 25942 } </pre> 260 261 <p>The output generated by this example will depend on the logging 262 environment, but should be very similar to the output generated by 263 the previous <code>NestedProfilerDemo</code> example. 264 </p> 265 266 <p>The log() method logs at level DEBUG using a marker named 267 "PROFILER".</p> 268 269 <p>If your logging system supports markers, e.g. logback, you could 270 specifically enable or disable output generated by SLF4J 271 profilers. Here is logback configuration file disabling output for 272 any logging event bearing the "PROFILER" marker, even if the logger 273 used by the profiler is enabled for the debug level. 274 </p> 275 276 277 <em>logback configuration disabling logging from profilers, and only 278 profilers</em> 279 280 <pre class="prettyprint source"><configuration> 281 282 <b><turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter"> 283 <Marker>PROFILER</Marker> 284 <OnMatch>DENY</OnMatch> 285 </turboFilter></b> 286 287 <appender name="STDOUT" 288 class="ch.qos.logback.core.ConsoleAppender"> 289 <layout class="ch.qos.logback.classic.PatternLayout"> 290 <Pattern>%-5level %logger{36} - %msg%n</Pattern> 291 </layout> 292 </appender> 293 294 <root> 295 <level value="DEBUG" /> 296 <appender-ref ref="STDOUT" /> 297 </root> 298</configuration> </pre> 299 300 301<!-- .............................................................. --> 302 303 <h2><a name="mdcStrLookup"></a>MDCStrLookup</h2> 304 305 <p>StrLookup is a class defined in Apache Commons Lang. It is used 306 in conjunction with the StrSubstitutor class to allow Strings to 307 have tokens in the Strings dynamically replaced at run time. There 308 are many cases where it is desirable to merge the values for keys 309 in the SLF4J MDC into Strings. MDCStrLookup makes this possible. 310 </p> 311 <p> 312 Apache Commons Configuration provides a ConfigurationInterpolator 313 class. This class allows new StrLookups to be registered and the 314 values can then be used to merge with both the configuration of 315 Commons Configuration as well as the configuration files it manages. 316 </p> 317 <p> 318 StrLookup obviously has a dependency on Commons Lang. The Maven 319 pom.xml for slf4j-ext lists this dependency as optional so 320 that those wishing to use other extensions are not required to 321 unnecessarily package the commons lang jar. Therefore, when using 322 MDCStrLookup the dependency for commons-lang must be explicitly 323 declared along with slf4j-ext. 324 </p> 325 326<!-- .............................................................. --> 327 328 <h2><a name="extended_logger"></a>Extended Logger</h2> 329 330 <p>The <a 331 href="apidocs/org/slf4j/ext/XLogger.html"><code>XLogger</code></a> 332 class provides a few extra logging methods that are quite useful 333 for following the execution path of applications. These methods 334 generate logging events that can be filtered separately from other 335 debug logging. Liberal use of these methods is encouraged as the 336 output has been found to 337 </p> 338 339 <ul> 340 <li>aid in problem diagnosis in development without requiring a 341 debug session</li> 342 343 <li>aid in problem diagnosis in production where no debugging is 344 possible</li> 345 346 <li>help educate new developers in learning the application.</li> 347 </ul> 348 349 350 <p>The two most used methods are the <code>entry()</code> and 351 <code>exit()</code> methods. <code>entry()</code> should be placed 352 at the beginning of methods, except perhaps for simple getters and 353 setters. <code>entry()</code> can be called passing from 0 to 4 354 parameters. Typically these will be parameters passed to the 355 method. The <code>entry()</code> method logs with a level of TRACE 356 and uses a <code>Marker</code> with a name of "ENTER" which is also 357 a "FLOW" Marker. 358 </p> 359 360 <p>The <code>exit()</code> method should be placed before any 361 return statement or as the last statement of methods without a 362 return. <code>exit()</code> can be called with or without a 363 parameter. Typically, methods that return void will use 364 <code>exit()</code> while methods that return an Object will use 365 exit(Object obj). The <code>entry()</code> method logs with a 366 level of TRACE and uses a Marker with a name of "EXIT" which is 367 also a "FLOW" Marker. 368 </p> 369 370 <p>The throwing() method can be used by an application when it is 371 throwing an exception that is unlikely to be handled, such as a 372 RuntimeException. This will insure that proper diagnostics are 373 available if needed. The logging event generated will have a level 374 of ERROR and will have an associated Marker with a name of 375 "THROWING" which is also an "EXCEPTION" Marker. 376 </p> 377 378 <p>The catching() method can be used by an application when it 379 catches an Exception that it is not going to rethrow, either 380 explicitly or attached to another Exception. The logging event 381 generated will have a level of ERROR and will have an associated 382 Marker with a name of "CATCHING" which is also an "EXCEPTION" 383 Marker. 384 </p> 385 386 <p>By using these extended methods applications that standardize on 387 SLF4J can be assured that they will be able to perform diagnostic 388 logging in a standardized manner. 389 </p> 390 391 <p>Note that XLogger instances are obtained to through the 392 <a 393 href="apidocs/org/slf4j/ext/XLoggerFactory.html"><code>XLoggerFactory</code></a> 394 utility class.</p> 395 396 <p>The following example shows a simple application using these 397 methods in a fairly typical manner. The <code>throwing()</code> 398 method is not present since no Exceptions are explicitly thrown and 399 not handled. 400 </p> 401 402 <pre class="prettyprint source">package com.test; 403 404import org.slf4j.ext.XLogger; 405import org.slf4j.ext.XLoggerFactory; 406 407import java.util.Random; 408 409public class TestService { 410 private XLogger logger = XLoggerFactory.getXLogger(TestService.class 411 .getName()); 412 413 private String[] messages = new String[] { "Hello, World", 414 "Goodbye Cruel World", "You had me at hello" }; 415 416 private Random rand = new Random(1); 417 418 public String retrieveMessage() { 419 logger.entry(); 420 421 String testMsg = getMessage(getKey()); 422 423 logger.exit(testMsg); 424 return testMsg; 425 } 426 427 public void exampleException() { 428 logger.entry(); 429 try { 430 String msg = messages[messages.length]; 431 logger.error("An exception should have been thrown"); 432 } catch (Exception ex) { 433 logger.catching(ex); 434 } 435 logger.exit(); 436 } 437 438 public String getMessage(int key) { 439 logger.entry(key); 440 441 String value = messages[key]; 442 443 logger.exit(value); 444 return value; 445 } 446 447 private int getKey() { 448 logger.entry(); 449 int key = rand.nextInt(messages.length); 450 logger.exit(key); 451 return key; 452 } 453}</pre> 454 455 <p>This test application uses the preceding service to generate 456 logging events. 457 </p> 458 459 <pre class="prettyprint source">package com.test; 460 461public class App { 462 public static void main( String[] args ) { 463 TestService service = new TestService(); 464 service.retrieveMessage(); 465 service.retrieveMessage(); 466 service.exampleException(); 467 } 468} </pre> 469 470 <p>The configuration below will cause all output to be routed to 471 target/test.log. The pattern for the FileAppender includes the 472 class name, line number and method name. Including these in the 473 pattern are critical for the log to be of value. 474 </p> 475 476 <pre class="prettyprint source"><?xml version='1.0' encoding='UTF-8'?> 477<configuration> 478 <appender name="console" class="ch.qos.logback.core.ConsoleAppender"> 479 <filter class="ch.qos.logback.classic.filter.LevelFilter"> 480 <level>ERROR</level> 481 <onMatch>ACCEPT</onMatch> 482 <onMismatch>DENY</onMismatch> 483 </filter> 484 <layout class="ch.qos.logback.classic.PatternLayout"> 485 <Pattern>%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n</Pattern> 486 </layout> 487 </appender> 488 <appender name="log" class="ch.qos.logback.core.FileAppender"> 489 <File>target/test.log</File> 490 <Append>false</Append> 491 <layout class="ch.qos.logback.classic.PatternLayout"> 492 <Pattern>%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n</Pattern> 493 </layout> 494 </appender> 495 496 <root> 497 <level value="trace" /> 498 <appender-ref ref="log" /> 499 </root> 500</configuration> 501</pre> 502 <p> 503 Here is the output that results from the Java classes and configuration above. 504 </p> 505<p class="source">00:07:57.725 TRACE com.test.TestService:22 retrieveMessage - entry 50600:07:57.738 TRACE com.test.TestService:57 getKey - entry 50700:07:57.739 TRACE com.test.TestService:59 getKey - exit with (0) 50800:07:57.741 TRACE com.test.TestService:47 getMessage - entry with (0) 50900:07:57.741 TRACE com.test.TestService:51 getMessage - exit with (Hello, World) 51000:07:57.742 TRACE com.test.TestService:26 retrieveMessage - exit with (Hello, World) 51100:07:57.742 TRACE com.test.TestService:22 retrieveMessage - entry 51200:07:57.742 TRACE com.test.TestService:57 getKey - entry 51300:07:57.743 TRACE com.test.TestService:59 getKey - exit with (1) 51400:07:57.745 TRACE com.test.TestService:47 getMessage - entry with (1) 51500:07:57.745 TRACE com.test.TestService:51 getMessage - exit with (Goodbye Cruel World) 51600:07:57.746 TRACE com.test.TestService:26 retrieveMessage - exit with (Goodbye Cruel World) 51700:07:57.746 TRACE com.test.TestService:32 exampleException - entry 51800:07:57.750 ERROR com.test.TestService:40 exampleException - catching 519java.lang.ArrayIndexOutOfBoundsException: 3 520 at com.test.TestService.exampleException(TestService.java:35) 521 at com.test.AppTest.testApp(AppTest.java:39) 522 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 523 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 524 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 525 at java.lang.reflect.Method.invoke(Method.java:585) 526 at junit.framework.TestCase.runTest(TestCase.java:154) 527 at junit.framework.TestCase.runBare(TestCase.java:127) 528 at junit.framework.TestResult$1.protect(TestResult.java:106) 529 at junit.framework.TestResult.runProtected(TestResult.java:124) 530 at junit.framework.TestResult.run(TestResult.java:109) 531 at junit.framework.TestCase.run(TestCase.java:118) 532 at junit.framework.TestSuite.runTest(TestSuite.java:208) 533 at junit.framework.TestSuite.run(TestSuite.java:203) 534 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 535 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 536 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 537 at java.lang.reflect.Method.invoke(Method.java:585) 538 at org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:213) 539 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140) 540 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127) 541 at org.apache.maven.surefire.Surefire.run(Surefire.java:177) 542 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 543 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 544 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 545 at java.lang.reflect.Method.invoke(Method.java:585) 546 at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338) 547 at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997) 54800:07:57.750 TRACE com.test.TestService:42 exampleException - exit</p> 549 550 <p>Simply changing the root logger level to DEBUG in the example 551 above will reduce the output considerably. 552 </p> 553 <p class="source">00:28:06.004 ERROR com.test.TestService:40 exampleException - catching 554java.lang.ArrayIndexOutOfBoundsException: 3 555 at com.test.TestService.exampleException(TestService.java:35) 556 at com.test.AppTest.testApp(AppTest.java:39) 557 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 558 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 559 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 560 at java.lang.reflect.Method.invoke(Method.java:585) 561 at junit.framework.TestCase.runTest(TestCase.java:154) 562 at junit.framework.TestCase.runBare(TestCase.java:127) 563 at junit.framework.TestResult$1.protect(TestResult.java:106) 564 at junit.framework.TestResult.runProtected(TestResult.java:124) 565 at junit.framework.TestResult.run(TestResult.java:109) 566 at junit.framework.TestCase.run(TestCase.java:118) 567 at junit.framework.TestSuite.runTest(TestSuite.java:208) 568 at junit.framework.TestSuite.run(TestSuite.java:203) 569 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 570 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 571 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 572 at java.lang.reflect.Method.invoke(Method.java:585) 573 at org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:213) 574 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140) 575 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127) 576 at org.apache.maven.surefire.Surefire.run(Surefire.java:177) 577 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 578 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 579 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 580 at java.lang.reflect.Method.invoke(Method.java:585) 581 at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338) 582 at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997) </p> 583 584 <!-- .............................................................. --> 585 586 <h2><a name="event_logger"></a>Event Logging</h2> 587 588 <p>The EventLogger class provides a simple mechanism for logging events that occur in an application. 589 While the EventLogger is useful as a way of initiating events that should be processed by an audit 590 Logging system, it does not implement any of the features an audit logging system would require 591 such as guaranteed delivery.</p> 592 593 <p>The recommended way of using the EventLogger in a typical web application is to populate 594 the SLF4J MDC with data that is related to the entire lifespan of the request such as the user's id, 595 the user's ip address, the product name, etc. This can easily be done in a servlet filter where 596 the MDC can also be cleared at the end of the request. When an event that needs to be recorded 597 occurs an EventData object should be created and populated. Then call EventLogger.logEvent(data) 598 where data is a reference to the EventData object.</p> 599 600 <pre class="prettyprint source">import org.slf4j.MDC; 601import org.apache.commons.lang.time.DateUtils; 602 603import javax.servlet.Filter; 604import javax.servlet.FilterConfig; 605import javax.servlet.ServletException; 606import javax.servlet.ServletRequest; 607import javax.servlet.ServletResponse; 608import javax.servlet.FilterChain; 609import javax.servlet.http.HttpSession; 610import javax.servlet.http.HttpServletRequest; 611import javax.servlet.http.Cookie; 612import javax.servlet.http.HttpServletResponse; 613import java.io.IOException; 614import java.util.TimeZone; 615 616public class RequestFilter implements Filter 617{ 618 private FilterConfig filterConfig; 619 private static String TZ_NAME = "timezoneOffset"; 620 621 public void init(FilterConfig filterConfig) throws ServletException { 622 this.filterConfig = filterConfig; 623 } 624 625 /** 626 * Sample filter that populates the MDC on every request. 627 */ 628 public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, 629 FilterChain filterChain) throws IOException, ServletException { 630 HttpServletRequest request = (HttpServletRequest)servletRequest; 631 HttpServletResponse response = (HttpServletResponse)servletResponse; 632 MDC.put("ipAddress", request.getRemoteAddr()); 633 HttpSession session = request.getSession(false); 634 TimeZone timeZone = null; 635 if (session != null) { 636 // Something should set this after authentication completes 637 String loginId = (String)session.getAttribute("LoginId"); 638 if (loginId != null) { 639 MDC.put("loginId", loginId); 640 } 641 // This assumes there is some javascript on the user's page to create the cookie. 642 if (session.getAttribute(TZ_NAME) == null) { 643 if (request.getCookies() != null) { 644 for (Cookie cookie : request.getCookies()) { 645 if (TZ_NAME.equals(cookie.getName())) { 646 int tzOffsetMinutes = Integer.parseInt(cookie.getValue()); 647 timeZone = TimeZone.getTimeZone("GMT"); 648 timeZone.setRawOffset((int)(tzOffsetMinutes * DateUtils.MILLIS_PER_MINUTE)); 649 request.getSession().setAttribute(TZ_NAME, tzOffsetMinutes); 650 cookie.setMaxAge(0); 651 response.addCookie(cookie); 652 } 653 } 654 } 655 } 656 } 657 MDC.put("hostname", servletRequest.getServerName()); 658 MDC.put("productName", filterConfig.getInitParameter("ProductName")); 659 MDC.put("locale", servletRequest.getLocale().getDisplayName()); 660 if (timeZone == null) { 661 timeZone = TimeZone.getDefault(); 662 } 663 MDC.put("timezone", timeZone.getDisplayName()); 664 filterChain.doFilter(servletRequest, servletResponse); 665 MDC.clear(); 666 } 667 668 public void destroy() { 669 } 670} </pre> 671 672 <p>Sample class that uses EventLogger.</p> 673 <pre class="prettyprint source">import org.slf4j.ext.EventData; 674import org.slf4j.ext.EventLogger; 675 676import java.util.Date; 677import java.util.UUID; 678 679public class MyApp { 680 681 public String doFundsTransfer(Account toAccount, Account fromAccount, long amount) { 682 toAccount.deposit(amount); 683 fromAccount.withdraw(amount); 684 EventData data = new EventData(); 685 data.setEventDateTime(new Date()); 686 data.setEventType("transfer"); 687 String confirm = UUID.randomUUID().toString(); 688 data.setEventId(confirm); 689 data.put("toAccount", toAccount); 690 data.put("fromAccount", fromAccount); 691 data.put("amount", amount); 692 EventLogger.logEvent(data); 693 return confirm; 694 } 695} </pre> 696 697 <p>The EventLogger class uses a Logger named "EventLogger". EventLogger uses a logging level 698 of INFO. The following shows a configuration using Logback.</p> 699 <pre class="prettyprint source"><configuration> 700 <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> 701 <layout class="ch.qos.logback.classic.PatternLayout"> 702 <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern> 703 </layout> 704 </appender> 705 706 <appender name="events" class="ch.qos.logback.core.ConsoleAppender"> 707 <layout class="ch.qos.logback.classic.PatternLayout"> 708 <Pattern>%d{HH:mm:ss.SSS} %X - %msg%n</Pattern> 709 </layout> 710 </appender> 711 712 <logger name="EventLogger" additivity="false"> 713 <level value="INFO"/> 714 <appender appender-ref="events"/> 715 </logger> 716 717 <root level="DEBUG"> 718 <appender-ref ref="STDOUT" /> 719 </root> 720 721</configuration> </pre> 722 723 <!-- .............................................................. --> 724 725 <h2><a name="javaagent"></a>Adding logging with Java agent</h2> 726 727 <p><b>NOTE: BETA RELEASE, NOT PRODUCTION QUALITY</b> </p> 728 729 <p>Quickstart for the impatient:</p> 730 731 <ol> 732 <li>Use Java 5 or later.</li> 733 <li>Download slf4j-ext-${project.version}.jar and javassist.jar, and put them 734 both in the same directory.</li> 735 <li>Ensure your application is properly configured with 736 slf4j-api-${project.version}.jar and a suitable backend.</li> 737 738 <li>Instead of "java ..." use "java --javaagent:PATH/slf4j-ext-${project.version}.jar=time,verbose,level=info ..." 739 <br/> 740 (replace PATH with the path to the jar) 741 </li> 742 <li>That's it!</li> 743 </ol> 744 745 <p>In some applications logging is used to trace the actual 746 execution of the application as opposed to log an occasional event. 747 One approach is using the <a href="#extended_logger">extended 748 logger</a> to add statements as appropriately, but another is to use 749 a tool which modifies compiled bytecode to add these statements! 750 Many exist, and the one included in slf4j-ext is not intended to 751 compete with these, but merely provide a quick way to get very basic 752 trace information from a given application. 753 </p> 754 755 <p>Java 5 added the Java Instrumentation mechanism, which allows you 756 to provide "Java agents" that can inspect and modify the byte code 757 of the classes as they are loaded. This allows the original class 758 files to remain unchanged, and the transformations done on the byte 759 codes depend on the needs at launch time. 760 </p> 761 762 <p>Given the well-known "Hello World" example:</p> 763 764 <pre class="prettyprint source">public class HelloWorld { 765 public static void main(String args[]) { 766 System.out.println("Hello World"); 767 } 768}</pre> 769 770 <p>a typical transformation would be similar to: (imports omitted)</p> 771 772 <pre class="prettyprint source">public class LoggingHelloWorld { 773 final static Logger _log = LoggerFactory.getLogger(LoggingHelloWorld.class.getName()); 774 775 public static void main(String args[]) { 776 if (_log.isInfoEnabled()) { 777 _log.info("> main(args=" + Arrays.asList(args) + ")"); 778 } 779 System.out.println("Hello World"); 780 if (_log.isInfoEnabled()) { 781 _log.info("< main()"); 782 } 783 } 784}</pre> 785 786 <p>which in turn produces the following result when run similar to 787 "java LoggingHelloWorld 1 2 3 4": 788 </p> 789 790 <p class="source">1 [main] INFO LoggingHelloWorld - > main(args=[1, 2, 3, 4]) 791Hello World 7921 [main] INFO LoggingHelloWorld - < main()</p> 793 794 <p>The same effect could have been had by using this command (with 795 the relative path to javassist.jar and 796 slf4j-ext-${project.version}.jar being ../jars):</p> 797 798 <p class="source">java -javaagent:../jars/slf4j-ext-${project.version}.jar HelloWorld 1 2 3 4</p> 799 800 <p></p> 801 802 803 <h3>How to use</h3> 804 <p>The javaagent may take one or more options separated by comma. The following options 805 are currently supported:</p> 806 807 <dl> 808 <dt><b>level</b>=X</dt> 809 <dd>The log level to use for the generated log statements. X is 810 one of "info", "debug" or "trace". Default is "info".</dd> 811 812 <dt><b>time</b></dt> 813 <dd>Print out the current date at program start, and again when 814 the program ends plus the execution time in milliseconds.</dd> 815 816 <dt><b>verbose</b></dt> 817 <dd>Print out when a class is processed as part of being loaded</dd> 818 819 <dt><b>ignore</b>=X:Y:...</dt> 820 <dd>(Advanced) Provide full list of colon separated prefixes of 821 class names NOT to add logging to. The default list is 822 "org/slf4j/:ch/qos/logback/:org/apache/log4j/". This does not override the fact that a class must be able to access the 823 slf4j-api classes in order to do logging, so if these classes are not visible to a given class it is not instrumented. 824 </dd> 825 </dl> 826 827 828 <p>Some classes may misbehave when being rendered with "object.toString()" so they may be explicitly disabled 829 in the logback configuration file permanently. For instance the ToStringBuilder in the Apache Jakarta commons lang 830 package is a prime candidate for this. For logback add this snippet to logback.xml: 831 <pre><logger name="org.apache.commons.lang.builder" level="OFF" /></pre> 832 </p> 833 834 835 836 <p>Note: These are not finalized yet, and may change.</p> 837 838 <h3>Locations of jar files</h3> 839 840 <p>The javassist library is used for the actual byte code 841 manipulation and must be available to be able to add any logging 842 statements. slf4j-ext-${project.version} has been configured to 843 look for the following: 844 </p> 845 846 <ul> 847 <li>"javassist-3.4.GA.jar" relatively to 848 slf4j-ext-${project.version}.jar as would be if Maven had downloaded 849 both from the repository and slf4j-ext-${project.version}.jar was 850 referenced directly in the Maven repository in the 851 "-javaagent"-argument.</li> 852 <li>"javassist-3.4.GA.jar" in the same directory as slf4j-ext</li> 853 <li>"javassist.jar" in the same directory as slf4j-ext</li> 854 </ul> 855 856 <p>A warning message is printed if the javassist library was not 857 found by the agent, and options requiring byte code transformations will not work. 858 </p> 859 860 861 <h3>Misc notes</h3> 862 863 <ul> 864 <li>A java agent is not invoked on any classes already loaded by the 865 class loader.</li> 866 <li>Exceptions in the java agent that would normally have been 867 printed, may be silently swallowed by the JVM.</li> 868 <li>The javaagent only logs to System.err.</li> 869 <li>The name of the logger variable is fixed (to a value unlikely to be used) so if that 870 name is already used, a failure occurs. This should be changed to determine 871 an unused name and use that instead.</li> 872 <li>Empty methods are not instrumented (an incorrect check for an interface). They should be</li> 873 874 </ul> 875 876 <p>(The agent is an adaption of the java.util.logging version 877 described in <a 878 href="http://today.java.net/pub/a/today/2008/04/24/add-logging-at-class-load-time-with-instrumentation.html" 879 >http://today.java.net/pub/a/today/2008/04/24/add-logging-at-class-load-time-with-instrumentation.html</a>) 880 </p> 881 882 <script src="templates/footer.js" type="text/javascript"></script> 883</div> 884</body> 885</html> 886 887