Remember a logback configuration file does not take effect troubleshooting

Problem Description

Recently, a JAVA microservice was built in the company, using the springboot framework and logback as the implementation of the log module. In the process of building, I remembered that I saw in the document that springboot supports logback-spring.xml as a customized logback configuration file. In this file, you can use spring's customized tags. For example, you can configure the log file according to the currently effective profile, which eliminates the need to configure multiple log files and specify the specific currently effective configuration in the profile. After reading the tutorial, I created a new logback-spring.xml configuration file in the resources directory with the following content:

<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>

This configuration file focuses on the springProfile label. This is a spring customized label. It is determined which section of configuration to use according to the currently effective profile. Here, when the effective profile=local or boe, the above section of configuration will be used, and vice versa. Use the following configuration. In essence, it is expected that the log level will be adjusted to DEBUG in the test environment, and in the production environment, the level will be adjusted to INFO and the ERROR log will be output to the ERROR file for easy investigation. But during the test, it was found that this configuration did not take effect, and the ERROR file was also printed in the test environment.

Investigation process

After asking Google to no avail, I checked it by interrupting the point when the application started. Springboot uses the org.springframework.boot.logging.logback.LogbackLoggingSystem class to parse the logback configuration file when the application starts. This class is a subclass of the LoggingSystem class, and there are other subclasses under the LoggingSystem class including JavaLoggingSystem, Log4j2LoggingSystem and other implementations to support different log modules.

When the application starts, spring will call the org.springframework.boot.logging.AbstractLoggingSystem#initialize method to initialize the logging system. If the configuration location is specified in the profile (via logging.file), the configuration will be searched and loaded according to the specified directory, otherwise, the project will be scanned and the configuration file will be searched according to the default configuration path of different logging systems.

    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);
    }

After entering initializeWithConventions, it will scan the default configuration path defined by different log systems and find the configuration file (getSelfInitializationConfig). In the getSelfInitializationConfig method, getStandardConfigLocations is called to obtain the default configuration path

    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 is an abstract method, and different logging systems have implemented their own. The file name provided by logback is as follows, you can see that there is no logback-spring file.

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

The findConfig method searches for these file names one by one under the classpath, and returns the first configuration file found.
When the default configuration file is not found under the classpath, look for the spring customized configuration file. The spring configuration file essentially adds the -spring suffix to the default configuration file name and retrieves it in the 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;
    }

When none of the above methods find the configuration, the default configuration provided by the logging system will be loaded. The configuration of logback is as follows:

    @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);
    }

So why doesn't springprofile take effect here. The break point found that the corresponding logback.xml file was found when getSelfInitializationConfig looked for the default configuration file of the log system, so that the spring customized configuration file would not be searched (that is, the default configuration file has a higher priority than the spring configuration file). And this logback file is dependent on the logback configuration introduced by other packages, which hinders the loading of the spring-boot file. ). Which dependency package is imported from, can be seen from the startup log of springboot:

There are two solutions to this problem:

1. Declare your logback-spring file as logback or logback.test.xml, it will overwrite the logback configuration introduced by other packages, but it will cause some spring tags to fail
2. Use logging.config to specify the configuration file path. This configuration can be declared in the application.properties file, or it can be declared at startup with -Dlogging.config in the startup command parameters

Summarize

Breakpoint is a good tool, use it a lot, practice makes perfect.