基于SLF4J MDC机制实现日志的链路追踪

一、打印HTTP request body和response body实现日志跟踪

request 的inputStream和response 的outputStream默认情况下是只能读一次， 不可重复读；这就导致要获取请求体或者响应体信息时必须要声明包裹类wrapper; spring为此提供了两个对应的包裹类ContentCachingRequestWrapper和ContentCachingResponseWrapper使得这两个流信息可重复读；

可以利用这两个类结合spring的WebUtil工具类来实现日志跟踪：

import lombok.extern.slf4j.Slf4j;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;
import org.springframework.web.util.ContentCachingRequestWrapper;
import org.springframework.web.util.ContentCachingResponseWrapper;
import org.springframework.web.util.WebUtils;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.annotation.WebFilter;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.io.UnsupportedEncodingException;
import java.util.Enumeration;
import java.util.UUID;

/**
 * @author: liumengbing
 * @date: 2019/03/12 10:10
 **/
@Component
@Slf4j
@WebFilter("/*")
public class WebLogFilter extends OncePerRequestFilter {

    private static Logger log = LoggerFactory.getLogger(WebLogFilter.class);

    public static final String SPLIT_STRING_M = "=";

    public static final String SPLIT_STRING_DOT = ", ";


    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        //日志trade
        MDC.clear();
        //使用唯一ID标识每次请求
        MDC.put("trade_id", UUID.randomUUID().toString().replaceAll("-",""));
        ContentCachingRequestWrapper wrapperRequest = new ContentCachingRequestWrapper(request);
        ContentCachingResponseWrapper wrapperResponse = new ContentCachingResponseWrapper(response);

        String urlParams = getRequestParams(request);
        log.info("request params[{}]", urlParams);
        filterChain.doFilter(wrapperRequest, wrapperResponse);

        String requestBodyStr = getRequestBody(wrapperRequest);
        log.info("request body:{}", requestBodyStr);

        String responseBodyStr = getResponseBody(wrapperResponse);

        log.info("response body:{}", responseBodyStr);
        wrapperResponse.copyBodyToResponse();
    }

    /**
     * 获取请求地址上的参数
     * @param request
     * @return
     */
    public static String getRequestParams(HttpServletRequest request) {
        StringBuilder sb = new StringBuilder();
        Enumeration<String> enu = request.getParameterNames();
        //获取请求参数
        while (enu.hasMoreElements()) {
            String name = enu.nextElement();
            sb.append(name + SPLIT_STRING_M).append(request.getParameter(name));
            if(enu.hasMoreElements()) {
                sb.append(SPLIT_STRING_DOT);
            }
        }
        return sb.toString();
    }

    /**
     * 打印请求参数
     * @param request
     */
    private String getRequestBody(ContentCachingRequestWrapper request) {
        ContentCachingRequestWrapper wrapper = WebUtils.getNativeRequest(request, ContentCachingRequestWrapper.class);
        if(wrapper != null) {
            byte[] buf = wrapper.getContentAsByteArray();
            if(buf.length > 0) {
                String payload;
                try {
                    payload = new String(buf, 0, buf.length, wrapper.getCharacterEncoding());
                } catch (UnsupportedEncodingException e) {
                    payload = "[unknown]";
                }
                return payload.replaceAll("\\n","");
            }
        }
        return "";
    }

    /**
     * 打印返回参数
     * @param response
     */
    private String getResponseBody(ContentCachingResponseWrapper response) {
        ContentCachingResponseWrapper wrapper = WebUtils.getNativeResponse(response, ContentCachingResponseWrapper.class);
        if(wrapper != null) {
            byte[] buf = wrapper.getContentAsByteArray();
            if(buf.length > 0) {
                String payload;
                try {
                    payload = new String(buf, 0, buf.length, wrapper.getCharacterEncoding());
                } catch (UnsupportedEncodingException e) {
                    payload = "[unknown]";
                }
                return payload;
            }
        }
        return "";
    }

}

在以上代码中还有一个技术点：使用了slf4j的MDC来跟踪请求信息，打印完整的请求处理日志；并在日志配置中加上了唯一ID，从而达到日志追踪的目的。

日志配置文件：

[%X{trade_id}]%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n

输出的日志信息：

