Return-Path: X-Original-To: apmail-logging-commits-archive@minotaur.apache.org Delivered-To: apmail-logging-commits-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id C31C59870 for ; Sun, 5 Feb 2012 21:50:29 +0000 (UTC) Received: (qmail 76586 invoked by uid 500); 5 Feb 2012 21:50:29 -0000 Delivered-To: apmail-logging-commits-archive@logging.apache.org Received: (qmail 76556 invoked by uid 500); 5 Feb 2012 21:50:29 -0000 Mailing-List: contact commits-help@logging.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@logging.apache.org Delivered-To: mailing list commits@logging.apache.org Received: (qmail 76549 invoked by uid 99); 5 Feb 2012 21:50:29 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 05 Feb 2012 21:50:29 +0000 X-ASF-Spam-Status: No, hits=-2000.0 required=5.0 tests=ALL_TRUSTED X-Spam-Check-By: apache.org Received: from [140.211.11.4] (HELO eris.apache.org) (140.211.11.4) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 05 Feb 2012 21:50:25 +0000 Received: from eris.apache.org (localhost [127.0.0.1]) by eris.apache.org (Postfix) with ESMTP id D7D6E2388A40; Sun, 5 Feb 2012 21:50:05 +0000 (UTC) Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Subject: svn commit: r1240834 - in /logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers: log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ src/site/ src/site/xdoc/manual/ Date: Sun, 05 Feb 2012 21:50:05 -0000 To: commits@logging.apache.org From: rgoers@apache.org X-Mailer: svnmailer-1.0.8-patched Message-Id: <20120205215005.D7D6E2388A40@eris.apache.org> Author: rgoers Date: Sun Feb 5 21:50:04 2012 New Revision: 1240834 URL: http://svn.apache.org/viewvc?rev=1240834&view=rev Log: Finish documenting the API Added: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/eventlogging.xml - copied, changed from r1236171, logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/flowtracing.xml - copied, changed from r1236171, logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/markers.xml - copied, changed from r1236171, logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml Modified: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ExtendedThrowablePatternConverter.java logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/PatternParser.java logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverter.java logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowablePatternConverter.java logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/site.xml logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/messages.xml logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/thread-context.xml Modified: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ExtendedThrowablePatternConverter.java URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ExtendedThrowablePatternConverter.java?rev=1240834&r1=1240833&r2=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ExtendedThrowablePatternConverter.java (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ExtendedThrowablePatternConverter.java Sun Feb 5 21:50:04 2012 @@ -64,6 +64,10 @@ public final class ExtendedThrowablePatt } ThrowableProxy t = (ThrowableProxy) throwable; String trace = t.getExtendedStackTrace(); + int len = toAppendTo.length(); + if (len > 0 && !Character.isWhitespace(toAppendTo.charAt(len - 1))) { + toAppendTo.append(" "); + } if (lines > 0) { StringBuilder sb = new StringBuilder(); String[] array = trace.split("\n"); Modified: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/PatternParser.java URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/PatternParser.java?rev=1240834&r1=1240833&r2=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/PatternParser.java (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/PatternParser.java Sun Feb 5 21:50:04 2012 @@ -414,7 +414,7 @@ public final class PatternParser { return null; } - Method[] methods = converterClass.getMethods(); + Method[] methods = converterClass.getDeclaredMethods(); Method newInstance = null; for (Method method : methods) { if (method.getName().equals("newInstance")) { Modified: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverter.java URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverter.java?rev=1240834&r1=1240833&r2=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverter.java (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverter.java Sun Feb 5 21:50:04 2012 @@ -65,6 +65,10 @@ public final class RootThrowablePatternC } ThrowableProxy t = (ThrowableProxy) throwable; String trace = t.getRootCauseStackTrace(); + int len = toAppendTo.length(); + if (len > 0 && !Character.isWhitespace(toAppendTo.charAt(len - 1))) { + toAppendTo.append(" "); + } if (lines > 0) { StringBuilder sb = new StringBuilder(); String[] array = trace.split("\n"); Modified: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowablePatternConverter.java URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowablePatternConverter.java?rev=1240834&r1=1240833&r2=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowablePatternConverter.java (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/log4j2-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowablePatternConverter.java Sun Feb 5 21:50:04 2012 @@ -96,6 +96,10 @@ public class ThrowablePatternConverter e if (t != null) { StringWriter w = new StringWriter(); t.printStackTrace(new PrintWriter(w)); + int len = toAppendTo.length(); + if (len > 0 && !Character.isWhitespace(toAppendTo.charAt(len - 1))) { + toAppendTo.append(" "); + } if (lines > 0) { StringBuilder sb = new StringBuilder(); String[] array = w.toString().split("\n"); Modified: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/site.xml URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/site.xml?rev=1240834&r1=1240833&r2=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/site.xml (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/site.xml Sun Feb 5 21:50:04 2012 @@ -48,8 +48,9 @@ - - + + + Modified: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml?rev=1240834&r1=1240833&r2=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml Sun Feb 5 21:50:04 2012 @@ -73,15 +73,6 @@ only occur when debug logging is enabled.

