旧项目维护-logback.xml

背景

在维护一个旧项目，忽然间看到服务输出的日志文件中的debug.log，里面的内容和info.log完全一致。

复现 & 排查

xml文件内容如下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="false" scanPeriod="30 seconds" debug="false">
    <contextName>app-xxx</contextName>
    <!--服务端日志目录-->
    <property name="log.path" value="/var/log/app-xxx/log"/>
    <property name="log.charset" value="utf-8"/>
    <property name="log.pattern"
              value="%contextName %red(%d{yyyy-MM-dd HH:mm:ss}) [%X{traceId}/%X{spanId}] %green([%thread]) %highlight(%-5level) %boldMagenta(%logger{36}) - %msg%n"/>

    <!-- Log file info output -->
    <appender name="info" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}/info.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${log.path}/%d{yyyy-MM, aux}/info.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>90</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%date [%thread] %-5level [%X{traceId}/%X{spanId}] [%logger{50}] %file:%line - %msg%n</pattern>
            <charset>${log.charset}</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
    </appender>

    <!-- Log file debug output -->
    <appender name="debug" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}/debug.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${log.path}/%d{yyyy-MM, aux}/debug.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>90</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%date [%thread] %-5level [%X{traceId}/%X{spanId}] [%logger{50}] %file:%line - %msg%n</pattern>
            <charset>${log.charset}</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>DEBUG</level>
        </filter>
    </appender>

    <!-- Log file error output -->
    <appender name="error" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}/error.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${log.path}/%d{yyyy-MM, aux}/error.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>90</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%date [%thread] %-5level [%X{traceId}/%X{spanId}] [%logger{50}] %file:%line - %msg%n</pattern>
            <charset>${log.charset}</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
        </filter>
    </appender>

    <!-- Level: FATAL 0  ERROR 3  WARN 4  INFO 6  DEBUG 7 -->
    <root level="INFO">
        <appender-ref ref="info"/>
    </root>
    <root level="ERROR">
        <appender-ref ref="error"/>
    </root>
    <root level="DEBUG">
        <appender-ref ref="debug"/>
    </root>

    <!--输出到控制台-->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${log.pattern}</pattern>
            <charset>${log.charset}</charset>
        </encoder>
    </appender>

    <!--普通日志输出到控制台-->
    <root level="info">
        <appender-ref ref="console"/>
    </root>

</configuration>

问题出现在多个root节点。

    <root level="INFO">
        <appender-ref ref="info"/>
    </root>
    <root level="ERROR">
        <appender-ref ref="error"/>
    </root>
    <root level="DEBUG">
        <appender-ref ref="debug"/>
    </root>

    <root level="info">
        <appender-ref ref="console"/>
    </root>

此时新建一个类（和启动类同包），如下

package com.app.xxx;

import lombok.extern.slf4j.Slf4j;
import org.springframework.boot.CommandLineRunner;
import org.springframework.stereotype.Component;

@Component
@Slf4j
public class LoggerTest implements CommandLineRunner {
    @Override
    public void run(String... args) throws Exception {
        log.debug("debug11111111111111111111");
        log.info("info111111111111111111111");
        log.warn("warn1111111111111111111111");
        log.error("error1111111111111111111111111111111");
    }
}

启动时发现debug.log和info.log里都是只有info111111111111111111111/warn1111111111111111111111/error1111111111111111111111111111111，也都没有debug11111111111111111111。

问了ai，说明logback会只使用最后一个root节点，也有说是合并多个root的子节点，按我运行的结果来看，上面多个root节点相当于如下

    <root level="INFO">
        <appender-ref ref="info"/>
        <appender-ref ref="error"/>
        <appender-ref ref="debug"/>
        <appender-ref ref="console"/>
    </root>

即以最后一个root节点为准（取其level），把其它root节点的子节点合并过来。

测试时把多个root节点中的 level=DEBUG移到最后一位。即

    <root level="ERROR">
        <appender-ref ref="error"/>
    </root>
    <root level="INFO">
        <appender-ref ref="info"/>
    </root>
    <root level="info">
        <appender-ref ref="console"/>
    </root>
    <root level="DEBUG">
        <appender-ref ref="debug"/>
    </root>

会发现debug.log中打印了很多日志，而info.log很少，且debug11111111111111111111出现在debug.log中，不在info.log中。

解决问题

该服务不需要打印debug日志。

修正后的xml如下。只使用info.log(打印info/warn/error级别的日志)，error.log（打印error级别日志）

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="false" scanPeriod="30 seconds" debug="false">
    <contextName>app-xxx</contextName>
    <!--服务端日志目录-->
    <property name="log.path" value="/var/log/app-xxx/log"/>

    <property name="log.charset" value="utf-8"/>
    <property name="console.log.pattern"
        value="%contextName %red(%d{yyyy-MM-dd HH:mm:ss}) [%X{traceId}/%X{spanId}] %green([%thread]) %highlight(%-5level) %boldMagenta(%logger{36}) - %msg%n"
    />

    <appender name="infoAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}/info.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${log.path}/%d{yyyy-MM, aux}/info.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>90</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%date [%thread] %-5level [%X{traceId}/%X{spanId}] [%logger{50}] - %msg%n</pattern>
            <charset>${log.charset}</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
    </appender>

    <appender name="errorAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}/error.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${log.path}/%d{yyyy-MM, aux}/error.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>90</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%date [%thread] %-5level [%X{traceId}/%X{spanId}] [%logger{50}] - %msg%n</pattern>
            <charset>${log.charset}</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
        </filter>
    </appender>

    <appender name="consoleAppender" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${console.log.pattern}</pattern>
            <charset>${log.charset}</charset>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="infoAppender"/>
        <appender-ref ref="errorAppender"/>
        <appender-ref ref="consoleAppender"/>
    </root>
</configuration>