#源码研读#spring boot 与日志

1,273 阅读8分钟

spring boot 与日志

1、一个小故事

spring boot中的日志体系在详细了解之前,需要理解java中的日志体系以及目前的生态分布,这个可以用一个故事来作为引子从而进一步引申出当前的java的日志体系。

小张是一个开发人员,为了能让程序运行的时候,更好的跟踪程序运行的日志,小张编写了一个日志框架xiaozhang-logging.jar,可以方便的控制日志输出,小张在开发完框架后,将框架应用到现在的系统中,但是随着框架的使用,小张发现这个版本的日志框架还是比较基础,当时有考虑不完善的地方,所以小张写了一个升级版本的日志框架xiaozhang-good-logging.jar。在写这个框架的同时小张也考虑了另外一个事情,就是这个升级版本的日志框架在未来也可能进行升级,那么每次升级是不是都要对系统进行jar包替换,这样的改动成本是业务系统没有办法消受的。因此小张又写了一个日志门面框架 xiaozhang-facade-logging.jar。这个门面框架中不包括日志实现,仅仅是将日志的接口对外进行开放,后面的日志实现有升级的话,就不需要对业务代码进行改动了,因为业务侧的日志是面向接口编程而不是面向实现编程。

2、SLF4J体系

上面讲的故事其实是slf4j框架背景故事,下图是slf4j官网的图示,其中slf4j-api.jar就是那个门面jar。logback-**.jar就是小张实现的新的日志框架,同时为了适应更多的日志实现类,SLF4J引入了适配层的概念,这样底层实现就可以使用如:log4j、jul这样的日志实现框架

ing-boot-slf4j日志.png)

从上面的日志框架体系中我们发现目前java中的日志框架分为两类,分别起不同的作用,一个是以slf4j为代表的门面框架,另一个是以logback为代表的日志实现框架,这两个框架要配合使用,方才能很好的为业务系统的日志体系服务。因此除了slf4j和logback之外,还有另外几个框架也归属于这里面。如下表所示

门面框架 实现框架
slf4j(sample logging facade for java)/jcl log4j/log4j2/logback/jul

其中加粗的部分,是目前spring boot默认的门面框架和实现框架的配套,也是我们推荐的日志框架配套。

3、spring boot 日志框架引入和处理

slf4j在官方网站中,给出了下图,并针对图做了一下说明

Often, some of the components you depend on rely on a logging API other than SLF4J. You may also assume that these components will not switch to SLF4J in the immediate future. To deal with such circumstances, SLF4J ships with several bridging modules which redirect calls made to log4j, JCL and java.util.logging APIs to behave as if they were made to the SLF4J API instead. The figure below illustrates the idea.

通常,我们引入的一些组件会依赖除了SLF4J的日志应用接口,并且在可预见的未来这些组件也没有准备转到SLF4J上来。为了处理这样的状况,SLF4J用了几个桥接模块去重定向来自log4j、JCL和JUL的调用,以完成SLF4J对其的替换,下图就是原理图

在上图的图示中,我们发现如果要替换对于jcl、log4j、jul等组件依赖的日志框架,那么需要对应的引入jcl-over-slf4j.jar/log4j-over-slf4j.jar/jul-to-slf4j.jar,这些jar再去调用slf4j-api.jar这样就可以达到使用logback的目的。其他原理图类似,只不过是绑定的日志实现不同罢了。

所以在spring boot的工程搭建过程中,如果引入的组件包括了其他的日志框架,但是我们还想使用logback作为我们的日志实现框架,就需要相应的引入替换jar包,同时将组件中的日志框架包进行排除;

如:spring 框架默认使用的是commons-logging但是springboot使用的是slf4j所以在引入spring框架后,要将commons-logging进行排除,同时引入jcl-over-slf.jar这样spring框架的日志实现框架就被替换成了logback了。这个在springboot1.XX中是这么处理的,但是如果使用spring boot2.2.7版本,我们发现pom文件中不在配置配出依赖了,那么spring的日志框架是如何处理的呢?通过跟踪源码我们发现了下面的信息

这说明在spring 5.2.6中,spring框架提供了spring-jcl来对commons-logging进行替换这样就自行解决了框架内部替换的问题,而spring将commons-logging替换成了那个门面框架呢?

