1. 首页
  2. 后端

Java 日志框架全解

  Java 日志框架全解

===========

`Java`日志框架全解

============

我们在写代码过程中,天天都在打印日志,一会儿是Slf4jLog4j,一会儿又是Log4j2Logback等等,各种花里胡哨的日志依赖,你们有没有一脸懵逼?今天就带着大家从零开始了解这些日志,主要包括以下几项内容:

  • 日志框架简介
  • Slf4j源码解析
  • Logback源码解析
  • SpringBoot整合Logback源码解析
  • Logback扩展

1.日志框架简介

要想了解这些日志,我们还是要先了解这些日志的历史,才能明白它们存在的意义。

1.1.日志框架历史

  • Log4j

1996年早期,由Ceki带领的欧洲安全电子市场项目组决定编写一套自己的程序跟踪APITracing API),经过不断完善称为一个广受欢迎的Java日志软件包,即**Log4j**。后来Log4j成为Apache基金会项目的一员,近乎成为Java社区的日志标准;

  • JUL

2002年管理Java标准库的Sun公司不甘寂寞,他们也想推出一套自己的日志库。在发布的Java1.4中推出日志库**JUL(Java Util Logging)**,其实就是抄了Log4j的实现;

  • JCL

随后Apache推出JCL(Jakarta Commons Logging),只是定义了一套日志接口,支持运行时动态加载日志组件的实现;

  • Slf4j & Logback

2006Ceki离开Apache,自己独创了**Slf4j**,这也是一套类似于JUL的日志门面,不止于此,他又独创了Logback,这是一个Slf4j的实现项目;

  • Log4j2

2012Apache眼看着势头要被Logback超越,然后重写Log4j 1.x,成立了新项目**Log4j2**,吸收了Logback的优秀设计,同时修复了Logback的一些设计上的缺陷。

1.2.日志框架分类

我们根据日志的功能以及源码的结构,可以把日志分为两类:记录型日志框架门面型日志框架

日志门面框架

  • JCL:Apcache 基金会管理项目,是一套 Java 日志接口,之前叫 Jakarta Commons Logging,后更名为 Commons Logging;
  • Slf4j(Simple Logging Facade for Java):一套建议的 Java 日志门面,本身并无日志实现

日志实现框架

  • Jul(Java Util Logging):JDK 自带的官方日志记录工具,也常被称为 JDKLog、jdk-logging;
  • Log4j:Apache 软件基金会管理的基于 Java 的日志记录工具;
  • Log4j2:Log4j 的下一个版本,变化较大,不兼容 Log4j;
  • **Logback:和 Slf4j 是同一个作者,性能更好(推荐使用)。**

1.3.Slf4j架构

Slf4j 设计思想简洁,使用了Facade设计模式,只提供了一个slf4j-api-version.jar包,这个 jar 主要是日志抽象接口,本身并没有对抽象出来的接口做实现;

对于不同的日志实现框架(如 Logback,Log4j 等),封装出不同的桥接组件(如logback-classic-version.jarslf4j-log4j12-version.jar等),这样使用过程中可以灵活选取自己项目里的日志实现。
整体关系图如下:

slf4j.png

可以看到,logbackslf4j-simpleslf4j-nop都直接实现了slf4j接口,所以我们在使用时直接引入对应的jar包即可;而log4jjul没有实现slf4j接口,所以要想符合slf4j接口规范,则需要使用桥接器实现;还有图中没有展示的log4j2也没有实现slf4j接口,所以也需要桥接器log4j-slf4j-impl

在做业务开发时如果你选择的日志框架是log4j2log2j等没有实现slf4j接口的日志框架,最好选择使用桥接器,主要优点是便于迁移(后面会讲到)。

1.4.Logback日志框架使用

以下案例先以Slf4j + Logback为例进行分析。首先进行如下配置:

  1. pom配置
< !-- slf4j-api 依赖 -->
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.25</version>
    <scope>compile</scope>
</dependency>

< !-- logback 依赖 -->
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.10</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-core</artifactId>
    <version>1.2.10</version>
</dependency>
  1. main函数LogbackApplication.class
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

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

    public static void main(String[] args)  {
        logger.info("hello world");
    }
}
  1. 添加一个logback.xml的配置文件:
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!-- 文件输出格式 -->
    <!-- 1格式化输出:%d表示日期,%thread表示线程名,%-5level:级别从左显示5个字符宽度%msg(或 %m / %message):日志消息,%n是换行符-->
    <property name="FILE_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50}:  %m%n"/>
    <!-- 日志最大保存数量 -->
    <property name="MAX_HISTORY" value="10"/>
    <!-- 日志文件大小 -->
    <property name="FILE_SIZE" value="10MB"/>
    <!-- 所有日志文件总大小 -->
    <property name="TOTAL_SIZE_CAP" value="10G"/>
    <!-- 日志文件存放路径 -->
    <!--<property name="FILE_PATH" value="/Users/imangozhang/logs/log_file/"/> -->
    <!-- audit文件,记录info级别日志 -->
    <appender name="INFO-OUT" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 实时输出的日志文件 -->
        <file>/Users/imangozhang/logs/info.log</file>
        <append>true</append>
        <!-- 历史日志分块,配置滚动的策略  - 这个更适用于生产 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>./packer_log/error.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>${FILE_SIZE}</maxFileSize>
            <totalSizeCap>${TOTAL_SIZE_CAP}</totalSizeCap>
            <maxHistory>${MAX_HISTORY}</maxHistory>
        </rollingPolicy>

        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${FILE_PATTERN}</pattern>
        </encoder>
        <!-- 过滤掉非info的日志,即此日志文件中只会输出info日志 -->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMissmatch>DENY</onMissmatch>
        </filter>
    </appender>

    <!-- 控制台输出 -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${FILE_PATTERN}</pattern>
        </encoder>
    </appender>

    <!-- 相当于logger元素,只是name值已经确定为root了,level 默认为 DEBUG -->
    <root level="INFO">
        <appender-ref ref="STDOUT" />
        <appender-ref ref="INFO-OUT" />
    </root>

</configuration>

2.Slf4j源码解析

我们的应用代码中直接调用的是Slf4j的接口,这就是所谓的日志门面,在运行时才会去动态绑定日志实现框架Logback。我们本章就来分析日志门面框架Slf4j的源码。

2.1.slf4j入口

我们的程序入口是slf4jLoggerFactory.getLogger(LogbackApplication.class)方法:

image-20231130065100060.png

image-20231130065313870.png

通过getILoggerFactory可以看到,返回的ILoggerFactory是一个单例类,如果没有初始化过,进行初始化:

image-20231130070058659.png

IloggerFactory初始化的核心就是bind()方法:

image-20231130070415782.png

image-20231130070415782.png

初始化的核心是绑定,主要可以分为 4 步:

(1)获取实现了slf4j绑定接口的对象实例org.slf4j.imp.StaticLoggerBinder

(2)记录获找到的绑定对象实例

(3)调用logback绑定对象org.slf4j.imp.StaticLoggerBinderinit()方法,将slf4jlogbackLogger进行绑定

(4)记录实际绑定的对象和事件等

2.2.StaticLoggerBinder

slf4j具体是如何找到绑定接口实现类org.slf4j.imp.StaticLoggerBinder的呢?通过ClassLoadergetResources*()方法去挨个遍历所有的实现类,找到实现了STATIC_LOGGER_BINDER_PATH接口的类:

