一个现网bug让我彻底弄懂微服务日志链路追踪
需求：
异步帮批量用户订购话费套餐，成功发送短信，失败记录信息。
问题描述：
根据运营人员及测试反馈最近有一批500个账户的套餐开通中，失败数+成功数=499，还有一笔订单凭空消失了，因为采用的是异步线程处理订单，因此日志很难定位。
问题解决：
尝试1：
公司程序采用的是springcloud微服务框架采用sleuth日志链路跟踪，由于是异步线程，因此根据traceid查找只能跟踪到主线程日志，因此我决定显示的在线程执行订购操作的前后打印日志，将traceid作为参数传入：
log.debug("tracid批量白名单订购={}，调用单个订购号码={}",traceid,l.getUseraccount());
JsonResult res = whiteListProductOrder(useraccount, l.getProductid(), batchno,
task.getPartnerId());
log.debug("tracid批量白名单订购={}，调用单个订购号码={},返回结果={}",traceid,l.getUseraccount(),res.getMessage().toString());可是事与愿违，打印的仅仅只有这两句，中间的过程日志还是无法追踪。
尝试2：
有问题找度娘，度娘说sleuth有子线程日志追踪功能，需要显示开启如下配置：
static {
System.setProperty("log4j2.isThreadContextMapInheritable", "true");
}
结果可想而知，一样无功而返。
尝试3：
日志追踪MDC:
MDC ( Mapped Diagnostic Contexts ) 有了日志之后，我们就可以追踪各种线上问题。但是，在分布式系统中，各种无关日志 穿 行其中，导致我们可能无法直接定位整个操作流程。因此，我们可能需要对一个用户的操作流程进行归类标记，比如使用线程+时间戳，或者用户身份标识等；如此，我们可以从大量日志信息中grep出某个用户的操作流程，或者某个时间的流转记录。其目的是为了便于我们诊断线上问题而出现的方法工具类。虽然，Slf4j 是用来适配其他的日志具体实现包的，但是针对 MDC功能，目前只有logback 以及 log4j 支持。
MDC原理：
简而言之，MDC就是日志框架提供的一个InheritableThreadLocal，项目代码中可以将键值对放入其中，然后使用指定方式取出打印即可。
InheritableThreadLocal:
InheritableThreadLocal主要用于子线程创建时，需要自动继承父线程的ThreadLocal变量，方便必要信息的进一步传递。
看着上述概念，好像和我们的问题还蛮契合，胆的去失败吧，反正你现在也没成功。
初步实现
首先创建拦截器，加入拦截列表中，在请求到达时生成traceId。当然你还可以根据需求在此处后或后续流程中放入spanId、订单流水号等需要打印的信息。
public class Constants {
/**
* 日志跟踪id名。
*/
public static final String LOG_TRACE_ID = "traceid";
/**
* 请求头跟踪id名。
*/
public static final String HTTP_HEADER_TRACE_ID = "app_trace_id";
}
import org.slf4j.MDC;
public class TraceInterceptor extends HandlerInterceptorAdapter {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
// "traceId"
MDC.put(Constants.LOG_TRACE_ID, TraceLogUtils.getTraceId());
return true;
}
}
然后在日志配置xml文件中添加traceId打印：
<property name="normal-pattern" value="[%p][%d{yyyy-MM-dd'T'HH:mm:ss.SSSZ,Asia/Shanghai}][%X{traceid}][%15.15t][%c:%L] %msg%n"/>
1
初步改造完成！是不是感觉还挺简单的？且慢，仅仅这样的改造在实际使用过程中会遇到以下问题：
线程池中的线程会打印错误的traceId
调用下游服务后会生成新的traceId，无法继续跟踪
下面来一一解决这些问题。
支持线程池跟踪
MDC使用的InheritableThreadLocal只是在线程被创建时继承，但是线程池中的线程是复用的，后续请求使用已有的线程将打印出之前请求的traceId。这时候就需要对线程池进行一定的包装，在线程在执行时读取之前保存的MDC内容。不仅自身业务会用到线程池，spring项目也使用到了很多线程池，比如@Async异步调用，zookeeper线程池、kafka线程池等。不管是哪种线程池都大都支持传入指定的线程池实现，拿@Async举例：
@Bean("SpExecutor")
public Executor getAsyncExecutor() {
// 对线程池进行包装，使之支持traceId透传
ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor() {
@Override
public <T> Future<T> submit(Callable<T> task) {
// 传入线程池之前先复制当前线程的MDC
return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public void execute(Runnable task) {
super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
};
executor.setCorePoolSize(config.getPoolCoreSize());
... // 其他配置
executor.initialize();
return executor;
}
public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {
return new Callable<T>() {
@Override
public T call() throws Exception {
// 实际执行前导入对应请求的MDC副本
if (context == null) {
MDC.clear();
} else {
MDC.setContextMap(context);
}
if (MDC.get(Constants.LOG_TRACE_ID) == null) {
MDC.put(Constants.LOG_TRACE_ID, TraceLogUtils.getTraceId());
}
try {
return callable.call();
} finally {
MDC.clear();
}
}
};
}
ThreadPoolExecutor的包装也类似，注意为了严谨考虑，需要对连接池中的所有调用方法进行封装。
在ThreadPoolExecutor中有：
public void execute(Runnable command)
public <T> Future<T> submit(Callable<T> task)
public Future<?> submit(Runnable task)
public <T> Future<T> submit(Runnable task, T result)
在ThreadPoolTaskExecutor中有：
public void execute(Runnable command)
public void execute(Runnable task, long startTimeout)
public Future<?> submit(Runnable task)
public <T> Future<T> submit(Runnable task, T result)
public <T> ListenableFuture<T> submitListenable(Callable<T> task)
public ListenableFuture<?> submitListenable(Runnable task)
方式与上述的实现类似，不做赘述。
提供一下我的工具类：
public class ThreadMdcUtil {
public static void setTraceIdIfAbsent() {
if (MDC.get(Constants.LOG_TRACE_ID) == null) {
MDC.put(Constants.LOG_TRACE_ID, TraceLogUtils.getTraceId());
}
}
public static void setTraceId() {
MDC.put(Constants.LOG_TRACE_ID, TraceLogUtils.getTraceId());
}
public static void setTraceId(String traceId) {
MDC.put(Constants.LOG_TRACE_ID, traceId);
}
public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {
return () -> {
if (context == null) {
MDC.clear();
} else {
MDC.setContextMap(context);
}
setTraceIdIfAbsent();
try {
return callable.call();
} finally {
MDC.clear();
}
};
}
public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {
return () -> {
if (context == null) {
MDC.clear();
} else {
MDC.setContextMap(context);
}
setTraceIdIfAbsent();
try {
runnable.run();
} finally {
MDC.clear();
}
};
}
public static class ThreadPoolTaskExecutorMdcWrapper extends ThreadPoolTaskExecutor {
@Override
public void execute(Runnable task) {
super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public void execute(Runnable task, long startTimeout) {
super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), startTimeout);
}
@Override
public <T> Future<T> submit(Callable<T> task) {
return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public Future<?> submit(Runnable task) {
return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public ListenableFuture<?> submitListenable(Runnable task) {
return super.submitListenable(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public <T> ListenableFuture<T> submitListenable(Callable<T> task) {
return super.submitListenable(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
}
public static class ThreadPoolExecutorMdcWrapper extends ThreadPoolExecutor {
public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
BlockingQueue<Runnable> workQueue) {
super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
}
public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory) {
super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory);
}
public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
BlockingQueue<Runnable> workQueue, RejectedExecutionHandler handler) {
super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, handler);
}
public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory,
RejectedExecutionHandler handler) {
super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
}
@Override
public void execute(Runnable task) {
super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public <T> Future<T> submit(Runnable task, T result) {
return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), result);
}
@Override
public <T> Future<T> submit(Callable<T> task) {
return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public Future<?> submit(Runnable task) {
return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
}
public static class ForkJoinPoolMdcWrapper extends ForkJoinPool {
public ForkJoinPoolMdcWrapper() {
super();
}
public ForkJoinPoolMdcWrapper(int parallelism) {
super(parallelism);
}
public ForkJoinPoolMdcWrapper(int parallelism, ForkJoinWorkerThreadFactory factory,
Thread.UncaughtExceptionHandler handler, boolean asyncMode) {
super(parallelism, factory, handler, asyncMode);
}
@Override
public void execute(Runnable task) {
super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public <T> ForkJoinTask<T> submit(Runnable task, T result) {
return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), result);
}
@Override
public <T> ForkJoinTask<T> submit(Callable<T> task) {
return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
}
}
}
下游服务使用相同traceId
以上方式在多级服务调用中每个服务都会生成新的traceId，导致无法衔接跟踪。这时就需要对http调用工具进行相应的改造了，在发送http请求时自动将traceId添加到header中，以RestTemplate为例，注册拦截器：
// 以下省略其他相关配置
RestTemplate restTemplate = new RestTemplate();
// 使用拦截器包装http header
restTemplate.setInterceptors(new ArrayList<ClientHttpRequestInterceptor>() {
{
add((request, body, execution) -> {
String traceId = MDC.get(Constants.LOG_TRACE_ID);
if (StringUtils.isNotEmpty(traceId)) {
request.getHeaders().add(Constants.HTTP_HEADER_TRACE_ID, traceId);
}
return execution.execute(request, body);
});
}
});
HttpComponentsClientHttpRequestFactory factory = new HttpComponentsClientHttpRequestFactory();
// 注意此处需开启缓存，否则会报getBodyInternal方法“getBody not supported”错误
factory.setBufferRequestBody(true);
restTemplate.setRequestFactory(factory);
下游服务的拦截器改为：
public class TraceInterceptor extends HandlerInterceptorAdapter {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
String traceId = request.getHeader(Constants.HTTP_HEADER_TRACE_ID);
if (StringUtils.isEmpty(traceId)) {
traceId = TraceLogUtils.getTraceId();
}
MDC.put(Constants.LOG_TRACE_ID, traceId);
return true;
}
}
若使用自定义的http客户端，则直接修改其工具类即可。
针对其他协议的调用暂无实践经验，可以借鉴上面的思路，通过拦截器插入特定字段，再在下游读取指定字段加入MDC中。
总结
实现日志跟踪的基本方案没有太大难度，重在实践中发现问题并一层一层解决问题的思路。
6322
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
