一个SpringBoot 日志配置失效的坑

大家好，我是摸鱼总工，懒惰是程序员的美德，摸鱼才能成为总工。

今天给大家分享最近的一个经历，SpringBoot 日志配置不生效的问题。

事情起因

最近因为组长的要求，要在 SpringBoot 启动前后加一些监控逻辑。我想当然地在里面打一些日志，结果到线上发现打出了很多 Debug 日志，而我在 Spring 配置里面明明白白写的是 INFO。

除去业务逻辑，代码大致如下面所示，在 SpringApplication 启动之前和之后，都加一些日志，分别有 INFO 相关的和 Debug 相关的：

然后运行起来，打印的日志如下：

可以清晰地看到，SpringApplication 启动前后的日志格式完全不一样，且启动之后，没有打印 Debug 日志，这说明 SpringApplication 启动前后走的是完全不同的日志逻辑，且 logging.level.root=INFO 的配置在 SpringApplication 启动之后才生效。

然而，这是为什么呢？

原理探索

那么，SpringApplication 具体是如何操作这个修改的呢？

下面，我通过一边 Debug 一边画序列图的方式，快速呈现这个逻辑。

Debug 一步一图

首先，配置我们关心的软件包前缀，分别是 org.slf4j 和 ch.qos。

其次，Debug with XCodeMap （这个启动过程与普通的 Debug 类似，只是它会实时绘制序列图）

最后，一步步查看序列图

XCodeMap 支持每 “Step Over” 下一行，就更新序列图，以方便我们查看序列图的变化！

我们可以清晰地看到，在执行 LoggerFactory.getLogger 时，会触发 autoConfig 和 configure 函数，这是在进行日志配置的初始化。而执行到 SpringApplication.run 这一行时，会触发 stop 和 reset 函数。通过名字也不难猜测，就是这个 stop 和 reset 函数，把日志配置给刷新了。

这里，我们大致知道了整个日志系统配置变化的过程，但是 Spring 具体是如何执行这一操作的呢？

这个时候，断点回溯法就可以发挥作用了！

断点回溯法

点击 stop 函数，XCodeMap 会跳转到源码，在源码处设置个断点，重新执行一遍到断点处，然后回溯整个堆栈。

通过简单回溯可以看到 onApplicationEvent 这个函数，以及其对应的类 LoggingApplicationListener，也就是说，SpringBoot 的日志配置是通过这个类进行设置的。其大致流程如下：

• 对 ApplicationEnvironmentPreparedEvent 进行处理，并生成 LoggingSystem
• LoggingSystem 的实现为 LogbackLoggingSystem，也就是说，针对不同的日志框架，会有不同的实现，然后系统会自动寻找一个实现，当然也可以通过配置指定用哪个实现（一般没必要）
• 调用 LoggingSystem 的 initialize 进行处理
• 先 stopAndReset LoggerContext （LoggerContext 实现 slf4j 的 ILoggerFactory，也就是说，它是 logback 框架的最终实现类）
• 初始化 Spring 写的 LogbackConfigurator，以刷新日志体系的配置

大致流程就是这样了，更详细的内容，各位看官可以去查看 XCodeMap 的序列图哦。

后记

那后面，我们的问题是如何解决的呢？

我们问了一下 AI，能否把 LoggingSystem 提前拎出来配置。结果 AI 告诫我们，SpringBoot 的设计初衷是尽量简化和自动化日志系统的初始化，因此手动控制其启动时机并不常见。

我们的问题，准确来讲，是因为对 SpringBoot 的设计理解不足导致的。正确的做法，应该是写一个 ApplicationListener，监听 ApplicationEnvironmentPreparedEvent，然后写上自己的逻辑。这样，就与 SpringBoot 的体系融为一体了。