- - - - - - - - - \ No newline at end of file Copied: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/eventlogging.xml (from r1236171, logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml) URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/eventlogging.xml?p2=logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/eventlogging.xml&p1=logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml&r1=1236171&r2=1240834&rev=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/eventlogging.xml Sun Feb 5 21:50:04 2012 @@ -24,64 +24,118 @@
- - -

- The Log4Jj 2.0 API provides the interface that applications should code to and provides the - adapter components required for implementers to create a logging implementation. Although Log4j 2 - is broken up between an API and an implementation, the primary purpose of doing so was not to - allow multiple implementations, although that is certainly possible, but to clearly define - what classes and methods are safe to use in "normal" application code. -

-

Hello World!

+ +

- No introduction would be complete without the customary Hello, World example. Here is ours. First, - a Logger with the name "HelloWorld" is obtained from the LogManager. Next, the logger is used to - write the "Hello, World!" message, however the message will be written only if the Logger is - configured to allow informational messages. -

- import org.apache.logging.log4j.LogManager; - import org.apache.logging.log4j.Logger; + The EventLogger class provides a simple mechansim 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, by itself it does not implement any of the features an audit logging system would require + such as guaranteed delivery. +

+

The recommended way of using the EventLogger in a typcial web application is to populate + the ThreadContext Map 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 fileter where + the ThreadContext Map can also be cleared at the end of the request. When an event that needs to be + recorded occurs a StructuredDataMessage should be created and populated. + Then call EventLogger.logEvent(msg) where msg is a reference to the StructuredDataMessage.

+ + import org.apache.logging.log4j.ThreadContext; + 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 class HelloWorld { - private static Logger logger = LogManager.getLogger("HelloWorld"); - public static void main(String[] args) { - logger.info("Hello, World!"); + 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; + ThreadContext.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) { + ThreadContext.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); + } + } + } + } + } + ThreadContext.put("hostname", servletRequest.getServerName()); + ThreadContext.put("productName", filterConfig.getInitParameter("ProductName")); + Threadcontext.put("locale", servletRequest.getLocale().getDisplayName()); + if (timeZone == null) { + timeZone = TimeZone.getDefault(); + } + ThreadContext.put("timezone", timeZone.getDisplayName()); + filterChain.doFilter(servletRequest, servletResponse); + ThreadContext.clear(); + } + + public void destroy() { } } -

- The output from the call to logger.info() will vary significantly depending on the configuration - used. See the Configuration section for more details. -

-

Parameter Substitution

-

- Frequently the purpose of logging is to provide information about what is happening in the system, - which requires including information about the objects being manipulated. In Log4j 1.x this could - be accomplished by doing: -

