coding……
但行好事 莫问前程

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 LoggingLog4JLog4J2Logback ,每种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详解

 

 

赞(0) 打赏
Zhuoli's Blog » Spring Boot日志管理
分享到: 更多 (0)

评论 抢沙发

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址

zhuoli's blog

联系我关于我

觉得文章有用就打赏一下文章作者

支付宝扫一扫打赏

微信扫一扫打赏