Spring Boot + Apollo 动态修改日志级别

起因

你是否碰到过如下场景：

1. 在测试环境未发现的BUG，上了生产环境之后偶现，但同样由于缺少调试信息，无法定位问题
2. 调用内部服务、第三方服务，在某些case下系统未按预期运行，排查代码后怀疑是被依赖方返回了错误的数据导致，但苦于打印Response的日志为DEBUG，没有证据

在以前的解决方案是，将日志级别改成DEBUG并上个线，排查完问题之后，再将日志级别改回INFO，再上一次线，整个生命周期很长；又或者为了省事，直接将调试日志级别定为INFO，避免上线。这两种方式，无论哪种都不够优雅，如果有一种方式，能够动态修改日志级别，在需要排查问题的时候改成DEBUG，不需要的时候就恢复INFO，岂不妙哉？

因此，我们期望实现的目标是：

1. 能够动态修改日志级别并及时生效(主要目标)
2. 在使用上，与Spring Boot提供的设置日志级别方式兼容(不另造轮子，降低学习成本)
3. 问题排查完之后，能够简单还原日志级别(移除之前的修改)

解决方案

针对需要实现的目标，逐条分析：

1. 借助一些工具(如Arthas)，直接修改运行时内存中的值，但是在集群环境下需要逐台修改，实施成本较高；借助配置中心(如Apollo)，修改之后由配置中心把数据推给应用服务器，时延取决于配置中心推送的能力
2. Spring Boot提供的设置日志级别的方式是，在application.properties/application.xml里配置logging.level.{loggerName} = DEBUG，希望仍然沿用这种方式
3. 为了排查问题，将某个类的日志级别设置为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);
        }
    }
}

能够实现的效果如下：

1. 在Apollo配置logging.level.com.example.web = DEBUG，能够将loggerName为com.example.web的日志级别改成DEBUG, 一般情况下，loggerName也等同于包名，也即是该包下的类日志级别都会被改成DEBUG(使用方式同等于在application.properties里的配置)
2. 在Apollo里删掉logging.level.com.example.web的配置项，系统会将com.example.web的日志级别设置为等于同com.example的日志级别，默认情况下com.example等同于ROOT的日志级别，也就是INFO，就达到了恢复的目的

原理分析

1. 在Spring Boot应用启动，运行到Spring容器的生命周期节点(扩展点)时，Spring会发出一些通知事件，例如ApplicationStartingEvent、ApplicationEnvironmentPreparedEvent、ApplicationPreparedEvent等等，让我们可以有机会监听这些事件，并且搞事情。Spring 内部也定义了一系列监听器，用于监听生命周期事件，来进行扩展(思想：微内核 + 插件)。
   如下图所示，Spring Boot内部定义了org.springframework.boot.context.logging.LoggingApplicationListener，并且监听了ApplicationStartingEvent事件，在事件中，构造了日志系统loggingSystem，并且执行初始化之前的回调，为初始化做准备

我们接着看org.springframework.boot.logging.LoggingSystem#get(java.lang.ClassLoader)

通过代码，我们知道有两种方式指定底层日志组件

• 1. 通过环境变量指定。例如下述方式指定了Logback做为底层日志组件

-Dorg.springframework.boot.logging.LoggingSystem=org.springframework.boot.logging.logback.LogbackLoggingSystem

• 2. 按Spring Boot预定义的日志系统顺序查找，排在前面的日志组件优先级高

可以看到，LoggingSystem支持的日志组件，按顺序有如下三种

• Logback
• Log4j2
• jul(java.util.logging)

一般情况下我们不会手动指定环境变量，而是采用一种约定优于配置的思想，交由Spring Boot判断：只要存在Logback相关类，就认为Logback应该生效作为底层的日志组件，其它的依此类推。

源码从侧面也透漏着一个信息：Spring Boot偏爱Logback

我们这里就以Logback为例，因此，此时应用激活的是org.springframework.boot.logging.logback.LogbackLoggingSystem

2. 系统继续运行，Spring会发出ApplicationEnvironmentPreparedEvent事件，并且仍由LoggingApplicationListener进行监听，在监听时进行了日志组件的初始化，如此，一个日志系统(LoggingSystem)便构造完毕

3. 在Apollo添加logging.level.{loggerName} = DEBUG的配置项，会触发应用去Apollo拉取最新的配置信息，并且将变更内容进行回调。在回调事件中，通过获取配置的日志级别，调用LoggingSystem#setLogLevel方法调整对应logger的日志级别；删除该配置项，同样会触发应用去Apollo拉取最新的配置信息，changedKeys包含删掉的配置项，此时调用Config#getProperty必然获取不到配置项的信息(因为已经删除)，因此getProperty第二个参数就是用于指定当获取的配置项值为null时的默认值。此处，我们获取了父Logger的Level作为默认值，便达到了恢复的目的。此处需要注意的一点是，如果照搬源码，使用的日志组件一定得Logback，缘由是在获取父Logger的EffectiveLevel实现方式上取了巧，如果使用的是Log4j2，会出现空指针异常---->究其原因，日志组件底层实现机制不同，行为也就不一样

总结

1. Spring Boot 在构建Spring容器的生命过程中，初始化了日志系统LoggingSystem，并和某种日志组件如Logback进行了绑定。如此，通过LoggingSystem暴露出来的setLogLevel接口，屏蔽了不同日志组件之间的差异，忽略底层日志组件存在的同时，又能在需要时刻调用接口修改日志级别(抽象的魅力)
2. 借助配置中心(如Apollo)的推送能力，应用能够准实时获取所配置的Logger日志级别，并调用LoggingSystem#setLogLevel进行日志级别的设置

题外话

1. 本文虽借助Spring Boot的日志系统机制，但本质上也是委托给底层的日志组件来实现的，也就是说，即便非Spring Boot应用，同样能够修改日志级别。我们需要具备发散思维的能力，知其然，并知其所以然。另一方面，即便拥有这样的能力，在Spring Boot环境下，仍然不建议直接访问日志组件设置日志级别的API，应该拥抱Spring Boot的生态，借助其对日志的抽象能力，面向接口编程，而不是面向实现编程
2. 本文虽借助Apollo来实现动态修改的能力，但实际上，能实现此能力的组件依然很多，例如ZK、Nacos、Spring Cloud Config + Spring Cloud Bus等等，在业务开发中，依赖这类基础组件是很正常的事情，这取决于公司的技术选型，相应改造一下方案即可
3. 本文虽以Logback为日志组件贯彻全文，但对于Log4j2以及jul仍然适用，对于一个日志组件而言，设置日志级别是最基本的功能之一。因此，可以根据公司的技术规范来确定日志组件，如无统一标准，建议跟着Spring Boot走，毕竟Log4j2出道6年，Spring Boot也从1.x到2.x，但仍然偏爱Logback，心里就没点数么(虽说log4j2快，但fastjson也很快，敢用否)