- if (logger.isDebugEnabled()) { - logger.debug("Logging in user " + user.getName() + " with id " + user.getId()); - } -

- Doing this repeatedly has the effect of making the code feel like it is more about logging than the - actual task at hand. In addition, it results in the logging level being checked twice; once on the - call to isDebugEnabled and once on the debug method. A better alternative would be: -

- logger.debug("Logging in user {} with id {}", user.getName(), user.getId()); -

- With the code above the logging level will only be checked once and the String construction will - only occur when debug logging is enabled. -

- - - +

Sample class that uses EventLogger.

+ import org.apache.logging.log4j.StructuredDataMessage; + import org.apache.logging.log4j.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); + String confirm = UUID.randomUUID().toString(); + StructuredDataMessage msg = new StructureDataMessage(confirm, null, "transfer"); + msg.put("toAccount", toAccount); + msg.put("fromAccount", fromAccount); + msg.put("amount", amount); + EventLogger.logEvent(data); + return confirm; + } + } +

The EventLogger class uses a Logger named "EventLogger". EventLogger uses a logging level + of OFF as the default to indicate that it cannot be filtered. These events can be + formatted for printing using the + StructuredDataLayout. +

+
\ No newline at end of file Copied: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/flowtracing.xml (from r1236171, logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml) URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/flowtracing.xml?p2=logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/flowtracing.xml&p1=logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml&r1=1236171&r2=1240834&rev=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/flowtracing.xml Sun Feb 5 21:50:04 2012 @@ -24,64 +24,219 @@
- - + +

- The Log4Jj 2.0 API provides the interface that applications should code to and provides the - adapter components required for implementers to create a logging implementation. Although Log4j 2 - is broken up between an API and an implementation, the primary purpose of doing so was not to - allow multiple implementations, although that is certainly possible, but to clearly define - what classes and methods are safe to use in "normal" application code. -

-

Hello World!

-

- No introduction would be complete without the customary Hello, World example. Here is ours. First, - a Logger with the name "HelloWorld" is obtained from the LogManager. Next, the logger is used to - write the "Hello, World!" message, however the message will be written only if the Logger is - configured to allow informational messages. + The Logger class provides 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 +

    +
  • aid in problem diagnosis in development without requiring a debug session
    • +
  • aid in problem diagnosis in production where no debugging is possible
    • +
  • help educate new deveopers in learning the application.
    • +

- import org.apache.logging.log4j.LogManager; - import org.apache.logging.log4j.Logger; - - public class HelloWorld { - private static Logger logger = LogManager.getLogger("HelloWorld"); - public static void main(String[] args) { - logger.info("Hello, World!"); - } - }

- The output from the call to logger.info() will vary significantly depending on the configuration - used. See the Configuration section for more details. + The two most used methods are the entry() and exit() methods. entry() should be placed at the + beginning of methods, except perhaps ofr simple getters and setters. entry() can be called + passing from 0 to 4 parameters. Typically these will be parameters passed to the method. + The entry() method logs with a level of TRACE and uses a Marker with a name of "ENTER" which + is also a "FLOW" Marker.

-

Parameter Substitution

- Frequently the purpose of logging is to provide information about what is happening in the system, - which requires including information about the objects being manipulated. In Log4j 1.x this could - be accomplished by doing: + The exit() method should be placed before any return statement or as the last statement of + methods without a return. exit() can be called with or without a parameter. Typically, methods + that return void will use exit() while methods that return an Object will use exit(Object obj). + The entry() method logs with a level of TRACE and uses a Marker with a name of "EXIT" which is + also a "FLOW" Marker.

- if (logger.isDebugEnabled()) { - logger.debug("Logging in user " + user.getName() + " with id " + user.getId()); - }

- Doing this repeatedly has the effect of making the code feel like it is more about logging than the - actual task at hand. In addition, it results in the logging level being checked twice; once on the - call to isDebugEnabled and once on the debug method. A better alternative would be: + The throwing() method can be used by an application when it is throwing an exception that is + unlikely to be handled, such as a RuntimeExcpetion. 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.

