日誌與追蹤的完美融合：OpenTelemetry MDC 實踐指南

前言

在前面兩篇實戰文章中：

• OpenTelemetry 實戰：從零實現分散式鏈路追蹤
• OpenTelemetry 實戰：從零實現應用指標監控

覆蓋了可觀測中的指標追蹤和 metrics 監控，下面理應開始第三部分：日誌。

但在開始日誌之前還是要先將鏈路追蹤和日誌結合起來看看應用實際使用的實踐。

通常我們排查問題的方式是先查詢異常日誌，判斷是否是當前系統的問題。

如果不是，則在日誌中撈出 trace_id 再到鏈路查詢系統中查詢鏈路，看看具體是哪個系統的問題，然後再做具體的排查。

類似於這樣：

日誌中會列印 trace_id 和 span_id。

如果日誌系統做的比較完善的話，還可以直接點選 trace_id 跳轉到鏈路系統裡直接查詢鏈路資訊。

MDC

這裡的日誌裡關聯 trace 資訊的做法有個專有名詞：MDC:(Mapped Diagnostic Context)。

簡單來說就是用於排查問題的上下文資訊，通常是由鍵值對組成，類似於這樣的資料：

{  
  "timestamp" : "2024-08-05 17:27:31.097",  
  "level" : "INFO",  
  "thread" : "http-nio-9191-exec-1",  
  "mdc" : {  
    "trace_id" : "26242f945af80b044a60226af00211fb",  
    "trace_flags" : "01",  
    "span_id" : "3a7842b3e28ed5c8"  
  },  
  "logger" : "com.example.demo.DemoApplication",  
  "message" : "request: name: \"1232\"\n",  
  "context" : "default"  
}

在 Java 中的 Log4j 和 Logback 都有提供對應的實現。

如果我們使用了 OpenTelemetry 提供的 javaagent 再配合 logback 或者 Log4j 時就會自動具備列印 MDC 的能力：

java -javaagent:/Users/chenjie/Downloads/blog-img/demo/opentelemetry-javaagent-2.4.0-SNAPSHOT.jar xx.jar

比如我們只需要這樣配置這樣一個JSON 輸出的 logback 即可：

<appender name="PROJECT_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">  
    <file>${PATH}/demo.log</file>  
  
    <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">  
        <fileNamePattern>${PATH}/demo_%i.log</fileNamePattern>  
        <maxIndex>1</maxIndex>  
    </rollingPolicy>  
  
    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">  
        <maxFileSize>100MB</maxFileSize>  
    </triggeringPolicy>  
  
    <layout class="ch.qos.logback.contrib.json.classic.JsonLayout">  
        <jsonFormatter  
                class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter">  
            <prettyPrint>true</prettyPrint>  
        </jsonFormatter>  
        <timestampFormat>yyyy-MM-dd' 'HH:mm:ss.SSS</timestampFormat>  
    </layout>  
  
</appender>  
  
<root level="INFO">  
    <appender-ref ref="STDOUT"/>  
    <appender-ref ref="PROJECT_LOG"/>  
</root>

就會在日誌檔案中輸出 JSON 格式的日誌，並且帶上 MDC 的資訊。

自動 MDC 的原理

我也比較好奇 OpenTelemetry 是如何自動寫入 MDC 資訊的，這裡以 logback 為例。

@Override  
public ElementMatcher<TypeDescription> typeMatcher() {  
  return implementsInterface(named("ch.qos.logback.classic.spi.ILoggingEvent"));  
}  
  
@Override  
public void transform(TypeTransformer transformer) {  
  transformer.applyAdviceToMethod(  
      isMethod()  
          .and(isPublic())  
          .and(namedOneOf("getMDCPropertyMap", "getMdc"))  
          .and(takesArguments(0)),  
      LoggingEventInstrumentation.class.getName() + "$GetMdcAdvice");  
}

會在呼叫 ch.qos.logback.classic.spi.ILoggingEvent.getMDCPropertyMap()/getMdc() 這兩個函式中進行埋點。

這些邏輯都是寫在 javaagent 中的。

