在分布式项目中需要引入 spring-cloud-starter-sleuth框架来记录跟踪请求在不同服务之前流转的路径。在整个流转路径通过traceid将所有的路径给串联起来。
项目中需要保存traceid来实现日志快速搜索和定位,可以通过MDC.get("traceId")获取到traceId。
当前项目集成了
<dependency> <groupId>org.springframework.cloud</groupId> <artifactId>spring-cloud-starter-sleuth</artifactId> <version>2.0.4.RELEASE</version> </dependency> <dependency> <groupId>org.springframework.cloud</groupId> <artifactId>spring-cloud-sleuth-core</artifactId> <version>2.0.4.RELEASE</version> </dependency>
MDC((Mapped Diagnostic Contexts))翻译过来就是映射的诊断上下文 。意思是:在日志中 (映射的) 请求ID(requestId),可以作为我们定位 (诊断) 问题的关键字 (上下文)。这并不是一个新鲜的产物,MDC类基本原理其实非常简单,其内部持有一个ThreadLocal实例,用于保存context数据,MDC提供了put/get/clear等几个核心接口,用于操作ThreadLocal中的数据。
我们在使用MDC获取traceid时要考虑traceid为什么能通过MDC获取到,按照调用顺序,分析以下的两个问题:
1.traceid从哪里取值的?
2.traceid从哪里赋值进去的?
1.traceid从哪里取值的
MDC.get("traceId")分析MDC类里调用的get方法
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);
}
在该方法中mdcAdapter是通过 MDC类里的静态方法块赋值的。
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();
}
}
public class StaticMDCBinder {
/**
* The unique instance of this class.
*/
public static final StaticMDCBinder SINGLETON = new StaticMDCBinder();
private StaticMDCBinder() {
}
/**
* Currently this method always returns an instance of
* {@link StaticMDCBinder}.
*/
public MDCAdapter getMDCA() {
return new LogbackMDCAdapter();
}
public String getMDCAdapterClassStr() {
return LogbackMDCAdapter.class.getName();
}
}
在上面的代码段中可以看到该属性对应的类类型为LogbackMDCAdapter
查看该类的get方法
public String get(String key) {
final Map<String, String> map = copyOnThreadLocal.get();
if ((map != null) && (key != null)) {
return map.get(key);
} else {
return null;
}
}
发现上面的方法是通过copyOnThreadLocal属性取值
final ThreadLocal<Map<String, String>> copyOnThreadLocal = new ThreadLocal<Map<String, String>>();
从上面的属性定义中我们可以看到,该属性值的来源源自线程Thread中的ThreaLocal中取值。
那么threadLocal里的值是在哪里赋值的?
2.traceid从哪里赋值进去的
在spring-cloud-sleuth-core这个jar包中找到了spring.factories文件。
在该文件中找到了TraceAutoConfiguration类,该类中注入了Tracing类型的bean。该bean对currentTraceContext属性赋值了一个CurrentTraceContext类型的bean。注意该上下文后面会用上。
@Bean
@ConditionalOnMissingBean
Tracing tracing(@Value("${spring.zipkin.service.name:${spring.application.name:default}}") String serviceName, Factory factory, CurrentTraceContext currentTraceContext, Reporter<Span> reporter, Sampler sampler, ErrorParser errorParser, SleuthProperties sleuthProperties) {
return Tracing.newBuilder().sampler(sampler).errorParser(errorParser).localServiceName(serviceName).propagationFactory(factory).currentTraceContext(currentTraceContext).spanReporter(this.adjustedReporter(reporter)).traceId128Bit(sleuthProperties.isTraceId128()).supportsJoin(sleuthProperties.isSupportsJoin()).build();
}
而CurrentTraceContext类型的bean是通过SleuthLogAutoConfiguration这个配置类注入的,可以看到以下代码,下面的代码通过后置处理器对CurrentTraceContext类型的bean进行处理,如果该CurrentTraceContext类型的bean不是Slf4jCurrentTraceContext类型的,则对该类型的bean通过代理的方式向spring容器中注入了Slf4jCurrentTraceContext类型的bean。
@Bean
@ConditionalOnProperty(
value = {"spring.sleuth.log.slf4j.enabled"},
matchIfMissing = true
)
@ConditionalOnBean({CurrentTraceContext.class})
public static BeanPostProcessor slf4jSpanLoggerBPP() {
return new SleuthLogAutoConfiguration.Slf4jConfiguration.Slf4jBeanPostProcessor();
}
static class Slf4jBeanPostProcessor implements BeanPostProcessor {
Slf4jBeanPostProcessor() {
}
public Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
return bean;
}
public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
return bean instanceof CurrentTraceContext && !(bean instanceof Slf4jCurrentTraceContext) ? Slf4jCurrentTraceContext.create((CurrentTraceContext)bean) : bean;
}
}
分析spring.factories文件中配置的TraceHttpAutoConfiguration类,在该类中通过@Bean的方式注入了HttpTracing 这个类型的bean对象。该对象的入参使用了Tracing类型的Bean对象。
@Bean
@ConditionalOnMissingBean
HttpTracing httpTracing(Tracing tracing, SkipPatternProvider provider) {
HttpSampler serverSampler = this.combineUserProvidedSamplerWithSkipPatternSampler(provider);
return HttpTracing.newBuilder(tracing).clientParser(this.clientParser).serverParser(this.serverParser).clientSampler(this.clientSampler).serverSampler(serverSampler).build();
}
分析spring.factories文件中配置的TraceWebServletAutoConfiguration类,在TraceWebServletAutoConfiguration类。在该类中通过以下代码
@Bean
@ConditionalOnMissingBean
public TracingFilter tracingFilter(HttpTracing tracing) {
return (TracingFilter)TracingFilter.create(tracing);
}
该方法的入参是前面通过TraceHttpAutoConfiguration类注入的HttpTracing类型的对象。在调用TracingFilter.create(tracing)方法时,会通过new TracingFilter(httpTracing)返回向spring容器中注入了TracingFilter类型的对象。在创建对象的同时向currentTraceContext属性赋值,该属性源自HttpTracing中生成时设置的上下文Slf4jCurrentTraceContext。
TracingFilter实现了Filter接口,意味着该对象是一个拦截器类型的对象。当接受到请求后,拦截器会拦截请求并执行拦截器中的doFilter方法。
查看doFilter方法
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
HttpServletRequest req = (HttpServletRequest)request;
HttpServletResponse res = this.servlet.httpServletResponse(response);
TraceContext context = (TraceContext)request.getAttribute(TraceContext.class.getName());
if (context != null) {
Scope scope = this.currentTraceContext.maybeScope(context);
try {
chain.doFilter(request, response);
} finally {
scope.close();
}
} else {
//该段代码生成Span,span通过TraceContext中持有traceid
Span span = this.handler.handleReceive(new HttpServletRequestWrapper(req));
request.setAttribute(SpanCustomizer.class.getName(), span);
request.setAttribute(TraceContext.class.getName(), span.context());
TracingFilter.SendHandled sendHandled = new TracingFilter.SendHandled();
request.setAttribute(TracingFilter.SendHandled.class.getName(), sendHandled);
Throwable error = null;
//通过该方法向MDC赋值
Scope scope = this.currentTraceContext.newScope(span.context());
boolean var17 = false;
try {
var17 = true;
chain.doFilter(req, res);
var17 = false;
} catch (Throwable var22) {
error = var22;
throw var22;
} finally {
if (var17) {
if (this.servlet.isAsync(req)) {
this.servlet.handleAsync(this.handler, req, res, span);
} else if (sendHandled.compareAndSet(false, true)) {
HttpServerResponse responseWrapper = HttpServletResponseWrapper.create(req, res, error);
this.handler.handleSend(responseWrapper, span);
}
scope.close();
}
}
if (this.servlet.isAsync(req)) {
this.servlet.handleAsync(this.handler, req, res, span);
} else if (sendHandled.compareAndSet(false, true)) {
HttpServerResponse responseWrapper = HttpServletResponseWrapper.create(req, res, error);
this.handler.handleSend(responseWrapper, span);
}
scope.close();
}
}
在上面的代码中重点关注this.currentTraceContext.newScope(span.context())方法,其中
此时的currentTraceContext是Slf4jCurrentTraceContext类型的。在Slf4jCurrentTraceContext类的newScope方法可以看到MDC.put("traceId", traceIdString)将traceid赋值到了MDC中。
public Scope newScope(@Nullable TraceContext currentSpan) {
final String previousTraceId = MDC.get("traceId");
final String previousParentId = MDC.get("parentId");
final String previousSpanId = MDC.get("spanId");
final String spanExportable = MDC.get("spanExportable");
final String legacyPreviousTraceId = MDC.get("X-B3-TraceId");
final String legacyPreviousParentId = MDC.get("X-B3-ParentSpanId");
final String legacyPreviousSpanId = MDC.get("X-B3-SpanId");
final String legacySpanExportable = MDC.get("X-Span-Export");
if (currentSpan != null) {
String traceIdString = currentSpan.traceIdString();
//重点关注此处
MDC.put("traceId", traceIdString);
MDC.put("X-B3-TraceId", traceIdString);
String parentId = currentSpan.parentId() != null ? HexCodec.toLowerHex(currentSpan.parentId()) : null;
replace("parentId", parentId);
replace("X-B3-ParentSpanId", parentId);
String spanId = HexCodec.toLowerHex(currentSpan.spanId());
MDC.put("spanId", spanId);
MDC.put("X-B3-SpanId", spanId);
String sampled = String.valueOf(currentSpan.sampled());
MDC.put("spanExportable", sampled);
MDC.put("X-Span-Export", sampled);
this.log("Starting scope for span: {}", currentSpan);
if (currentSpan.parentId() != null && log.isTraceEnabled()) {
log.trace("With parent: {}", currentSpan.parentId());
}
} else {
MDC.remove("traceId");
MDC.remove("parentId");
MDC.remove("spanId");
MDC.remove("spanExportable");
MDC.remove("X-B3-TraceId");
MDC.remove("X-B3-ParentSpanId");
MDC.remove("X-B3-SpanId");
MDC.remove("X-Span-Export");
}
final Scope scope = this.delegate.newScope(currentSpan);
class ThreadContextCurrentTraceContextScope implements Scope {
ThreadContextCurrentTraceContextScope() {
}
public void close() {
Slf4jCurrentTraceContext.this.log("Closing scope for span: {}", currentSpan);
scope.close();
Slf4jCurrentTraceContext.replace("traceId", previousTraceId);
Slf4jCurrentTraceContext.replace("parentId", previousParentId);
Slf4jCurrentTraceContext.replace("spanId", previousSpanId);
Slf4jCurrentTraceContext.replace("spanExportable", spanExportable);
Slf4jCurrentTraceContext.replace("X-B3-TraceId", legacyPreviousTraceId);
Slf4jCurrentTraceContext.replace("X-B3-ParentSpanId", legacyPreviousParentId);
Slf4jCurrentTraceContext.replace("X-B3-SpanId", legacyPreviousSpanId);
Slf4jCurrentTraceContext.replace("X-Span-Export", legacySpanExportable);
}
}
return new ThreadContextCurrentTraceContextScope();
}
跟踪MDC的put方法最后发现,该方法中将key和对应的value放置到了copyOnThreadLocal属性中。该属性是ThreadLocal类型的,这样在线程的任何地方都可以通过MDC.get来获取到traceid了。
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) {
Map<String, String> newMap = duplicateAndInsertNewMap(oldMap);
newMap.put(key, val);
} else {
oldMap.put(key, val);
}
}