一、问题背景
为了方便运维日常定位排查问题时,使用traceId查询日志时可以完整的查看当前业务请求的完整日志链路,需使用traceId(日志跟踪号)将日志串联起来。
系统采用LogBack日志组件,在输出日志时输出_traceId日志跟踪号,logback.xml配置如下:
../log/${ServerName}/${AppName}.log ../log/${ServerName}/${AppName}.log.%d{yyyy-MM-dd} 7 %d{HH:mm:ss.SSS} %-5level [%.15thread][%X{_traceId}] %logger{36} – %.-4096msg%n
公司系统采用分布式架构,从接收到请求到业务处理完成并返回,涉及SpringMVC入口、服务间dubbo调用、基于RocketMQ实现的业务解耦、以及来自第三方渠道的http通知回调。
现在的问题是从业务请求入口到返回业务响应,如何使用同一traceId将日志做串联?
二、解决方案
在介绍具体解决方案之前,首先介绍下Slf4j日志框架的MDC机制。映射诊断上下文(Mapped Diagnostic Context,简称MDC)可以简单理解为当前日志线程的上下文,也是一个k-v格式的map结构。
当服务器几乎同时处理多个请求时,日志输出通常是交错的,而MDC是基于每个线程进行管理的,子线程自动继承其父线程的MDC的副本。可以通过往MDC里塞入traceId,达到串联日志的目的。
以下为MDC填充获取traceId方法:
public final static String TRACE_ID = “_traceId”;static private String generateTraceId() { return UUID.randomUUID().toString().replaceAll(“-“, “”);}public static String getTraceId() { return MDC.get(TRACE_ID);}public static void setTraceId(String traceId) { MDC.put(TRACE_ID, traceId);}public static void clearTrace() { MDC.remove(TRACE_ID);}public static void initTrace() { String traceId = generateTraceId(); setTraceId(traceId);}
2.1、接收http请求时的日志链路串联
解决思路:可以从HttpServletRequest获取traceId并塞到MDC中。
具体如下:
public static void initTraceFromRequest(HttpServletRequest request) { String traceId; // 从前端表单提交里获取traceId traceId = request.getParameter(TRACE_ID); if (StringUtils.isNotBlank(traceId)) { setTraceId(traceId, request); return; } // 从forward后端转发请求里获取traceId traceId = (String) request.getAttribute(TRACE_ID); if (StringUtils.isNotBlank(traceId)) { setTraceId(traceId, request); return; } // 从请求url路径中里获取traceId Map pathVariables = (Map) request.getAttribute(HandlerMapping.URI_TEMPLATE_VARIABLES_ATTRIBUTE); if (pathVariables != null) { traceId = (String) pathVariables.get(TRACE_ID); } if (StringUtils.isNotBlank(traceId)) { setTraceId(traceId, request); return; } // 以上都获取不到的话,就生成一个traceId并填充到MDC以及Session中 traceId = generateTraceId(); setTraceId(traceId, request);}
具体解决方案:使用SpringMVC拦截器机制拦截所有web请求,获取并串联traceId。
public class LogTraceInterceptor extends HandlerInterceptorAdapter { @Autowired private ConfigBean configBean; @Override public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception { if(handler instanceof HandlerMethod) { TraceUtil.initTraceFrom(request); } return true; } @Override public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception { }}
实际测试时发现如下问题:
后台controller间有redirect重定向或forward转发跳转时,跳转前后的日志traceId没有串联上。
分析如下:
- 1、redirect重定向前后是两个不同的request,就算拦截器拦截到也是跳转后的request,没法串联上跳转前的traceId。
- 2、forward转发前后是同一个request,但是不同于redirect重定向跳转,forward跳转系服务器内部跳转,不经过拦截器,依旧无法串联traceId。
针对上述问题,解决方案如下:
1、针对redirect跳转,将traceId存到session中,通过session串联traceId。
traceId = (String)request.getSession().getAttribute(DataConstants.TRACE_ID);if(StringUtils.isNotBlank(traceId)) { setTraceId(traceId, request); return;}
2、针对forward跳转,由于是服务器内部跳转,没有找到可用的拦截手段,只能在forward转发后的controller入口处主动调用initTraceFromRequest()方法,从request中获取traceId。
2.2、dubbo调用间的日志链路串联
解决思路:dubbo调用一样有上下文的概念RpcContext,可以将traceId塞到RpcContext中达到dubbo调用间传递traceId。
具体如下:
// 往RPCContext填充traceIdpublic static void initTraceFrom(RpcContext context) { String traceId = (String) context.getAttachment(TRACE_ID); if (traceId == null) { traceId = generateTraceId(); } setTraceId(traceId);}// 从RPCContext获取traceIdpublic static void putTraceInto(RpcContext context) { String traceId = getTraceId(); if (traceId != null) { context.setAttachment(TRACE_ID, traceId); }}
具体解决方案:使用Filter过滤器拦截dubbo调用,获取或填充traceId。
public class TraceDubboFilter implements Filter { @Override public Result invoke(Invoker invoker, Invocation invocation) throws RpcException { RpcContext context = RpcContext.getContext(); if (context.isConsumerSide()) { TraceUtil.putTraceInto(context); } else if (context.isProviderSide()) { TraceUtil.initTraceFrom(context); } return invoker.invoke(invocation); }}
3.3、MQ异步处理时的日志链路串联
解决思路:RocketMQ消息可以通过MessageExt.getUSerProperty()/setUserProperty()来获取或设置traceid。
//生产者填充traceIdpublic static void putTraceInto(MessageExt msg) { String traceId = getTraceId(); if (traceId != null) { message.putUserProperty(TRACE_ID, traceId);; }}//消费者获取traceIdpublic static void initTraceFrom(MessageExt msg) { String traceId = msg.getUserProperty(TRACE_ID); if (traceId == null) { traceId = generateTraceId(); } setTraceId(traceId);}
具体解决方案:使用RocketMQ的消息过滤器MessageFilter统一拦截消息,获取traceId。
public class MessageFilterImpl implements MessageFilter{ public boolean match(MessageExt msg, FilterContext arg1) { initTraceFrom(msg); return true; }}
3.4、http调用第三方服务时回调串联traceId
解决思路:在上送给第三方的通知回调地址url中拼上_traceId
具体解决方案如下:
@RequestMapping(“/notify.do/{orderId}/{createTime}/{_traceId}”)public void receiveNotify(HttpServletRequest request, HttpServletResponse response, @PathVariable(“orderId”) String id, @PathVariable(“createTime”) String time, @PathVariable(“_traceId”) String traceId) {}