- logger.debug("Logging in user {} with id {}", user.getName(), user.getId());

- With the code above the logging level will only be checked once and the String construction will - only occur when debug logging is enabled. + The catching() method can be used by an application when it catches an Exception that it is not + going to rethrow, either explicitely 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.

- - - +

+ The following example shows a simple application using these methods in a fairly typcial manner. The + throwing() is not present since no Exceptions are explicitely thrown and not handled. +

+ package com.test; - - - + import org.apache.logging.log4j.Logger; + import org.apache.logging.log4j.LogManager; - + import java.util.Random; + + public class TestService { + private Logger logger = LogManager.getLogger(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()); + + return logger.exit(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]; + + return logger.exit(value); + } + + private int getKey() { + logger.entry(); + int key = rand.nextInt(messages.length); + return logger.exit(key); + } + } +

+ This test application uses the preceding service to generate logging events. +

+ package com.test; + + public class App { + + public static void main( String[] args ) { + TestService service = new TestService(); + service.retrieveMessage(); + service.retrieveMessage(); + service.exampleException(); + } + } +

+ 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. +

+ + + + + + + + + + + + + + + + + ]]> +

+ Here is the output that results from the Java classes and configuration above. +

+ + 19:08:07.056 TRACE com.test.TestService 19 retrieveMessage - entry + 19:08:07.060 TRACE com.test.TestService 46 getKey - entry + 19:08:07.060 TRACE com.test.TestService 48 getKey - exit with (0) + 19:08:07.060 TRACE com.test.TestService 38 getMessage - entry parms(0) + 19:08:07.060 TRACE com.test.TestService 42 getMessage - exit with (Hello, World) + 19:08:07.060 TRACE com.test.TestService 23 retrieveMessage - exit with (Hello, World) + 19:08:07.061 TRACE com.test.TestService 19 retrieveMessage - entry + 19:08:07.061 TRACE com.test.TestService 46 getKey - entry + 19:08:07.061 TRACE com.test.TestService 48 getKey - exit with (1) + 19:08:07.061 TRACE com.test.TestService 38 getMessage - entry parms(1) + 19:08:07.061 TRACE com.test.TestService 42 getMessage - exit with (Goodbye Cruel World) + 19:08:07.061 TRACE com.test.TestService 23 retrieveMessage - exit with (Goodbye Cruel World) + 19:08:07.062 TRACE com.test.TestService 27 exampleException - entry + 19:08:07.077 DEBUG com.test.TestService 32 exampleException - catching java.lang.ArrayIndexOutOfBoundsException: 3 + at com.test.TestService.exampleException(TestService.java:29) [classes/:?] + at com.test.App.main(App.java:9) [classes/:?] + at com.test.AppTest.testApp(AppTest.java:15) [test-classes/:?] + at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29] + at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29] + at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29] + at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29] + at org.junit.internal.runners.TestMethodRunner.executeMethodBody(TestMethodRunner.java:99) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestMethodRunner.runUnprotected(TestMethodRunner.java:81) [junit-4.3.1.jar:?] + at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestMethodRunner.runMethod(TestMethodRunner.java:75) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestMethodRunner.run(TestMethodRunner.java:45) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestClassMethodsRunner.invokeTestMethod(TestClassMethodsRunner.java:66) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestClassMethodsRunner.run(TestClassMethodsRunner.java:35) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestClassRunner$1.runUnprotected(TestClassRunner.java:42) [junit-4.3.1.jar:?] + at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestClassRunner.run(TestClassRunner.java:52) [junit-4.3.1.jar:?] + at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:35) [surefire-junit4-2.7.2.jar:2.7.2] + at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:115) [surefire-junit4-2.7.2.jar:2.7.2] + at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:97) [surefire-junit4-2.7.2.jar:2.7.2] + at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29] + at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29] + at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29] + at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29] + at org.apache.maven.surefire.booter.ProviderFactory$ClassLoaderProxy.invoke(ProviderFactory.java:103) [surefire-booter-2.7.2.jar:2.7.2] + at $Proxy0.invoke(Unknown Source) [?:?] + at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:150) [surefire-booter-2.7.2.jar:2.7.2] + at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcess(SurefireStarter.java:91) [surefire-booter-2.7.2.jar:2.7.2] + at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:69) [surefire-booter-2.7.2.jar:2.7.2] + 19:08:07.087 TRACE com.test.TestService 34 exampleException - exit +

