记一次logback配置文件未生效问题排查

问题描述

最近在公司新建了一个JAVA微服务，采用的是springboot框架，logback作为日志模块的实现。在搭建的的过程中想起之前在文档中看到springboot支持用logback-spring.xml作为定制的logback配置文件。在这个文件中可以使用spring的定制化标签，比如可以根据当前生效的profile对日志文件进行配置，从而省去配置多份日志文件并在profile中指定具体当前生效的配置。在阅读了一下教程之后，我在resources目录下新建了logback-spring.xml的配置文件，内容如下：

<configuration scan="true" scanPeriod="100000" debug="false">

    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>

    <property name="LOG_BASE" value="logs/"/>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <!--  所有应用日志   -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_BASE}/application.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <!-- rollover daily -->
            <fileNamePattern>${LOG_BASE}/application.log-%d{yyyy-MM-dd}.%i</fileNamePattern>
            <!-- each file should be at most 500MB, keep 60 days worth of history, but at most 20GB -->
            <maxFileSize>500MB</maxFileSize>
            <maxHistory>60</maxHistory>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>
    <appender name="ASYNC-FILE" class="ch.qos.logback.classic.AsyncAppender">
        <!-- 不丢失日志 -->
        <discardingThreshold >0</discardingThreshold>
        <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
        <queueSize>512</queueSize>
        <!-- 添加附加的appender,最多只能添加一个 -->
        <appender-ref ref ="FILE"/>
    </appender>

    <!--  ERROR日志  -->
    <appender name="ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_BASE}/application-error.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <!-- rollover daily -->
            <fileNamePattern>${LOG_BASE}/application-error.log-%d{yyyy-MM-dd}.%i</fileNamePattern>
            <!-- each file should be at most 500MB, keep 60 days worth of history, but at most 20GB -->
            <maxFileSize>500MB</maxFileSize>
            <maxHistory>60</maxHistory>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
        </filter>
    </appender>
    <appender name="ASYNC-ERROR" class="ch.qos.logback.classic.AsyncAppender">
        <!-- 不丢失日志 -->
        <discardingThreshold >0</discardingThreshold>
        <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
        <queueSize>512</queueSize>
        <!-- 添加附加的appender,最多只能添加一个 -->
        <appender-ref ref ="ERROR"/>
    </appender>


    <springProfile name="local | boe">
        <root level="DEBUG">
            <appender-ref ref="CONSOLE"/>
            <appender-ref ref="ASYNC-FILE"/>
        </root>
    </springProfile>
    <springProfile name="!(local | boe)">
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
            <appender-ref ref="ASYNC-FILE"/>
            <appender-ref ref="ASYNC-ERROR"/>

        </root>
    </springProfile>
</configuration>

这个配置文件中重点关注springProfile这个标签，这个是spring定制的标签，根据当前生效的profile来决定使用哪一段配置，在这里当生效的profile=local或者boe时，会采用上面这段配置，反之则采用下面这段配置。本质上是期望在测试环境时将日志的级别调整为DEBUG，而到生产环境是则将级别调整为INFO并专门将ERROR日志输出到ERROR文件中便于排查。但是在测试时发现这个配置并没有生效，在测试环境也打印了ERROR文件、

排查过程

在询问谷歌无果后，通过在应用程序启动的时候打断点进行排查。springboot通过org.springframework.boot.logging.logback.LogbackLoggingSystem这个类在应用启动的时候解析logback配置文件。这个类是LoggingSystem这个类的子类，而LoggingSystem类下还有其它的子类包括JavaLoggingSystem，Log4j2LoggingSystem等实现，从而实现支持不同日志模块。

在应用启动的时候，spring会调用org.springframework.boot.logging.AbstractLoggingSystem#initialize方法对日志系统进行初始化。如果在profile中指定了配置的位置（通过logging.file），则会按照指定的目录寻找并加载配置，否则会扫描项目并根据不同日志系统的默认配置路径寻找配置文件。

    public void initialize(LoggingInitializationContext initializationContext,
            String configLocation, LogFile logFile) {
        // 指定了配置文件目录
        if (StringUtils.hasLength(configLocation)) {
            initializeWithSpecificConfig(initializationContext, configLocation, logFile);
            return;
        }
        // 从默认路径中寻找配置文件
        initializeWithConventions(initializationContext, logFile);
    }

    private void initializeWithSpecificConfig(
            LoggingInitializationContext initializationContext, String configLocation,
            LogFile logFile) {
        // 根据目录加载日志文件
        configLocation = SystemPropertyUtils.resolvePlaceholders(configLocation);
        loadConfiguration(initializationContext, configLocation, logFile);
    }

