Spring Boot日志管理

日志作为一个项目必备的一个模块，对于排查问题是必不可少的。在开始写本篇文章之前，先讲一下几个概念Sl4j、LogBack、Log4j、Apache commons Log等概念的联系和区别，这对于了解本文是非常重要的。

slf4j是The Simple Logging Facade for Java的简称，是一个简单日志门面抽象框架，它本身只提供了日志Facade API和一个简单的日志类实现。也就是说SLF4J不是一个真正的日志实现，而是一个抽象层，它允许你在后台使用任意一个日志类库，比如LogBack、Log4J等。SLF4J定义了统一的日志抽象接口，而真正的日志实现则是在运行时决定的——它提供了各类日志框架的binding。使用SLF4J可以做到让代码独立于任意一个特定的日志API，这在编写供内外部都可以使用的API或者通用类库是非常重要的。

Logback、log4j、Apache commons Log等都是日志类库，提供具体日志实现。其中Logback是log4j框架的作者开发的新一代日志框架，它效率更高、能够适应诸多的运行环境，同时Logback天然支持SLF4J。总的来说，可以讲各种日志类库和SLF4J配合使用，这样可以灵活地替换底层日志框架。

Spring Boot在所有内部日志中使用Commons Logging，但是默认配置也提供了对常用日志的支持，如：Java Util Logging，Log4J, Log4J2和Logback ，每种Logger都可以通过配置使用控制台或者文件输出日志内容。默认情况下，Spring Boot会用Logback来记录日志，日志默认输出到控制台，但也可以通过配置输出到文件中。本文会简单的介绍一下Spring Boot默认日志Logback的配置和使用，在下一篇文章我会简单介绍一下Spring Boot + Slf4J + Log4j2的配置和使用。

• Logback

通过spring-boot-starter-web会默认引入spring-boot-starter-logging，因此不需要再单独引入，默认情况下日志级别是INFO(高于WARN级别的日志都会输出)，控制台会输出ERROR、WARN和INFO级别的日志信息，如下：

2018-07-25 16:35:22.180  INFO 94488 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-07-25 16:35:22.244  INFO 94488 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2018-07-25 16:35:22.249  INFO 94488 --- [           main] .z.s.s.l.SpringBootLogApplicationContext : Started SpringBootLogApplicationContext in 3.076 seconds (JVM running for 4.406)

可以看到，默认日志输出包含以下内容：

• 时间日期：精确到毫秒
• 日志级别：ERROR, WARN, INFO, DEBUG,TRACE，FATAL
• 进程ID
• 分隔符：--- 标识实际日志的开始
• 线程名：方括号括起来
• Logger名：通常使用源代码的类名
• 日志内容

 

• Logback与SLF4J配合使用原理

使用SLF4J后，向程序员隐藏了底层实际使用的Logger的细节，只需要使用SLF4J提供的Logger实例即可，运行时，SLF4J会根据项目中的具体日志进行动态绑定，下面我们通过代码来简单看一下具体实现，首先获取SLF4J实例：

Logger logger = LoggerFactory.getLogger(xxx.class);

LoggerFactory是slf4j的日志工厂，运行时底层获取具体logger实例的方法如下:

public static Logger getLogger(String name) {
    ILoggerFactory iLoggerFactory = getILoggerFactory();
    return iLoggerFactory.getLogger(name);
}

这个方法里面有分为两个过程，第一个过程是获取真正的日志工厂ILoggerFactory，第二个过程从真正的日志工厂ILoggerFactory中获取实际的logger。第一个过程分为三步：

第一步，加载org/slf4j/impl/StaticLoggerBinder.class文件

//STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class"
paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH);

第二步，随机选取一个StaticLoggerBinder.class来创建一个单例，比如在项目中同时存在Logback和slf4j两个日志库，SLF4J会随机选择一个StaticLoggerBinder.class来创建一个单例：

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/C:/Users/zhuoli/.m2/repository/ch/qos/logback/logback-classic/1.2.3/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/C:/Users/zhuoli/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.10.0/log4j-slf4j-impl-2.10.0.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]