public Map<String, String> getMDCPropertyMap() {  
    // populate mdcPropertyMap if null  
    if (mdcPropertyMap == null) {  
        MDCAdapter mdc = MDC.getMDCAdapter();  
        if (mdc instanceof LogbackMDCAdapter)  
            mdcPropertyMap = ((LogbackMDCAdapter) mdc).getPropertyMap();  
        else  
            mdcPropertyMap = mdc.getCopyOfContextMap();  
    }    
    // mdcPropertyMap still null, use emptyMap()  
    if (mdcPropertyMap == null)  
        mdcPropertyMap = Collections.emptyMap();  
  
    return mdcPropertyMap;  
}

這個函式其實預設情況下會返回一個 logback 內建 MDC 的 map 資料（這裡的資料我們可以自定義配置）。

而這裡要做的就是將 trace 的上下文資訊寫入這個 mdcPropertyMap 中。

以下是 OpenTelemetry agent 中的原始碼：

Map<String, String> spanContextData = new HashMap<>();  
  
SpanContext spanContext = Java8BytecodeBridge.spanFromContext(context).getSpanContext();  
  
if (spanContext.isValid()) {  
  spanContextData.put(traceIdKey(), spanContext.getTraceId());  
  spanContextData.put(spanIdKey(), spanContext.getSpanId());  
  spanContextData.put(traceFlagsKey(), spanContext.getTraceFlags().asHex());  
}  
spanContextData.putAll(ConfiguredResourceAttributesHolder.getResourceAttributes());  
  
if (LogbackSingletons.addBaggage()) {  
  Baggage baggage = Java8BytecodeBridge.baggageFromContext(context);  
  
  // using a lambda here does not play nicely with instrumentation bytecode process  
  // (Java 6 related errors are observed) so relying on for loop instead  for (Map.Entry<String, BaggageEntry> entry : baggage.asMap().entrySet()) {  
    spanContextData.put(  
        // prefix all baggage values to avoid clashes with existing context  
        "baggage." + entry.getKey(), entry.getValue().getValue());  
  }}  
  
if (contextData == null) {  
  contextData = spanContextData;  
} else {  
  contextData = new UnionMap<>(contextData, spanContextData);  
}

這就是核心的寫入邏輯，從這個程式碼中也可以看出直接從上線文中獲取的 span 的 context，而我們所需要的 trace_id/span_id 都是存放在 context 中的，只需要 get 出來然後寫入進 map 中即可。

從原始碼裡還得知，只要我們開啟 -Dotel.instrumentation.logback-mdc.add-baggage=true 配置還可以將 baggage 中的資料也寫入到 MDC 中。

而得易於 OpenTelemetry 中的 trace 是可以跨執行緒傳輸的，所以即便是我們在多執行緒裡列印日誌時 MDC 資料依然可以準確無誤的傳遞。

MDC 的原理

public static final String MDC_ATTR_NAME = "mdc";

在 logback 的實現中是會呼叫剛才的 getMDCPropertyMap() 然後寫入到一個 key 為 mdc 的 map 裡，最終可以寫入到檔案或者控制檯。

這樣整個原理就可以串起來了。

自定義日誌 資料

提到可以自定義 MDC 資料其實也是有使用場景的，比如我們的業務系統經常有類似的需求，需要在日誌中列印一些常用業務資料：

• userId、userName
• 客戶端 IP等資訊時

此時我們就可以建立一個 Layout 類來繼承 ch.qos.logback.contrib.json.classic.JsonLayout:

public class CustomJsonLayout extends JsonLayout {
    public CustomJsonLayout() {
    }

    protected void addCustomDataToJsonMap(Map<String, Object> map, ILoggingEvent event) {
        map.put("user_name", context.getProperty("userName"));
        map.put("user_id", context.getProperty("userId"));
        map.put("trace_id", TraceContext.traceId());
    }
}