public abstract class LogFactory {

   /**
    * Convenience method to return a named logger.
    * @param clazz containing Class from which a log name will be derived
    */
   public static Log getLog(Class<?> clazz) {
      return getLog(clazz.getName());
   }

   /**
    * Convenience method to return a named logger.
    * @param name logical name of the <code>Log</code> instance to be returned
    */
   public static Log getLog(String name) {
      return LogAdapter.createLog(name);
   }
}
final class LogAdapter {
  public static Log createLog(String name) {
     switch (logApi) {
        case LOG4J:
           return Log4jAdapter.createLog(name);
        case SLF4J_LAL:
           return Slf4jAdapter.createLocationAwareLog(name);
        case SLF4J:
           return Slf4jAdapter.createLog(name);
        default:
           // Defensively use lazy-initializing adapter class here as well since the
           // java.logging module is not present by default on JDK 9. We are requiring
           // its presence if neither Log4j nor SLF4J is available; however, in the
           // case of Log4j or SLF4J, we are trying to prevent early initialization
           // of the JavaUtilLog adapter - e.g. by a JVM in debug mode - when eagerly
           // trying to parse the bytecode for all the cases of this switch clause.
           return JavaUtilAdapter.createLog(name);
     }
  }
}
private static class Slf4jAdapter {

   public static Log createLocationAwareLog(String name) {
      Logger logger = LoggerFactory.getLogger(name);
      return (logger instanceof LocationAwareLogger ?
            new Slf4jLocationAwareLog((LocationAwareLogger) logger) : new Slf4jLog<>(logger));
   }

   public static Log createLog(String name) {
      return new Slf4jLog<>(LoggerFactory.getLogger(name));
   }
}

通过以上三段代码的跟踪,我们发现,底层调用的是SLF4J这样spring就完成了对于日志框架门面的替换。

4、spring boot 常用配置