+ Simply changing the root logger level to DEBUG in the example above will reduce the output + considerably. +

+ + 19:13:24.963 DEBUG com.test.TestService 32 exampleException - catching java.lang.ArrayIndexOutOfBoundsException: 3 + at com.test.TestService.exampleException(TestService.java:29) [classes/:?] + at com.test.App.main(App.java:9) [classes/:?] + at com.test.AppTest.testApp(AppTest.java:15) [test-classes/:?] + at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29] + at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29] + at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29] + at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29] + at org.junit.internal.runners.TestMethodRunner.executeMethodBody(TestMethodRunner.java:99) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestMethodRunner.runUnprotected(TestMethodRunner.java:81) [junit-4.3.1.jar:?] + at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestMethodRunner.runMethod(TestMethodRunner.java:75) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestMethodRunner.run(TestMethodRunner.java:45) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestClassMethodsRunner.invokeTestMethod(TestClassMethodsRunner.java:66) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestClassMethodsRunner.run(TestClassMethodsRunner.java:35) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestClassRunner$1.runUnprotected(TestClassRunner.java:42) [junit-4.3.1.jar:?] + at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?] + at org.junit.internal.runners.TestClassRunner.run(TestClassRunner.java:52) [junit-4.3.1.jar:?] + at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:35) [surefire-junit4-2.7.2.jar:2.7.2] + at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:115) [surefire-junit4-2.7.2.jar:2.7.2] + at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:97) [surefire-junit4-2.7.2.jar:2.7.2] + at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29] + at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29] + at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29] + at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29] + at org.apache.maven.surefire.booter.ProviderFactory$ClassLoaderProxy.invoke(ProviderFactory.java:103) [surefire-booter-2.7.2.jar:2.7.2] + at $Proxy0.invoke(Unknown Source) [?:?] + at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:150) [surefire-booter-2.7.2.jar:2.7.2] + at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcess(SurefireStarter.java:91) [surefire-booter-2.7.2.jar:2.7.2] + at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:69) [surefire-booter-2.7.2.jar:2.7.2] +
\ No newline at end of file Copied: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/markers.xml (from r1236171, logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml) URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/markers.xml?p2=logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/markers.xml&p1=logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml&r1=1236171&r2=1240834&rev=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/api.xml (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/markers.xml Sun Feb 5 21:50:04 2012 @@ -24,64 +24,74 @@
- - -

- The Log4Jj 2.0 API provides the interface that applications should code to and provides the - adapter components required for implementers to create a logging implementation. Although Log4j 2 - is broken up between an API and an implementation, the primary purpose of doing so was not to - allow multiple implementations, although that is certainly possible, but to clearly define - what classes and methods are safe to use in "normal" application code. -

-

Hello World!

+ +

- No introduction would be complete without the customary Hello, World example. Here is ours. First, - a Logger with the name "HelloWorld" is obtained from the LogManager. Next, the logger is used to - write the "Hello, World!" message, however the message will be written only if the Logger is - configured to allow informational messages. -

- import org.apache.logging.log4j.LogManager; - import org.apache.logging.log4j.Logger; + One of the primary purpose of a logging framework is to provide the means to generate debugging and + diagnostic information only when it is needed, and to allow filtering of that information so that it + does not overwhelm the system or the individuals who need to make use of it. As an example, an + application desires to log its entry, exit and other operations separately from SQL statements + being executed, and wishes to be able to log queries separate from updates. One way to accomplish + this is shown below: +

+ -

- The output from the call to logger.info() will vary significantly depending on the configuration - used. See the Configuration section for more details. -

-

Parameter Substitution

-

- Frequently the purpose of logging is to provide information about what is happening in the system, - which requires including information about the objects being manipulated. In Log4j 1.x this could - be accomplished by doing: -

- if (logger.isDebugEnabled()) { - logger.debug("Logging in user " + user.getName() + " with id " + user.getId()); - } + + public String doUpdate(String table, Map params) { + logger.entry(param); + + if (logger.isDebugEnabled()) { + logger.debug(UPDATE_MARKER, "UPDATE {} SET {}", table, formatCols); + + return logger.exit(); + } + + private String formatCols(Map cols) { + StringBuilder sb = new StringBuilder(); + boolean first = true; + for (Map.Entry entry : cols.entrySet()) { + if (!first) { + sb.append(", "); + } + sb.append(entry.getKey()).append("=").append(entry.getValue()); + first = false; + } + return sb.toString(); + } + }]]>

