Log4j 2 API

流程追踪

原文地址

Logger类提供一些非常有用的日志方法供应用程序在执行路径中使用。这些方法生成一些可以从其他的debug日志中分离出来的日志事件。当输出有以下几种情况时，这些方法被鼓励使用：

• 协助开发中的问题诊断，而无需调试会话
• 在不可能进行调试的生产中协助问题诊断
• 帮助新手开发者学习应用程序

最常用的方法是entry()或traceEntry()，和exit()或tranceExit()方法。entry()或traceEntry()应该出现在方法的开头，可能除了那些简单的getter、setter方法。entry()方法可以通过0到4个参数调用，通常就是传递给方法的那些参数。tranceEntry()可以传递一个格式字符串，以及一些参数列表，或一个Message。entry()和traceEntry()方法以TRACE级别进行记录，并且使用一个名为“ENTER”的Marker（同样也是一个“FLOW”的Marker），所有的字符串都将以“event”开头，即便用了一个格式字符串或Message。

entry和traceEntry的主要区别在于entry方法接受的参数对象列表基本没一个都是方法参数。而traceEntry方法接受一个格式字符串，后面跟着一个对象列表，基本都包含在格式字符串中。不可能使用一个方法来同时包含这两种情况，因为第一个字符串是参数还是格式是有歧义的。

一个exit()或traceExit()方法应当出现在任何一个return语句之前，或者在没有return时作为方法的最后一句。exit()和traceExit()可以带参数或不带地调用。通常地，没有返回值时使用exit()或tranceExit()方法，而返回一个对象时使用exit(Object obj)或tranceExit(object, new SomeMessage(object))方法。exit()和traceExit()方法通过TRACE级别进行记录，并且用一个名为“EXIT”的Marker（同样也是一个“FLOW”的Marker），所有的字符串都将以“exit”开头，即便用了一个格式字符串或Message。

当应用程序正在抛出一个看上去不会被捕获的异常时，可以使用throwing()方法，例如RuntimeException。这会确保合适的诊断信息在需要时是可用的。生成的日志事件将会拥有ERROR级别，并且与名为“THROWING”的Marker关联（同样也是一个“EXCEPTION”的Marker）。

当应用程序捕获了一个异常却不打算重新抛出或封装为另一个异常时，可以使用catching()方法。生成的日志事件将会拥有ERROR级别，并且与名为“CATCHING”的Marker关联（同样也是一个“EXCEPTION”的Marker）。

下面的例子展示了一个简单的应用程序在常见的场景中使用这些方法。但throwing()方法并不在其中，因为没有异常会被显示抛出且不被处理。

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 void setMessages(String[] messages) {
        logger.traceEntry(new JsonMessage(messages));
        this.messages = messages;
        logger.traceExit();
    }

    public String[] getMessages() {
        logger.traceEntry();
        return logger.traceExit(messages, new JsonMessage(messages));
    }

    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);
    }
}

这个测试应用使用之前的服务来生成日志事件。

package com.test;

public class App {

    public static void main( String[] args ) {
        TestService service = new TestService();
        service.retrieveMessage();
        service.retrieveMessage();
        service.exampleException();
    }
}

下面的配置会将所有的输出路由到target/test.log文件中。FileAppender的模式包含类名称、行号和方法名称。模式中包含的这些是日志的关键价值所在。

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="error">
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/>
      <!-- 流程追踪是展示位置的最有效手段，
           下面的模式中有类名称、行号和方法名 -->
      <PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level %class{36} %L %M - %msg%xEx%n"/>
    </Console>
    <File name="log" fileName="target/test.log" append="false">
      <PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level %class{36} %L %M - %msg%xEx%n"/>
    </File>
  </Appenders>
  <Loggers>
    <Root level="trace">
      <AppenderRef ref="log"/>
    </Root>
  </Loggers>
</Configuration>

这是上面的Java类和配置的结果输出：

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

简单地将示例中的根Logger级别设置为DEBUG，会明显合并这些输出。

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]