引入sleuth zipkin是怎么打印traceId的?
<!--包含了sleuth+zipkin-->
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-starter-zipkin</artifactId>
</dependency>
一直有个疑问,为什么引入sleuth+zipkin之后,日志中会输出traceId和spanId:
2021-03-11 16:03:04.142 INFO [8b349996dff0d892,8b349996dff0d892,false] 8480 --- [p-nio-90-exec-1] a.s.s.m.AbstractValidatingSessionManager : Enabling session validation scheduler...
2021-03-11 16:03:04.178 INFO [8b349996dff0d892,8b349996dff0d892,false] 8480 --- [p-nio-90-exec-1] o.a.shiro.cache.ehcache.EhCacheManager : Using existing EHCache named [shiro-activeSessionCache]
从上面logback的配置文件FILE_LOG_PATTERN
并未发现相关配置,其中必有妖怪!
通过分析引入的sleuth依赖,终于发现在spring-cloud-sleuth-core-xxx.jar找到,请看这个类
org.springframework.cloud.sleuth.autoconfig.TraceEnvironmentPostProcessor
@Override
public void postProcessEnvironment(ConfigurableEnvironment environment,
SpringApplication application) {
Map<String, Object> map = new HashMap<String, Object>();
// This doesn't work with all logging systems but it's a useful default so you see
// traces in logs without having to configure it.
if (Boolean.parseBoolean(environment.getProperty("spring.sleuth.enabled", "true"))) {
map.put("logging.pattern.level",
"%5p [${spring.zipkin.service.name:${spring.application.name:-}},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-Span-Export:-}]");
}
addOrReplace(environment.getPropertySources(), map);
}
这段代码在项目启动阶段,把环境变量logging.pattern.level
替换了,增加了spring.application.name
、X-B3-TraceId
和X-B3-SpanId
。实际上就是替换了环境变量LOG_LEVEL_PATTERN
,再回到logback的配置文件FILE_LOG_PATTERN
:
${FILE_LOG_PATTERN:-%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}} ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}
其中${LOG_LEVEL_PATTERN:-%5p}
就是引用了这个环境变量。
到此为止,是不是就完了呢?No~~!增加的spring.application.name
、X-B3-TraceId
和X-B3-SpanId
的值从哪里来呢?继续看代码
org.springframework.cloud.sleuth.log.Slf4jCurrentTraceContext
这个类中通过MDC ( Mapped Diagnostic Contexts )
的方式把traceId、spanId插入到日志内容中。
//
// Source code recreated from a .class file by IntelliJ IDEA
// (powered by Fernflower decompiler)
//
package org.springframework.cloud.sleuth.log;
import brave.internal.HexCodec;
import brave.internal.Nullable;
import brave.propagation.CurrentTraceContext;
import brave.propagation.TraceContext;
import brave.propagation.CurrentTraceContext.Default;
import brave.propagation.CurrentTraceContext.Scope;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
/** @deprecated */
@Deprecated
public final class Slf4jCurrentTraceContext extends CurrentTraceContext {
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";
private static final Logger log = LoggerFactory.getLogger(Slf4jCurrentTraceContext.class);
final CurrentTraceContext delegate;
public static Slf4jCurrentTraceContext create() {
return create(Default.inheritable());
}
public static Slf4jCurrentTraceContext create(CurrentTraceContext delegate) {
return new Slf4jCurrentTraceContext(delegate);
}
Slf4jCurrentTraceContext(CurrentTraceContext delegate) {
if (delegate == null) {
throw new NullPointerException("delegate == null");
} else {
this.delegate = delegate;
}
}
public TraceContext get() {
return this.delegate.get();
}
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();
}
private void log(String text, TraceContext span) {
if (span != null) {
if (log.isTraceEnabled()) {
log.trace(text, span);
}
}
}
static void replace(String key, @Nullable String value) {
if (value != null) {
MDC.put(key, value);
} else {
MDC.remove(key);
}
}
}