- Doing this repeatedly has the effect of making the code feel like it is more about logging than the - actual task at hand. In addition, it results in the logging level being checked twice; once on the - call to isDebugEnabled and once on the debug method. A better alternative would be: + In the example above it is now possible to add MarkerFilters to only allow SQL update operations + to be logged, all SQL updates to be logged or to log everything in MyApp.

- logger.debug("Logging in user {} with id {}", user.getName(), user.getId());

- With the code above the logging level will only be checked once and the String construction will - only occur when debug logging is enabled. + Some important rules about Markers must be considered when using them. +

    +
  1. Markers must be unique. They are permanently registered by name so care should be taken + to insure that Markers used in your application are distinct from those in the application's + dependencies, unless that is what is desired.
    2. +
  2. Like many objects in Log4J2, Markers are immutable. If a marker has a parent, the parent + must be named when the Marker is created and the parent cannot be changed after creation.
    3. +
  3. Markers only have a single parent. Markers can, however, have many children that reference + them.
    4. +

- - - - - - - - -
\ No newline at end of file Modified: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/messages.xml URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/messages.xml?rev=1240834&r1=1240833&r2=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/messages.xml (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/messages.xml Sun Feb 5 21:50:04 2012 @@ -23,9 +23,9 @@ -
- - +
+ +

Although Log4j 2 provides Logger methods that accept Strings and Objects, all of these are ulitmately captured in Message objects that are then associated with the log event. Applications are free to @@ -66,10 +66,110 @@ are encountered. With Messages the Layout has the option of delegating the formatting to the Message or performing its formatting based on the type of Message encountered.

+

+ Borrowing from the earlier example illustrating Markers to identify SQL statements being logged, Messages + can also be leveraged. First, the Message is defined. +

+ + public class SQLMessage implements Message { + public enum SQLType { + UPDATE, + QUERY + }; + + prviate final SQLType type; + private final String table; + private final Map cols; + + public SQLMessage(SQLType type, String table) { + this(type, table, null); + } + + public SQLMessage(SQLType type, String table, Map cols) { + this.type = type; + this.table = table; + this.cols = cols; + } + + public String getFormattedMessage() { + switch (type) { + case UPDATE: + return createUpdateString(); + break; + case QUERY: + return createQueryString(); + break; + default; + } + } + + public String getMessageFormat() { + return type + " " + table; + } + + public Object getParameters() { + return cols; + } + + private String createUpdateString() { + } + + private String createQueryString() { + } + + private String formatCols(Map cols) { + StringBuilder sb = new StringBuilder(); + boolean first = true; + for (Map.Entry entry : cols.entrySet()) { + if (!first) { + sb.append(", "); + } + sb.append(entry.getKey()).append("=").append(entry.getValue()); + first = false; + } + return sb.toString(); + } + }]]> +

+ Next we can use the message in our application. +

