分布式环境下，由于系统不再是单点，一个业务可能会有多个系统参与执行。这就涉及到请求在多个系统之间来回转发，
如果没有一个全局的标识能够追踪单个业务调用，那么就会在发生业务故障时盲目查日志，造成问题定位困难。
如果我们能在系统间透明的传递一个全局唯一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！