[16fbd9304e23492cab3ccabb6a85d0c0]2019-03-12 10:40:49.127  INFO 13712 --- [nio-8188-exec-1] xxx.xx.xx.filter.WebLogFilter       : request params[{}]：account=xxxxx,  v_code=056036}
[16fbd9304e23492cab3ccabb6a85d0c0]2019-03-12 10:40:49.130  INFO 13712 --- [nio-8188-exec-1] xxx.xx.xx.filter.WebLogFilter       : request body:{}：{    "account":"xxxxx",  "v_code":"056036"}
[16fbd9304e23492cab3ccabb6a85d0c0]2019-03-12 10:40:49.131  INFO 13712 --- [nio-8188-exec-1] xxx.xx.xx.filter.WebLogFilter       : response body:{}：{"code":1,"msg":"请输入正确的验证码","data":"","success":false}

二、基于SLF4J MDC机制实现日志的链路追踪

问题引入：

系统上线之后，我们可能经常需要进行线上问题排查，排查问题必须用到的方式就是查看日志，但是在分布式系统中，各种无关日志穿行其中，导致我们没办法快速定位用户在某一次请求中的所有日志。因此，我们可能需要对一个用户的操作流程进行归类标记，比如使用线程+时间戳，或者用户身份标识等方式。这样的话，我们就可以从大量日志信息中grep出某个用户的操作流程，或者某个时间的流转记录，从而便于我们诊断线上问题。

解决方案：

1.在每次请求的时候，获取到请求的sessionId，或者自己生成一个伪sessionId，在每次输出日志的时候将这个sessionId连同日志信息一起输出。这个方式实现起来非常简单，但是代码侵入性强，每次输出的时候都需要额外多输出一个参数，重复且工作量大，但是可控粒度高；
2.使用LogBack的MDC机制，在日志模板中加入sessionId，如上面我们使用到的：

[%X{trade_id}]%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n

这种方式工作量小，代码侵入小，易扩展，但是可控粒度较低。

方案一：

logger.info("sessionId: {}, message: {}", sessionId, "日志信息");

方案二（以springmvc为例）：

1、新建一个日志拦截器，拦截所有的请求，在处理请求前将sessionId放到MDC中，处理完请求之后清除MDC中的内容。这就解决了80%的问题；
2、在旧版本中新启线程时MDC会自动将父线程的MDC内容复制给子线程，因为MDC内部使用的是InheritableThreadLocal，但是因为性能问题在最新的版本中被取消了，所以子线程不会自动获取父线程MDC的内容。官方建议我们在父线程新建子线程之前调用MDC.getCopyOfContextMap()方法将父线程的MDC内容取出传给子线程，子线程在执行操作之前先调用MDC.setContextMap()方法将父线程的MDC内容设置到子线程中去。
3、设置日志输出格式

[%X{trade_id}]%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n

MDC对外提供的方法：

package org.slf4j;
public class MDC {
  // 将一个K-V的键值对放到容器，其实是放到当前线程的ThreadLocalMap中
  public static void put(String key, String val);
  // 根据key在当前线程的MDC容器中获取对应的值
  public static String get(String key);
  // 根据key移除容器中的值
  public static void remove(String key);
  // 清空当前线程的MDC容器
  public static void clear();
}

MDC实现原理：

Slf4j 的实现原则就是调用底层具体实现类，比如logback,log4j等包；而不会去实现具体的输出打印等操作。这里使用了装饰者模式，看源码就能看出来，所有的方法都是在对mdcAdapter 这个属性进行操作。所以实现核心是MDCAdapter类。

public interface MDCAdapter {
    public void put(String key, String val);
    public String get(String key);
    public void remove(String key);
    public void clear();
    public Map<String, String> getCopyOfContextMap();
    public void setContextMap(Map<String, String> contextMap);
}

MDCAdapter有三个实现类：BasicMDCAdapter、LogbackMDCAdapter，NOPMDCAdapter。其中Logback使用的是LogbackMDCAdapter。通过查看源码发现它们的底层都是使用ThreadLocal实现的，这里不再具体分析源码，有兴趣的可以自己去看一下。

参考资料：
https://www.jianshu.com/p/afdd31bfbf94
https://www.jianshu.com/p/06b1d35526c2
https://blog.csdn.net/xiaolyuh123/article/details/80560662
https://www.jianshu.com/p/3dca4aeb6edd