StaticLoggerBinder.getSingleton()

第三步，通过第二步获取的单例获取真正的日志工厂ILoggerFactory实例

StaticLoggerBinder.getSingleton().getLoggerFactory();

与SLF4J集成的日志框架，都会包含StaticLoggerBinder.class这样的一个类文件，并且提供一个ILoggerFactory的实现。

• Logback控制台输出配置

默认情况下，Logback日志级别是INFO，控制台会输出ERROR、WARN和INFO级别的日志信息，Spring Boot中提供一种调试模式，可以在控制台看到除ERROR、WARN和INFO之外的一些信息，可以通过如下两种方式打开调试模式：

1. 在运行命令后加入–debug标志，如：$ java -jar xx.jar –debug
2. 在application.properties中配置debug=true，该属性置为true的时候，核心Logger（包含嵌入式容器、hibernate、spring）会输出更多内容，但是你自己应用的日志并不会输出为DEBUG级别。

• Logback文件输出配置

默认情况下，Spring Boot将日志输出到控制台，不会写到日志文件。如果要编写除控制台输出之外的日志文件，则需在application.properties中设置logging.file或logging.path属性。

1. logging.file，设置文件，可以是绝对路径，也可以是相对路径。如：logging.file=my.log
2. logging.path，设置目录，会在该目录下创建spring.log文件，并写入日志内容，如：logging.path=/var/log
3. logging.file.max-size： 限制日志文件大小
4. logging.file.max-history： 限制日志保留天数

如果只配置 logging.file，会在项目的当前路径下生成一个 xxx.log 日志文件。如果只配置 logging.path，在 /var/log文件夹生成一个日志文件为 spring.log。二者不能同时使用，如若同时使用，则只有logging.file生效，默认情况下，日志文件的大小达到10MB时会切分一次，产生新的日志文件，默认级别为：ERROR、WARN、INFO

• Logback日志级别配置

所有支持的日志记录系统都可以在Spring环境中设置记录级别(例如在application.properties中)，格式为：’logging.level.* = LEVEL’

1. logging.level：日志级别控制前缀，*为包名或Logger名
2. LEVEL：选项TRACE, DEBUG, INFO, WARN, ERROR, FATAL, OFF

• Logback自定义日志配置

由于日志在ApplicationContext之前就初始化好了，所以SpringBoot为我们提供了logging.config属性，方便我们配置自定义日志文件，默认情况它会根据日志的依赖自动加载。

Logging System	Customization
JDK (Java Util Logging)	logging.properties
Log4j2、ERROR	log4j2-spring.xml 或 log4j2.xml
Logback	logback-spring.xml、logback-spring.groovy、logback.xml、logback.groovy

比如Logback再加载配置的时候，logback-spring.xml、logback-spring.groovy、logback.xml、logback.groovy中任何一项找到了，就不进行后续扫描，按照对应的配置进行logback的初始化。当所有以上四项都找不到的情况下，logback会调用ch.qos.logback.classic.BasicConfigurator的configure方法，构造一个ConsoleAppender用于向控制台输出日志，默认日志输出格式为”%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} – %msg%n”。Spring Boot官方推荐优先使用带有-spring的文件名作为你的日志配置（如使用logback-spring.xml，而不是logback.xml），命名为logback-spring.xml的日志配置文件，spring boot可以为它添加一些spring boot特有的配置项，如springProfile，可以很方便的配置多环境日志。

如果想使用自定义配置，但同时又不想使用默认logback.xml作为Logback配置的名字，可以通过在application.properties中定义logging.config属性指定自定义的名字：

logging.config=classpath:logging-config.xml

