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

科技 06-14 来源：最爱小磨叽

一、问题背景

为了方便运维日常定位排查问题时，使用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机制提供了上述问题的解决方案。

二、解决方案

在介绍具体解决方案之前，首先介绍下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) {

}