起因
你是否碰到过如下场景：
- 在测试环境未发现的BUG，上了生产环境之后偶现，但同样由于缺少调试信息，无法定位问题
- 调用内部服务、第三方服务，在某些case下系统未按预期运行，排查代码后怀疑是被依赖方返回了错误的数据导致，但苦于打印Response的日志为
DEBUG，没有证据
在以前的解决方案是，将日志级别改成DEBUG并上个线，排查完问题之后，再将日志级别改回INFO，再上一次线，整个生命周期很长；又或者为了省事，直接将调试日志级别定为INFO，避免上线。这两种方式，无论哪种都不够优雅，如果有一种方式，能够动态修改日志级别，在需要排查问题的时候改成DEBUG，不需要的时候就恢复INFO，岂不妙哉？
因此，我们期望实现的目标是：
- 能够动态修改日志级别并及时生效(主要目标)
- 在使用上，与
Spring Boot提供的设置日志级别方式兼容(不另造轮子，降低学习成本) - 问题排查完之后，能够简单还原日志级别(移除之前的修改)
解决方案
针对需要实现的目标，逐条分析：
- 借助一些工具(如
Arthas)，直接修改运行时内存中的值，但是在集群环境下需要逐台修改，实施成本较高；借助配置中心(如Apollo)，修改之后由配置中心把数据推给应用服务器，时延取决于配置中心推送的能力 -
Spring Boot提供的设置日志级别的方式是，在application.properties/application.xml里配置logging.level.{loggerName} = DEBUG，希望仍然沿用这种方式 - 为了排查问题，将某个类的日志级别设置为
DEBUG，完事之后，通过将本Logger日志级别设置为父Logger的日志级别进行还原
Spring Boot提供了抽象日志系统(org.springframework.boot.logging.LoggingSystem)，通过借助LoggingSystem可以实现修改日志级别的目的，而Apollo则为动态修改提供了可能性
因此，最终采用的方案为Spring Boot(LoggingSystem) + Apollo，选用的日志组件为Logback为例，源码如下：
public class LoggingLevelRefresher {
private final static Logger log = LoggerFactory.getLogger(LoggingLevelRefresher.class);
private static final String PREFIX = "logging.level.";
private static final String ROOT = LoggingSystem.ROOT_LOGGER_NAME;
private static final String SPLIT = ".";
@Resource
private LoggingSystem loggingSystem;
@ApolloConfig
private Config config;
@PostConstruct
private void init() {
refreshLoggingLevels(config.getPropertyNames());
}
@ApolloConfigChangeListener(interestedKeyPrefixes = PREFIX)
private void onChange(ConfigChangeEvent changeEvent) {
refreshLoggingLevels(changeEvent.changedKeys());
}
private void refreshLoggingLevels(Set<String> changedKeys) {
for (String key : changedKeys) {
// key may be : logging.level.com.example.web
if (StringUtils.startsWithIgnoreCase(key, PREFIX)) {
String loggerName = PREFIX.equalsIgnoreCase(key) ? ROOT : key.substring(PREFIX.length());
String strLevel = config.getProperty(key, parentStrLevel(loggerName));
LogLevel level = LogLevel.valueOf(strLevel.toUpperCase());
loggingSystem.setLogLevel(loggerName, level);
log(loggerName, strLevel);
}
}
}
private String parentStrLevel(String loggerName) {
String parentLoggerName = loggerName.contains(SPLIT) ? loggerName.substring(0, loggerName.lastIndexOf(SPLIT)) : ROOT;
return loggingSystem.getLoggerConfiguration(parentLoggerName).getEffectiveLevel().name();
}
/**
* 获取当前类的Logger对象有效日志级别对应的方法，进行日志输出。举例：
* 如果当前类的EffectiveLevel为WARN，则获取的Method为 `org.slf4j.Logger#warn(java.lang.String, java.lang.Object, java.lang.Object)`
* 目的是为了输出`changed {} log level to:{}`这一行日志
*/
private void log(String loggerName, String strLevel) {
try {
LoggerConfiguration loggerConfiguration = loggingSystem.getLoggerConfiguration(log.getName());
Method method = log.getClass().getMethod(loggerConfiguration.getEffectiveLevel().name().toLowerCase(), String.class, Object.class, Object.class);
method.invoke(log, "changed {} log level to:{}", loggerName, strLevel);
} catch (Exception e) {
log.error("changed {} log level to:{} error", loggerName, strLevel, e);
}
}
}
能够实现的效果如下：
- 在
Apollo配置logging.level.com.example.web = DEBUG，能够将loggerName为com.example.web的日志级别改成DEBUG, 一般情况下，loggerName也等同于包名，也即是该包下的类日志级别都会被改成DEBUG(使用方式同等于在application.properties里的配置) - 在
Apollo里删掉logging.level.com.example.web的配置项，系统会将com.example.web的日志级别设置为等于同com.example的日志级别，默认情况下com.example等同于ROOT的日志级别，也就是INFO，就达到了恢复的目的
原理分析
源码基于
Spring Boot 2.1.10.RELEASE
- 在
Spring Boot应用启动，运行到Spring容器的生命周期节点(扩展点)时，Spring会发出一些通知事件，例如ApplicationStartingEvent、ApplicationEnvironmentPreparedEvent、ApplicationPreparedEvent等等，让我们可以有机会监听这些事件，并且搞事情。Spring 内部也定义了一系列监听器，用于监听生命周期事件，来进行扩展(思想：微内核 + 插件)。
如下图所示，Spring Boot内部定义了org.springframework.boot.context.logging.LoggingApplicationListener，并且监听了ApplicationStartingEvent事件，在事件中，构造了日志系统loggingSystem，并且执行初始化之前的回调，为初始化做准备
image.png
我们接着看org.springframework.boot.logging.LoggingSystem#get(java.lang.ClassLoader)
image.png
通过代码，我们知道有两种方式指定底层日志组件
- 通过环境变量指定。例如下述方式指定了
Logback做为底层日志组件
- 通过环境变量指定。例如下述方式指定了
-Dorg.springframework.boot.logging.LoggingSystem=org.springframework.boot.logging.logback.LogbackLoggingSystem
- 按
Spring Boot预定义的日志系统顺序查找，排在前面的日志组件优先级高
- 按
image.png
可以看到，LoggingSystem支持的日志组件，按顺序有如下三种
- Logback
- Log4j2
- jul(java.util.logging)
一般情况下我们不会手动指定环境变量，而是采用一种约定优于配置的思想，交由Spring Boot判断：只要存在Logback相关类，就认为Logback应该生效作为底层的日志组件，其它的依此类推。
源码从侧面也透漏着一个信息：Spring Boot偏爱Logback
我们这里就以Logback为例，因此，此时应用激活的是org.springframework.boot.logging.logback.LogbackLoggingSystem
- 系统继续运行，
Spring会发出ApplicationEnvironmentPreparedEvent事件，并且仍由LoggingApplicationListener进行监听，在监听时进行了日志组件的初始化，如此，一个日志系统(LoggingSystem)便构造完毕
image.png
image.png
- 在
Apollo添加logging.level.{loggerName} = DEBUG的配置项，会触发应用去Apollo拉取最新的配置信息，并且将变更内容进行回调。在回调事件中，通过获取配置的日志级别，调用LoggingSystem#setLogLevel方法调整对应logger的日志级别；删除该配置项，同样会触发应用去Apollo拉取最新的配置信息，changedKeys包含删掉的配置项，此时调用Config#getProperty必然获取不到配置项的信息(因为已经删除)，因此getProperty第二个参数就是用于指定当获取的配置项值为null时的默认值。此处，我们获取了父Logger的Level作为默认值，便达到了恢复的目的。此处需要注意的一点是，如果照搬源码，使用的日志组件一定得Logback，缘由是在获取父Logger的EffectiveLevel实现方式上取了巧，如果使用的是Log4j2，会出现空指针异常---->究其原因，日志组件底层实现机制不同，行为也就不一样
image.png
总结
-
Spring Boot在构建Spring容器的生命过程中，初始化了日志系统LoggingSystem，并和某种日志组件如Logback进行了绑定。如此，通过LoggingSystem暴露出来的setLogLevel接口，屏蔽了不同日志组件之间的差异，忽略底层日志组件存在的同时，又能在需要时刻调用接口修改日志级别(抽象的魅力) - 借助配置中心(如
Apollo)的推送能力，应用能够准实时获取所配置的Logger日志级别，并调用LoggingSystem#setLogLevel进行日志级别的设置
题外话
- 本文虽借助
Spring Boot的日志系统机制，但本质上也是委托给底层的日志组件来实现的，也就是说，即便非Spring Boot应用，同样能够修改日志级别。我们需要具备发散思维的能力，知其然，并知其所以然。另一方面，即便拥有这样的能力，在Spring Boot环境下，仍然不建议直接访问日志组件设置日志级别的API，应该拥抱Spring Boot的生态，借助其对日志的抽象能力，面向接口编程，而不是面向实现编程 - 本文虽借助
Apollo来实现动态修改的能力，但实际上，能实现此能力的组件依然很多，例如ZK、Nacos、Spring Cloud Config + Spring Cloud Bus等等，在业务开发中，依赖这类基础组件是很正常的事情，这取决于公司的技术选型，相应改造一下方案即可 - 本文虽以
Logback为日志组件贯彻全文，但对于Log4j2以及jul仍然适用，对于一个日志组件而言，设置日志级别是最基本的功能之一。因此，可以根据公司的技术规范来确定日志组件，如无统一标准，建议跟着Spring Boot走，毕竟Log4j2出道6年，Spring Boot也从1.x到2.x，但仍然偏爱Logback，心里就没点数么(虽说log4j2快，但fastjson也很快，敢用否)