Key Default Value Description
debug false Enable debug logs.开启Debug级别的日志,默认不开启
info.* Arbitrary properties to add to the info endpoint.
logging.config Location of the logging configuration file. For instance, classpath:logback.xml for Logback.指定logging配置文件位置,用来做初始化用
logging.exception-conversion-word %wEx Conversion word used when logging exceptions.
logging.file.clean-history-on-start false Whether to clean the archive log files on startup. Only supported with the default logback setup.
logging.file.max-history 7 Maximum number of days archive log files are kept. Only supported with the default logback setup.
logging.file.max-size 10MB Maximum log file size. Only supported with the default logback setup.
logging.file.name Log file name (for instance, myapp.log). Names can be an exact location or relative to the current directory.
logging.file.path Location of the log file. For instance, /var/log.
logging.file.total-size-cap 0B Total size of log backups to be kept. Only supported with the default logback setup.
logging.group.* Log groups to quickly change multiple loggers at the same time. For instance, logging.group.db=org.hibernate,org.springframework.jdbc.
logging.level.* Log levels severity mapping. For instance, logging.level.org.springframework=DEBUG.
logging.pattern.console %clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx} Appender pattern for output to the console. Supported only with the default Logback setup.
logging.pattern.dateformat yyyy-MM-dd HH:mm:ss.SSS Appender pattern for log date format. Supported only with the default Logback setup.
logging.pattern.file %d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}} ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx} Appender pattern for output to a file. Supported only with the default Logback setup.
logging.pattern.level %5p Appender pattern for log level. Supported only with the default Logback setup.
logging.pattern.rolling-file-name ${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz Pattern for rolled-over log file names. Supported only with the default Logback setup.
logging.register-shutdown-hook false Register a shutdown hook for the logging system when it is initialized.

以上是spring boot默认支持的logging配置属性信息,我们从描述中可以看到,很多属性都是仅支持spring boot默认集成的logback日志框架,若是其他日志框架则不能支持在配置文件中配置这些属性,这些属性我们可以从上面的表格中获取,是否存在另外一种办法从我们的源代码中来找寻这些配置呢?我们在前面的讲解中知道spring boot在做自动配置的时候,会加载properties文件作为属性配置的统一配置文件。但是logging框架有点特殊,是通过监听器作为入口进而加载logging属性

日志相关配置信息-代码

LoggingApplicationListener.class

/**
 * Initialize the logging system according to preferences expressed through the
 * {@link Environment} and the classpath.
 * @param environment the environment
 * @param classLoader the classloader
 */
protected void initialize(ConfigurableEnvironment environment, ClassLoader classLoader) {
   new LoggingSystemProperties(environment).apply();//准备环境,并将日志环境属性进行配置,调用LoggingSystemProperties类的apply()方法,进行属性配置初始化操作
   this.logFile = LogFile.get(environment);//获取logfile相关配置信息
   if (this.logFile != null) {
      this.logFile.applyToSystemProperties();
   }
   this.loggerGroups = new LoggerGroups(DEFAULT_GROUP_LOGGERS);
   initializeEarlyLoggingLevel(environment);
   initializeSystem(environment, this.loggingSystem, this.logFile);
   initializeFinalLoggingLevels(environment, this.loggingSystem);
   registerShutdownHookIfNecessary(environment, this.loggingSystem);
}

LoggingSystemProperties.apply

public void apply(LogFile logFile) {
   PropertyResolver resolver = getPropertyResolver();//获取视图解析器
   setSystemProperty(resolver, EXCEPTION_CONVERSION_WORD, "exception-conversion-word");
   setSystemProperty(PID_KEY, new ApplicationPid().toString());
   setSystemProperty(resolver, CONSOLE_LOG_PATTERN, "pattern.console");
   setSystemProperty(resolver, FILE_LOG_PATTERN, "pattern.file");
   setSystemProperty(resolver, FILE_CLEAN_HISTORY_ON_START, "file.clean-history-on-start");
   setSystemProperty(resolver, FILE_MAX_HISTORY, "file.max-history");
   setSystemProperty(resolver, FILE_MAX_SIZE, "file.max-size");
   setSystemProperty(resolver, FILE_TOTAL_SIZE_CAP, "file.total-size-cap");
   setSystemProperty(resolver, LOG_LEVEL_PATTERN, "pattern.level");
   setSystemProperty(resolver, LOG_DATEFORMAT_PATTERN, "pattern.dateformat");
   setSystemProperty(resolver, ROLLING_FILE_NAME_PATTERN, "pattern.rolling-file-name");
   if (logFile != null) {
      logFile.applyToSystemProperties();
   }
}

private void setSystemProperty(PropertyResolver resolver, String systemPropertyName, String propertyName) {
  setSystemProperty(systemPropertyName, resolver.getProperty("logging." + propertyName));
}

因此,在logging的配置属性,大部分都可以从LoggingSystemProperties以及logfile文件中获取到,所以配置依据也来自于这两个文件中;

  • 调整日志输出级别

在application.properties文件中设置日志输出的级别

#打开debug模式,系统加载的过程会把debug级别的日志打印出来,可以通过这些日志信息知道系统生效了哪些自动配置类
debug=true 
#spring boot支持指定包下的日志输出级别trace/debug/info/warn/error这五个级别,指定任意一个,后面的级别都默认包含在其中,比如指定级别为trace,那么这五个级别的日志信息都会输出
logging.level.tech.bricklayer=warn 

springboot的日志输出就会如下所示

2020-06-02 08:46:02.016  INFO 22172 --- [           main] t.b.s.SpringBoot03LoggingApplication     : Starting SpringBoot03LoggingApplication on liucsdeMacBook-Pro.local with PID 22172 (/Users/liucs/CodeingZH/IdeaProjects/spring-boot-03-logging/target/classes started by liucs in /Users/liucs/CodeingZH/IdeaProjects/spring-boot-03-logging)
2020-06-02 08:46:02.018  INFO 22172 --- [           main] t.b.s.SpringBoot03LoggingApplication     : No active profile set, falling back to default profiles: default
2020-06-02 08:46:02.018 DEBUG 22172 --- [           main] o.s.boot.SpringApplication               : Loading source class tech.bricklayer.springboot.SpringBoot03LoggingApplication
2020-06-02 08:46:02.073 DEBUG 22172 --- [           main] o.s.b.c.c.ConfigFileApplicationListener  : Loaded config file 'file:/Users/liucs/CodeingZH/IdeaProjects/spring-boot-03-logging/target/classes/application.properties' (classpath:/application.properties)
2020-06-02 08:46:02.074 DEBUG 22172 --- [           main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@10e92f8f
2020-06-02 08:46:02.882 DEBUG 22172 --- [           main] .s.b.w.e.t.TomcatServletWebServerFactory : Code archive: /Users/liucs/.m2/repository/org/springframework/boot/spring-boot/2.2.7.RELEASE/spring-boot-2.2.7.RELEASE.jar
2020-06-02 08:46:02.882 DEBUG 22172 --- [           main] .s.b.w.e.t.TomcatServletWebServerFactory : Code archive: /Users/liucs/.m2/repository/org/springframework/boot/spring-boot/2.2.7.RELEASE/spring-boot-2.2.7.RELEASE.jar
2020-06-02 08:46:02.883 DEBUG 22172 --- [           main] .s.b.w.e.t.TomcatServletWebServerFactory : None of the document roots [src/main/webapp, public, static] point to a directory and will be ignored.
2020-06-02 08:46:02.907  INFO 22172 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2020-06-02 08:46:02.917  INFO 22172 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-06-02 08:46:02.917  INFO 22172 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.34]
2020-06-02 08:46:02.984  INFO 22172 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-06-02 08:46:02.985 DEBUG 22172 --- [           main] o.s.web.context.ContextLoader            : Published root WebApplicationContext as ServletContext attribute with name [org.springframework.web.context.WebApplicationContext.ROOT]
2020-06-02 08:46:02.986  INFO 22172 --- [           main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 912 ms
2020-06-02 08:46:02.999 DEBUG 22172 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Mapping filters: characterEncodingFilter urls=[/*] order=-2147483648, formContentFilter urls=[/*] order=-9900, requestContextFilter urls=[/*] order=-105
2020-06-02 08:46:02.999 DEBUG 22172 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Mapping servlets: dispatcherServlet urls=[/]
2020-06-02 08:46:03.026 DEBUG 22172 --- [           main] o.s.b.w.s.f.OrderedRequestContextFilter  : Filter 'requestContextFilter' configured for use
2020-06-02 08:46:03.027 DEBUG 22172 --- [           main] s.b.w.s.f.OrderedCharacterEncodingFilter : Filter 'characterEncodingFilter' configured for use
2020-06-02 08:46:03.027 DEBUG 22172 --- [           main] o.s.b.w.s.f.OrderedFormContentFilter     : Filter 'formContentFilter' configured for use
2020-06-02 08:46:03.150  INFO 22172 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-06-02 08:46:03.158 DEBUG 22172 --- [           main] s.w.s.m.m.a.RequestMappingHandlerAdapter : ControllerAdvice beans: 0 @ModelAttribute, 0 @InitBinder, 1 RequestBodyAdvice, 1 ResponseBodyAdvice
2020-06-02 08:46:03.216 DEBUG 22172 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : 2 mappings in 'requestMappingHandlerMapping'
2020-06-02 08:46:03.236 DEBUG 22172 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Patterns [/webjars/**, /**] in 'resourceHandlerMapping'
2020-06-02 08:46:03.243 DEBUG 22172 --- [           main] .m.m.a.ExceptionHandlerExceptionResolver : ControllerAdvice beans: 0 @ExceptionHandler, 1 ResponseBodyAdvice
2020-06-02 08:46:03.297 DEBUG 22172 --- [           main] ConditionEvaluationReportLoggingListener : 


============================
CONDITIONS EVALUATION REPORT
============================


Positive matches:
-----------------
  • 调整日志输出格式
logging.pattern.console=%d{yyyy-MM-dd HH:mm:ss.SSS} <---> [%thread] --- %-5level --- %logger{50} --- - %msg%n
# %d代表输出的时间格式,可以指定格式为{yyyy-MM-dd HH:mm:ss.SSS}放在大括号中
# [%thread]输出的是线程名称
# %-5level输出的是日志级别,如INFO、WARN、ERROR
# %logger{50}输出定位信息,最长50个字符
# %msg 日志信息
# %n 换行

spring boot支持日志输出格式通过properties配置,如上图所示,可以 设置日志输出的格式信息

  • 自定义配置文件加载和配置

下面的文件是可以在spring boot工程中配置的一个logback-spring.xml配置文件,来自定义日志输出的信息和格式以及控制日志文件的生成规则

logging.level.tech.bricklayer=info
logging.file.path=./bricklayerlog
<?xml version="1.0" encoding="UTF-8"?>
<configuration  scan="true" scanPeriod="60 seconds" debug="false">
    <!--属性的配置,和java中定义变量起到的作用一样-->
    <property name="context-name" value="bricklayer" />
    <!--从application.properties中获取配置信息-->
    <springproperty name="logging-level" source="logging.level.tech.bricklayer"></springproperty>
    <springproperty name="logging-path" source="logging.file.path"></springproperty>


    <contextName>${context-name}}</contextName>

    <!--输出到控制台,使用ConsoleAppender类-->
    <!--pattern指定输出格式-->
    <!--指定编码,如果不指定的话,中文会报乱码-->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %contextName [%thread] %-5level  %logger{36} - %msg%n</pattern>
            <charset>utf-8</charset>
        </encoder>
    </appender>

    <!--自定义的日志打印类,这里可以做自定义操作,比如拦截到error级别的日志时,可以发邮件给指定的邮箱或者做特定的操作-->
    <appender name="LoggerAlarm" class="tech.bricklayer.springboot.config.LoggerAlarm">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>${logging-level}</level>
        </filter>
    </appender>

    <!--输出到文件,引用rollingfileappender类-->
    <appender name="STDOUT" class="ch.qos.logback.core.rolling.RollingFileAppender">

        <!--追加到现有的文件上-->
        <append>true</append>

        <!--边界值过滤器,可以设置level级别,当达到级别后,才能输出-->
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>${logging-level}</level>
        </filter>

        <!--日志输出地址和文件名-->
        <file>
            ${logging-path}/bricklayer/bricklayer-loggerone.log
        </file>

        <!--只有当配置了rollingfileappender时,这个才需要配置,可以指定每天生成文件,重命名文件名-->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${logging-path}/bricklayer/bricklayer-loggerone.log.%d{yyyy-MM-dd}</FileNamePattern>
            <MaxHistory>2</MaxHistory>
        </rollingPolicy>
        <!--日志输出格式-->
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} ---> %contextName [%thread] %-5level  %logger{36} - %msg%n</pattern>
            <charset>utf-8</charset>
        </encoder>

    </appender>

    <!--只输出error级别的日志-->
    <appender name="ERROR-APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">

        <append>true</append>

        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>error</level>
        </filter>

        <file>
            ${logging-path}/bricklayer/bricklayer-error.log
        </file>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${logging-path}/bricklayer/bricklayer-error.log.%d{yyyy-MM-dd}</FileNamePattern>
            <MaxHistory>2</MaxHistory>
        </rollingPolicy>

        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} ---> %contextName [%thread] %-5level  %logger{36} - %msg%n</pattern>
            <charset>utf-8</charset>
        </encoder>

    </appender>

    <!--日志打印控制,用来指定日志生效的范围,比如可以是包或者是类-->
    <!--level是指定日志的等级-->
    <!--additivity用来指定,当日志匹配上后,是否需要继续匹配其他日志-->
    <logger name="tech.bricklayer" level="${logging-level}" additivity="false">
        <appender-ref ref="STDOUT"></appender-ref>
        <appender-ref ref="ERROR-APPENDER"></appender-ref>
        <appender-ref ref="console" />
        <appender-ref ref="LoggerAlarm"></appender-ref>
    </logger>


    <root level="${logging-level}">
        <appender-ref ref="console" />
    </root>

</configuration>

针对于配置文件中配置的LoggerAlarm信息,是通过自定义实现来做的个性化配置,代码如下

public class LoggerAlarm extends AppenderBase<ILoggingEvent> {

    Logger logger = LoggerFactory.getLogger(LoggerAlarm.class);
    @Override
    protected void append(ILoggingEvent iLoggingEvent) {
        logger.info("================我是一个神奇的用来提醒日志的代码==============="+iLoggingEvent.getFormattedMessage());
    }
}

系列文章可以关注公众号 《正涣》 将给带来框架源码解读和算法分析方面的知识,帮助你进阶程序员之路