从头分析一则traceId穿透问题(附解决方案)
常用的链路追踪组件
现在常用的开源组件有google的Dapper,Twitter的zipkin和Apache SkyWalking等，商用的比较有代表性的是阿里的Eagleeye(鹰眼)。它们的工作模式不外乎是客户端在同一个trace的不同span上采点上传到server端然后server端进行存储后以web界面的形式将整个链路以traceId和spanId进行关联起来就形成了整个调用链路。用于串起整个链路的id主要分为traceId和spanId。
但是，这里不会介绍上面的任何一种组件，这里主要来分析并解决下spring-cloud-sleuth与logback整合后线程池中输出的日志中没有traceId的问题。
spring-cloud-sleuth
sleuth主要功能是在分布式系统中提供追踪解决方案，并且兼容支持了zipkin(提供了链路追踪的可视化功能)。sleuth是对zipkin的封装，包括一个http请求进入后对应Span，Trace等信息的生成以及向Zipkin server发送采集信息等全部自动化完成（如果需要发送到zipkin server的话需要引入相应的包并进行相应配置）。
先来看一下它的依赖，pom依赖为：
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-sleuth-core</artifactId>
</dependency>jar中的依赖关系如下图：
可以看到，在sleuth中依赖了zipkin-brave，在brave中主要提供了一系列的instrumentation组件（如上图所示），能够更加方便地对trace进行处理。
http请求的处理链路
我们来分析一下，一个请求进入后的处理链路，如下图：
对trace的处理逻辑主要在brave.servlet.TracingFilter#TracingFilter的doFilter方法中。
继续来看一下在doFilter方法中的处理逻辑：
上面标注了五个地方，其实逻辑很简单，主要分为以下几步：
•A处会去获取TraceContext上下文；•如果获取到的TraceContext不为空则会进入B处，进入filter链中进行相应请求的处理逻辑；•如果获取到的TraceContext为空则进入C处创建一个scope；•在D处继续进行业务逻辑的处理；•在E处对创建的新的scope进行处理，比如关闭操作或者发送span信息等。
下面我们重点看下上面C处的newScope方法，即brave.propagation.ThreadLocalCurrentTraceContext#newScope方法：
static final ThreadLocal<TraceContext> DEFAULT = new ThreadLocal<>();
@SuppressWarnings("ThreadLocalUsage") // intentional: to support multiple Tracer instances
final ThreadLocal<TraceContext> local;
ThreadLocalCurrentTraceContext(
CurrentTraceContext.Builder builder,
ThreadLocal<TraceContext> local
) {
super(builder);
if (local == null) throw new NullPointerException("local == null");
this.local = local;
}
@Override public Scope newScope(@Nullable TraceContext currentSpan) {
// 从threadLocal中获取之前的TraceContext
final TraceContext previous = local.get();
// 向threadLocal中设置当前的TraceContext对象
local.set(currentSpan);
class ThreadLocalScope implements Scope {
@Override public void close() {
local.set(previous);
}
}
// 创建新的ThreadLocalScope对象
Scope result = new ThreadLocalScope();
return decorateScope(currentSpan, result);
}这里用了一个ThreadLocal对象来维护TraceContext对象，并创建新的ThreadLocalScope对象，然后装饰这个scope对象。我们接着来看下brave.propagation.CurrentTraceContext#decorateScope方法：
protected Scope decorateScope(@Nullable TraceContext currentSpan, Scope scope) {
// 遍历scopeDecorators列表，对当前TraceContext进行装饰
int length = scopeDecorators.size();
for (int i = 0; i < length; i++) {
scope = scopeDecorators.get(i).decorateScope(currentSpan, scope);
}
return scope;
}这里会遍历整个scopeDecorators列表，对当前TraceContext进行装饰，在这里我们主要关注下针对日志的decorator即org.springframework.cloud.sleuth.log.Slf4jScopeDecorator，我们来看下它的decorateScope方法如下：
private static final String LEGACY_EXPORTABLE_NAME = "X-Span-Export";
private static final String LEGACY_PARENT_ID_NAME = "X-B3-ParentSpanId";
private static final String LEGACY_TRACE_ID_NAME = "X-B3-TraceId";
private static final String LEGACY_SPAN_ID_NAME = "X-B3-SpanId";
@Override
public CurrentTraceContext.Scope decorateScope(TraceContext currentSpan,
CurrentTraceContext.Scope scope) {
--------省略部分代码---------------
final List<AbstractMap.SimpleEntry<String, String>> previousMdc = Stream
.concat(whitelistedBaggageKeysWithValue(currentSpan),
whitelistedPropagationKeysWithValue(currentSpan))
.map((s) -> new AbstractMap.SimpleEntry<>(s, MDC.get(s)))
.collect(Collectors.toList());
if (currentSpan != null) {// 将当前TraceContext设置到MDC中去
String traceIdString = currentSpan.traceIdString();
MDC.put("traceId", traceIdString);
MDC.put(LEGACY_TRACE_ID_NAME, traceIdString);
String parentId = currentSpan.parentId() != null
? HexCodec.toLowerHex(currentSpan.parentId()) : null;
replace("parentId", parentId);
replace(LEGACY_PARENT_ID_NAME, parentId);
String spanId = HexCodec.toLowerHex(currentSpan.spanId());
MDC.put("spanId", spanId);
MDC.put(LEGACY_SPAN_ID_NAME, spanId);
String sampled = String.valueOf(currentSpan.sampled());
MDC.put("spanExportable", sampled);
MDC.put(LEGACY_EXPORTABLE_NAME, sampled);
log("Starting scope for span: {}", currentSpan);
if (currentSpan.parentId() != null) {
if (log.isTraceEnabled()) {
log.trace("With parent: {}", currentSpan.parentId());
}
}
whitelistedBaggageKeysWithValue(currentSpan).forEach(
(s) -> MDC.put(s, ExtraFieldPropagation.get(currentSpan, s)));
whitelistedPropagationKeysWithValue(currentSpan).forEach(
(s) -> MDC.put(s, ExtraFieldPropagation.get(currentSpan, s)));
}
else {//如果当前TraceContext为空，则清理MDC
MDC.remove("traceId");
MDC.remove("parentId");
MDC.remove("spanId");
MDC.remove("spanExportable");
MDC.remove(LEGACY_TRACE_ID_NAME);
MDC.remove(LEGACY_PARENT_ID_NAME);
MDC.remove(LEGACY_SPAN_ID_NAME);
MDC.remove(LEGACY_EXPORTABLE_NAME);
whitelistedBaggageKeys().forEach(MDC::remove);
whitelistedPropagationKeys().forEach(MDC::remove);
}这里除了一些白名单携带的key的处理之外主要就是两步操作：
•如果当前TraceContext不为空则设置相应trace信息到MDC中去；•如果当前TraceContext为空，则清理MDC。
那么这个用于存放trace信息的MDC又是什么样的结构呢？我们带着这个疑问往下看。
MDC
属性
org.slf4j.MDC的属性很简单，就只有一个mdcAdapter对象：
static MDCAdapter mdcAdapter
static {
try {
mdcAdapter = bwCompatibleGetMDCAdapterFromBinder();
} catch (NoClassDefFoundError ncde) {
mdcAdapter = new NOPMDCAdapter();
String msg = ncde.getMessage();
if (msg != null && msg.contains("StaticMDCBinder")) {
Util.report("Failed to load class "org.slf4j.impl.StaticMDCBinder".");
Util.report("Defaulting to no-operation MDCAdapter implementation.");
Util.report("See " + NO_STATIC_MDC_BINDER_URL + " for further details.");
} else {
throw ncde;
}
} catch (Exception e) {
// we should never get here
Util.report("MDC binding unsuccessful.", e);
}
}
private static MDCAdapter bwCompatibleGetMDCAdapterFromBinder() throws NoClassDefFoundError {
try {
return StaticMDCBinder.getSingleton().getMDCA();
} catch (NoSuchMethodError nsme) {
// binding is probably a version of SLF4J older than 1.7.14
return StaticMDCBinder.SINGLETON.getMDCA();
}
} 这个mdcAdapter对象的初始化操作在静态代码块中，具体的获取方式见上面的代码，最后生成的adapter对象为LogbackMDCAdapter类型的，对于LogbackMDCAdapter我们看下它的关键属性和方法：
final ThreadLocal<Map<String, String>> copyOnThreadLocal = new ThreadLocal<Map<String, String>>();
// 写操作
private static final int WRITE_OPERATION = 1;
// copy操作
private static final int MAP_COPY_OPERATION = 2;
// keeps track of the last operation performed
final ThreadLocal<Integer> lastOperation = new ThreadLocal<Integer>();
public String get(String key) {
final Map<String, String> map = copyOnThreadLocal.get();
if ((map != null) && (key != null)) {
return map.get(key);
} else {
return null;
}
}
public void put(String key, String val) throws IllegalArgumentException {
if (key == null) {
throw new IllegalArgumentException("key cannot be null");
}
Map<String, String> oldMap = copyOnThreadLocal.get();
Integer lastOp = getAndSetLastOperation(WRITE_OPERATION);
if (wasLastOpReadOrNull(lastOp) || oldMap == null) {// oldMap为空则创建新的map
Map<String, String> newMap = duplicateAndInsertNewMap(oldMap);
newMap.put(key, val);
} else {
oldMap.put(key, val);
}
}从代码中可以看到，LogbackMDCAdapter中也是通过一个ThreadLocal对象来维护当前上下文信息的。
方法
对于MDC中的方法我们主要来看下get和put方法：
public static String get(String key) throws IllegalArgumentException {
if (key == null) {
throw new IllegalArgumentException("key parameter cannot be null");
}
if (mdcAdapter == null) {
throw new IllegalStateException("MDCAdapter cannot be null. See also " + NULL_MDCA_URL);
}
return mdcAdapter.get(key);
}
public static void put(String key, String val) throws IllegalArgumentException {
if (key == null) {
throw new IllegalArgumentException("key parameter cannot be null");
}
if (mdcAdapter == null) {
throw new IllegalStateException("MDCAdapter cannot be null. See also " + NULL_MDCA_URL);
}
mdcAdapter.put(key, val);
}可以看到在get和put方法的内部调用的是mdcAdapter的get和put方法，也就是说trace的上下文信息也是通过一个ThreadLocal来维护的。
日志处理
在logback.xml中做如下配置：
<property name="CONSOLE_LOG_PATTERN" value="%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(-){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
<contextName>${APP_NAME}</contextName>
<!-- 控制台输出 -->
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<!-- Minimum logging level to be presented in the console logs-->
<level>DEBUG</level>
</filter>
<encoder>
<pattern>${CONSOLE_LOG_PATTERN}</pattern>
<charset>utf8</charset>
</encoder>
</appender>做了上面配置之后我们通过logger.info方法输出一条log时，我们来看下它的具体处理链路：
下面将涉及到的方法按照调用顺序罗列如下：
Appender中的操作和LogEvent对象的创建
第一步来看一下ch.qos.logback.classic.Logger#buildLoggingEventAndAppend方法：
private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
final Throwable t) {
LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
le.setMarker(marker);
callAppenders(le);
}这里主要涉及到两步：创建LoggingEvent和callAppenders操作，这里有兴趣的可以去看下callAppenders方法，这里我们主要关注一下我们配置的ConsoleAppender的父类OutputStreamAppender中的几个属性：
protected Encoder<E> encoder;
protected final ReentrantLock lock = new ReentrantLock(false);
private void writeBytes(byte[] byteArray) throws IOException {
if(byteArray == null || byteArray.length == 0)
return;
lock.lock();
try {
this.outputStream.write(byteArray);
if (immediateFlush) {
this.outputStream.flush();
}
} finally {
lock.unlock();
}
}encoder在下文中会具体地分析，这里我们主要关注下这个ReentrantLock，这里创建的是一个非公平锁，在appender的很多方法中会使用这个lock进行同步，这里只列举出了writeBytes方法。这个加锁操作也是为什么现在大家都在推崇log4j2的原因，原因细品。
另外，在创建LoggingEvent时会需要关注几点，先上代码：
private Map<String, String> mdcPropertyMap;
public Map<String, String> getMDCPropertyMap() {
// populate mdcPropertyMap if null
if (mdcPropertyMap == null) {
// mdcPropertyMap的获取源头来自于MDCAdapter对象
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;
}
public Map<String, String> getMdc() {
return getMDCPropertyMap();
}从上面可以看出mdcPropertyMap的获取源头来自于MDCAdapter对象，即上文中提到的那个ThreadLocal对象。
ch.qos.logback.core.encoder.LayoutWrappingEncoder#encode方法:
public byte[] encode(E event) {
String txt = layout.doLayout(event);
return convertToBytes(txt);
}在上文中我们配置的PatternLayout为：
在ch.qos.logback.classic.PatternLayout#doLayout方法内部：
public String doLayout(ILoggingEvent event) {
if (!isStarted()) {
return CoreConstants.EMPTY_STRING;
}
return writeLoopOnConverters(event);
}
protected String writeLoopOnConverters(E event) {
StringBuilder strBuilder = new StringBuilder(INTIAL_STRING_BUILDER_SIZE);
Converter<E> c = head;
while (c != null) {
c.write(strBuilder, event);
c = c.getNext();
}
return strBuilder.toString();
}有兴趣的可以去看下ch.qos.logback.core.pattern.PatternLayoutBase#start方法，在start方法中会根据pattern进行解析得到一个converter的链表。在writeLoopOnConverters方法中会遍历这个链表来对当前的LogEvent对象进行处理，我们忽略掉其他converter的处理部分，只关注下与本文相关的ch.qos.logback.classic.pattern.MDCConverter，我们来看一下它的convert方法：
@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;
}
}
}在这个方法中是不是看到了我们在创建LoggingEvent对象时提到的很重要的一个点？没错，就是getMDCPropertyMap其实也是从MdcAdapter的那个ThreadLocal对象中获取的，也就是说sleuth和zipkin-brave中携带下来的trace信息是通过ThreadLocal一路传递下来的，最终在logger中输出出来。
日志分析
在上述的配置中输出的日志格式为：
2020-09-17 17:26:37.753 INFO [recommendEngine,583cc7b7c07fecd7,583cc7b7c07fecd7,false] 47692 - [io-19380-exec-2] c.d.b.r.b.s.impl.RecommendServiceImpl重点解释一下日志中的 [appname,traceId,spanId,exportable] 各部分所代表的含义：
•appname：记录日志的应用的名称，即spring.application.name的值；•traceId：Sleuth为一次请求链路生成的唯一ID，一个Trace中可以包含多个Span；•spanId：请求链路基本的工作单元，代表发生一次特定的操作，例如：发送一个Http请求；•exportable：是否需要将日志导出到 Zipkin。
问题
看起来这个trace的传递过程很完美，其实也是存在一些问题的，比如一个异步线程池输出的日志是下面这样的：
2020-09-17 17:26:37.740 INFO [recommendEngine,,,] 47692 - [onPool-worker-1] jdbc.resultset看看是不是缺少了点啥？没错，traceId和spanId都丢失了，这就是TreadLocal在异步线程池处理场景下的一个短板，关于这一点，之前也有写过一篇文章专门介绍过ThreadLocal、InheritThreadLocal和TransmitableThreadLocal之间的区别和特点，有兴趣的可以自行翻阅。
解决方法
traceId 在子线程或线程池打印到日志中
是问题就会有对象的解决方案，这里的解决方案也很简单，使用logback-mdc-ttl就能解决上面的问题啦，详情见：https://github.com/ofpay/logback-mdc-ttl
三步操作如下：
1.项目依赖
<dependency>
<groupId>com.ofpay</groupId>
<artifactId>logback-mdc-ttl</artifactId>
<version>1.0.2</version>
</dependency>1.在Java的启动参数加上：
•-Xbootclasspath/a:/path/to/transmittable-thread-local-2.x.x.jar•-javaagent:/path/to/transmittable-thread-local-2.x.x.jar这步操作也可以不使用javaagent的方式，直接在代码中手动的使用ttl对线程池进行包装即可。
1.在logback配置文件中增加TtlMdcListener
<?xml version="1.0" encoding="UTF-8"?>
<configuration >
<!-- ...(略) -->
<contextListener class="com.ofpay.logback.TtlMdcListener"/>
<!--例子: %X{uuid} 支持在跨线程池时传递-->
<property scope="context" name="APP_PATTERN"
value='%d{yyyy-MM-dd HH:mm:ss.SSS}|%X{uuid}|%level|%M|%C:%L|%thread|%replace(%.-2000msg){"(r|n)","t"}|"%.-2000ex{full}"%n'/>
</configuration>注：在log4j2中应用时可引入log4j2-ttl-thread-context-map依赖来解决。
改动之后，异步线程池的日志输出如下：
2020-09-17 17:47:08.727 INFO [recommendEngine,27fceb2f30ea045e,27fceb2f30ea045e,false] 40944 - [onPool-worker-1] jdbc.resultset问题解决。
参考
•https://github.com/alibaba/transmittable-thread-local•https://github.com/ofpay/logback-mdc-ttl•http://www.saily.top/2018/12/29/springcloud/sleuth-lost-traceId/•https://www.jianshu.com/p/ae855779f30b•https://github.com/openzipkin/brave•https://github.com/openzipkin/zipkin
http://www.manongjc.com/detail/57-lkpoikidcfynise.html
