日志與追蹤的完美融合：OpenTelemetry MDC實踐指南
前言
通常我們排查問題的方式是先查詢異常日志，判斷是否是當(dāng)前系統(tǒng)的問題。
如果不是，則在日志中撈出 trace_id 再到鏈路查詢系統(tǒng)中查詢鏈路，看看具體是哪個系統(tǒng)的問題，然后再做具體的排查。
類似于這樣：
圖片
日志中會打印 trace_id 和 span_id。
如果日志系統(tǒng)做的比較完善的話，還可以直接點擊 trace_id 跳轉(zhuǎn)到鏈路系統(tǒng)里直接查詢鏈路信息。
MDC
這里的日志里關(guān)聯(lián) trace 信息的做法有個專有名詞：MDC:(Mapped Diagnostic Context)。
簡單來說就是用于排查問題的上下文信息，通常是由鍵值對組成，類似于這樣的數(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 都有提供對應(yīng)的實現(xiàn)。
如果我們使用了 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 格式的日志，并且?guī)?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");
}會在調(diào)用 ch.qos.logback.classic.spi.ILoggingEvent.getMDCPropertyMap()/getMdc() 這兩個函數(shù)中進(jìn)行埋點。
這些邏輯都是寫在 javaagent 中的。
這個函數(shù)其實默認(rèn)情況下會返回一個 logback 內(nèi)置 MDC 的 map 數(shù)據(jù)（這里的數(shù)據(jù)我們可以自定義配置）。
而這里要做的就是將 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 出來然后寫入進(jìn) map 中即可。
從源碼里還得知，只要我們開啟 -Dotel.instrumentation.logback-mdc.add-baggage=true 配置還可以將 baggage 中的數(shù)據(jù)也寫入到 MDC 中。
而得易于 OpenTelemetry 中的 trace 是可以跨線程傳輸?shù)模约幢闶俏覀冊诙嗑€程里打印日志時 MDC 數(shù)據(jù)依然可以準(zhǔn)確無誤的傳遞。
MDC 的原理
public static final String MDC_ATTR_NAME = "mdc";
圖片
在 logback 的實現(xiàn)中是會調(diào)用剛才的 getMDCPropertyMap() 然后寫入到一個 key 為 mdc 的 map 里，最終可以寫入到文件或者控制臺。
這樣整個原理就可以串起來了。
自定義日志 數(shù)據(jù)
提到可以自定義 MDC 數(shù)據(jù)其實也是有使用場景的，比如我們的業(yè)務(wù)系統(tǒng)經(jīng)常有類似的需求，需要在日志中打印一些常用業(yè)務(wù)數(shù)據(jù)：
- userId、userName
- 客戶端 IP等信息時
此時我們就可以創(chuàng)建一個 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 提供的函數(shù)：org.apache.skywalking.apm.toolkit.trace.TraceContext#traceId
接著只需要在 logback.xml 中配置這個 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>雖然這個功能也可以使用日志切面來打印，但還是沒有直接在日志中輸出更加方便，它可以直接和我們的日志關(guān)聯(lián)在一起，只是多加了這幾個字段而已。
Spring Boot 使用
OpenTelemetry 有給 springboot 應(yīng)用提供一個 spring-boot-starter 包，用于在不使用 javaagent 的情況下也可以自動埋點。
<dependencies>
<dependency>
<groupId>io.opentelemetry.instrumentation</groupId>
<artifactId>opentelemetry-spring-boot-starter</artifactId>
<version>OPENTELEMETRY_VERSION</version>
</dependency>
</dependencies>但在早期的版本中還不支持直接打印 MDC 日志：
圖片
最新的版本已經(jīng)支持
即便已經(jīng)支持默認(rèn)輸出 MDC 后，我們依然可以自定義的內(nèi)容，比如我們想修改一下 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 即可。
他的實現(xiàn)邏輯其實和之前的 auto instrument 中的類似，只不過使用的 API 不同而已。
auto instrument 是直接攔截代碼邏輯修改 map 的返回值，而 OpenTelemetryAppender 是繼承了 ch.qos.logback.core.UnsynchronizedAppenderBase 接口，從而獲得了重寫 MDC 的能力，但本質(zhì)上都是一樣的，沒有太大區(qū)別。
不過使用它的前提是我們需要引入以下一個依賴：
<dependencies>
<dependency>
<groupId>io.opentelemetry.instrumentation</groupId>
<artifactId>opentelemetry-logback-mdc-1.0</artifactId>
<version>OPENTELEMETRY_VERSION</version>
</dependency>
</dependencies>如果不想修改 logback.yaml ，對于 springboot 來說還有更簡單的方案，我們只需要使用以下配置即可自定義 MDC 數(shù)據(jù)：
logging.pattern.level = trace_id=%mdc{trace_id} span_id=%mdc{span_id} trace_flags=%mdc{trace_flags} %5p這里的 key 也可以自定義，只要占位符沒有取錯即可。
使用這個的前提是需要加載 javaagent，因為這里的數(shù)據(jù)是 javaagent 里寫進(jìn)去的。
總結(jié)
以上就是關(guān)于 MDC 在 OpenTelemetry 中的使用，從使用和源碼邏輯上都分析了一遍，希望對 MDC 和 OpenTelemetry 的理解更加深刻一些。
關(guān)于 MDC 相關(guān)的概念與使用還是很有用的，是日常排查問題必不可少的一個工具。