image-20231130074145567.png

image-20231130074145567.png

此时我们可以去logback-class-1.2.10.jar去确认一下是否有该实现:

image-20231130074818931.png

如果获取到有实现了 slf4j 接口的日志框架,需要记录下来:

image-20231130075157285.png

2.3.Logback绑定接口实现

接下来我们看一下logback是如何完成与slf4j的绑定的。StaticLoggerBinder.getSingleton()logback绑定的核心工作,它负责解析logback.xml的配置信息,然后初始化到LoggerContext对象当中。

由于现在还没有进行初始化,所以先进行单例初始化:

image-20231130085453203.png

初始化调用init() 方法:

image-20231130085557803.png

init() 方法的核心逻辑就是解析logback.xml文件的解析到LoggerContext,然后与slf4j

image-20231130090115172.png

logback.xml解析到LoggerContext用到了joran框架,后面分析logback源码时详细分析。

到此为止我们就获得了对接口ILoggerFactory实现后的对象LoggerContext

image-20231130090607632.png

LoggerContext中的Logger对象即为我们slf4j入口函数getLogger需要的返回参数:

image-20231213080329211.png

logbackLogger对象也完全实现类slf4jLogger接口,这是能够完成绑定的关键所在:

image-20231213080546334.png

2.4.总结

  1. 业务侧调用slf4jgetLogger方法获取Logger接口的实现类;
  2. slf4j找到并调用logback的绑定接口实现类;
  3. logback通过joran 框架解析并处理logback.xml配置文件,初始化到slf4j.Logger的实现类logback.classic.Logger对象中返回;
  4. 业务侧获取的Logger接口,其实绑定的是logbackLogger对象。

1.绑定.png

3.Logback源码解析

上面我们分析了slf4j的源码入口,以及logback如何与slf4j进行绑定,但是关于logback的处理细节还没看到。本节来分析logback的源码细节。

3.1.初识joran

上面已经提到,logback实现了slf4j的绑定接口StaticLoggerBinder,这是logback日志框架初始化的入口:

image-20231205081008060.png

autoConfig完成了对logback.xml的所有初始化配置,我们看下它都干了什么:

image-20231205081458523.png

可以看到主要分为 2 步:

  1. findURLOfDefaultConfigurationFile获取配置文件路径
  2. configureByResource配置

获取文件路径的优先级分为:

logback.configurationFile –> logback-test.xml –> logback.xml

image-20231205082426111.png

image-20231205082104518.png

image-20231205082259159.png

3.1.1.joran入口

配置的最终结果是生成一个JoranConfigurator对象,然后将loggerContext即日志上下文记录到该对象当中:

image-20231205082628143.png

我们可以看到JoranConfigurator位于ch.qos.logback.classic.joran包中,joranlogback专门设计用来处理配置的框架,具体如何运作的?我们一路追踪到buildInterpreter()

image-20231205082806840.png

image-20231205082905682.png

image-20231205083048352.png

image-20231205083132856.png

到这里为止,joran执行流程被分成了 3 步:

  • SaxParserlogback.xml中的标签解析为SaxEvent事件列表;
  • buildInterpreter构造事件解析器;
  • play运行事件绑定的方法。

大胆猜想,第一步必然是给interperter这个字段进行赋值,然后第二步play就是依靠配置好的interperter来处理事件列表eventList

3.1.2.joranSaxEvent

joran框架运行的第一步就是利用SaxParserlogback.xml中的标签解析为SaxEvent事件列表。SaxParserJDK提供的解析XML文件的工具类,是一种基于流的解析方式,边读取XML边解析,并以事件回调的方式让调用者获取数据:

image-20231213231548426.png

这里的入参inputSource就是将logback.xml的内容转换成了字节流,parse方法我们简单理解,就是读取到不同的标签,回执行对应的事件回调,通过事件回调将标签转换为logbackSaxEvent

3.1.3.joranbuildInterpreter

到了这里,别头大,代码真的很简单,你只要跟进去,就会发现这些内容很熟悉!

image-20231205085132221.png

首先是addInstanceRules,这是一个抽象方法,我们刚刚不是看过JoranConfigurator嘛,它实现了这个方法:

image-20231205085901875.png

怎么样,熟悉吗?这不就是我们在logback.xml里用到的一些标签嘛!看类名,**Rules**ActionElementSelector所以addInstanceRules的作用就是将logback.xml的不同标签匹配路径和对应的动作进行绑定,然后保存到RuleStore中,这就是模式匹配!

我们顺便看一眼这些**Action的类,你会发现它们其实都继承了Action这个类:

image-20231205090447171.png

**所有继承了Action的类都要实现beginend方法,这很重要!**然后还在implicitActions中增加了处理其它标签的模式匹配规则NestedComplexPropertyIANestedBasicPropertyIA

image-20231206090243460.png

我们上面的addInstanceRules方法里,其实是没有添加类似<encode><file>等等这些标签的匹配规则,这是因为这些标签都属于嵌套标签,它们都与NestedComplexPropertyIANestedBasicPropertyIA进行绑定。

3.1.4.joranplay

我们现在代码追踪到了EventPlayer.play

image-20231206054225680.png

image-20231206054143577.png

play的主要逻辑很直观:遍历事件列表List<SaxEvent>,处理每一个事件,事件包括 3 种类型:StartEventBodyEventEndEvent。我们先来看一下这个List<SaxEvent>都有什么内容(一共有 61 个元素,我只截取了一部分):

image-20231206061633883.png

image-20231206061122456.png

就是我们配置文件中定义的各个标签,而且我们发现了 2 个规律:

  1. 标签和事件的映射关系如下:<pattern>–>StartEventcontext–>BodyEvent</pattern>–>EndEvent
  2. 标签的嵌套关系与List<SaxEvent>顺序完全一致;
  3. 如果标签中没有内容,就不会映射BodyEvent事件。

3.1.5.总结

  1. logback使用JDK提供的XML解析工具类SAXParserlogback.xml解析为自己定义的SaxEvent子类,包括StartEventBodyEventEndEvent
  2. 同时构造解析器,加载支持所有的模式匹配规则到RuleStore,默认匹配规则到implicitActions
  3. 遍历事件列表,根据模式匹配规则找到对应的Action,回调事件对应的方法,StartEvent回调Action.begin()BodyEvent回调Action.body()EndEvent回调Action.end()

2.joran主流程.png

3.2.简单嵌套标签的事件执行流程

下面我们就以<file>标签为例,分别来分析简单嵌套标签的事件执行流程。然后在此基础上,去对比分析<encode><appender>等标签。

3.2.1.<file>StartEvent

只有 2 行,调用startElementfireInPlay

image-20231206065556184.png

startElement获取到标签绑定的Action对象(回顾上面的addInstanceRules),先将它们塞到actionListStack当中,供后面的BodyEvent使用,然后调用Action对象的begin()方法:

image-20231206070633960.png

首先获取标签对应的Action对象:

image-20231208073718093.png

先到ruleStore里边找,这里存放的都是我们一开始JoranConfigurator类的addInstanceRules方法写入的所有模式匹配规则:

image-20231208074759776.png

在这里找不到,继续通过lookupImplicitActionimplicitActions找(一开始JoranConfigurator类的addImplicitRules写入的 2 个对象):

image-20231208075215163.png

