分布式鏈路追蹤：TraceIdFilter + MDC + Skywalking

查線上日誌時，同一個 Pod 內多執行緒日誌交錯，很難追蹤每個請求對應的日誌資訊。

日誌收集工具將多個 Pod 的日誌收集到同一個資料庫中後，情況就更加混亂不堪了。

解決

unset unset TraceId + MDC unset unset

MDC：

https://logback.qos.ch/manual/mdc.html

publicvoiddoFilter(ServletRequest request, ServletResponse response, FilterChain chain)
throws IOException, ServletException {
HttpServletRequest httpServletRequest = (HttpServletRequest) request;
String traceId = httpServletRequest.getHeader(TRACE_ID_HEADER_KEY);
if (StrUtil.isBlank(traceId)) {
traceId = UUID.randomUUID().toString();
}
MDC.put(MDC_TRACE_ID_KEY, traceId);
try {
chain.doFilter(request, response);
} finally {
MDC.remove(MDC_TRACE_ID_KEY);
}
}


<?xml version="1.0" encoding="UTF-8"?>
<configurationdebug="false">
<propertyname="pattern"value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-5level [%thread] %logger %line [%X{traceId}] [%tid] - %msg%n"/>


unset unset 整合 Feign unset unset

發起服務間呼叫時，需要將 MDC 中的 traceId 傳遞到被呼叫服務。我們計畫中統一使用 Feign Client，實作服務間的 HTTP 遠端呼叫，在 Feign RequestInterceptor 中，取出 MDC 中的 traceId，塞到請求頭中： requestTemplate.header(TRACE_ID_HEADER_KEY, MDC.get(MDC_TRACE_ID_KEY));

@Override
publicvoidapply(RequestTemplate template){
template.header(TRACE_ID_HEADER_KEY, MDC.get(MDC_TRACE_ID_KEY));
}


unset unset 多執行緒適配 unset unset

Please note that MDC as implemented by logback- classic assumes that values are placed into the MDC with moderate frequency. Also note that a child thread does not automatically inherit a copy of the mapped diagnostic context of its parent.

在子執行緒執行任務前，將父執行緒的 MDC 內容設定到子執行緒的 MDC 中；在子執行緒任務執行完成後，清除子執行緒 MDC 中的內容。

適配 JDK ThreadPoolExecutor：

public classMdcAwareThreadPoolExecutorextendsThreadPoolExecutor{
@Override
publicvoidexecute(Runnable command){
Map<String, String> parentThreadContextMap = MDC.getCopyOfContextMap();
super.execute(MdcTaskUtils.adaptMdcRunnable(command, parentThreadContextMap));
}
}

適配 Spring TaskDecorator：

@Component
public classMdcAwareTaskDecoratorimplementsTaskDecorator{
@Override
public Runnable decorate(Runnable runnable){
Map<String, String> parentThreadContextMap = MDC.getCopyOfContextMap();
return MdcTaskUtils.adaptMdcRunnable(runnable, parentThreadContextMap);
}
}

MdcTaskUtils#adaptMdcRunnable() ：采用裝飾者模式，裝飾原生的 Runnable runnable 物件，在原生 Runnable 物件執行前，將父執行緒的 MDC 設定到子執行緒中，在原生 Runnable 物件執行結束後，清除子執行緒 MDC 中的內容。

@Slf4j
publicabstract classMdcTaskUtils{
publicstatic Runnable adaptMdcRunnable(Runnable runnable, Map<String, String> parentThreadContextMap){
return () -> {
log.debug("parentThreadContextMap: {}, currentThreadContextMap: {}", parentThreadContextMap,
MDC.getCopyOfContextMap());
if (MapUtils.isEmpty(parentThreadContextMap) || !parentThreadContextMap.containsKey(MDC_TRACE_ID_KEY)) {
log.debug("can not find a parentThreadContextMap, maybe task is fired using async or schedule task.");
MDC.put(MDC_TRACE_ID_KEY, UUID.randomUUID().toString());
} else {
MDC.put(MDC_TRACE_ID_KEY, parentThreadContextMap.get(MDC_TRACE_ID_KEY));
}
try {
runnable.run();
} finally {
MDC.remove(MDC_TRACE_ID_KEY);
}
};
}
}


unset unset 整合 Skywalking unset unset

Skywalking 官方提供了對 logback 1.x 版本的適配： apm-toolkit-logback-1.x ，可以在 logback 中打印 skywalking traceId ，可以將 X-App-Trace-Id 和 skywalking traceId 結合起來，方便介面業務和效能問題的排查。

