自己写分布式链路追踪框架1--TraceId/SpanId/ParentSpanId生成及传递
文章目录
分布式环境下，由于系统不再是单点，一个业务可能会有多个系统参与执行。这就涉及到请求在多个系统之间来回转发，
如果没有一个全局的标识能够追踪单个业务调用，那么就会在发生业务故障时盲目查日志，造成问题定位困难。
如果我们能在系统间透明的传递一个全局唯一ID，将请求在分布式系统中的流转路径聚合并在使用中保存和传递该id，最后
通过页面进行可视化的展示，让开发、运维等人员能够轻松的发现系统故障，那么对问题的快速定位，系统的快速恢复有着
非凡的意义。
本文我们就根据谷歌的dapper论文的模型，自己开发一个最简的分布式链路追踪框架。工程上传至github，可以自行下载研究。
地址
首先罗列下需求。
需求说明
- 基于HTTP同步调用，能实现TraceId的传递，SpanId的生成及传递，ParentSpanId的获取。
- 应用层无感知，业务请求无需显示传递链路信息。
- 支持Spring框架
代码实现及分析
工程名命名为lite-tracer-agent。
1. TraceId、SpanId、ParentSpanId的生成及存储
由于要实现TraceId的传递，SpanId的生成及传递，ParentSpanId的获取等功能，我们首先想到Spring的拦截器，在拦截器的
preHandle()方法中进行数据的获取及存储。
preHandle(..)方法返回boolean值，可用此方法停止或继续处理过程。
如果此方法返回true，则处理过程继续，
如果此方法返回false，DispatcherServlet认为该截断器接手处理请求 (比如，渲染一个视图)，
所以就不再执行别的截断器和处理器。
代码如下，工程中位置为：lite-tracer/lite-tracer-agent/src/main/java/com.snowalker.tracer.interceptor.TraceInterceptor
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
LOGGER.info("[TraceInterceptor]进入Trace拦截器[preHandle()]");
String traceId = request.getHeader(Constants.HTTP_HEADER_TRACE_ID);
String lastSpanId = request.getHeader(Constants.HTTP_HEADER_SPAN_ID);
String parentSpanId = "";
/**当前SpanId*/
String spanId = "";
traceId = validateTraceId(traceId);
parentSpanId = getParentSpanId(lastSpanId);
spanId = getSpanId();
/**将Trace信息写入线程局部变量*/
saveTraceInfoToRequestContext(traceId, parentSpanId, spanId);
if (LOGGER.isDebugEnabled()) {
LOGGER.debug("[TraceInterceptor]当前请求中,TraceId={},SpanId={},ParentSpanId={}", traceId, spanId, parentSpanId);
}
return true;
}
由于我们是在应用层协议传递TraceId、SpanId、parentSpanId，则Http头是传递参数的最佳位置。这里只进行HTTP协议层的传递，如果要进一步
实现在RPC协议中的传递，我们就需要在RPC的序列化协议中增加定制化字段，将TraceId、SpanId传递下去。
这里有个地方要注意，对于SpanId而言，每次请求都是新的，因此直接分配即可，代码如下
/**每一次的SpanId都是新的，直接分配即可*/
private String getSpanId() {
String spanId;
spanId = IdGenerator.getInstance().nextSpanId();
if (LOGGER.isDebugEnabled()) {
LOGGER.debug("[TraceInterceptor]当前请求的SpanId={}", spanId);
}
return spanId;
}
对于ParentSpanId而言，首次请求的时候，父Span不存在，因此默认为-1，后续进行分析的时候只要遇到某个Trace节点的父Span为-1，则表示这个请求
是首次请求，也就是Dapper论文中提到的Trace树形结构中的根节点。
/**
* 当前请求的parentSpanId就是上个spanId
* 如果上一个spanId为空，则表明当前没有父Span，则父Span为-1
*/
private String getParentSpanId(String lastSpanId) {
String parentSpanId;
if (StringUtils.isEmpty(lastSpanId)) {
parentSpanId = "-1";
if (LOGGER.isDebugEnabled()) {
LOGGER.debug("[TraceInterceptor]首次请求获取到的ParentSpanId不存在，默认分配ParentSpanId={}", parentSpanId);
}
} else {
parentSpanId = lastSpanId;
if (LOGGER.isDebugEnabled()) {
LOGGER.debug("[TraceInterceptor]当前请求获取到的ParentSpanId={}", parentSpanId);
}
}
return parentSpanId;
}
对于最重要的TraceId而言，首次请求为空，如果从Header中获取TraceId为空，则分配一个信息，如果非空，则表示当前请求为请求链路中的某
请求，直接将这个值传递下去即可。
/**TraceId默认第一个为空，如果没值则分配一个*/
private String validateTraceId(String traceId) {
if (StringUtils.isEmpty(traceId)) {
traceId = IdGenerator.getInstance().nextTraceId();
if (LOGGER.isDebugEnabled()) {
LOGGER.debug("[TraceInterceptor]首次请求未分配TraceId,生成首次TraceId={}", traceId);
}
}
return traceId;
}
获取到TraceId、SpanId、ParentSpanId之后需要将他们保存并传递下去，直接保存在ThreadLocal即可，因为在JavaWeb中每个请求都是一个
线程来处理的。
这段代码中，我们从请求头中获取了TraceId和SpanId并将他们保存在了ThreadLoacl中，详细的保存过程如下。
private void saveTraceInfoToRequestContext(String traceId, String parentSpanId, String spanId) {
RequestContext.addTraceId(traceId);
RequestContext.addSpanId(spanId);
RequestContext.addParentSpanId(parentSpanId);
}
RequestContext封装了对应ThreadLocal的操作。
public class RequestContext {
private final static ThreadLocal<String> traceIdThreadLocal = new ThreadLocal<>();
private final static ThreadLocal<String> spanIdThreadLocal = new ThreadLocal<>();
private final static ThreadLocal<String> parentSpanIdThreadLocal = new ThreadLocal<>();
public static void addTraceId(String id) {
traceIdThreadLocal.set(id);
}
public static String getTraceId() {
return traceIdThreadLocal.get();
}
public static void removeTraceId() {
traceIdThreadLocal.remove();
}
public static void addSpanId(String id) {
spanIdThreadLocal.set(id);
}
public static String getSpanId() {
return spanIdThreadLocal.get();
}
public static void removeSpanId() {
spanIdThreadLocal.remove();
}
public static void addParentSpanId(String id) {
parentSpanIdThreadLocal.set(id);
}
public static String getParentSpanId() {
return parentSpanIdThreadLocal.get();
}
public static void removeParentSpanId() {
parentSpanIdThreadLocal.remove();
}
}
这样做的目的是为了在进程内随时能够获取到对应的链路数据。
2. TraceId、SpanId、ParentSpanId的清理
当进程内一个请求结束后应当对存储的临时变量进行清理，避免对后续的请求造成影响。
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
RequestContext.removeTraceId();
RequestContext.removeSpanId();
RequestContext.removeParentSpanId();
LOGGER.info("[TraceInterceptor]进入Trace拦截器[afterCompletion]清理本次请求的trace信息完成");
return;
}
方法afterCompletion:该方法也是需要当前对应的Interceptor 的preHandle 方法的返回值为true 时才会执行。
顾名思义，该方法将在整个请求结束之后，也就是在DispatcherServlet 渲染了对应的视图之后执行。
这个方法的主要作用是用于进行资源清理工作的。
我们简单的调用了ThreadLocal的remove()方法清空了临时存储的值，以便下次请求过来的时候能够更新。
3. 封装RestTemplate传递Trace信息
Trace信息的接收部分基本完成，我们还需要将这部分信息传递下去，这里就需要对HTTP客户端进行改写，将Trace信息写入HTTP头中。
这里我以RestTemplate为基础，对它进行了包装，封装了Trace信息的传递部分的逻辑。
@Component
public class RestTemplateWrapper {
/**
* 获取包装trace信息之后的RestTemplate
* @return
*/
public RestTemplate getRestTemlate() {
// 使用拦截器包装http header
RestTemplate restTemplate = new RestTemplate();
restTemplate.setInterceptors(new ArrayList<ClientHttpRequestInterceptor>() {
{
add((request, body, execution) -> {
String traceId = RequestContext.getTraceId();
String spanId = RequestContext.getSpanId();
String parentSpanId = RequestContext.getParentSpanId();
if (StringUtils.isNotEmpty(traceId)) {
request.getHeaders().add(Constants.HTTP_HEADER_TRACE_ID, traceId);
}
if (StringUtils.isNotEmpty(spanId)) {
request.getHeaders().add(Constants.HTTP_HEADER_SPAN_ID, spanId);
}
if (StringUtils.isNotEmpty(parentSpanId)) {
request.getHeaders().add(Constants.HTTP_HEADER_PARENT_SPAN_ID, parentSpanId);
}
return execution.execute(request, body);
});
}
});
HttpComponentsClientHttpRequestFactory factory = new HttpComponentsClientHttpRequestFactory();
// 注意此处需开启缓存，否则会报getBodyInternal方法“getBody not supported”错误
factory.setBufferRequestBody(true);
restTemplate.setRequestFactory(factory);
return restTemplate;
}
}
简单解释下，我们对原生的RestTemplate添加了过滤器ClientHttpRequestInterceptor，在请求头中添加了上下文获取到的TraceId、
SpanId、ParentSpanId等信息。这样在使用该包装后的RestTemplate发起Http请求的时候，就可以隐式地在Http头中传递Trace信息了。
由于使用了HttpComponentsClientHttpRequestFactory，因此需要添加Httpclient的包，依赖如下
<!-- https://mvnrepository.com/artifact/org.apache.httpcomponents/httpclient -->
<dependency>
<groupId>org.apache.httpcomponents</groupId>
<artifactId>httpclient</artifactId>
<version>4.5.3</version>
</dependency>
实战测试
主要的功能及代码介绍完毕，我们写个demo测试下，demo和框架本身的代码都在文章开头的地址中，可以自行下载测试哦。
为了方便起见，我这里建立了两个web工程，均为springboot项目，起名为tracer-demo-A,tracer-demo-B。
测试场景为，发请求到demoA的一个接口，demoA接口会在处理请求之后再次发送一个请求到demoB，根据日志来分析是否在请求到达
demoA的时候生成了Trace信息且按照规则成功传递到demoB。
tracer-demo-A主要代码
这里我只展示demoA的核心代码，DemoControllerA.java
@RestController
public class DemoControllerA {
private static final Logger LOGGER = LoggerFactory.getLogger(DemoController.class);
@Autowired
RestTemplateWrapper restTemplateWrapper;
@RequestMapping(value = "trace")
public @ResponseBody String trace(HttpServletRequest request, HttpServletResponse response) {
LOGGER.info("[trace]--traceId={},spanId={},parantSpanId={}",
RequestContext.getTraceId(),
RequestContext.getSpanId(),
RequestContext.getParentSpanId());
String result =
restTemplateWrapper.getRestTemlate().getForObject("http://localhost:8081/trace", String.class);
return "Send Message To B,result= " + result;
}
}
我们在收到请求发送至http://localhost:8080/trace的请求之后，打印一行日志，并将请求转发至地址为http://localhost:8081/trace
的demoB，并将demoB接口返回值打印在接口响应体中。
tracer-demo-B主要代码
@RestController
public class DemoControllerB {
private static final Logger LOGGER = LoggerFactory.getLogger(DemoController.class);
@RequestMapping(value = "trace")
public String trace(HttpServletRequest request, HttpServletResponse response) {
LOGGER.info("[trace]--traceId={},spanId={},parantSpanId={}",
RequestContext.getTraceId(),
RequestContext.getSpanId(),
RequestContext.getParentSpanId());
return "[trace]--traceId="+ RequestContext.getTraceId() +
",spanId=" + RequestContext.getSpanId() +
",parantSpanId={}" + RequestContext.getParentSpanId() +
"\nrequestUrl=" + request.getRequestURL();
}
}
demoB的逻辑很简单，就是收到请求后打印日志，并返回一个字符串。
运行结果
我们运行两个demo，端口分别为8080，8081。为了分析全面，开启日志等级为debug。
发送请求至http://localhost:8080/trace，可以收到返回串为：
Send Message To B,result= [trace]--traceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,spanId=SPAN-e87d82079daa4ea792a782a083451250,parantSpanId={}SPAN-de63425a1dc445e5a93d1d2369cafc3b
requestUrl=http://localhost:8081/trace
demoB的返回成功被demoA请求完成，我们来看下日志打印结果。
1. demoA日志
首先看demoA的日志。
2018-09-03 14:14:28.514 -INFO [http-nio-8080-exec-5]
com.snowalker.tracer.interceptor.TraceInterceptor [26] -
[TraceInterceptor]进入Trace拦截器[preHandle()]
2018-09-03 14:14:28.514 -DEBUG [http-nio-8080-exec-5]
com.snowalker.tracer.interceptor.TraceInterceptor [84] -
[TraceInterceptor]首次请求未分配TraceId,生成首次TraceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0
2018-09-03 14:14:28.515 -DEBUG [http-nio-8080-exec-5]
com.snowalker.tracer.interceptor.TraceInterceptor [68] -
[TraceInterceptor]首次请求获取到的ParentSpanId不存在，默认分配ParentSpanId=-1
2018-09-03 14:14:28.515 -DEBUG [http-nio-8080-exec-5]
com.snowalker.tracer.interceptor.TraceInterceptor [54] -
[TraceInterceptor]当前请求的SpanId=SPAN-de63425a1dc445e5a93d1d2369cafc3b
2018-09-03 14:14:28.515 -DEBUG [http-nio-8080-exec-5]
com.snowalker.tracer.interceptor.TraceInterceptor [38] -
[TraceInterceptor]当前请求中,TraceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,SpanId=SPAN-de63425a1dc445e5a93d1d2369cafc3b,ParentSpanId=-1
2018-09-03 14:14:28.515 -INFO [http-nio-8080-exec-5]
com.snowalker.tracer.aop.TraceHandler [35]
-traceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,spanId=SPAN-de63425a1dc445e5a93d1d2369cafc3b,parentSpanId=-1,方法执行[开始],methodName=trace
2018-09-03 14:14:28.515 -INFO [http-nio-8080-exec-5]
com.snowalker.tracer.demoA.controller.DemoController [35] -[trace]
--traceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,spanId=SPAN-de63425a1dc445e5a93d1d2369cafc3b,parantSpanId=-1
2018-09-03 14:14:28.869 -INFO [http-nio-8080-exec-5]
com.snowalker.tracer.aop.TraceHandler [40]
-traceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,spanId=SPAN-de63425a1dc445e5a93d1d2369cafc3b,parentSpanId=-1,方法执行[结束],methodName=trace
2018-09-03 14:14:28.884 -DEBUG [http-nio-8080-exec-5]
org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor [249]
-Written [Send Message To B,result= [trace]
--traceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,spanId=SPAN-e87d82079daa4ea792a782a083451250,parantSpanId={}SPAN-de63425a1dc445e5a93d1d2369cafc3b
2018-09-03 14:14:28.884 -INFO [http-nio-8080-exec-5]
com.snowalker.tracer.interceptor.TraceInterceptor [96]
-[TraceInterceptor]进入Trace拦截器[afterCompletion]清理本次请求的trace信息完成
2018-09-03 14:14:28.884 -DEBUG [http-nio-8080-exec-5]
org.springframework.web.servlet.DispatcherServlet [1000]
-Successfully completed request
lite-tracer-agent判断请求为首次，因此生成了traceId、SpanId。由于是首次，父SpanId不存在，因此设置为-1。到这里都符合我们的设计。
接着看demoB的日志。
2018-09-03 14:14:28.714 -INFO [http-nio-8081-exec-10]
com.snowalker.tracer.interceptor.TraceInterceptor [26] -
[TraceInterceptor]进入Trace拦截器[preHandle()]
2018-09-03 14:14:28.718 -DEBUG [http-nio-8081-exec-10]
com.snowalker.tracer.interceptor.TraceInterceptor [73] -
[TraceInterceptor]当前请求获取到的ParentSpanId=SPAN-de63425a1dc445e5a93d1d2369cafc3b
2018-09-03 14:14:28.720 -DEBUG [http-nio-8081-exec-10]
com.snowalker.tracer.interceptor.TraceInterceptor [54] -
[TraceInterceptor]当前请求的SpanId=SPAN-e87d82079daa4ea792a782a083451250
2018-09-03 14:14:28.720 -DEBUG [http-nio-8081-exec-10]
com.snowalker.tracer.interceptor.TraceInterceptor [38] -
[TraceInterceptor]当前请求中,TraceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,SpanId=SPAN-e87d82079daa4ea792a782a083451250,ParentSpanId=SPAN-de63425a1dc445e5a93d1d2369cafc3b
2018-09-03 14:14:28.737 -INFO [http-nio-8081-exec-10]
com.snowalker.tracer.aop.TraceHandler [35]
-traceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,spanId=SPAN-e87d82079daa4ea792a782a083451250,parentSpanId=SPAN-de63425a1dc445e5a93d1d2369cafc3b,方法执行[开始],methodName=trace
2018-09-03 14:14:28.746 -INFO [http-nio-8081-exec-10]
com.snowalker.tracer.demoB.controller.DemoController [24]
-[trace]--traceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,spanId=SPAN-e87d82079daa4ea792a782a083451250,parantSpanId=SPAN-de63425a1dc445e5a93d1d2369cafc3b
2018-09-03 14:14:28.746 -INFO [http-nio-8081-exec-10]
com.snowalker.tracer.aop.TraceHandler [40]
-traceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,spanId=SPAN-e87d82079daa4ea792a782a083451250,parentSpanId=SPAN-de63425a1dc445e5a93d1d2369cafc3b,方法执行[结束],methodName=trace
2018-09-03 14:14:28.798 -DEBUG [http-nio-8081-exec-10]
org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor [249]
-Written [[trace]--traceId=TRACE-3b63c42d0a1244b690b77e3e035a7cc0,spanId=SPAN-e87d82079daa4ea792a782a083451250,parantSpanId={}SPAN-de63425a1dc445e5a93d1d2369cafc3b
2018-09-03 14:14:28.799 -INFO [http-nio-8081-exec-10]
com.snowalker.tracer.interceptor.TraceInterceptor [96]
-[TraceInterceptor]进入Trace拦截器[afterCompletion]清理本次请求的trace信息完成
2018-09-03 14:14:28.799 -DEBUG [http-nio-8081-exec-10]
org.springframework.web.servlet.DispatcherServlet [1000]
-Successfully completed request
请求从demoA服务发送至demoB服务，被lite-tracer-agent的拦截器拦截，解析出TraceId并设置到demoB对应的ThreadLocal中，
生成demoB对应的SpanId，同时将demoA的SpanId设置为当前请求的ParentSpanId。
完美的操作~
开个玩笑哈，到这里，我们成功的实现了对跨服务HTTP的链路信息的传递，并实现了对dapper的基本模型的模拟，当然本工程还是不完善的，比如
- 没有实现对线程池的trace跟踪
- 没有实现对队列的trace跟踪
- 没有实现对链路信息的分析等操作
这些功能会在后续慢慢完善。
小结
分布式链路追踪（APM）是分布式及微服务环境下不可或缺的部分，掌握这部分知识对于构建一个完善的分布式服务体系是极为重要的，
感谢你们阅读到这里，跟随笔者的脚步构建了一个玩具级别的链路追踪工程，在后续的文章中我们将继续完善它的功能，相信这将加深我们
的思考能力及编码水平，don’t talk, show me the code！
