Sleuth与服务调用日志收集

在SpringCloud中，官方推荐使用Sleuth与Zipkin实现日志的收集与可视化，本文将介绍一下日志收集的主要流程

注意: Zipkin仅对RPC通信过程进行记录，注意它与业务代码日志是无关的，如果你希望找到一款LogAppender来分析所有Log4j留下的日志，那么建议还是使用Kakfa+ELK这种传统的方法来实现。

术语

Span/Trace: 来自Google的Dapper论文，Span表示单个调用的间隔描述，Trace表示Span的集合，在Zipskin中作为Span的JSON数组
spring-cloud-starter-sleuth: 英文名是侦探，它的功能是在项目中自动为日志加入Tag与序列号
Zipkin: 来自Twitte的分布式日志收集工具，分为上传端(spring-cloud-starter-zipkin，集成到项目中)与服务端(独立部署，默认将数据存到内存中)

内部实现

综述

调用侧请求中加入额外的Span序列号等上下文信息放入Header中(通过注入Feign定制Client实现)
被调用侧通过全局Filter模拟AOP记录执行情况，计算执行情况与耗时，并存入定制的ByteBoundedQueue队列中，然后通过HTTP等将信息异步发送到Zipkin收集器中
Zipkin收集器通过UI显示调用详情

考虑到可能有通信的小伙伴，Zipkin实现与电话计费中的CDR(Call Detail Record, 呼叫详情记录)比较类似

使用前

假设有如下调用UpperCase的微服务调用，其中Feign是请求，UpperCaseService是被调用的微服务

sequenceDiagram
  	Feign-->>UpperCaseService: POST /uppercase?s=Test
    activate UpperCaseService
    UpperCaseService-->>Feign: HTTP 1.1/OK
    deactivate UpperCaseService

（上述过程具体可以去Feign中查看）

可以发现，如果服务出现异常/过载问题，我们只能配置Feign的LogLevel，翻本地Log文件了，效率比较低

使用Sleuth与Zip后

首先我们按照Tutorial搭建环境后，并在Zipkin上下载收集器后（此部分自行搭建），执行服务调用，在Zipkin的本地页面即可看到请求详细路线图。

总体修改后的流程如下

sequenceDiagram
  	Feign->>modifiedRequest: TraceFeignClient
  	modifiedRequest-->>TraceFilter: POST /uppercase?s=Test
  	TraceFilter->>UpperCaseService: 
    activate UpperCaseService
    UpperCaseService-->>Feign: HTTP 1.1/OK
    deactivate UpperCaseService
    TraceFilter->>Zipkin: async send log to collector

其中添加了如下组件

TraceFeignClient: 请求端注入的FeignClient，为Request的Header添加SpanID, TraceID等信息
TraceFilter: 接收端注入的定制Filter，它将解析Request中的Header，执行业务，计算耗时，最终算出一个完整的JSON格式的Span，通过队列异步发送到收集器ZipKin中
ZipKin: 日志收集器，读取JSON格式的SPAN信息，并存储与展示

源码分析

分析请求端源码，发现在请求端为Feign集成了新的Client，为请求加入了Span的Header编码

// add span http headers in http request
org.springframework.cloud.sleuth.instrument.web.client.feign.TraceFeignClient#execute

值得注意的是，这里添加Header是在Client中进行，而不是在Inteceptors中，因此就算Feign的日志级别配置为FULL，也无法看到真实发送的请求

分析接收端源码，发现新增了一个全局Filter以拦截Span请求，注意这里不是AOP，而是try/finally包装实现的

// org.springframework.cloud.sleuth.instrument.web.TraceFilter
@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse,
                     FilterChain filterChain) throws IOException, ServletException {
    //...
    String name = HTTP_COMPONENT + ":" + uri;
    Throwable exception = null;
    try {
        // parse Span headers from request
        spanFromRequest = createSpan(request, skip, spanFromRequest, name);
        // do business
        filterChain.doFilter(request, new TraceHttpServletResponse(response, spanFromRequest));
    } finally {
        // add span to Queue with BoundedAsyncReporter#report
        // it will be sent in another thread
        detachOrCloseSpans(request, response, spanFromRequest, exception);
    }
}

接收侧在AsyncReporter专门开了一个消费者线程，用于异步发送缓存的Span信息

// 接收侧通过新开一个线程消费队列（ByteBoundedQueue）
final Thread flushThread = new Thread("AsyncReporter{" + sender + "}") {
    @Override public void run() {
         //...
         // 循环执行 zipkin2.reporter.AsyncReporter.BoundedAsyncReporter#flush
         // 通过 Condition 进行阻塞轮循获取Filter刚刚放入的信息
         while (!result.closed.get()) {
             result.flush(consumer);
         }
         //...
    }
};

总的来说，还是一套比较复杂的方案，原理挺好懂，但是让自己来写队列，异步就困难了。

REFFERENCE

http://tech.lede.com/2017/04/19/rd/server/SpringCloudSleuth/
https://wu-sheng.github.io/me/articles/metrics-tracing-and-logging