在进入initializeWithConventions后，会先扫描不同日志系统定义的默认配置路径并找到配置文件（getSelfInitializationConfig）。在getSelfInitializationConfig这个方法中调用了getStandardConfigLocations获得默认配置路径

    private void initializeWithConventions(
            LoggingInitializationContext initializationContext, LogFile logFile) {
        // 获取当前日志系统的默认配置文件
        String config = getSelfInitializationConfig();
        if (config != null && logFile == null) {
            // self initialization has occurred, reinitialize in case of property changes
            reinitialize(initializationContext);
            return;
        }
        // 未在classpath下找到默认配置文件，则寻找spring定制的配置文件
        if (config == null) {
            config = getSpringInitializationConfig();
        }
        if (config != null) {
            loadConfiguration(initializationContext, config, logFile);
            return;
        }
        loadDefaults(initializationContext, logFile);
    }

    protected String getSelfInitializationConfig() {
        return findConfig(getStandardConfigLocations());
    }

getStandardConfigLocations是一个抽象方法，不同的日志系统都进行了自己的实现。logback提供的文件名称如下，可以看到并没有logback-spring文件。

    @Override
    protected String[] getStandardConfigLocations() {
        return new String[] { "logback-test.groovy", "logback-test.xml", "logback.groovy",
                "logback.xml" };
    }

而findConfig方法则在classpath下按照这些文件名称逐个寻找，并返回找到的第一个配置文件。
当没有在classpath下找到默认配置文件，则寻找spring定制的配置文件，spring配置文件本质上是在默认配置文件名称后加上-spring后缀并在classpath中进行检索、

    protected String[] getSpringConfigLocations() {
        String[] locations = getStandardConfigLocations();
        for (int i = 0; i < locations.length; i++) {
            String extension = StringUtils.getFilenameExtension(locations[i]);
            locations[i] = locations[i].substring(0,
                    locations[i].length() - extension.length() - 1) + "-spring."
                    + extension;
        }
        return locations;
    }

而当上述方法都没有找到配置的时候，就会加载日志系统提供的默认配置。logback的配置如下：

    @Override
    protected void loadDefaults(LoggingInitializationContext initializationContext,
            LogFile logFile) {
        LoggerContext context = getLoggerContext();
        stopAndReset(context);
        LogbackConfigurator configurator = new LogbackConfigurator(context);
        context.putProperty("LOG_LEVEL_PATTERN",
                initializationContext.getEnvironment().resolvePlaceholders(
                        "${logging.pattern.level:${LOG_LEVEL_PATTERN:%5p}}"));
        new DefaultLogbackConfiguration(initializationContext, logFile)
                .apply(configurator);
        context.setPackagingDataEnabled(true);
    }

那么为什么这里springprofile没有生效呢。打断点发现在getSelfInitializationConfig查找日志系统默认配置文件时就找到了对应的logback.xml文件，从而不会再查找spring定制化配置文件（即默认配置文件的优先级高于spring配置文件）。而这个logback文件是依赖的别的包引入的logback配置，从而阻碍了spring-boot文件的加载(这里也顺便说一下，提供给别人的二方包中正确的做法是不要引入日志的配置文件~)。具体从哪个依赖包中引入的可以从springboot的启动日志中看到：

这个问题的解决方法有两个：

1. 将自己的logback-spring文件声明成logback或logback.test.xml，它会覆盖别的包引入的logback配置，但是会导致部分spring标签失效
2. 使用logging.config指定配置文件路径，这个配置可以是在application.properties文件中声明，也可以是在启动命令参数中用-Dlogging.config在启动时声明

总结

断点是一个好工具，多多使用，熟能生巧。