Logback学习笔记

知识点

• logback在会先加载classpath下的logback-test.xml，如果没有找到再加载logback.xml。
• Logback中三大核心概念：Logger、Appender和Layout。
• Logger采用层级架构，采用类似java的package的命名方式，名为a.b的Logger是a.b.c的parent，而后者则为前者的child，如果两个logger之间间隔了几层，比如a.b和a.b.c.d，那么a.b为a.b.c.d的ancestor，反之a.b.c.d为a.b的descendant。
• Logger本身可以设置Level，Level从高到低有：ERROR，WARN，INFO，DEBUG，TRACE。除了设置Level之外，在实际打日志时通过logger.info()其实指定的是请求Level，只有当请求Level高于Logger的设置Level时，该Logger才生效。这个不难理解，因为Level级别越高，表示越应该记录下该Logger。比如，当设置Level为INFO时，表示输入一些正常的日志事件，但是如果系统中出现了错误，即通过logger.error()输入日志，很明显这个错误是我们更应该关心的，因此该日志时需要记录下来的。
• 多数时候，我们没有必要为每个logger设置level，此时并不代表logger没有level，而是继承了离其最近的ancestor，此处Logger的层级架构便起作用了。在层级的最上层，有个固定的名为ROOT的logger，表示任何logger如果没有设置的ancestor，那么其Level便继承自ROOT。Logback的ROOT的默认Level为DEBUG。
• Logger在输出日志时，是通过Appender来完成的，有的Appender将日志输出到命令行，有的输出到文件，有的则输出到数据库或者消息队列。一个Logger可以有多个Appender，也即该Logger的日志会输出到多个地方。
• 对于Appender，Logback有个重要的性质：如果某个Logger得到了启用（即请求Level高于其有效设置Level），那么除了该Logger自身所拥有的Appender会输出日志之外，该Logger的所有ancestor的Appender也会输出日志。这也是为什么在通常情况下，我们只需要为ROOT设置appender的原因。Logabck的这个性质其实依赖于Logback的additivity属性，事实上是该属性确定了是否将日志请求向上级Logger的appender发送。在默认情况下，additivity=true，则表示日志会输送到所有上级Logger的appender。当然，我们可以设置为false，使某个Logger的日志只是输出到某些特定的地方。比如，我们希望只将性能测试的日志输入到某个文件中，而将系统中的所有其他日志输出到命令行中。
• 需要注意的是，additivity与level无关，就是说即便child logger的level比parent logger的低，child logger的additivity=true，那么只要child logger被启用，那么其日志依然会上传到parent logger的appender中。

案例项目

└── src
    └── main
        ├── java
        │   └── davenkin
        │       └── parent
        │           ├── Parent.java
        │           ├── child1
        │           │   └── Child1.java
        │           └── child2
        │               └── Child2.java
        └── resources
            └── logback.xml

Github地址: https://github.com/davenkin/logback-learning

其中Parent中main函数分别输出Parent，Child1和Child2的日志。

• logback.xml：

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="ROOT_FILE" class="ch.qos.logback.core.FileAppender">
        <file>root.log</file>
        <append>true</append>
        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="info">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="ROOT_FILE"/>
    </root>
</configuration>

• Parent:

package davenkin.parent;

import davenkin.parent.child1.Child1;
import davenkin.parent.child2.Child2;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Parent {
    private static final Logger logger = LoggerFactory.getLogger(Parent.class);

    public static void main(String[] args) {
        logger.info("info from parent");
        logger.debug("debug from parent");
        new Child1().hello();
        new Child2().hello();
    }

}

• Child1:

package davenkin.parent.child1;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Child1 {
    private static final Logger logger = LoggerFactory.getLogger(Child1.class);

    public void hello() {
        logger.info("info from child1");
        logger.debug("debug from child1");
    }
}

• Child2:

package davenkin.parent.child2;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Child2 {
    private static final Logger logger = LoggerFactory.getLogger(Child2.class);

    public void hello() {
        logger.info("info from child2");
        logger.debug("debug from child2");
    }
}

常用配置

以上例子是一个常见的日志配置，其中：没有为任何Logger显式配置Level与additivity属性，而只是配置了一个root logger，即表示所有日志最终都会打到root logger所对应的appender中，日志同时打到了命令行和文件中。root logger的Level设置成了INFO，表示debug的日志请求不会得到输出。这样的配置常见于生产环境，因为很多第三方类库都会输出大量的debug日志，这样会使得我们正常的INFO级别的业务记录日志淹没在debug日志中。

此时的命令行输出日志如下：

09:03:01.304 INFO  davenkin.parent.Parent - info from parent
09:03:01.306 INFO  davenkin.parent.child1.Child1 - info from child1
09:03:01.306 INFO  davenkin.parent.child2.Child2 - info from child2

