Logback结合SLF4J无法打印MDC中设置的值问题排查

我使用Logback 1.4.7和SLF4J 2.0.7，Logback配置如下：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
  <include resource="org/springframework/boot/logging/logback/base.xml"/>
  <property name="CONSOLE_LOG_PATTERN"
    value="${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSSXXX}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(%X{debug_tag}) %clr(${PID:- }){magenta} %clr(---){faint} %clr(${LOGGED_APPLICATION_NAME:-}[%15.15t]){faint} %clr(${LOG_CORRELATION_PATTERN:-}){faint}%clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
  <property name="FILE_LOG_PATTERN"
    value="${FILE_LOG_PATTERN:-%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSSXXX}} ${LOG_LEVEL_PATTERN:-%5p} %clr(%X{debug_tag}) ${PID:- } --- ${LOGGED_APPLICATION_NAME:-}[%t] ${LOG_CORRELATION_PATTERN:-}%-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
  <root level="WARN"/>
  <!--  SnapshotVerifier prints detailed snapshot on failure. Suppress that!-->
  <logger name="au.com.origin.snapshots.SnapshotVerifier" level="ERROR"/>
  <logger name="com.spotnana" level="INFO"/>

  <!--  Suppress the noise from Kafka in tests where broker is not available. !-->
  <logger name="org.apache.kafka.clients.NetworkClient" level="ERROR"/>
</configuration>

配置中引用的base.xml和default.xml来自Spring Boot官方内置的logback配置资源。

我通过以下代码在MDC中设置值：

public class GrpcContext {
...
    public GrpcContext() {
        MDC.put("debug_tag", "abc_def");
        log.info("Tuk");    
    }
... 
}

但输出的日志中并未显示MDC的值，日志内容如下：

2023-06-28T17:15:21.799+05:30  INFO   --- [Pool-1-worker-1] c.s.servicetests.grpc.stubs.GrpcContext  : Tuk

请问我哪里操作出错了？

问题出在配置加载顺序上：

• 你先执行了<include resource="org/springframework/boot/logging/logback/base.xml"/>，而base.xml内部已经初始化了ConsoleAppender，并使用了当时的CONSOLE_LOG_PATTERN值（即Spring Boot默认格式，不包含你的%X{debug_tag}）。
• 之后再定义CONSOLE_LOG_PATTERN属性时，已创建好的ConsoleAppender不会重新读取新属性值，导致MDC字段无法被日志格式识别。

修复方法有两种：

方法1：调整配置顺序，先定义属性再引入base.xml #

把property标签移到include前面，这样base.xml加载时会直接使用你自定义的日志格式：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
  <property name="CONSOLE_LOG_PATTERN"
    value="${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSSXXX}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(%X{debug_tag}) %clr(${PID:- }){magenta} %clr(---){faint} %clr(${LOGGED_APPLICATION_NAME:-}[%15.15t]){faint} %clr(${LOG_CORRELATION_PATTERN:-}){faint}%clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
  <property name="FILE_LOG_PATTERN"
    value="${FILE_LOG_PATTERN:-%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSSXXX}} ${LOG_LEVEL_PATTERN:-%5p} %clr(%X{debug_tag}) ${PID:- } --- ${LOGGED_APPLICATION_NAME:-}[%t] ${LOG_CORRELATION_PATTERN:-}%-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
  <include resource="org/springframework/boot/logging/logback/base.xml"/>
  
  <root level="WARN"/>
  <logger name="au.com.origin.snapshots.SnapshotVerifier" level="ERROR"/>
  <logger name="com.spotnana" level="INFO"/>
  <logger name="org.apache.kafka.clients.NetworkClient" level="ERROR"/>
</configuration>

方法2：重新定义ConsoleAppender，显式指定自定义格式 #

如果不想调整顺序，可以重新定义ConsoleAppender，直接绑定你的自定义模式：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
  <include resource="org/springframework/boot/logging/logback/base.xml"/>
  <property name="CONSOLE_LOG_PATTERN"
    value="${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSSXXX}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(%X{debug_tag}) %clr(${PID:- }){magenta} %clr(---){faint} %clr(${LOGGED_APPLICATION_NAME:-}[%15.15t]){faint} %clr(${LOG_CORRELATION_PATTERN:-}){faint}%clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
  <property name="FILE_LOG_PATTERN"
    value="${FILE_LOG_PATTERN:-%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSSXXX}} ${LOG_LEVEL_PATTERN:-%5p} %clr(%X{debug_tag}) ${PID:- } --- ${LOGGED_APPLICATION_NAME:-}[%t] ${LOG_CORRELATION_PATTERN:-}%-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
  
  <!-- 重新配置ConsoleAppender，覆盖base.xml中的定义 -->
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>${CONSOLE_LOG_PATTERN}</pattern>
    </encoder>
  </appender>
  
  <root level="WARN"/>
  <logger name="au.com.origin.snapshots.SnapshotVerifier" level="ERROR"/>
  <logger name="com.spotnana" level="INFO"/>
  <logger name="org.apache.kafka.clients.NetworkClient" level="ERROR"/>
</configuration>

额外确认点：

• 从日志线程[Pool-1-worker-1]来看，设置MDC的线程和输出日志的线程是同一个，这部分无问题。
• 代码中先执行MDC.put再输出日志，顺序正确，MDC值在日志输出前已被设置。

内容的提问来源于stack exchange，提问作者tuk