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

朱雀 2022-03-09 04:25 196阅读 0赞

一、**打印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_afdd31bfbf94]  
[https://www.jianshu.com/p/06b1d35526c2][https_www.jianshu.com_p_06b1d35526c2]  
[https://blog.csdn.net/xiaolyuh123/article/details/80560662][https_blog.csdn.net_xiaolyuh123_article_details_80560662]  
[https://www.jianshu.com/p/3dca4aeb6edd][https_www.jianshu.com_p_3dca4aeb6edd]

[https_www.jianshu.com_p_afdd31bfbf94]: https://www.jianshu.com/p/afdd31bfbf94
[https_www.jianshu.com_p_06b1d35526c2]: https://www.jianshu.com/p/06b1d35526c2
[https_blog.csdn.net_xiaolyuh123_article_details_80560662]: https://blog.csdn.net/xiaolyuh123/article/details/80560662
[https_www.jianshu.com_p_3dca4aeb6edd]: https://www.jianshu.com/p/3dca4aeb6edd