一、背景
开发排查系统问题用得最多的手段就是查看系统日志,在分布式环境中一般使用ELK
来统一收集日志,但是在并发大时使用日志定位问题还是比较麻烦,由于大量的其他用户/其他线程的日志也一起输出穿行其中导致很难筛选出指定请求的全部相关日志,以及下游线程/服务对应的日志。
二、解决思路
- 每个请求都使用一个
唯一标识
来追踪全部的链路显示在日志中,并且不修改原有的打印方式(代码无入侵)
- 使用Logback的
MDC
机制日志模板中加入traceId
标识,取值方式为%X{traceId}
MDC(Mapped Diagnostic Context,映射调试上下文)是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。MDC 可以看成是一个与当前线程绑定的Map,可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时,只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说,通常是在请求被处理的最开始保存这些数据。
三、方案实现
由于MDC
内部使用的是ThreadLocal
所以只有本线程才有效,子线程和下游的服务MDC
里的值会丢失;所以方案主要的难点是解决值的传递问题。
3.1. 修改日志模板
logback配置文件模板格式添加标识%X{traceId}
3.2. 网关添加过滤器
生成traceId
并通过header传递给下游服务
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31
| @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() { String traceId = IdUtil.fastSimpleUUID(); MDC.put(CommonConstant.LOG_TRACE_ID, traceId); RequestContext ctx = RequestContext.getCurrentContext(); ctx.addZuulRequestHeader(CommonConstant.TRACE_ID_HEADER, traceId); return null; } }
|
3.3. 下游服务增加spring拦截器
接收并保存traceId
的值
拦截器
1 2 3 4 5 6 7 8 9 10
| 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; } }
|
注册拦截器
1 2 3 4 5 6 7 8 9
| public class DefaultWebMvcConfig extends WebMvcConfigurationSupport { @Override protected void addInterceptors(InterceptorRegistry registry) { registry.addInterceptor(new TraceInterceptor()).addPathPatterns("/**");
super.addInterceptors(registry); } }
|
3.4. 下游服务增加feign拦截器
继续把当前服务的traceId
值传递给下游服务
1 2 3 4 5 6 7 8 9 10 11 12 13
| public class FeignInterceptorConfig { @Bean public RequestInterceptor requestInterceptor() { RequestInterceptor requestInterceptor = template -> { String traceId = MDC.get(CommonConstant.LOG_TRACE_ID); if (StrUtil.isNotEmpty(traceId)) { template.header(CommonConstant.TRACE_ID_HEADER, traceId); } }; return requestInterceptor; } }
|
3.5. 扩展线程池
主要针对业务会使用线程池(异步、并行处理),并且spring
自己也有@Async
注解来使用线程池,所以需要扩展ThreadPoolTaskExecutor
线程池实现将父线程的MDC
内容复制给子线程
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55
| public class CustomThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {
@Override public void execute(Runnable runnable) { Map<String, String> mdcContext = MDC.getCopyOfContextMap(); super.execute(() -> run(runnable, mdcContext)); }
@Override public <T> Future<T> submit(Callable<T> task) { Map<String, String> mdcContext = MDC.getCopyOfContextMap(); return super.submit(() -> call(task, mdcContext)); }
private void run(Runnable runnable, String tenantId, Map<String, String> mdcContext) { if (mdcContext != null) { MDC.setContextMap(mdcContext); } try { runnable.run(); } finally { MDC.clear(); } }
private <T> T call(Callable<T> task, Map<String, String> mdcContext) throws Exception { if (mdcContext != null) { MDC.setContextMap(mdcContext); } try { return task.call(); } finally { MDC.clear(); } } }
|
四、场景测试
4.1. 测试代码如下
4.2. api网关打印的日志
网关生成traceId
值为13d9800c8c7944c78a06ce28c36de670
4.3. 请求跳转到文件服务时打印的日志
显示的traceId
与网关相同,这里特意模拟发生异常的场景
4.4. ELK聚合日志通过traceId
查询整条链路日志
当系统出现异常时,可直接通过该异常日志的traceId
的值,在日志中心中询该请求的所有日志信息
五、源码下载
附上我的开源微服务框架(包含本文中的代码),欢迎 star 关注
https://gitee.com/zlt2000/microservices-platform