会顺序遍历这两个对象**(NestedComplexPropertyIA在前NestedBasicPropertyIA在后)**,调用它们的isApplicable方法判断该标签是否适用当前的Action。首先是NestedComplexPropertyIAisApplicable方法:

image-20231208084812074.png

parentBean.computeAggregationType方法计算结果为AS_COMPLEX_*的标签,会使用NestedComplexPropertyIA。计算AggregationType前会先获取父类 Bean,我们以logback.xml中的<file>标签为例,它的父类就是<appender>标签指定的class参数ch.qos.logback.core.rolling.RollingFileAppender:

image-20231208085643322.png

image-20231208085720542.png

image-20231208085851932.png

这里最关键的一步是将父类RollingFileAppendergetsetadd方法分别放入propertyNameToGetterpropertyNameToGetterpropertyNameToGetter Map 当中。在判别是使用哪个Action时会用到该信息:

image-20231209072726385.png

先去RollingFileAppender类中找是否存在addFile方法,如果没有,再去找setFile,后者是有的,所以要通过computeRawAggregationType(setter)判别:

image-20231209073401164.png

先获取入参类型,然后判断入参类型是简单类型还是复杂类型,如果没有入参类型或者是简单类型就用NestedBasicPropertyIA,如果是复杂类型就用NestedComplexPropertyIAsetFile的第一个入参类型为java.lang.String,不为空,所以继续判断入参类型:

image-20231209075048217.png

类型判断共有 5 种情况:

  1. 是否是JDK基本类型,包括BooleanCharacterByteShortIntegerLongFloatDoubleVoid
  2. 是否是java.lang包中的类**(为什么单独把java.lang拿了出来?)**;
  3. 是否是静态类;
  4. 是否是枚举;
  5. 是否是Charset类型,或其子类。

这里命中了第 3 种情况,所以NestedComplexPropertyIA.isApplicable最终返回的是AS_BASIC_PROPERTY,这个类型自然不能使用复杂Action了,那接着会判断能否使用简单的Action,调用NestedBasicPropertyIA.isApplicable

image-20231209083034779.png

可以看到主体逻辑和复杂Action大差不差!唯一区别,就是如果是简单类型,那此刻要将父类Bean等信息构建成的IADataForBasicProperty添加到actionDataStash当中(你回上文看一下,会发现复杂类型也有类似操作)。

然后我们去看一下这个简单的Action,它的begin()方法干了什么:

image-20231209080955493.png

空实现,好吧,还真是简单……

调用完begin()方法后,就这就是fireInPlay方法,主要用来执行注册的监听器:

image-20231206073819884.png

只有配置文件中有<else>等条件标签以及<sift>等日志隔离的标签,才会在listenerList中注册监听器,例如<then>标签对应的ThenAction的父类ThenOrElseActionBase

image-20231206074834045.png

我们这里没有,直接跳过。

总结一下<file>标签的StartEvent处理流程:

5.2.1.file-startEvent.png

  1. 查找标签对应的Action类型,先到RuleStore中找,没找到去ImplicitActions找,找到后将Action推送到actionListStack
  2. 如果是ImplicitAction类型,则先调用NestedComplexPropertyIAisApplicable方法判断能否使用该类型处理标签;
  3. 如果不行则继续调用ImplicitActions中的下一个类型的isApplicable方法,即NestedBasicPropertyIA
  4. 找到ImplicitAction处理类后,将该类型推送到actionDataStack中,然后调用事件对应的play方法。

3.2.2.<file>BodyEvent

<file>标签在执行完BeginEvent之后,就该执行BodyEvent了。前面入口的细节我们就不列了,直接分析一下重点。首先,不是每个标签的StartEvent后面都有BodyEvent,只有像<file>标签这种标签内有内容才会有BodyEvent

image-20231206080507266.png

BodyEvent的主要处理流程:

image-20231207085552578.png

actionListStack是我们上面在执行StartEvent的时候塞好的,上面StartEvent已经分析过了,直接调用NestedBasicPropertyIAbody()方法即可:

image-20231209081902686.png

image-20231209082200077.png

可以看到,这里直接把body的内容作为setFile的入参,调用setFile

image-20231209082256381.png

setFile内部调用了父类FileAppendersetFile方法:

image-20231209221730795.png

setFile方法只是把日志文件的完整路径保存到fileName字段当中。

总结一下BodyEvent的执行流程:

5.2.2.file-bodyEvent.png

  1. 解析器直接读取actionListStack中的Action类型为NestedBasicPropertyIA,调用NestedBasicPropertyIAbody()方法;
  2. body()内部获取父类Bean(这里是RollingFileAppender)的setFile方法,将内容赋值给fileName

3.2.3.<file>EndEvent

调用完BodyEvent事件之后,就该接着执行<file>标签的EndEvent事件了,同样,还是调用NestedBasicPropertyIAend()方法:

image-20231209222124737.png

可以看到end()方法非常简单,只是单纯把actionDataStack中塞进去的和<file>标签相关的上下文清除。到此为止我们对<file>标签的全部解析过程就分析完了。

3.2.4.总结

<file>标签执行的所有事件流程整理如下:

5.2.4.file-总结.png

3.3.复杂嵌套标签的事件执行流程

<file>标签对应的 3 个事件的执行逻辑比较简单,下面我们分析一个比较复杂的标签<encoder>,这也是logback最核心的功能交汇处,控制日志的输出格式和方式。我们先来回顾一下<encoder>相关的事件都有哪些:

image-20231210082421744.png

image-20231209230050514.png

可以看到事件顺序和配置文件当中的标签嵌套关系是一致的。我们如果回去看一下JoranConfiguratoraddInstanceRules方法,会发现并没有往RuleStore当中添加和<encoder><pattern>相关的模式匹配规则,所以它们必然还是调用NestedBasicPropertyIANestedComplexPropertyIA的方法。

<encoder>标签指定的beanPatternLayoutEncoder,这是logback目前唯一有用且默认的 encoder 。

3.3.1.<encoder>StartEvent

首先是<encoder>标签的StartEvent事件,还是先后通过NestedComplexPropertyIA.isApplicableNestedBasicPropertyIA.isApplicable判别使用哪个Action

image-20231210083824563.png

encoderfile对应的是同一个父类RollingFileAppender,所以这里要去判断该父类有没有实现addEncodersetEncoder方法,实际上其父类OutputStreamAppender实现了,然后通过判断最终会调用到NestedComplexPropertyIA.begin()

哇塞,这个复杂Actionbegin我们还没看过哦:

image-20231210095027072.png

begin主要完成了 3 件事:

  1. PatternLayoutEncoder记录到NestedComplexProperty
  2. 将上下文context记录到NestedComplexProperty.context
  3. NestedComplexPropertyObject类型,真实类型为PatternLayoutEncoder)推送到objectStack

3.3.2.<pattern>StartEvent

执行完<encoder>StartEvent之后,就要执行<pattern>标签的StartEvent了。<pattern>标签在NestedComplexPropertyIA.isApplicable进行判断时,通过ic.peekObject()获取到的栈顶bean是刚刚推送进去的PatternLayoutEncoder

image-20231210084357010.png

OK,获取到PartternLayoutEncoder之后就要判断它是否实现了setPatternaddPattern方法:

image-20231210090243056.png

我们可以直接看一下PartternLayoutEncoder的内容:

image-20231210090335194.png

它只有一个start()方法,然后我们还要去看它的父类PatternLayoutEncoderBase

image-20231210101526878.png

