日志與追蹤的完美融合：OpenTelemetry MDC實(shí)踐指南

作者：crossoverJie 2024-09-11 08:10:46

通常我們排查問題的方式是先查詢異常日志，判斷是否是當(dāng)前系統(tǒng)的問題。如果不是，則在日志中撈出 trace_id 再到鏈路查詢系統(tǒng)中查詢鏈路，看看具體是哪個(gè)系統(tǒng)的問題，然后再做具體的排查。

前言

通常我們排查問題的方式是先查詢異常日志，判斷是否是當(dāng)前系統(tǒng)的問題。

如果不是，則在日志中撈出 trace_id 再到鏈路查詢系統(tǒng)中查詢鏈路，看看具體是哪個(gè)系統(tǒng)的問題，然后再做具體的排查。

類似于這樣：

圖片

日志中會(huì)打印 trace_id 和 span_id。

如果日志系統(tǒng)做的比較完善的話，還可以直接點(diǎn)擊 trace_id 跳轉(zhuǎn)到鏈路系統(tǒng)里直接查詢鏈路信息。

MDC

這里的日志里關(guān)聯(lián) trace 信息的做法有個(gè)專有名詞：MDC:(Mapped Diagnostic Context)。

簡(jiǎn)單來說就是用于排查問題的上下文信息，通常是由鍵值對(duì)組成，類似于這樣的數(shù)據(jù)：

{  
  "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 都有提供對(duì)應(yīng)的實(shí)現(xiàn)。

如果我們使用了 OpenTelemetry 提供的 javaagent 再配合 logback 或者 Log4j 時(shí)就會(huì)自動(dòng)具備打印 MDC 的能力：

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

比如我們只需要這樣配置這樣一個(gè)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>

圖片

就會(huì)在日志文件中輸出 JSON 格式的日志，并且?guī)?MDC 的信息。

自動(dòng) MDC 的原理

我也比較好奇 OpenTelemetry 是如何自動(dòng)寫入 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");  
}

會(huì)在調(diào)用 ch.qos.logback.classic.spi.ILoggingEvent.getMDCPropertyMap()/getMdc() 這兩個(gè)函數(shù)中進(jìn)行埋點(diǎn)。

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

這個(gè)函數(shù)其實(shí)默認(rèn)情況下會(huì)返回一個(gè) logback 內(nèi)置 MDC 的 map 數(shù)據(jù)（這里的數(shù)據(jù)我們可以自定義配置）。

而這里要做的就是將 trace 的上下文信息寫入這個(gè) 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);  
}

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

從源碼里還得知，只要我們開啟 -Dotel.instrumentation.logback-mdc.add-baggage=true 配置還可以將 baggage 中的數(shù)據(jù)也寫入到 MDC 中。

而得易于 OpenTelemetry 中的 trace 是可以跨線程傳輸?shù)模约幢闶俏覀冊(cè)诙嗑€程里打印日志時(shí) MDC 數(shù)據(jù)依然可以準(zhǔn)確無誤的傳遞。

MDC 的原理

public static final String MDC_ATTR_NAME = "mdc";

圖片

在 logback 的實(shí)現(xiàn)中是會(huì)調(diào)用剛才的 getMDCPropertyMap() 然后寫入到一個(gè) key 為 mdc 的 map 里，最終可以寫入到文件或者控制臺(tái)。

這樣整個(gè)原理就可以串起來了。

自定義日志數(shù)據(jù)

提到可以自定義 MDC 數(shù)據(jù)其實(shí)也是有使用場(chǎng)景的，比如我們的業(yè)務(wù)系統(tǒng)經(jīng)常有類似的需求，需要在日志中打印一些常用業(yè)務(wù)數(shù)據(jù)：

userId、userName
客戶端 IP等信息時(shí)

此時(shí)我們就可以創(chuàng)建一個(gè) 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 的時(shí)候由 skywalking 提供的函數(shù)：org.apache.skywalking.apm.toolkit.trace.TraceContext#traceId

接著只需要在 logback.xml 中配置這個(gè) CustomJsonLayoutEncoder 就可以按照我們自定義的數(shù)據(jù)輸出日志了：

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

雖然這個(gè)功能也可以使用日志切面來打印，但還是沒有直接在日志中輸出更加方便，它可以直接和我們的日志關(guān)聯(lián)在一起，只是多加了這幾個(gè)字段而已。

Spring Boot 使用

OpenTelemetry 有給 springboot 應(yīng)用提供一個(gè) spring-boot-starter 包，用于在不使用 javaagent 的情況下也可以自動(dòng)埋點(diǎn)。

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

但在早期的版本中還不支持直接打印 MDC 日志：

圖片