<?xml version="1.0" encoding="UTF-8"?>
<configurationdebug="false">
<propertyname="pattern"value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-5level [%thread] %logger %line [%X{traceId}] [%tid] - %msg%n"/>
<appendername="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<layout class="org.apache.skywalking.apm.toolkit.log.logback.v1.x.TraceIdPatternLogbackLayout">
<pattern>${pattern}</pattern>
</layout>
</encoder>
</appender>

TraceIdPatternLogbackLayout 類初始化時，添加了兩個 PatternConverter ：

public classTraceIdPatternLogbackLayoutextendsPatternLayout{
publicTraceIdPatternLogbackLayout(){
}
static {
defaultConverterMap.put("tid", LogbackPatternConverter. class.getName());
defaultConverterMap.put("sw_ctx", LogbackSkyWalkingContextPatternConverter. class.getName());
}
}

LogbackPatternConverter#convert() 方法寫死了返回 " TID: N/A "，這是怎麽回事呢？

public classLogbackPatternConverterextends classicConverter{
publicLogbackPatternConverter(){
}
public String convert(ILoggingEvent iLoggingEvent){
return"TID: N/A";
}
}

啟動 Java 套用時，指定 java agent 啟動參數 -javaagent:-javaagent:/opt/tools/skywalking-agent.jar。skywalking agent 會代理 LogbackPatternConverter 類，重寫 convert() 方法的邏輯。

package org.apache.skywalking.apm.toolkit.log.logback.v1.x;
import ch.qos.logback. classic.pattern. classicConverter;
import ch.qos.logback. classic.spi.ILoggingEvent;
import java.lang.reflect.Method;
import org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.EnhancedInstance;
import org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter;
import org.apache.skywalking.apm.toolkit.log.logback.v1.x.LogbackPatternConverter$auxiliary$pJ6Zrqzi;
public classLogbackPatternConverter
extends classicConverter
implementsEnhancedInstance{
privatevolatile Object _$Enhanced classField_ws;
publicstaticvolatile/* synthetic */ InstMethodsInter delegate$mo3but1;
privatestaticfinal/* synthetic */ Method cachedValue$oeLgRjrq$u5j8qu3;
public String convert(ILoggingEvent iLoggingEvent){
return (String)delegate$mo3but1.intercept(this, new Object[]{iLoggingEvent}, new LogbackPatternConverter$auxiliary$pJ6Zrqzi(this, iLoggingEvent), cachedValue$oeLgRjrq$u5j8qu3);
}
private/* synthetic */ String convert$original$T8InTdln(ILoggingEvent iLoggingEvent) {
/*34*/return"TID: N/A";
}
@Override
publicvoidsetSkyWalkingDynamicField(Object object){
this._$Enhanced classField_ws = object;
}
@Override
public Object getSkyWalkingDynamicField(){
returnthis._$Enhanced classField_ws;
}
static {
classLoader.getSystem classLoader().load class("org.apache.skywalking.apm.dependencies.net.bytebuddy.dynamic.Nexus").getMethod("initialize", class. class, Integer.TYPE).invoke(null, LogbackPatternConverter. class, -1942176692);
cachedValue$oeLgRjrq$u5j8qu3 = LogbackPatternConverter. class.getMethod("convert", ILoggingEvent. class);
}
final/* synthetic */ String convert$original$T8InTdln$accessor$oeLgRjrq(ILoggingEvent iLoggingEvent) {
returnthis.convert$original$T8InTdln(iLoggingEvent);
}
}








MDC 原理

MDC 在 slf4j-api jar 包中，MDC 是 slf4j 的規範，對 MDC 的所有操作都會落到 MDCAdapter 介面的方法上。

public classMDC{
staticfinal String NULL_MDCA_URL = "http://www.slf4j.org/codes.html#null_MDCA";
staticfinal String NO_STATIC_MDC_BINDER_URL = "http://www.slf4j.org/codes.html#no_static_mdc_binder";
static MDCAdapter mdcAdapter;
publicstaticvoidput(String key, String val)throws IllegalArgumentException {
if (key == null) {
thrownew IllegalArgumentException("key parameter cannot be null");
}
if (mdcAdapter == null) {
thrownew IllegalStateException("MDCAdapter cannot be null. See also " + NULL_MDCA_URL);
}
mdcAdapter.put(key, val);
}
}


MDCAdapter 是 slf4j 提供的 MDC 介面卡介面，也就是 MDC 的規範。任何日誌框架想要使用 MDC 功能，需要遵守 MDCAdapter 介面介面規範，實作介面中的方法。