下面我们来看一个简单的Logback日志配置文件:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds" debug="false">
    <contextName>logback</contextName>
    <property name="log.path" value="D:\\log\\logback.log"/>
    <!--输出到控制台-->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %contextName [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <!--输出到文件-->
    <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>logback.%d{yyyy-MM-dd}.log</fileNamePattern>
        </rollingPolicy>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %contextName [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <logger name="java"/>

    <root level="debug">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="file"/>
    </root>
</configuration>

根节点<Configuration>

自定义配置文件根节点是<configuration>，<configuration>只有三个属性：

1. scan：当scan被设置为true时，当配置文件发生改变，将会被重新加载，默认为true
2. scanPeriod：检测配置文件是否有修改的时间间隔，如果没有给出时间单位，默认为毫秒，当scan=true时这个值生效，默认时间间隔为1分钟
3. debug：当被设置为true时，将打印出logback内部日志信息，实时查看logback运行信息，默认为false

子节点<contextName>

设置打印日志的应用程序名，用于区分不同应用程序的记录。设置后, 可以通过%contextName来打印名称。

<contextName>logback</contextName>

子节点<property>

用来定义变量值的标签， 有两个属性，name和value；其中name的值是变量的名称，value的值时变量定义的值。通过定义的值会被插入到logger上下文中。定义变量后，可以使“${}”来使用变量。

<property name="log.path" value="D:\\log\\logback.log" />

子节点<appender>

appender用来格式化日志输出节点，有俩个属性name和class，class用来指定哪种输出策略，常用就是控制台输出策略和文件输出策略。

ConsoleAppender的作用是将日志输出到控制台，配置示例为：

 <!--输出到控制台-->
 <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
     <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
         <level>ERROR</level>
     </filter>
     <encoder>
         <pattern>%d{HH:mm:ss.SSS} %contextName [%thread] %-5level %logger{36} - %msg%n</pattern>
     </encoder>
 </appender>

其中，encoder表示对参数进行格式化，<encoder>是0.9.19版本之后引进的，以前的版本使用<layout>，logback极力推荐的是使用<encoder>而不是<layout>。encode子节点pattern使用的通配符：

1. %d{HH: mm:ss.SSS}——日志输出时间
2. %thread——输出日志的进程名字，这在Web应用以及异步任务处理中很有用
3. %-5level——日志级别，并且使用5个字符靠左对齐
4. %logger{36}——日志输出者的名字
5. %msg——日志消息
6. %n——平台的换行符

ThresholdFilter为系统定义的拦截器，例如我们用ThresholdFilter来过滤掉ERROR级别以下的日志不输出，如果包含次filter，会发现项目启动控制台是没有日志输出的

RollingFileAppender的作用是将日志输出到文件，配置示例为：

<!--输出到文件-->
<appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${log.path}</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>logback.%d{yyyy-MM-dd}.log</fileNamePattern>
        <maxHistory>30</maxHistory>
        <totalSizeCap>1GB</totalSizeCap>
    </rollingPolicy>
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %contextName [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>

其中重要的是rollingPolicy的定义，上例中<fileNamePattern>logback.%d{yyyy-MM-dd}.log</fileNamePattern>定义了日志的切分方式——把每一天的日志归档到一个文件中，<maxHistory>30</maxHistory>表示只保留最近30天的日志，以防止日志填满整个磁盘空间。同理，可以使用%d{yyyy-MM-dd_HH-mm}来定义精确到分的日志切分方式。<totalSizeCap>1GB</totalSizeCap>用来指定日志文件的上限大小，例如设置为1GB的话，那么到了这个值，就会删除旧的日志。

子节点<logger>和<root>

首先看一个例子，logback.xml配置文件如上述示例 ，代码中log打印逻辑：

@RestController
@RequestMapping(value = "/health")
public class HealthCheckController {
    private final Logger logger = LoggerFactory.getLogger(Object.class);

    @RequestMapping(value = "/check", method = RequestMethod.GET)
    public String check(){
        logger.trace("health check controller trace……");
        logger.debug("health check controller debug……");
        logger.info("health check controller info……");
        logger.warn("health check controller warn……");
        logger.error("health check controller error……");
        return "ok";
    }
}

首先讲一下，<logger>节点name属性表示的是LoggerFactory.getLogger(XXX.class)，XXX的包路径，包路径越少越是父级，测试代码里面是Object.class，name可以是”java”或者”java.lang”，name=”java”是name=”java.lang”的父级，root是所有<logger>的父级。输出结果：

11:43:10.818 logback [http-nio-8080-exec-1] DEBUG java.lang.Object - health check controller debug……
11:43:10.818 logback [http-nio-8080-exec-1] INFO  java.lang.Object - health check controller info……
11:43:10.818 logback [http-nio-8080-exec-1] WARN  java.lang.Object - health check controller warn……
11:43:10.818 logback [http-nio-8080-exec-1] ERROR java.lang.Object - health check controller error……

出现这样的结果是因为：

1. <logger>中没有配置level，即继承父级的level，<logger>的父级为<root>，那么level=debug
2. 没有配置additivity，那么additivity=true，表示此<logger>的打印信息向父级<root>传递
3. 没有配置<appender-ref>，表示此<logger>不会打印出任何信息

由此可知，<logger>的打印信息向<root>传递，<root>使用”STDOUT”这个<appender>打印出所有大于等于debug级别的日志。举一反三，我们将<logger>的additivity配置为false，那么控制台应该不会打印出任何日志，因为<logger>的打印信息不会向父级<root>传递且<logger>没有配置任何<appender>。

假如我们把logback配置文件修改为：

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds" debug="false">
    <contextName>logback</contextName>
    <property name="log.path" value="D:\\log\\logback.log"/>
    <!--输出到控制台-->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %contextName [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <!--输出到文件-->
    <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>logback.%d{yyyy-MM-dd}.log</fileNamePattern>
        </rollingPolicy>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %contextName [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <logger name="java" additivity="false" />
    <logger name="java.lang" level="warn">
        <appender-ref ref="STDOUT" />
    </logger>

    <root level="debug">
        <appender-ref ref="STDOUT" />
        <appender-ref ref="file"/>
    </root>
</configuration>

如果读懂了上面的例子，那么这个例子应当很好理解：

1. LoggerFactory.getLogger(Object.class)，首先找到name=”java.lang”这个<logger>，将日志级别大于等于warn的使用”STDOUT”这个<appender>打印出来
2. name=”java.lang”这个<logger>没有配置additivity，那么additivity=true，打印信息向上传递，传递给父级name=”java”这个<logger>
3. name=”java”这个<logger>的additivity=false且不关联任何<appender>，那么name=”java”这个<appender>不会打印任何信息

打印结果为：

11:57:49.724 logback [http-nio-8080-exec-1] WARN  java.lang.Object - health check controller warn……
11:57:49.724 logback [http-nio-8080-exec-1] ERROR java.lang.Object - health check controller error……

由此，总结一下logger的用法：

<loger>用来设置某一个包或者具体的某一个类的日志打印级别、以及指定<appender>。<loger>仅有一个name属性，一个可选的level和一个可选的addtivity属性。

1. name:用来指定受此loger约束的某一个包或者具体的某一个类。
2. level:用来设置打印级别，大小写无关：TRACE, DEBUG, INFO, WARN, ERROR, ALL 和 OFF，还有一个特俗值INHERITED或者同义词NULL，代表强制执行上级的级别。如果未设置此属性，那么当前loger将会继承上级的级别。
3. addtivity:是否向上级loger传递打印信息。默认是true。

• Logback多环境日志输出

据不同环境（prod:生产环境，test:测试环境，dev:开发环境）来定义不同的日志输出，在 logback-spring.xml中使用 springProfile 节点来定义，方法如下：

<!-- 测试环境+开发环境. 多个使用逗号隔开. -->
<springProfile name="test,dev">
    <logger name="com.dudu.controller" level="info" />
</springProfile>
<!-- 生产环境. -->
<springProfile name="prod">
    <logger name="com.dudu.controller" level="ERROR" />
</springProfile>

当通过配置**相应环境后，对应的logger就可以生效了

• Logback异步日志配置

日志通常来说都以文件形式记录到磁盘，例如使用<RollingFileAppender>，这样的话一次写日志就会发生一次磁盘IO，这对于性能是一种损耗，因此更多的，对于每次请求必打的日志（例如请求日志，记录请求API、参数、请求时间），我们会采取异步写日志的方式而不让此次写日志发生磁盘IO，阻塞线程从而造成不必要的性能损耗。下面看一下logback进行异步写日志配置：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration scan="false" scanPeriod="60000" debug="false">

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

    <appender name="ROLLING-FILE-1" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>D:/log/rolling-file-%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%-4relative [%thread] %-5level %lo{35} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- 异步输出 -->
    <appender name ="ASYNC" class= "ch.qos.logback.classic.AsyncAppender">
        <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
        <discardingThreshold>0</discardingThreshold>
        <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
        <queueSize>256</queueSize>
        <!-- 添加附加的appender,最多只能添加一个 -->
        <appender-ref ref ="ROLLING-FILE-1"/>
    </appender>

    <logger name="java" additivity="false" />
    <logger name="java.lang" level="DEBUG">
        <appender-ref ref="ASYNC" />
    </logger>

    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>

</configuration>

即，我们引入了一个AsyncAppender，先说一下AsyncAppender的原理，再说一下几个参数：

当我们配置了AsyncAppender，系统启动时会初始化一条名为”AsyncAppender-Worker-ASYNC”的线程

当Logging Event进入AsyncAppender后，AsyncAppender会调用appender方法，appender方法中再将event填入Buffer（使用的Buffer为BlockingQueue，具体实现为ArrayBlockingQueye）前，会先判断当前Buffer的容量以及丢弃日志特性是否开启，当消费能力不如生产能力时，AsyncAppender会将超出Buffer容量的Logging Event的级别进行丢弃，作为消费速度一旦跟不上生产速度导致Buffer溢出处理的一种方式。

上面的线程的作用，就是从Buffer中取出Event，交给对应的appender进行后面的日志推送

从上面的描述我们可以看出，AsyncAppender并不处理日志，只是将日志缓冲到一个BlockingQueue里面去，并在内部创建一个工作线程从队列头部获取日志，之后将获取的日志循环记录到附加的其他appender上去，从而达到不阻塞主线程的效果。因此AsyncAppender仅仅充当的是事件转发器，必须引用另外一个appender来做事。

从上述原理，我们就能比较清晰地理解几个参数的作用了：

• discardingThreshold，假如等于20则表示，表示当还剩20%容量时，将丢弃TRACE、DEBUG、INFO级别的Event，只保留WARN与ERROR级别的Event，为了保留所有的events，可以将这个值设置为0，默认值为queueSize/5
• queueSize比较好理解，BlockingQueue的最大容量，默认为256
• includeCallerData表示是否提取调用者数据，这个值被设置为true的代价是相当昂贵的，为了提升性能，默认当event被加入BlockingQueue时，event关联的调用者数据不会被提取，只有线程名这些比较简单的数据
• appender-ref表示AsyncAppender使用哪个具体的<appender>进行日志输出

所以，上述配置后，生成”D:\log\rolling-file-2018-07-27″日志文件，打印内容为：

74613 [http-nio-8080-exec-1] DEBUG java.lang.Object - health check controller debug……
74613 [http-nio-8080-exec-1] INFO  java.lang.Object - health check controller info……
74613 [http-nio-8080-exec-1] WARN  java.lang.Object - health check controller warn……
74613 [http-nio-8080-exec-1] ERROR java.lang.Object - health check controller error……

示例代码：码云 – 卓立 – logback日志配置

参考链接：

1. Spring Boot干货系列：（七）默认日志logback配置解析
2. Java日志框架：logback详解