SpringCloud Sleuth 实现业务逻辑日志包含 Span 和 Trace信息

概述

SpringCloud Sleuth是Spring Cloud的核心组件之一，实现了一种分布式链路跟踪的功能。在调用链层级很深的分布式系统中，为定位问题提供了很大便利。

Sleuth 大致的原理是自定义了一个拦截器：TraceFeignRequestInterceptor，该拦截器继承了 Feign 的拦截器接口：RequestInterceptor，所以在服务与服务直接调用时，可以进行一些埋点操作。比如在请求的head中存入具体的span信息，包括TraceId、SpanId。有两个问题：
1）在前置服务或者是数据聚合服务层面，一些对外的接口如何生成 Span 信息？
2）如何将生成的 TraceId 和 SpanId 打印到日志中？类似日志格式：

---

源码

问题一 ：在接口层面生成对应的 Span 信息，可以通过切面的方式实现。通过切面拦截所有的 Controller 接口，参数和返回结果也可以保存到 Span 中。如何实现呢？
在Sleuth中，Span的生成逻辑被封装在 DefaultTracer中，所以在切面中可以将该 bean 传入切面即可。

自定义配置：

@Configuration
public class CustomerSleuthStreamAutoConfiguration
{
  @Bean
  public CustomerTraceAspect customerTraceAspect(Tracer tracer)
  {
    return new CustomerTraceAspect(tracer);
  }
}

切面逻辑：

@Aspect
public class CustomerTraceAspect
{
  private final Tracer tracer;
  
  public CustomerTraceAspect(Tracer tracer)
  {
    this.tracer = tracer;
  }
  
  @Pointcut("@within(org.springframework.web.bind.annotation.RestController) || @within(org.springframework.stereotype.Controller)")
  private void traceHandlerInterceptorPointcut() {}
  
  @Around("traceHandlerInterceptorPointcut()")
  public Object wrapWithCorrelationId(ProceedingJoinPoint pjp)
    throws Throwable
  {
    boolean filter = filterNoRequestMappingMethod(pjp);
    ObjectMapper mapper = new ObjectMapper();
    if (filter)
    {
    // 通过 DefaultTracer 生成 Span 信息
	this.tracer.addTag("params", tagValue);
    }
    Object callable = pjp.proceed();
    if (filter) {
        this.tracer.addTag("result", mapper.writeValueAsString(callable));
    }
    return callable;
  }

看一下 tracer.addTag具体如何生成 Span，在DefaultTracer类中：

	@Override
	public void addTag(String key, String value) {
	 //获取当前请求已经创建Span
		Span s = getCurrentSpan();
		if (s != null && s.isExportable()) {
		//存储 key-value信息，参数和返回结果等
			s.tag(key, value);
		}
	}

	@Override
	public Span getCurrentSpan() {
		//从ThreadLocal中获取当前线程的 Span
		return SpanContextHolder.getCurrentSpan();
	}
	 static Span getCurrentSpan() {
		return isTracing() ? CURRENT_SPAN.get().span : null;
	}

---

问题二：将日志打印格式中如何包含 Span 信息，可以采用logback的MDC方式。

MDC（Mapped Diagnostic Context，映射调试上下文），即将一些运行时的上下文数据通过logback打印出来，是 一种方便在多线程条件下记录日志的功能。
也就是说通过MDC方式，在打印日志时，可以打印一些具有标识意义的参数，用来标识业务唯一性。

MDC底层实现主要是通过ThreadLocal,在生成 Span 信息之后，将Span信息存入到当前线程的变量中。而在日志打印时，可以打印通过之前存入的变量，比如下面日志中打印了 traceId 和 spanId：

[com.Ok] [Ok.java:30] [traceId=e6721ddf0ee927f1,spanId=e6721ddf0ee927f1]  - admin

来看一下如何存入 traceId 和 spanId ：
继续来看一下DefaultTracer类：

@Override
	public Span createSpan(String name, Sampler sampler) {
		Span span;
		if (isTracing()) {
			span = createChild(getCurrentSpan(), name);
		}
		else {
			long id = createId();
			span = Span.builder().begin(System.currentTimeMillis()).name(name).traceId(id)
					.spanId(id).build();
			if (sampler==null) {
				sampler = this.defaultSampler;
			}
			span = sampledSpan(name, id, span, sampler);
			this.spanLogger.logStartedSpan(null, span);
		}
		// MDC处理
		return continueSpan(span);
	}

在生成 span 信息之后会调用continueSpan方法，该方法中会有 mdc 相关逻辑处理：

