Google Git
Sign in
android / platform / external / slf4j / 9057c64dfe3e552f0801483d1f9368226e9e1ae3 / . / slf4j-site / src / site / pages / extensions.html
blob: d46958109e35e7f6e27b43f3c6e397905ba01cb7 [file] [log] [blame]
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]1<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
2 "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
3
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]4<html xmlns="http://www.w3.org/1999/xhtml">
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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" />
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]10 <link rel="stylesheet" type="text/css" href="css/prettify.css" />
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]11 </head>
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]12 <body onload="prettyPrint()">
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]13 <script type="text/javascript">prefix='';</script>
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]14 <script type="text/javascript" src="js/prettify.js"></script>
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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">
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]20
21 <h1>SLF4J extensions</h1>
22
23 <p>SLF4J extensions are packaged within <em>slf4j-ext.jar</em>
Thorbjorn Ravn Andersen41145152008-11-12 20:15:53 +0000[diff] [blame]24 which ships with SLF4J. </p>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]25
Thorbjorn Ravn Andersen41145152008-11-12 20:15:53 +0000[diff] [blame]26
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]27 <ul>
28 <li><a href="#profiler">Profiler</a></li>
29 <li><a href="#extended_logger">Extended logger</a></li>
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]30 <li><a href="#event_logger">Event Logging</a></li>
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]31 <li><a href="#javaagent">Logging added with Java agent (requires Java 5)</a></li>
32 </ul>
Thorbjorn Ravn Andersen41145152008-11-12 20:15:53 +0000[diff] [blame]33
34 <h2><a name="profiler"></a>Profilers</h2>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]60 <pre class="prettyprint source">[omitted]
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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 }
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]76[omitted]</pre>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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
Ceki Gulcu03319122008-10-16 16:55:17 +0000[diff] [blame]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.
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]123 <pre class="prettyprint source">33 public class NestedProfilerDemo {
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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 }
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]15262 }</pre>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]159 <pre class="prettyprint source">[omitted]
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]1606 public class SortAndPruneComposites {
1617
1628 static String NESTED_PROFILER_NAME = "SORT_AND_PRUNE";
1639
16410 final int[] originalArray;
Craig P. Motlin4b710c82013-12-14 19:01:57 -0500[diff] [blame]16511 final int originalArrayLength;
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]16612
16713 public SortAndPruneComposites(int[] randomArray) {
16814 this.originalArray = randomArray;
Craig P. Motlin4b710c82013-12-14 19:01:57 -0500[diff] [blame]16915 this.originalArrayLength = randomArray.length;
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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 }
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]187[omitted] </pre>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]233 <pre class="prettyprint source">[omitted]
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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 }
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]25942 } </pre>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]280 <pre class="prettyprint source">&lt;configuration>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]281
282 <b>&lt;turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
283 &lt;Marker>PROFILER&lt;/Marker>
284 &lt;OnMatch>DENY&lt;/OnMatch>
285 &lt;/turboFilter></b>
286
287 &lt;appender name="STDOUT"
288 class="ch.qos.logback.core.ConsoleAppender">
289 &lt;layout class="ch.qos.logback.classic.PatternLayout">
290 &lt;Pattern>%-5level %logger{36} - %msg%n&lt;/Pattern>
291 &lt;/layout>
292 &lt;/appender>
293
294 &lt;root>
295 &lt;level value="DEBUG" />
296 &lt;appender-ref ref="STDOUT" />
297 &lt;/root>
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]298&lt;/configuration> </pre>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]299
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]300
Ralph Goers52d3f242008-11-15 22:10:29 +0000[diff] [blame]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>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]325
326<!-- .............................................................. -->
327
328 <h2><a name="extended_logger"></a>Extended Logger</h2>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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
Craig P. Motlin4b710c82013-12-14 19:01:57 -0500[diff] [blame]346 <li>help educate new developers in learning the application.</li>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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
Craig P. Motlin4b710c82013-12-14 19:01:57 -0500[diff] [blame]372 RuntimeException. This will insure that proper diagnostics are
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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
Thorbjorn Ravn Andersen0a0d6342008-12-27 23:37:28 +0000[diff] [blame]391 <p>Note that XLogger instances are obtained to through the
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]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
Craig P. Motlin4b710c82013-12-14 19:01:57 -0500[diff] [blame]397 methods in a fairly typical manner. The <code>throwing()</code>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]398 method is not present since no Exceptions are explicitly thrown and
399 not handled.
400 </p>
401
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]402 <pre class="prettyprint source">package com.test;
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]403
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]404import org.slf4j.ext.XLogger;
405import org.slf4j.ext.XLoggerFactory;
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]406
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]407import java.util.Random;
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]408
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]409public class TestService {
410 private XLogger logger = XLoggerFactory.getXLogger(TestService.class
411 .getName());
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]412
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]413 private String[] messages = new String[] { "Hello, World",
414 "Goodbye Cruel World", "You had me at hello" };
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]415
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]416 private Random rand = new Random(1);
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]417
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]418 public String retrieveMessage() {
419 logger.entry();
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]420
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]421 String testMsg = getMessage(getKey());
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]422
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]423 logger.exit(testMsg);
424 return testMsg;
425 }
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]426
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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);
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]434 }
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]435 logger.exit();
436 }
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]437
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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 }
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]453}</pre>
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]454
455 <p>This test application uses the preceding service to generate
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]456 logging events.
457 </p>
458
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]459 <pre class="prettyprint source">package com.test;
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]460
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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 }
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]468} </pre>
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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.
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]474 </p>
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]475
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]476 <pre class="prettyprint source">&lt;?xml version='1.0' encoding='UTF-8'?>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]477&lt;configuration&gt;
478 &lt;appender name="console" class="ch.qos.logback.core.ConsoleAppender"&gt;
479 &lt;filter class="ch.qos.logback.classic.filter.LevelFilter"&gt;
480 &lt;level&gt;ERROR&lt;/level&gt;
481 &lt;onMatch&gt;ACCEPT&lt;/onMatch&gt;
482 &lt;onMismatch&gt;DENY&lt;/onMismatch&gt;
483 &lt;/filter&gt;
484 &lt;layout class="ch.qos.logback.classic.PatternLayout"&gt;
485 &lt;Pattern&gt;%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n&lt;/Pattern&gt;
486 &lt;/layout&gt;
487 &lt;/appender&gt;
488 &lt;appender name="log" class="ch.qos.logback.core.FileAppender"&gt;
489 &lt;File&gt;target/test.log&lt;/File&gt;
490 &lt;Append&gt;false&lt;/Append&gt;
491 &lt;layout class="ch.qos.logback.classic.PatternLayout"&gt;
492 &lt;Pattern&gt;%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n&lt;/Pattern&gt;
493 &lt;/layout&gt;
494 &lt;/appender&gt;
495
496 &lt;root&gt;
497 &lt;level value="trace" /&gt;
498 &lt;appender-ref ref="log" /&gt;
499 &lt;/root&gt;
500&lt;/configuration&gt;
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]501</pre>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]502 <p>
503 Here is the output that results from the Java classes and configuration above.
504 </p>
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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.
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]552 </p>
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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>
Thorbjorn Ravn Andersen41145152008-11-12 20:15:53 +0000[diff] [blame]583
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]584 <!-- .............................................................. -->
585
586 <h2><a name="event_logger"></a>Event Logging</h2>
587
Craig P. Motlin4b710c82013-12-14 19:01:57 -0500[diff] [blame]588 <p>The EventLogger class provides a simple mechanism for logging events that occur in an application.
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]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
Dale9b073242012-05-29 11:57:30 +0300[diff] [blame]593 <p>The recommended way of using the EventLogger in a typical web application is to populate
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]594 the SLF4J MDC with data that is related to the entire lifespan of the request such as the user's id,
Craig P. Motlin4b710c82013-12-14 19:01:57 -0500[diff] [blame]595 the user's ip address, the product name, etc. This can easily be done in a servlet filter where
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]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
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]600 <pre class="prettyprint source">import org.slf4j.MDC;
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]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 }
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]670} </pre>
671
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]672 <p>Sample class that uses EventLogger.</p>
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]673 <pre class="prettyprint source">import org.slf4j.ext.EventData;
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]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 }
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]695} </pre>
696
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]697 <p>The EventLogger class uses a Logger named "EventLogger". EventLogger uses a logging level
Craig P. Motlin4b710c82013-12-14 19:01:57 -0500[diff] [blame]698 of INFO. The following shows a configuration using Logback.</p>
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]699 <pre class="prettyprint source">&lt;configuration&gt;
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]700 &lt;appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"&gt;
701 &lt;layout class="ch.qos.logback.classic.PatternLayout"&gt;
702 &lt;Pattern&gt;%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n&lt;/Pattern&gt;
703 &lt;/layout&gt;
704 &lt;/appender&gt;
705
706 &lt;appender name="events" class="ch.qos.logback.core.ConsoleAppender"&gt;
707 &lt;layout class="ch.qos.logback.classic.PatternLayout"&gt;
708 &lt;Pattern&gt;%d{HH:mm:ss.SSS} %X - %msg%n&lt;/Pattern&gt;
709 &lt;/layout&gt;
710 &lt;/appender&gt;
711
712 &lt;logger name="EventLogger" additivity="false"&gt;
713 &lt;level value="INFO"/&gt;
714 &lt;appender appender-ref="events"/&gt;
715 &lt;/logger&gt;
716
717 &lt;root level="DEBUG"&gt;
718 &lt;appender-ref ref="STDOUT" /&gt;
719 &lt;/root&gt;
720
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]721&lt;/configuration&gt; </pre>
Ralph Goers42b42f72009-02-26 23:18:58 +0000[diff] [blame]722
723 <!-- .............................................................. -->
724
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]725 <h2><a name="javaagent"></a>Adding logging with Java agent</h2>
Thorbjorn Ravn Andersen41145152008-11-12 20:15:53 +0000[diff] [blame]726
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]727 <p><b>NOTE: BETA RELEASE, NOT PRODUCTION QUALITY</b> </p>
Thorbjorn Ravn Andersen41145152008-11-12 20:15:53 +0000[diff] [blame]728
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]729 <p>Quickstart for the impatient:</p>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]730
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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
Ceki Gulcu5e1276d2008-11-13 11:38:41 +0000[diff] [blame]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/>
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]740 (replace PATH with the path to the jar)
741 </li>
742 <li>That's it!</li>
743 </ol>
Thorbjorn Ravn Andersen41145152008-11-12 20:15:53 +0000[diff] [blame]744
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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>
Thorbjorn Ravn Andersen41145152008-11-12 20:15:53 +0000[diff] [blame]754
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]761
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]762 <p>Given the well-known "Hello World" example:</p>
763
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]764 <pre class="prettyprint source">public class HelloWorld {
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]765 public static void main(String args[]) {
766 System.out.println("Hello World");
767 }
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]768}</pre>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]769
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]770 <p>a typical transformation would be similar to: (imports omitted)</p>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]771
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]772 <pre class="prettyprint source">public class LoggingHelloWorld {
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]773 final static Logger _log = LoggerFactory.getLogger(LoggingHelloWorld.class.getName());
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]774
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]775 public static void main(String args[]) {
776 if (_log.isInfoEnabled()) {
777 _log.info("> main(args=" + Arrays.asList(args) + ")");
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]778 }
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]779 System.out.println("Hello World");
780 if (_log.isInfoEnabled()) {
781 _log.info("&lt; main()");
782 }
783 }
Ceki Gulcue69cd9f2009-09-04 19:50:15 +0200[diff] [blame]784}</pre>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]785
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]786 <p>which in turn produces the following result when run similar to
787 "java LoggingHelloWorld 1 2 3 4":
788 </p>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]789
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]790 <p class="source">1 [main] INFO LoggingHelloWorld - > main(args=[1, 2, 3, 4])
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]791Hello World
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]7921 [main] INFO LoggingHelloWorld - &lt; main()</p>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]793
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]797
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]798 <p class="source">java -javaagent:../jars/slf4j-ext-${project.version}.jar HelloWorld 1 2 3 4</p>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]799
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]800 <p></p>
Thorbjorn Ravn Andersen41145152008-11-12 20:15:53 +0000[diff] [blame]801
802
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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>
Thorbjorn Ravn Andersen41145152008-11-12 20:15:53 +0000[diff] [blame]806
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]818
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]819 <dt><b>ignore</b>=X:Y:...</dt>
820 <dd>(Advanced) Provide full list of colon separated prefixes of
Thorbjorn Ravn Andersen05e2e712008-11-14 22:50:07 +0000[diff] [blame]821 class names NOT to add logging to. The default list is
Thorbjorn Ravn Andersen0a0d6342008-12-27 23:37:28 +0000[diff] [blame]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.
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]824 </dd>
825 </dl>
Thorbjorn Ravn Andersene5151762009-01-11 13:11:48 +0000[diff] [blame]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>&lt;logger name="org.apache.commons.lang.builder" level="OFF" /&gt;</pre>
832 </p>
833
834
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]835
836 <p>Note: These are not finalized yet, and may change.</p>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]837
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]838 <h3>Locations of jar files</h3>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]839
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]845
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]846 <ul>
847 <li>"javassist-3.4.GA.jar" relatively to
Ceki Gulcu5c4bca12008-11-13 11:36:38 +0000[diff] [blame]848 slf4j-ext-${project.version}.jar as would be if Maven had downloaded
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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
Thorbjorn Ravn Andersen0a0d6342008-12-27 23:37:28 +0000[diff] [blame]857 found by the agent, and options requiring byte code transformations will not work.
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]858 </p>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]859
860
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]861 <h3>Misc notes</h3>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]862
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]863 <ul>
Thorbjorn Ravn Andersen0a0d6342008-12-27 23:37:28 +0000[diff] [blame]864 <li>A java agent is not invoked on any classes already loaded by the
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]865 class loader.</li>
Thorbjorn Ravn Andersen0a0d6342008-12-27 23:37:28 +0000[diff] [blame]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>
Thorbjorn Ravn Andersende0c6e52008-11-14 23:09:36 +0000[diff] [blame]869 <li>The name of the logger variable is fixed (to a value unlikely to be used) so if that
Craig P. Motlin4b710c82013-12-14 19:01:57 -0500[diff] [blame]870 name is already used, a failure occurs. This should be changed to determine
Thorbjorn Ravn Andersende0c6e52008-11-14 23:09:36 +0000[diff] [blame]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
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]874 </ul>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]875
Ceki Gulcu09a33ba2008-11-13 11:34:03 +0000[diff] [blame]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>
Ceki Gulcu8026cf32008-11-21 14:20:41 +0000[diff] [blame]881
882 <script src="templates/footer.js" type="text/javascript"></script>
Thorbjorn Ravn Andersenda3197e2008-11-12 23:11:19 +0000[diff] [blame]883</div>
Ceki Gulcu7d4b1e92008-10-16 15:27:03 +0000[diff] [blame]884</body>
885</html>
886