// This interface abstracts the service offered by various MDC implementations.
publicinterfaceMDCAdapter{
publicvoidput(String key, String val);
public String get(String key);
}


Logback 日誌框架提供了對 MDCAdapter 的適配： LogbackMDCAdapter ，底層采用 ThreadLocal 實作。

public classLogbackMDCAdapterimplementsMDCAdapter{
// The internal map is copied so as
// We wish to avoid unnecessarily copying of the map. To ensure
// efficient/timely copying, we have a variable keeping track of the last
// operation. A copy is necessary on 'put' or 'remove' but only if the last
// operation was a 'get'. Get operations never necessitate a copy nor
// successive 'put/remove' operations, only a get followed by a 'put/remove'
// requires copying the map.
// See http://jira.qos.ch/browse/LOGBACK-620 for the original discussion.
// We no longer use CopyOnInheritThreadLocal in order to solve LB classIC-183
// Initially the contents of the thread local in parent and child threads
// reference the same map. However, as soon as a thread invokes the put()
// method, the maps diverge as they should.
final ThreadLocal<Map<String, String>> copyOnThreadLocal = new ThreadLocal<Map<String, String>>();
privatestaticfinalint WRITE_OPERATION = 1;
privatestaticfinalint MAP_COPY_OPERATION = 2;
// keeps track of the last operation performed
final ThreadLocal<Integer> lastOperation = new ThreadLocal<Integer>();

publicvoidput(String key, String val)throws IllegalArgumentException {
if (key == null) {
thrownew IllegalArgumentException("key cannot be null");
}
Map<String, String> oldMap = copyOnThreadLocal.get();
Integer lastOp = getAndSetLastOperation(WRITE_OPERATION);
if (wasLastOpReadOrNull(lastOp) || oldMap == null) {
Map<String, String> newMap = duplicateAndInsertNewMap(oldMap);
newMap.put(key, val);
} else {
oldMap.put(key, val);
}
}
public String get(String key){
final Map<String, String> map = copyOnThreadLocal.get();
if ((map != null) && (key != null)) {
return map.get(key);
} else {
returnnull;
}
}
}









Logback 占位符

PatternLayout 類初始化時，設定了 logback 常用占位符對應的 Converter。