父类实现了setPattern,所以<pattern>标签的StartEvent事件必然会调用NestedBasicPropertyIA.begin()对吧!NestedBasicPropertyIAbegin()body()end()5.1.3节分析<file>标签的事件流程时都分析过了,这里不再赘述。主要关注的一点是,body()方法会调用setPattern()将日志格式%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50}: %m%n赋值到PatternLayoutEncoderBase.pattern字段,后面会用到!

3.3.3.<encoder>EndEvent

<pattern>标签的所有事件执行完之后,就要执行<encoder>标签的EndEvent了,调用的是NestedComplexPropertyIA.end()

image-20231210105845727.png

因为我们在begin()方法中将NestedComplexProperty已经推送到actionDataStack了,NestedComplexProperty的真实类型为PatternLayoutEncoder,它实现了LifeCycle接口,所以end()当中会调用PatternLayoutEncoder.start()

image-20231210110536374.png

这是LifeCycle第一次被唤醒,这次是用来启动encoder!后面还有一次哦~~~

start()方法主要逻辑:

  1. 构造PatternLayout对象;
  2. 调用PatternLayoutBase对象的start()方法;
  3. 调用LayoutWrappingEncoder对象的start()方法。

PatternLayoutlogback中非常重要的概念,它是encoder完成日志格式转换的关键对象。

  • 构造PatternLayout

PatternLayout构造PatternLayout对象时会加载静态资源DEFAULT_CONVERTER_MAP

image-20231210213502517.png

image-20231210213624627.png

是不是很眼熟?这些就是在<pattern>标签中的日志格式支持的所有可解析的标识符,以及标识符对应的格式转换器。

我们可以通过继承PatternLayout类,然后向DEFAULT_CONVERTER_MAP添加自定义的格式转换器,实现在日志中打印一些业务需要的内容,会在后面的扩展部分详细讲解。

  • PatternLayoutBase.start()

PatternLayoutBase.start()会完成对日志模版的所有预置解析工作:

image-20231210222253524.png

首先将pattern拆分成格式标识符和关键词后封装到Converter<E>链表当中,因为我们的日志pattern%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50}: %m%n,所以解析后的链表以PatternLayoutBase.head为头节点,内容如下:

image-20231212090114832.png

image-20231212090445626.png

然后ConverterUtil.startConverters(this.head)会利用上面加载的静态资源DEFAULT_CONVERTER_MAP遍历每个Converter调用它们的start()方法。我们以DateConvert类为例:

image-20231213061704212.png

它会解析optionList的第一个option,我们从上面的head内容可以得知此处为yyyy-MM-dd HH:mm:ss:SSSstart()方法会将该option赋值给cachingDateFormatter

  • LayoutWrappingEncoder.start()

LayoutWrappingEncoder.start()内容比较简单,如果是需要立即刷新,则需要设置immediateFlush标识,最后将started标识置为trun

image-20231210225241113.png

到此为止,<encoder>标签的所有事件就处理完了,logback所有配置工作也完成了,接下来就是打印日志了。

3.3.4.<appender>EndEvent

对于<appender>标签,它在匹配模式中被绑定的Action类型为AppenderActionStartEvent.begin()没有太多可说的,它也没有重写body()方法,因为<appender>标签内都是<encoder><filter><file>等嵌套标签,没有标签内容。

我们重点分析一下EndEvent调用的end()方法:

image-20231212073708420.png

这是LifeCycle第二次被唤醒,这次用来启动appender

这里启动了appender,会触发RollingFileAppender.start()

image-20231212074232782.png

然后像多米诺骨牌一样,层层向上调用父类的start()方法:

RollingFileAppender -> FileAppender -> OutputStreamAppender -> UnsynchronizedAppender

OK,最终调用到UnsynchronizedAppender.start()才停止:

image-20231212074504178.png

started字段赋值为true

3.3.5.总结

<encoder><appender>的完整执行流程整理如下:

5.2.4.encode-总结.png

3.4.打印日志

上面分析了主要涉及的标签通过joran框架的解析,完成初始化的流程。完成初始化后就可以进行日志打印了。

3.4.1.获取Logger对象

要想打印日志,首先要获取Logger对象,例如我们的示例程序:

image-20231211071031067.png

我们先看看logbackLogger对象中都包含哪些内容:

image-20231201083249682.png

image-20231202085945566.png

首先,logback直接实现了slf4j的接口org.slf4j.Loggerlogback直接实现了所有slf4j的接口,这也是logback不需要桥接器的原因!)Logger中各个字段含义如下:

| 字段 | 说明 |
| — | — |
| name | logger标签中name属性值,表示名称,如果配置文件中没有指明,则和包的层级对应。 |
| level | logger标签中level属性值,表示日志级别,Level类型,包括OFF/ERROR/WARN/INFO/DEBUG/TRAVE/ALL七个级别,父子层级之间具有传递性,可以为null。 |
| effectiveLevelInt | 日志级别,int类型。 |
| parent | 父节点,所有节点至少都有一个共同的父节点root。 |
| childList | 子节点列表。 |
| aai | 所有appender-ref标签列表,如果配置文件中没有则为null。 |
| additive | logger标签中additivity属性值,表示是否继承父节点的日志级别和Appender等属性,默认为true。 |
| loggerContext | logger上下文,维护所有父子节点信息、过滤器、整个配置文件信息等内容。 |

这些字段我们现在可能还不清楚有什么作用,不着急,等我们后面分析logger.info() 方法是用到了给大家详细讲解。

我们先来分析一下iLoggerFactory.getLogger(name)的流程,getLogger的核心流程只有下面这部分:

image-20231202084934179.png

主要分为两步:

  1. 逐级获取目录名称
  2. 根据目录名称获取对应的Logger对象,如果没有获取到,则创建并缓存

我们传入的完整包名为com.combat.logback.LogbackApplication,看下最终完成遍历后的loggerCache结果:

| logger标签名称 | Logger对象内容 |
| — | — |
| ROOT | { “name”: “ROOT”, “level”: “INFO”, “effectiveLevelInt”: 20000, “parent”: null, “childList”: [ {Logger@com} ], “aai”: [ {ConsoleAppender}, {RollingFileAppender} ], “additive”: true, “loggerContext”: {LoggerContext@1121}<} |
| com | { “name”: “com”, “level”: “null”, “effectiveLevelInt”: 20000, “parent”: {Logger@ROOT}, “childList”: [ {Logger@com.combat} ], “aai”: null, “additive”: true, “loggerContext”: {LoggerContext@1121}<} |
| com.combat | { “name”: “com.combat”, “level”: “null”, “effectiveLevelInt”: 20000, “parent”: {Logger@com}, “childList”: [ {Logger@com.combat.logback} ], “aai”: null, “additive”: true, “loggerContext”: {LoggerContext@1121}} |
| com.combat.logback | { “name”: “com.combat.logback”, “level”: “null”, “effectiveLevelInt”: 20000, “parent”: {Logger@com}, “childList”: [ {Logger@com.combat.logback.LogbackApplication} }, “aai”: null, “additive”: true, “loggerContext”: {LoggerContext@1121}<} |
| com.combat.logback.LogbackApplication | { “name”: “com.combat.logback.LogbackApplication”, “level”: “null”, “effectiveLevelInt”: 20000, “parent”: {Logger@com.combat.logback}, “childList”: null, “aai”: null, “additive”: true, “loggerContext”: {LoggerContext@1121}<} |

