日志排查问题困难分布式日志链路跟踪来帮你

作者：朱乐陶，软件架构师，具备多年 Java 开发及架构设计经验，擅长微服务领域
作者博客：https://blog.csdn.net/zlt2000

背景

开发排查系统问题用得最多的手段就是查看系统日志，在分布式环境中一般使用 ELK 来统一收集日志，但是在并发大时使用日志定位问题还是比较麻烦，由于大量的其他用户 / 其他线程的日志也一起输出穿行其中导致很难筛选出指定请求的全部相关日志，以及下游线程 / 服务对应的日志。

 

解决思路

每个请求都使用一个唯一标识来追踪全部的链路显示在日志中，并且不修改原有的打印方式 (代码无入侵)
使用 Logback 的 MDC 机制日志模板中加入 traceId 标识，取值方式为 %X{traceId}

MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。MDC 可以看成是一个与当前线程绑定的 Map，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据。

方案实现

由于 MDC 内部使用的是 ThreadLocal 所以只有本线程才有效，子线程和下游的服务 MDC 里的值会丢失；所以方案主要的难点是解决值的传递问题，主要包括以几下部分：

• API 网关中的 MDC 数据如何传递给下游服务
• 服务如何接收数据，并且调用其他远程服务时如何继续传递
• 异步的情况下 (线程池) 如何传给子线程

修改日志模板

logback 配置文件模板格式添加标识 %X{traceId}

网关添加过滤器

生成 traceId 并通过 header 传递给下游服务

@Component
public class TraceFilter extends ZuulFilter {
    @Autowired
    private TraceProperties traceProperties;

    @Override
    public String filterType() {return FilterConstants.PRE_TYPE;}

    @Override
    public int filterOrder() {return FORM_BODY_WRAPPER_FILTER_ORDER - 1;}

    @Override
    public boolean shouldFilter() {
        // 根据配置控制是否开启过滤器
        return traceProperties.getEnable();}

    @Override
    public Object run() {
        // 链路追踪 id
        String traceId = IdUtil.fastSimpleUUID();
        MDC.put(CommonConstant.LOG_TRACE_ID, traceId);
        RequestContext ctx = RequestContext.getCurrentContext();
        ctx.addZuulRequestHeader(CommonConstant.TRACE_ID_HEADER, traceId);
        return null;
    }
}

下游服务增加 spring 拦截器

接收并保存 traceId 的值
拦截器

public class TraceInterceptor implements HandlerInterceptor {
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {String traceId = request.getHeader(CommonConstant.TRACE_ID_HEADER);
        if (StrUtil.isNotEmpty(traceId)) {MDC.put(CommonConstant.LOG_TRACE_ID, traceId);
        }
        return true;
    }
}

注册拦截器

public class DefaultWebMvcConfig extends WebMvcConfigurationSupport {
  @Override
  protected void addInterceptors(InterceptorRegistry registry) {
    // 日志链路追踪拦截器
    registry.addInterceptor(new TraceInterceptor()).addPathPatterns("/**");

    super.addInterceptors(registry);
  }
}

下游服务增加 feign 拦截器

继续把当前服务的 traceId 值传递给下游服务

public class FeignInterceptorConfig {
    @Bean
    public RequestInterceptor requestInterceptor() {
        RequestInterceptor requestInterceptor = template -> {
            // 传递日志 traceId
            String traceId = MDC.get(CommonConstant.LOG_TRACE_ID);
            if (StrUtil.isNotEmpty(traceId)) {template.header(CommonConstant.TRACE_ID_HEADER, traceId);
            }
        };
        return requestInterceptor;
    }
}

解决父子线程传递问题

主要针对业务会使用线程池(异步、并行处理)，并且 spring 自己也有 @Async 注解来使用线程池，要解决这个问题需要以下两个步骤

重写 logback 的 LogbackMDCAdapter

由于 logback 的 MDC 实现内部使用的是 ThreadLocal 不能传递子线程，所以需要重写替换为阿里的 TransmittableThreadLocal

TransmittableThreadLocal 是 Alibaba 开源的、用于解决“在使用线程池等会缓存线程的组件情况下传递 ThreadLocal”问题的 InheritableThreadLocal 扩展。若希望 TransmittableThreadLocal 在线程池与主线程间传递，需配合 TtlRunnable 和 TtlCallable 使用。

TtlMDCAdapter 类

package org.slf4j;

import com.alibaba.ttl.TransmittableThreadLocal;
import org.slf4j.spi.MDCAdapter;

public class TtlMDCAdapter implements MDCAdapter {
    /**
     * 此处是关键
     */
    private final ThreadLocal<Map<String, String>> copyOnInheritThreadLocal = new TransmittableThreadLocal<>();

    private static TtlMDCAdapter mtcMDCAdapter;

    static {mtcMDCAdapter = new TtlMDCAdapter();
        MDC.mdcAdapter = mtcMDCAdapter;
    }

    public static MDCAdapter getInstance() {return mtcMDCAdapter;}

其他代码与 ch.qos.logback.classic.util.LogbackMDCAdapter 一样，只需改为调用 copyOnInheritThreadLocal 变量

TtlMDCAdapterInitializer 类用于程序启动时加载自己的 mdcAdapter 实现

public class TtlMDCAdapterInitializer implements ApplicationContextInitializer<ConfigurableApplicationContext> {
    @Override
    public void initialize(ConfigurableApplicationContext applicationContext) {
        // 加载 TtlMDCAdapter 实例
        TtlMDCAdapter.getInstance();}
}

扩展线程池实现

增加 TtlRunnable 和 TtlCallable 扩展实现 TTL

public class CustomThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {
    @Override
    public void execute(Runnable runnable) {Runnable ttlRunnable = TtlRunnable.get(runnable);
        super.execute(ttlRunnable);
    }

    @Override
    public <T> Future<T> submit(Callable<T> task) {Callable ttlCallable = TtlCallable.get(task);
        return super.submit(ttlCallable);
    }

    @Override
    public Future<?> submit(Runnable task) {Runnable ttlRunnable = TtlRunnable.get(task);
        return super.submit(ttlRunnable);
    }

    @Override
    public ListenableFuture<?> submitListenable(Runnable task) {Runnable ttlRunnable = TtlRunnable.get(task);
        return super.submitListenable(ttlRunnable);
    }

    @Override
    public <T> ListenableFuture<T> submitListenable(Callable<T> task) {Callable ttlCallable = TtlCallable.get(task);
        return super.submitListenable(ttlCallable);
    }
}

场景测试

测试代码如下

api 网关打印的日志

网关生成 traceId 值为 13d9800c8c7944c78a06ce28c36de670

请求跳转到文件服务时打印的日志

显示的 traceId 与网关相同，这里特意模拟发生异常的场景

ELK 聚合日志通过 traceId 查询整条链路日志

当系统出现异常时，可直接通过该异常日志的 traceId​的值，在日志中心中询该请求的所有日志信息

源码下载

附上我的开源微服务框架(包含本文中的代码)，欢迎 star 关注

https://gitee.com/zlt2000/mic…

<div>

<p align="center">
    <img src="https://www.fangzhipeng.com/img/avatar.jpg" width="258" height="258"/>
    <br>
    扫一扫，支持下作者吧
</p>
<p align="center" style="margin-top: 15px; font-size: 11px;color: #cc0000;">
    <strong>（转载本站文章请注明作者和出处 <a href="https://www.fangzhipeng.com"> 方志朋的博客 </a>）</strong>
</p>

</div>