public class CustomJsonLayoutEncoder extends LayoutWrappingEncoder<ILoggingEvent> {  
    public CustomJsonLayoutEncoder() {  
    }  
    public void start() {  
        CustomJsonLayout jsonLayout = new CustomJsonLayout();  
        jsonLayout.setContext(this.context);  
        jsonLayout.setIncludeContextName(false);  
        jsonLayout.setAppendLineSeparator(true);  
        jsonLayout.setJsonFormatter(new JacksonJsonFormatter());  
        jsonLayout.start();  
        super.setCharset(StandardCharsets.UTF_8);  
        super.setLayout(jsonLayout);  
        super.start();  
    }}

這裡的 trace_id 是之前使用 skywalking 的時候由 skywalking 提供的函式：org.apache.skywalking.apm.toolkit.trace.TraceContext#traceId

接著只需要在 logback.xml 中配置這個 CustomJsonLayoutEncoder 就可以按照我們自定義的資料輸出日誌了：

<appender name="PROJECT_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">  
    <file>${PATH}/app.log</file>  
  
    <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">  
        <fileNamePattern>${PATH}/app_%i.log</fileNamePattern>  
        <maxIndex>1</maxIndex>  
    </rollingPolicy>  
  
    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">  
        <maxFileSize>100MB</maxFileSize>  
    </triggeringPolicy>  
  
    <encoder class="xx.CustomJsonLayoutEncoder"/>  
</appender>

<root level="INFO">  
    <appender-ref ref="STDOUT"/>  
    <appender-ref ref="PROJECT_LOG"/>  
</root>

雖然這個功能也可以使用日誌切面來列印，但還是沒有直接在日誌中輸出更加方便，它可以直接和我們的日誌關聯在一起，只是多加了這幾個欄位而已。

Spring Boot 使用

OpenTelemetry 有給 springboot 應用提供一個 spring-boot-starter 包，用於在不使用 javaagent 的情況下也可以自動埋點。

<dependencies>
  <dependency>
    <groupId>io.opentelemetry.instrumentation</groupId>
    <artifactId>opentelemetry-spring-boot-starter</artifactId>
    <version>OPENTELEMETRY_VERSION</version>
  </dependency>
</dependencies>

但在早期的版本中還不支援直接列印 MDC 日誌：

最新的版本已經支援

即便已經支援預設輸出 MDC 後，我們依然可以自定義的內容，比如我們想修改一下 key 的名稱，由 trace_id 修改為 otel_trace_id 等。

<appender name="OTEL" class="io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender">
  <traceIdKey>otel_trace_id</traceIdKey>
  <spanIdKey>otel_span_id</spanIdKey>
  <traceFlagsKey>otel_trace_flags</traceFlagsKey>
</appender>

還是和之前類似，修改下 logback.xml 即可。

他的實現邏輯其實和之前的 auto instrument 中的類似，只不過使用的 API 不同而已。

auto instrument 是直接攔截程式碼邏輯修改 map 的返回值，而 OpenTelemetryAppender 是繼承了 ch.qos.logback.core.UnsynchronizedAppenderBase 介面，從而獲得了重寫 MDC 的能力，但本質上都是一樣的，沒有太大區別。

不過使用它的前提是我們需要引入以下一個依賴：

<dependencies>
  <dependency>
    <groupId>io.opentelemetry.instrumentation</groupId>
    <artifactId>opentelemetry-logback-mdc-1.0</artifactId>
    <version>OPENTELEMETRY_VERSION</version>
  </dependency>
</dependencies>

如果不想修改 logback.yaml ，對於 springboot 來說還有更簡單的方案，我們只需要使用以下配置即可自定義 MDC 資料：

logging.pattern.level = trace_id=%mdc{trace_id} span_id=%mdc{span_id} trace_flags=%mdc{trace_flags} %5p

這裡的 key 也可以自定義，只要佔位符沒有取錯即可。

使用這個的前提是需要載入 javaagent，因為這裡的資料是 javaagent 裡寫進去的。

總結

以上就是關於 MDC 在 OpenTelemetry 中的使用，從使用和原始碼邏輯上都分析了一遍，希望對 MDC 和 OpenTelemetry 的理解更加深刻一些。

關於 MDC 相關的概念與使用還是很有用的，是日常排查問題必不可少的一個工具。