通过上面的列表我们可以得出如下结论:

  1. Logger对象通过parentchildList将目录层级串联起来,最上层com的父节点是ROOT
  2. ROOT根节点的日志级别与我们配置文件一致,为INFO,其他层级均为null,因为我们并没有在配置文件中配置logger标签;
  3. ROOT根节点有 2 个appender-ref标签,其他层级没有定义,所以为null
  4. 所有节点的additive属性均默认为true;
  5. 所有层级关联的loggerContext为同一个对象,即维护同一份上下文。

3.4.2.打印日志入口

获取到Logger对象后就可以调用slf4j规范提供的接口来打印日志了。本节我们分析当我们调用logbacklogger.info()方法打印日志时,logback是如何运行的。

Logbacklogback-classic.jarLogger对象中实现了slf4j所有日志打印方法,以info()为例:

image-20231202160450494.png

入参msg为我们需要打印的日志信息,info内部调用filterAndLog_0_Or3Plus方法,入参除了msg还有两个:

  • FQCN: 日志实现类完整名称,即 ch.qos.logback.classic.Logger

image-20231202160821327.png

  • Level.INFO: 日志级别,Level对象各个日志级别对应的取值如下(包含 2 个字段,levelIntlevelStr):

image-20231202161119684.png

INFO的取值:

image-20231202160915674.png

image-20231202161301708.png

日志级别越高,levelInt值越大!

然后进入filterAndLog_0_Or3Plus方法:

image-20231202162558555.png

我们看到打印日志主要分为两步:

  1. getTurboFilterChainDecision_0_3OrMore:获取TurboFilter链的计算结果,类型为FilterReply
  2. buildLoggingEventAndAppend:构建日志事件,进行日志输出。

3.4.3.过滤器TurboFilter

TurboFilger顾名思义,是一种过滤器,如果配置文件中设置了各种过滤器,这里通过对过滤器链进行计算,得出的结果决定是否打印日志。这个计算结果类型为FilterReply

image-20231202163043408.png

接下来我们就去探索一下FilterReply的获取过程:

image-20231202163241332.png

image-20231206090243460.png

通过分析这两段代码基本可以搞清楚TurboFilter过滤器列表的计算逻辑了:

  1. turboFilterList中没有过滤器,则默认返回NEUTRUAL(中立)
  2. turboFilterList中只有一个TurboFilter,则返回该过滤器decide方法的结果;
  3. turboFilterList中有多个TurboFilter,则从头开始遍历,只要有一个过滤器的decide方法计算结果为DENY(拒绝)或者ACCEPT(接受),则返回该结果,如果为NEUTRAL则跳过判断下一个;
  4. turboFilterList中所有过滤器的decide方法计算结果都为NEUTRAL,则返回NEUTRAL

深入细节:什么是TurboFilter?它的decide方法是如何算出FilterReply结果的?

image-20231202214249392.png

Logback一共有 5 种TurboFilter,我们大概都扫一眼这些过滤器,DynamicThresholdFilter过滤器注释非常详细:

image-20231202215145062.png

在配置文件中使用<turboFilter>标签就可以定义一个turboFilter过滤器,后面的class参数指定的就是这 5 种过滤器中的一种。下面看看这个过滤器的作用:

image-20231202215550018.png

  1. 如果日志中的关键字userId=user1,日志级别 >= DEBUG 才会打印;
  2. 如果日志中的关键字userId=user2,日志级别 >= TRACE 才会打印;
  3. 如果日志中的关键字userId=其它值,日志级别 >= ERROR 才会打印。

所有,TurboFilter过滤器是为我们提供了一些策略,来决定是否打印日志。decide计算过程我们先不去深入分析了,主要思想就如上述示例所示。

3.4.4.appender

执行完过滤器的判断逻辑后,如果通过了过滤规则,接下来就要打印日志了,打印日志调用的是buildLoggingEventAndAppend:

image-20231203103655296.png

一共就 3 行代码,首先构建了LoggingEvent对象,然后设置了marker字段的值,由于我们上层传过来的是null,所以这里就跳过了,最后调用callAppenders应该是用来打印日志的。如何封装LoggingEvent对象我们就不看了,直接来看callAppenders(le)

image-20231203150613426.png

callAppenders的逻辑主要分为两部分:

  1. Logger对象依次向上层递归,调用父节点的appendLoopOnAppenders
  2. 如果没有任何父节点需要处理,则执行noAppenderDefinedWarning方法。

我们先来看一下appendLoopOnAppenders

image-20231203151907392.png

由 5.1 的列表我们知道,只有ROOT根节点的aai字段不为空,为什么?我们先找到aai是在哪里赋值的,给aai赋值在Logger只类中有一个方法:

image-20231211083237913.png

该方法是被AppenderRefAction.begin调用的,begin()会将该节点绑定的appender追加到appenderList当中:

image-20231211083427918.png

这又回到了joran框架,必然是joran解析配置文件时,解析到与该Action绑定的标签时,执行StartEvent调用的begin()方法:

image-20231211083810559.png

我们的配置文件中正是使用了<root/appender-ref>标签:

image-20231211083905947.png

所以最终遍历到ROOT节点才会执行aai.appendLoopOnAppenders(event)方法:

image-20231203202105493.png

其中appenderList包含 2 个对象:

  • INFO-OUT指定的beanch.qos.logback.core.rolling.RollingFileAppender
    • STDOUT指定的beanch.qos.logback.core.ConsoleAppender

然后就是挨个执行这 2 个appender的日志打印逻辑doAppend(E var1)

appenderList中的两个对象都继承自UnsynchronizedAppenderBase, 所以最终调用的是UnsynchronizedAppenderBase.doAppend(E)

image-20231203205643437.png

doAppend通过guard实现线程安全保证,然后通过started判断appender是否启动,我们上面 5.5 节已经分析过了,会在<appender>标签的EndEvent事件中,调用UnsynchronizedAppenderBase.start()started赋值为true,所以此时appender已经启动了。

doAppend调用了抽象方法append,在我们指定的RollingFileAppender的父类OutputStreamAppender中实现了:

image-20231203205831551.png

image-20231212075614839.png

writeBytes完成最终日志的输出。 完成日志输出前,还有 2 步预处理工作:

  1. LoggingEvent.prepareForDeferredProcessing
  2. LayoutWrappingEncoder.encode

  3. LoggingEvent.prepareForDeferredProcessing

image-20231212080311846.png

第一次预处理需要获取 3 个信息:格式化后的日志内容、线程名称和MDC属性。格式化后的内容这里就是我们在启动类中写的hello world字符串;线程名称为当前线程名称mainMDC属性由于我们还没有使用,所以这里获取的Map为空(后面会在实战当中为大家展示MDC的作用)。

  • LayoutWrappingEncoder.encode

image-20231212081418622.png

encode方法内部调用了最后一个关键步骤PatternLayout.doLayout

image-20231212081617480.png

image-20231212081910423.png

PatternLayoutBase.head应该很眼熟了,在PatternLayoutBase.start()时将<pattern>标签的内容预处理为Convert<E>链表,head即为链表的头节点。这个while循环就是要跟据Convert<E>链表按照<pattern>标签的内容格式构建出最终的日志内容。

我们先看一下Convert<E>链表的内容,后面的逻辑就很好理解了:

c.write内部调用的就是封装好的每个Convert实现的write方法,然后将结果拼接到buf当中:

