在分布式项目中需要引入 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.14return 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@ConditionalOnMissingBeanTracing 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@ConditionalOnMissingBeanHttpTracing 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@ConditionalOnMissingBeanpublic 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中持有traceidSpan 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);}}