	@Override
	public Span continueSpan(Span span) {
		if (span != null) {
			this.spanLogger.logContinuedSpan(span);
		} else {
			return null;
		}
		Span newSpan = createContinuedSpan(span, SpanContextHolder.getCurrentSpan());
		SpanContextHolder.setCurrentSpan(newSpan);
		return newSpan;
	}

上述方法中，spanLogger的默认实现为Slf4jSpanLogger:

public class Slf4jSpanLogger implements SpanLogger {
	//......
	@Override
	public void logContinuedSpan(Span span) {
		MDC.put(Span.SPAN_ID_NAME, Span.idToHex(span.getSpanId()));
		MDC.put(Span.TRACE_ID_NAME, Span.idToHex(span.getTraceId()));
		MDC.put(Span.SPAN_EXPORT_NAME, String.valueOf(span.isExportable()));
		log("Continued span: {}", span);
	}
}	

可以看到上面通过MDC方式存入了Span信息，这是默认的实现方式，并没有存入 SpanId 和 TraceId，所以需要自己实现spanLogger，实现方式很简单：

public class ZaLogSpanLogger implements SpanLogger {
    private static final Logger log = LoggerFactory.getLogger(ZaLogSpanLogger.class);
 
    public void logContinuedSpan(Span span) {
        this.putMDCValue(span);
        this.log("Continued span: {}", span);
    }

    private void putMDCValue(Span span) {
    	//存入 SpanId
        MDC.put("X-B3-SpanId", Span.idToHex(span.getSpanId()));
        //存入 TraceId
        MDC.put("X-B3-TraceId", Span.idToHex(span.getTraceId()));
        //存入 ParentSpan TraceId
        MDC.put("X-B3-ParentSpanId", CollectionUtils.isEmpty(span.getParents()) ? "" : Span.idToHex((Long)span.getParents().get(0)));
        MDC.put("X-Span-Name", span.getName());
        //存入应用名称
        MDC.put("appname", this.appname);
        MDC.put("begintime", Span.idToHex(span.getBegin()));
        MDC.put("fin-X1-time", Span.idToHex(span.getEnd()));
    }

    private void clearMDCValue() {
        MDC.remove("X-B3-SpanId");
        MDC.remove("X-B3-TraceId");
        MDC.remove("X-B3-ParentSpanId");
        MDC.remove("X-Span-Name");
        MDC.remove("appname");
        MDC.remove("begintime");
        MDC.remove("fin-X1-time");
    }
}

上面 traceId 和 spanId 对应的变量为 X-B3-TraceId,X-B3-SpanId，然后在 logback.xml中定义日志打印格式，格式中包含这两个变量即可：

<property name="TRACE_LOG_PATTERN"
              value="%d [%thread] %-5p [%c] [%F:%L] [trace=%X{X-B3-TraceId:-},span=%X{X-B3-SpanId:-}]  - %msg%n"/>

<appender name="infoAppender"
			  class="ch.qos.logback.core.rolling.RollingFileAppender">
		<file>${log.dir}/logs/${HOSTNAME}-ss_micro_app_${projectname}_lt_info.log</file>
		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
			<fileNamePattern>${log.dir}/logs/${HOSTNAME}_${projectname}-%d{yyyy-MM-dd}.log
			</fileNamePattern>
			<maxHistory>30</maxHistory>
		</rollingPolicy>
		<encoder charset="UTF-8">
			//引用上述变量即可
			<pattern>${TRACE_LOG_PATTERN}</pattern>
		</encoder>
	</appender>

---

总结

本篇主要介绍了在接口层面如何生成 Span 信息，以及通过MDC方式，将 Span 相关信息打印在日志中。