image-20231212090903775.png

image-20231212090950998.png

我们以最简单的DateConverter为例:

image-20231213062729717.png

timestamp是调用logger.info()时的时间戳,cachingDateFormatter是在上面 5.4 节PatternLayoutBase.start()的最后调用DataConvert.start(),将时间格式yyyy-MM-dd HH:mm:ss.SSS赋值进去的,所以这里将时间戳转换成了我们日志配置文件中pattern规定的时间格式。

到此为止,貌似我们已经完成了对logback整个源码主要流程的解读!如果你可以像上文一样,自己耐心打断点调试一遍,会有更多收获。

3.4.5.总结

打印日志整体流程整理如下:

5.5.5.打印日志-总结.png

4.Log4j2Logback对比

Log4j2Log4j的升级,同时借鉴了Logback的优秀设计,并修复了Logback架构中的一些问题,号称是目前最优秀的Java日志框架。它本身就是日志门面,可以不依赖Slf4j独立使用,也可以使用Slf4j+Log4j2的架构。

4.1.使用Log4j2框架

如果是单纯使用Log4j2作为日志门面和实现框架,只需要引入 2 个包:

  • log4j-apiLog4j2自带的日志门面
  • log4j-coreLog4j2具体的日志实现

maven配置如下:

<dependencies>
    <!--Log4j2自带的日志门面-->
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-api</artifactId>
        <version>2.17.1</version>
    </dependency>
    <!--Log4j2具体的日志实现-->
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-core</artifactId>
        <version>2.17.1</version>
    </dependency>
</dependencies>

项目中需要通过LogManager获取日志对象:

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class Log4j2Application {
    public static final Logger logger = LogManager.getLogger(Log4j2Application.class);

        public static void main(String[] args) {
            logger.info("hello world");
        }
}

而如果是使用Slf4j作为日志门面,因为Log4j2本身没有实现Slf4j规范的接口,所以需要额外再引入一个包log4j-slf4j-impl作为桥接器:

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-slf4j-impl</artifactId>
    <version>2.17.1</version>
</dependency>

使用Slf4j作为日志门面,那在项目中获取日志对象的方式自然也是使用Slf4j的接口:

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

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

    public static void main(String[] args) {
            logger.info("hello world");
        }
}

如果我们的项目使用的日志框架为Slf4j2+Log4j2,可以看到这里的代码和Logbackmain函数语法一致,那么迁移到Logback的日志框架就不需要修改代码,直接修改依赖和配置文件即可。

阿里的《Java 开发手册》明确提出:应用中不可直接使用日志系统(log4j、logback)中的 API ,而应依赖使用日志框架 SLF4J 中的 API 。使用门面模式的日志框架,有利于维护和各个类的日志处理方式的统一。

Slf4j的配置文件和Logback略有区别,我们需要在resources下新建一个log4j2.xml的文件:

<?xml version="1.0" encoding="UTF-8" ?>
<!--monitorInterval属性值(秒数)为一个非零值来让Log4j每隔指定的秒数来重新读取配置文件,可以用来动态应用Log4j配置-->
<Configuration status="debug" monitorInterval="30">
    <!--用来自定义一些变量-->
    <Properties>
        <!--变量定义-->
        <Property name="myPattern" value="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
        <Property name="dir_url">/Users/imangozhang/logs</Property>
    </Properties>
    <!--使用Appenders元素可以将日志事件数据写到各种目标位置-->
    <Appenders>
        <!-- 默认打印到控制台 -->
        <Console name="ConsoleAppend" target="SYSTEM_OUT">
            <!-- 默认打印格式 -->
            <PatternLayout pattern="${myPattern}"/>
        </Console>
        <!-- 打印到日志文件上 -->
        <File name="FileAppend" fileName="${dir_url}/fileLog.log" bufferedIO="true" immediateFlush="true">
            <PatternLayout>
                <pattern>${myPattern}</pattern>
            </PatternLayout>
        </File>
    </Appenders>
    <!--定义logger,只有定义了logger并引入的appender,appender才会生效-->
    <Loggers>
        <!-- 默认打印日志级别为 error -->
        <Root level="INFO">
            <AppenderRef ref="ConsoleAppend"/>
            <AppenderRef ref="FileAppend"/>
        </Root>
    </Loggers>
</Configuration>

当然也支持jsonyml等格式的文件,最常用的还是xml。格式其实和Logback大差不差,主体框架都是一样的,只是部分标签略有区别而已(这里的标签首字母大小,如果改成首字母小写也是可以的)。

4.2.Log4j2迁移到Logback

Log4j2迁移到Logback主要考虑下面几个因素:

  • 配置文件迁移
  • 接口迁移: 如果使用的是纯Log4j2,则需要修改为使用Slf4j接口
  • 自定义业务迁移: 如果业务有自定义的layoutappender,则需要迁移,它们的部分实现略有区别

4.2.1.配置文件迁移

如果我们的Log4j2的配置文件是log4j2.properties文件,则可以尝试使用官方提供的迁移工具,转换为logback.xml文件(很少用,如果你是这种,可以去尝试一下)。

但如果你是log4j2.xml,这个迁移工具是肯定用不了的,我试过了……只能手动去改了!

4.2.2.接口迁移

如果使用的是纯Log4j2,业务代码中引入的包是org.apache.commons.log4j.*,但如果要迁移到Logback框架的话,需要统一使用Slf4j接口,所以我们需要修改 2 个地方:

  • 引入的包修改
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

修改为:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
  • 接口修改
public static final Logger logger = LogManager.getLogger(Log4j2Application.class);

修改为:

public static final Logger logger = LoggerFactory.getLogger(Log4j2Application.class);

这里如果我们的项目比较庞大,无需一个个文件去手动修改,这里Logback官方提供了一个代码迁移工具,可以帮我吗干这个事情。

4.2.3.自定义业务迁移

  • layout迁移

假设我们现在要迁移一个简单的,名叫 TrivialLog4jLayout 的 log4j layout,它将日志事件中的消息作为格式化消息返回。代码如下:

package chapters.migrationFromLog4j;

import org.apache.log4j.Layout;
import org.apache.log4j.spi.LoggingEvent;


public class TrivialLog4jLayout extends Layout {
    public void activateOptions() {
    }

    public String format(LoggingEvent loggingEvent) {
        return loggingEvent.getRenderedMessage();
    }

    public boolean ignoresThrowable() {
        return true;
    }
}

等价的 logback-classic TrivialLogbackLayout 如下:

package chapters.migrationFromLog4j;

import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.LayoutBase;

public class TrivialLogbackLayout extends LayoutBase<ILoggingEvent> {
  public String doLayout(ILoggingEvent loggingEvent) {
    return loggingEvent.getMessage();
  }
}

正如你所见,在logback-classic layout中,格式化的方法叫做doLayout,而在 log4j 中叫format()。因为在 logback-classic 中没有等价的方法,所以 ignoresThrowable() 方法则不需要。logback-classic layout 必须继承 LayoutBase<ILoggingEvent> 类。

activateOptions() 方法的优点值得进一步讨论。在 log4j 中,一个 layout 有它自己的 activateOptions() 方法,通过 log4j 的配置程序,也就是 PropertyConfiguratorDOMConfigurator,会在 layout 所有的选项都设置完之后调用。因此,layout 有机会去检查它的所有的选项是否一致,如果是,那么开始进行初始化。