public classPatternLayoutextendsPatternLayoutBase<ILoggingEvent> {
publicstaticfinal Map<String, String> DEFAULT_CONVERTER_MAP = new HashMap<String, String>();
publicstaticfinal Map<String, String> CONVERTER_ class_TO_KEY_MAP = new HashMap<String, String>();
/**
* @deprecated replaced by DEFAULT_CONVERTER_MAP
*/
publicstaticfinal Map<String, String> defaultConverterMap = DEFAULT_CONVERTER_MAP;
publicstaticfinal String HEADER_PREFIX = "#logback. classic pattern: ";
static {
DEFAULT_CONVERTER_MAP.putAll(Parser.DEFAULT_COMPOSITE_CONVERTER_MAP);
DEFAULT_CONVERTER_MAP.put("d", DateConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("date", DateConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(DateConverter. class.getName(), "date");
DEFAULT_CONVERTER_MAP.put("r", RelativeTimeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("relative", RelativeTimeConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(RelativeTimeConverter. class.getName(), "relative");
DEFAULT_CONVERTER_MAP.put("level", LevelConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("le", LevelConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("p", LevelConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(LevelConverter. class.getName(), "level");

DEFAULT_CONVERTER_MAP.put("t", ThreadConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("thread", ThreadConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(ThreadConverter. class.getName(), "thread");
DEFAULT_CONVERTER_MAP.put("lo", LoggerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("logger", LoggerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("c", LoggerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(LoggerConverter. class.getName(), "logger");
DEFAULT_CONVERTER_MAP.put("m", MessageConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("msg", MessageConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("message", MessageConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(MessageConverter. class.getName(), "message");
DEFAULT_CONVERTER_MAP.put("C", classOfCallerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put(" class", classOfCallerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put( classOfCallerConverter. class.getName(), " class");
DEFAULT_CONVERTER_MAP.put("M", MethodOfCallerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("method", MethodOfCallerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(MethodOfCallerConverter. class.getName(), "method");
DEFAULT_CONVERTER_MAP.put("L", LineOfCallerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("line", LineOfCallerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(LineOfCallerConverter. class.getName(), "line");
DEFAULT_CONVERTER_MAP.put("F", FileOfCallerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("file", FileOfCallerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(FileOfCallerConverter. class.getName(), "file");
DEFAULT_CONVERTER_MAP.put("X", MDCConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("mdc", MDCConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("ex", ThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("exception", ThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("rEx", RootCauseFirstThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("rootException", RootCauseFirstThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("throwable", ThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("xEx", ExtendedThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("xException", ExtendedThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("xThrowable", ExtendedThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("nopex", NopThrowableInformationConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("nopexception", NopThrowableInformationConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("cn", ContextNameConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("contextName", ContextNameConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(ContextNameConverter. class.getName(), "contextName");
DEFAULT_CONVERTER_MAP.put("caller", CallerDataConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(CallerDataConverter. class.getName(), "caller");
DEFAULT_CONVERTER_MAP.put("marker", MarkerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(MarkerConverter. class.getName(), "marker");
DEFAULT_CONVERTER_MAP.put("property", PropertyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("n", LineSeparatorConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("black", BlackCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("red", RedCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("green", GreenCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("yellow", YellowCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("blue", BlueCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("magenta", MagentaCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("cyan", CyanCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("white", WhiteCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("gray", GrayCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldRed", BoldRedCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldGreen", BoldGreenCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldYellow", BoldYellowCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldBlue", BoldBlueCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldMagenta", BoldMagentaCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldCyan", BoldCyanCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldWhite", BoldWhiteCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("highlight", HighlightingCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("lsn", LocalSequenceNumberConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(LocalSequenceNumberConverter. class.getName(), "lsn");
DEFAULT_CONVERTER_MAP.put("prefix", PrefixCompositeConverter. class.getName());
}
}


























ThreadConverter ：將 %thread 占位符轉換為 logger 執行緒。

public classThreadConverterextends classicConverter{
public String convert(ILoggingEvent event){
return event.getThreadName();
}
)

在 PatternLayout 中，預設添加了對 MDC 的支持，可以將 %X{key} 或者 %mdc{key} 占位符轉換為 MDC.get(key) 。

DEFAULT_CONVERTER_MAP.put("X", MDCConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("mdc", MDCConverter. class.getName());


MDCConverter 為何可以將 %X{traceId} 或者 %mdc{traceId} 占位符轉換為 MDC.get("traceId") ？

在程式啟動時， ch.qos.logback.core.pattern.parser.Compiler#compile() 會解析使用者配置的 pattern 運算式，得到 pattern 中需要動態解析的占位符，比如 %d{yyyy-MM-dd HH:mm:ss.SSS} ， %X{traceId} 。將這些動態占位符傳遞給 DynamicConverter#optionList 欄位（ MDCConverter 本質就是 DynamicConverter ），optionList 欄位包含程式要處理的占位符名稱，比如 traceId。

程式啟動時，logback 進行 Convert 初始化，會呼叫 MDCConverter#start() 方法，將成員變量 private String key 的值設定為 traceId（MDCConverter#getFirstOption() 返回使用者配置的 traceId）。

在 MDCConverter#convert() 方法中，將 traceId 占位符轉換為 MDC.get(key)：String value = mdcPropertyMap.get(key) 。

public classMDCConverterextends classicConverter{
private String key;
private String defaultValue = "";
@Override
publicvoidstart(){
String[] keyInfo = extractDefaultReplacement(getFirstOption());
key = keyInfo[0];
if (keyInfo[1] != null) {
defaultValue = keyInfo[1];
}
super.start();
}
@Override
public String convert(ILoggingEvent event){
Map<String, String> mdcPropertyMap = event.getMDCPropertyMap();
if (mdcPropertyMap == null) {
return defaultValue;
}
if (key == null) {
return outputMDCForAllKeys(mdcPropertyMap);
} else {
String value = mdcPropertyMap.get(key);
if (value != null) {
return value;
} else {
return defaultValue;
}
}
}
}






ILoggingEvent 介面的實作類 LoggingEvent 中，對 MDCAdapter 做了適配：

public classLoggingEventimplementsILoggingEvent{
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;
}
}


來源：juejin.cn/post/7278498472860581925

>>

END

精品資料，超贊福利，免費領

微信掃碼/長按辨識 添加【技術交流群】

群內每天分享精品學習資料

最近開發整理了一個用於速刷面試題的小程式；其中收錄了上千道常見面試題及答案(包含基礎、並行、JVM、MySQL、Redis、Spring、SpringMVC、SpringBoot、SpringCloud、訊息佇列等多個型別)，歡迎您的使用。

👇👇

👇點選"閱讀原文"，獲取更多資料（持續更新中）