为某个package下的日志设置单独的Level

有时为了调试方便，我们可能需要将某个package下的debug或者trace日志输出，比如在用Spring的WebserviceTemplate时，我们希望打印出请求和返回的XML数据，那么此时便可以显式地为对应logger设置Level：

   <logger name="org.springframework.ws.client.MessageTracing">
    <level value="TRACE"/> 
   </logger>
   <logger name="org.springframework.ws.server.MessageTracing">
    <level value="TRACE"/> 
   </logger>

对应到上面的案例项目，如果我们希望child1包下能够打印出debug级别的日志，那么可以修改logback.xml文件，在其中显式配置logger：

  <logger name="davenkin.parent.child1">
        <level value="DEBUG"/>
    </logger>

此时输出日志中便包含了child1下的DEBUG日志，但是不包含其他package下的DEBUG日志：

09:09:10.935 INFO  davenkin.parent.Parent - info from parent
09:09:10.938 INFO  davenkin.parent.child1.Child1 - info from child1
09:09:10.938 DEBUG davenkin.parent.child1.Child1 - debug from child1
09:09:10.938 INFO  davenkin.parent.child2.Child2 - info from child2

将不同logger的日志打入到不同的文件中

有时我们希望将某些logger的日志输出到单独的文件中，比如在做性能测试时，需要将所有性能测试的日志输出到perfomance.log中，这时需要为性能测试专门创建一个logger，比如名为perfomance-logger，我们需要做3件事情：

• 在代码中输出日志时，不能使用类名来命名logger，而是直接使用performance-logger：

Logger performanceLogger = LoggerFactory.getLogger("performance-logger");

• 专门配置一个属于性能日志的appender：

   <appender name="PERFORMANCE_LOG" class="ch.qos.logback.core.FileAppender">
        <file>performance.log</file>
        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>

• 然后在配置logger时，设置perfomance-logger的additivity=false，这样便可防止性能日志输出到其他地方。

    <logger name="performance-logger" level="DEBUG" additivity="false">
        <appender-ref ref="PERFORMANCE_LOG"/>
    </logger>

对于，上面的例子项目，加入Child3：

package davenkin.parent.child3;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Child3 {
    private static final Logger logger = LoggerFactory.getLogger("performance-logger");

    public void hello() {
        logger.debug("debug from performance");
    }
}

在logback.xml中加入以下配置：

    <appender name="PERFORMANCE_LOG" class="ch.qos.logback.core.FileAppender">
        <file>performance.log</file>
        <append>true</append>
        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>

    <logger name="performance-logger" level="DEBUG" additivity="false">
        <appender-ref ref="PERFORMANCE_LOG"/>
    </logger>

再修改Parent让其输出Child3的日志：

 public static void main(String[] args) {
        logger.info("info from parent");
        logger.debug("debug from parent");
        new Child1().hello();
        new Child2().hello();
        new Child3().hello();
    }

得到命令行输出：

09:38:58.301 INFO  davenkin.parent.Parent - info from parent
09:38:58.304 INFO  davenkin.parent.child1.Child1 - info from child1
09:38:58.304 DEBUG davenkin.parent.child1.Child1 - debug from child1
09:38:58.304 INFO  davenkin.parent.child2.Child2 - info from child2

可以看到，命令行中不包含performance日志，而在performance.log中得到了performance日志：

198  [main] DEBUG performance-logger - debug from performance

将不同Level的日志打到不同文件中

可以通过配置Filter的方式将不同Level的日志打到不同的文件中，Filter是配置在Appender中的，具体参考这里和这里。

最佳实践

• log不应该包含敏感信息，比如用户密码等。
• log中应该包含对应资源ID，比如在操作某个User时，应该记录该User的ID。
• log中应该包含足够多的上下文信息。
• 创建log时，采用static和final关键字：

    private static final Logger LOG = LoggerFactory.getLogger(Foo.class);

• 对于异常日志应该统一处理，比如在Spring的ExceptionHandler中打印异常日志，而此时异常的message应该包含足够的上下文信息。
• 发生异常时，不要打印日志然后再次抛出异常，这样导致日志输出2次：

catch (NoSuchMethodException e) { LOG.error("Blah", e); throw e; }

• log中应该包含请求的ID，可以将请求ID放在MDC中。
• log中应该包含操作者的ID，在Spring Security完成认证后，可以将操作者ID放在MDC中。
• 在WriteApplicationService中，应该记录下业务日志，也即每次对系统一个业务操作，都应该有记录，而在ApplicationService中时最合适的，因此它对应了一次业务用例。
• 在ReadApplicationService中，通常没有必要记录日志，除非此时系统产生了异常。