logback-classiclayout必须实现 LifeCycle 接口,该接口包含了一个 start() 方法。这个 start() 方法相当 log4j 中的 activateOptions() 方法。

  • appender迁移

迁移appender与迁移layout类似。下面是有一个名为 TrivialLog4jAppender 的简单appender,它会在控制台输出由它的layout返回的字符串。

package chapters.migrationFromLog4j;

import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.spi.LoggingEvent;

public class TrivialLog4jAppender extends AppenderSkeleton {
  protected void append(LoggingEvent loggingevent) {
     String s = this.layout.format(loggingevent);
     System.out.println(s);
  }

  public void close() {
     // nothing to do
  }

  public boolean requiresLayout() {
     return true;
  }
}

logback-classic中等价的写法为 TrivialLogbackAppender,如下:

package chapters.migrationFromLog4j;

import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.AppenderBase;

public class TrivialLogbackAppender extends AppenderBase<ILoggingEvent> {

  @Override
  public void start() {
    if (this.layout == null) {
      addError("No layout set for the appender named [" + name + "].");
      return;
    }
    super.start();
  }

  @Override
  protected void append(ILoggingEvent loggingevent) {
    // AppenderBase.doAppend 只会在这个 appender 成功启动之后调用这个方法
    String s = this.layout.doLayout(loggingevent);
    System.out.println(s);
  }
}

比较这两个类,你会发现 append() 方法的内容没有改变。requiresLayout 方法在 logback 中没有用到,所以它可以被移除。在 logback 中,stop() 方法与 log4j 中的 close() 方法等价。然而,logback-classic 中的 AppenderBase 包含一个没有实现的 stop 方法,但是在这个简单的 appender 已经足够了。

5.SpringBoot整合Logback

如果我们使用的是SpirngBoot 项目,如何打印日志呢?SpringBoot已经整合了所有主流的日志框架,当然包括我们上面介绍的LogbackLog4j2

5.1.依赖和配置

SpringBoot项目默认使用的日志框架是Logback,也就是说只要你引入任意一个SpringBootstarter依赖,它默认会引入Logback日志框架。例如:

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
    <version>2.7.12</version>
</dependency>

执行mvn dependency:tree获取的Maven依赖树如下:

[INFO] com.combat:spring-logback:jar:1.0-SNAPSHOT
[INFO] \- org.springframework.boot:spring-boot-starter-web:jar:2.7.12:compile
[INFO]    +- org.springframework.boot:spring-boot-starter:jar:2.7.12:compile
[INFO]    |  +- org.springframework.boot:spring-boot:jar:2.7.12:compile
[INFO]    |  +- org.springframework.boot:spring-boot-autoconfigure:jar:2.7.12:compile
[INFO]    |  +- org.springframework.boot:spring-boot-starter-logging:jar:2.7.12:compile
[INFO]    |  |  +- ch.qos.logback:logback-classic:jar:1.2.12:compile
[INFO]    |  |  |  +- ch.qos.logback:logback-core:jar:1.2.12:compile
[INFO]    |  |  |  \- org.slf4j:slf4j-api:jar:1.7.32:compile
[INFO]    |  |  +- org.apache.logging.log4j:log4j-to-slf4j:jar:2.17.2:compile
[INFO]    |  |  |  \- org.apache.logging.log4j:log4j-api:jar:2.17.2:compile
[INFO]    |  |  \- org.slf4j:jul-to-slf4j:jar:1.7.36:compile

可以看到spring-boot-starter-web已经添加了依赖logback-classiclog4j-to-slf4jjul-to-slf4j

由此看出,SpringBoot通过spring-boot-starter-logging不仅整合了logback,还整合了log4j

如果你还不确定用哪些SpringBootstart,那就直接使用spring-boot-starter-logging即可:

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-logging</artifactId>
    <version>2.7.12</version>
</dependency>

配置文件的读取略有区别,初了可以自动读取logback.xmlSpringBoot还支持下面的格式:

  • logback-spring.xml
  • logback.xml
  • logback-spring.groovy
  • logback.groovy

官方更建议使用logback-spring.xml

配置文件的格式没有变化。

如果我们需要修改日志等级,可以修改logback-spring.xml配置文件,也可以在我们项目的配置文件application.properties中指定:

logger.level.root = INFO

application.properties中的优先级高于logback-spring.xml

5.2.源码分析

SpringBoot通过事件的发布订阅模式(即观察者模式)完成Logback日志框架的初始化。我们首先简单回顾一下SpringBoot的事件发布和订阅(这部分详细分析属于SpringBoot源码范畴,这里不做太深入的介绍,大家自行网上搜资料学习),然后看SpringBoot如果完成对Logback的初始化。

5.2.1.SpringBoot事件机制

SpringBoot的事件机制是对JDK的事件机制的扩展。JDK中定义了事件和监听者:

  • JDK事件
package java.util;

public class EventObject implements java.io.Serializable {
    private static final long serialVersionUID = 5516075349620653480L;
    protected transient Object  source;

    public EventObject(Object source) {
        if (source == null)
            throw new IllegalArgumentException("null source");
        this.source = source;
    }

    public Object getSource() {
        return source;
    }

    public String toString() {
        return getClass().getName() + "[source=" + source + "]";
    }
}
  • JDK监听者
package java.util;

/**
 * A tagging interface that all event listener interfaces must extend.
 * @since JDK1.1
 */
public interface EventListener {
}

SpringBoot中定义了很多种事件,这些事件的基类是ApplicationEvent,而ApplicationEvent则继承自JDKEventObject

package org.springframework.context;

import java.time.Clock;
import java.util.EventObject;

public abstract class ApplicationEvent extends EventObject {

    /** use serialVersionUID from Spring 1.2 for interoperability. */
    private static final long serialVersionUID = 7099057708183571937L;
    /** System time when the event happened. */
    private final long timestamp;

    public ApplicationEvent(Object source) {
        super(source);
        this.timestamp = System.currentTimeMillis();
    }

    public ApplicationEvent(Object source, Clock clock) {
        super(source);
        this.timestamp = clock.millis();
    }

    public final long getTimestamp() {
        return this.timestamp;
    }
}

相比JDKEventObjectApplicationEvent多了timestamp字段。SpringBoot的事件包括下面这些:

image-20231221084722145.png

SpringBoot会在不同的运行阶段发布对应的事件:

spring-event-list.png

SpringBoot的监听者都实现了ApplicationListener,它又继承自JDKEventListener

image-20231221085104201.png

SpringBoot的事件发布由ApplicationEventPublish接口的publishEvent方法完成,而AbstractApplicationContext唯一实现了该方法,所以有它完成事件的发布。

监听者有很多,如何让多个监听者顺序执行呢?—— 让监听者实现Ordered接口,然后实现getOrder方法,给这些监听者指定顺序。例如SmartApplicationListener

image-20231221090858185.png

5.2.2.SpringBoot完成Logback的初始化

SpringBoot通过LoggingApplicationListener来完成Logback的初始化:

image-20231221170233523.png

image-20231221170412030.png

主要看一下下面这几个事件的处理逻辑:

  • onApplicationStartingEvent
  • onApplicationEnvironmentPreparedEvent
  • onApplicationPreparedEvent

onApplicationStartingEvent事件是容器刚启动时触发的,主要完成SpringBoor容器中的Bean实例化前的一些准备工作:

image-20231221171017360.png