+ params) { + logger.entry(param); + + logger.debug(UPDATE_MARKER, new SQLMessage(SQLMessage.SQLType.UPDATE, table, parmas); + + return logger.exit(); + } + }]]> +

+ Notice that in contrast to the prior version of this example, the logger.debug in doUpdate no longer + needs to be wrapped in an isDebugEnabled call as creation of the SQLMessage is on the same order of + magnitude of performing that check. Furthermore, all the formatting of the SQL columns is now hidden + in the SQLMessage instead of having to take place in the business logic. Finally, if desired, Filters + and/or Layouts can be written to take special action when an SQLMessage is encountered. +

- +

FormattedMessage

A FormattedMessage will have setFormat and getFormat methods. The setFormat method may be called by a Layout to provide advice on how the Message should be formatted. If the Message doesn't recognize the @@ -77,9 +177,8 @@ StructuredDataMessage which accepts a format String of "XML" which will cause it to format the event data as XML instead of the RFC 5424 format.

- - +

LocalizedMessage

LocalizedMessage is provided primarily to provide compatibility with Log4j 1.x. Generally, @@ -91,60 +190,52 @@ LocalizedMessage will attempt to locate a bundle with the name of the Logger used to log the event. The parameters to the Message will be incorporated into the Message whereever the "{}" placeholders occur.

- - +

LoggerNameAwareMessage

LoggerNameAwareMessage is an interface with a setLoggerName method. This method will be called during event construction so that the Message has the name of the Logger used to log the event when the message is being formatted.

- - +

MapMessage

A MapMessage contains a Map of String keys and values. MapMessage implements FormattedMessage and accepts a format specifier of "XML", in which case the Map will be formatted as XML. Otherwise, the Map will be formatted as "key1=value1 key2=value2...".

- - +

ObjectMessage

Formats an Object by calling its toString method.

- - +

ParameterizedMessage

ParameterizedMessage handles messages that contain "{}" in the format to represent replaceable tokens and the replacement parameters.

- - +

SimpleMessage

SimpleMessage contains a String that requires no formatting.

- - +

StructuredDataMessage

StructuredDataMessage allows applications to add items to a Map as well as set the id to allow a message to be formatted as a Structured Data element in accordance with RFC 5424.

- - +

ThreadDumpMessage

A ThreadDumpMessage, if logged, will generate stack traces for all threads. If running on Java 6+ the stack traces will include any locks that are held.

- - +

TimestampMessage

A TimestampMessage will provide a getTimestamp method that is called during event construction. The timestamp in the Message will be used in lieu of the current timestamp. Modified: logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/thread-context.xml URL: http://svn.apache.org/viewvc/logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/thread-context.xml?rev=1240834&r1=1240833&r2=1240834&view=diff ============================================================================== --- logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/thread-context.xml (original) +++ logging/log4j/branches/BRANCH_2_0_EXPERIMENTAL/rgoers/src/site/xdoc/manual/thread-context.xml Sun Feb 5 21:50:04 2012 @@ -23,8 +23,9 @@ -

- +
+ +

Introduction

Log4j introduced the concept of the Mapped Diagnostic Context or MDC. It has been documented and discussed in numerous places including Log4j MDC: What and Why and @@ -40,8 +41,7 @@ NDC. Although these are frequently used for purposes other than diagnosing problems, they are still frequently referred to as the MDC and NDC in Log4j 2 since they are already well known by those acronyms.

- - +

Fish Tagging

Most real-world systems have to deal with multiple clients simultaneously. In a typical multithreaded implementation of such asystem, different threads will handle different clients. Logging is especially well suited to trace and debug complex distributed applications. A common approach to @@ -109,8 +109,7 @@ ThreadContext class are static.

- - +

Including the ThreadContext when writing logs

The PatternLayout provides mechanisms to print the contents of the ThreadContext Map and Stack. Using %X by itself will cause the full contents of the Map to be included while %X{key} will cause the value