基于Slf4j的MDC实现日志链路串联

Posted 2022-11-04 kuailefangyuan

基于Slf4j的MDC实现日志链路串联

一、问题背景

为了方便运维日常定位排查问题时，使用traceId查询日志时可以完整的查看当前业务请求的完整日志链路，需使用traceId（日志跟踪号）将日志串联起来。

系统采用LogBack日志组件，在输出日志时输出_traceId日志跟踪号，logback.xml配置如下：

<appender name="rollingFile"
	class="ch.qos.logback.core.rolling.RollingFileAppender">
	<file>../log/$ServerName/$AppName.log</file>
	<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
		<fileNamePattern>../log/$ServerName/$AppName.log.%dyyyy-MM-dd
		</fileNamePattern>
		<maxHistory>7</maxHistory>
	</rollingPolicy>
	<encoder>
		<pattern>%dHH:mm:ss.SSS %-5level [%.15thread][%X_traceId] %logger36 - %.-4096msg%n</pattern>
	</encoder>
</appender>

公司系统采用分布式架构，从接收到请求到业务处理完成并返回，涉及SpringMVC入口、服务间dubbo调用、基于RocketMQ实现的业务解耦、以及来自第三方渠道的http通知回调。

现在的问题是从业务请求入口到返回业务响应，如何使用同一traceId将日志做串联？

Slf4j的MDC机制提供了上述问题的解决方案。

二、解决方案

在介绍具体解决方案之前，首先介绍下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填充traceId
public static void initTraceFrom(RpcContext context) 
    String traceId = (String) context.getAttachment(TRACE_ID);
    if (traceId == null) 
        traceId = generateTraceId();
    
    setTraceId(traceId);


// 从RPCContext获取traceId
public 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。

//生产者填充traceId
public static void putTraceInto(MessageExt msg) 
    String traceId = getTraceId();
    if (traceId != null) 
        message.putUserProperty(TRACE_ID, traceId);;
    


//消费者获取traceId
public 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)