beforeInitialize()是一个抽象方法,SpringBoot分别实现了Log4j2LogbackSlf4j等日志框架初始化的准备工作:

image-20231221171215703.png

image-20231221171251186.png

image-20231221171317436.png

如果你认真研读了前面几章关于Logback源码的分析,到这里应该很熟悉了:这里直接调用了Logback的绑定方法StaticLoggerBinder.getSingleton()完成了LogbackSlf4j日志门面的绑定工作!

onApplicationEnvironmentPreparedEvent事件是SpringBoot创建好抽象环境类后发布的事件,这里监听到该事件后正式完成Logback日志对象的初始化:

image-20231221171040274.png

初始化主要关注 2 个关键步骤,initializeSysteminitializeFinalLoggingLevels,前者用于设置日志文件路径,优先读取application.properties文件设的logging.config值,没有则去读取logback-spring.xml中的文件路径;后者用于设置日志级别,优先读取application.properties文件设的logging.level.root值,没有则去读取logback-spring.xml中的日志级别:

image-20231221174431431.png

onApplicationPreparedEventSpringBoot已经构建好上下文以后发布的事件,这里主要完成日志Bean的注入工作:

image-20231221171101383.png

到这里我们完整分析了SpringBoot是如何整合Logback日志框架的。当然,一些非主流链路的细节,我们这里就不分析了,大家感兴趣的话可以去调试和验证,我这里写再多也比不上你动手实践一遍的!

6.Logback常用扩展

我们如果只会配置Logback,然后让它打印规定格式的日志,很多时候还是无法满足业务要求的。就比如我想在所有业务日志中统一打印一些业务字段,但是这些字段Logback本身是不认识的,无法为我们解析和转换怎么办?如果我想对日志中的一些敏感信息进行脱敏处理怎么办?本节我们就列举一些常用的Logback扩展功能。

6.1.添加业务字段

业务中最常见的需求就是在日志中打印一次请求的RequestId以串联起一次请求的所有日志,或者打印用户的uid以方便确认某个用户的行为。我们给一个如何在SpringBoot项目的日志中添加RequestId的示例。

给日志添加业务字段的核心手段是AOP(AOP 的概念就不在这里普及了,大家自行了解),所以我们在第 5 章SpringBoot项目的基础上,添加依赖:

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
    <version>2.7.12</version>
</dependency>

我们的项目结构如下:

image-20231223090030787.png

主要是添加了一个切面类 LoggerAspect

image-20231223090155680.png

@Component帮助我们将切面类注入到SpringBoot容器中,@Aspect能够让SpringBoot识别到这是一个切面类。@Pointcut���点指向的是controller包下的所有方法(这是@Pointcut的语法规则)。

然后定义@Before注解方法:

image-20231223090745412.png

如果请求Header中包含RequestId字段,则放到dataMap当中,如果是请求入参当中有RequestId,会覆盖Header的值,最终会在recoredRequestId方法中将RequestId字段放到MDC当中,这样就完成对RequestId字段的添加了(如果没有值,这里通过UUID做默认处理):

image-20231223091117532.png

然后是@AfterRunning注解打印请求完成时的日志:

image-20231223092100919.png

打印的日志中还包含了接口耗时信息,注意这里还用到了ThreadLocal。打印完请求返回日志后要进行资源清理,防止内存泄漏或者请求直接串值。我们的示例请求接口很简单:

image-20231223092309023.png

最后别忘记在我们的Logback配置文件logback-spring.xml的日志格式中添加requestId字段:

<property name="FILE_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %X{requestId} %-5level %logger{50}:  %m%n"/>

到此为止我们就完成业务字段requestId的添加了,来看一下执行效果:

image-20231223092523637.png

6.2.日志脱敏

如果我们的业务中涉及一些账号、密码、验证码或者提取码等敏感信息的打印,为了方式日志泄漏后对用户造成不必要的损失,在业务中往往需要对日志进行脱敏处理。脱敏即去除敏感信息,例如:我们的邮箱源数据为13312348080@163.com,则日志中仅打印1*********8@163.com;而密码我们则固定打印为******

Java项目中的脱敏手段主要有 2 中方式:

  • 在需要脱敏的字段上添加注解,通过Logback对带有注解的字段进行统一处理,这种方式直接引入houbb/sensitive即可;
  • 直接在Logback配置文件中添加自定义规则,实现自定义Converter类。

第一种方式我们暂时不在这里展开讲,如果是在业务开发早期就对脱敏有规划,那我建议优先使用这种方式,因为这种方式性能好还不会有遗漏。但是如果对于一个我们不想有任何代码改动的项目,对性能以及脱敏的结果又没有那么苛刻,我更建议使用第二种,这种方式也可以应付大多是情况了,下面我们介绍一下第 2 中方式。

首先,我们要继承MessageConverter类,实现自定义的日志内容转换类,在这个类里完成日志的脱敏工作:

package com.combat.logback.converter;

import ch.qos.logback.classic.pattern.MessageConverter;
import ch.qos.logback.classic.spi.ILoggingEvent;

import java.util.HashMap;
import java.util.Map;

public class SensitiveMessageConverter extends MessageConverter {
    private static final Map<String, String> regexMap = new HashMap<>();

    static {
        // 手机号脱敏
        regexMap.put("(mobile|手机号)(=|=\[|\":\"|:|:|='|':')(1)([3-9]{2})(\d{4})(\d{4})(\]|\"|'|)", "$1$2$3$4****$6$7");
        // ���码脱敏
        regexMap.put("(password|pwd|PASSWORD)([=|\"|\\\\|:|:|\\[|'|\\s]+)([\\w\\d\\s$@$!%*?&/+=]{1,128})(\\w*)", "$1$2******$4");
    }

    @Override
    public String convert(ILoggingEvent event) {
        String oriLogMsg = event.getFormattedMessage();
        String afterLogMsg = oriLogMsg;
        if (afterLogMsg == null || afterLogMsg.length() <= 0) {
            return afterLogMsg;
        }

        for (Map.Entry<String, String> regexPair : regexMap.entrySet()) {
            afterLogMsg = afterLogMsg.replaceAll(regexPair.getKey(), regexPair.getValue());
        }
        return afterLogMsg;
    }
}

我们在上面分析Logback源码时知道Logback提供的Converter的继承类有很多,这里为什么实现类MessageConverter就可以呢?我们看一下该类的内容:

image-20231218085758984.png

MessageConverter是日志格式化完成的最后一个Converter,它将格式化好的内容直接返回给appender,所以我们继承该类后重写convert方法,对日志内容进行最后的修改,即可完成脱敏。

然后,我们还需在logback.xml中添加一条自定义规则:

<conversionRule conversionWord="m" converterClass="com.combat.logback.converter.SensitiveMessageConverter"/>

conversionWord的值要和我们的日志格式中的关键字对应(%m,这里还支持%msg%message):

<property name="FILE_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50}:  %m%n"/>

converterClass指定我们自定义的脱敏类。

7.参考文献

  1. Logback官方文档:logback.qos.ch/manual/intr…
  2. Logback中文文档:logbackcn.gitbook.io/logback/13-…
  3. Log4j2官网:logging.apache.org/log4j/2.x/i…
    原文链接: https://juejin.cn/post/7385784332445646859

文章收集整理于网络,请勿商用,仅供个人学习使用,如有侵权,请联系作者删除,如若转载,请注明出处:http://www.cxyroad.com/17767.html

QR code