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

参考资料

谷歌dapper论文中文译文