Java服务_分布式服务日志追踪工具MDC

发表于 | 分类于

Java服务_分布式服务日志追踪工具MDC

1.情景介绍

MDC 是解决分布式服务日志追踪方案中的有效工具。比如现在有个分布式的项目：alearner-api、alearner-service，该项目使用了阿里开源的框架dubbo，alearner-api作为consumer端，是和前端浏览器直接交互的模块，alearner-service作为provide端，是为consumer端提供一系列数据支持的模块。且consumer端和provide端均有多个实例部署在不同的主机上。基于以上情景，将会出现以下问题： 对于某一个固定的前端请求，在整个项目大流量访问的情况下，无法在后端的日志中精确的锁定该请求所涉及的日志，即无法快速准确的锁定该请求在consumer端和provide端的业务流程以及consumer端和provider端的对应逻辑。

映射的诊断上下文（简称MDC）就是用于区分来自不同源的交叉日志输出的工具。当服务器几乎同时处理多个客户端时，日志输出通常是交错的。 MDC基于每个线程进行管理。子线程自动继承其父级的映射诊断上下文的副本。

2.MDC介绍

Mapped Diagnostic Context(MDC)，以下是MDC类的注释，可以详细的说明该类的作用和应用场景：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
/*
* This class hides and serves as a substitute for the underlying logging
* system's MDC implementation.
*
* 该类隐藏并用作底层日志记录系统的MDC实现的替代。
*
* <p>
* If the underlying logging system offers MDC functionality, then SLF4J's MDC,
* i.e. this class, will delegate to the underlying system's MDC. Note that at
* this time, only two logging systems, namely log4j and logback, offer MDC
* functionality. For java.util.logging which does not support MDC,
* {@link BasicMDCAdapter} will be used. For other systems, i.e. slf4j-simple
* and slf4j-nop, {@link NOPMDCAdapter} will be used.
*
* 如果底层日志系统提供MDC功能，那么SLF4J的MDC，即这个类，将委托给底层系统的MDC。这次值得注意的
* 是，只有log4j和logback两个日志系统，提供MDC功能。对于不支持MDC的java.util.logging，将使用
* BasicMDCAdapter。对于其他系统，即slf4j-simple和slf4j-nop，NOPMDCAdapter
* 将被使用。
*
* <p>
* Thus, as a SLF4J user, you can take advantage of MDC in the presence of log4j,
* logback, or java.util.logging, but without forcing these systems as
* dependencies upon your users.
*
* 因此，作为SLF4J用户，您可以在存在log4j，logback或java.util.logging的情况下利用MDC，
* 但不必将这些系统强制为依赖于您的用户。
*
* <p>
* For more information on MDC please see the <a
* href="http://logback.qos.ch/manual/mdc.html">chapter on MDC</a> in the
* logback manual.
*
* <p>
* Please note that all methods in this class are static.
*
* 请注意，此类中的所有方法都是静态的。
*/

MDC类中的主要方法如下：

# 名称 返回值 作用
1 MDC() 无参构造
2 mdcAdapter MDCAdapter MDC适配器接口
3 MDCCloseable static class 静态内部类
4 put(String,String) void 向MDC中存放键值对
5 putCloseable(String,String) MDC.MDCCloseable 创建一个特定key值的MDCCloseable对象，并将key、val存放入MDC，当对象调用close()方法时MDC删除该key对应的键值对
6 get(String) String 获取某一特定key的值
7 remove(String) void 移除某一特定key的键值对
8 clear() void 清空所有储存的键值对
9 getCopyOfContextMap() Map<String, String> 获取MDC中所有的键值对
10 setContextMap(Map<String, String>) void 设置MDC的键值对
11 getMDCAdapter() MDCAdapter 获得MDC的适配器

3.ThreadLocal

MDC的本质是使用ThreadLocal来实现的，ThreadLoal变量，它的基本原理是，同一个ThreadLocal所包含的对象（对ThreadLocal< String >而言即为String类型变量），在不同的Thread中有不同的副本（实际是不同的实例）。这里有几点需要注意：

1）ThreadLocal类型的变量本质是一个被多线程线程共享的入口变量；

2）同一个ThreadLocal变量在不同线程中被使用时，实际上会创建一个独属于该线程的ThreadLocal对象；

3）ThreadLocal类内有一个静态内部类ThreadLocalMap，每个线程调用ThreadLocal变量时实际上是访问
该Map中独属于该线程的entry；

4）这个entry的key就是独属于该线程的ThreadLocal对象，线程通过本线程的ThreadLocal对象就可以拿到
这个entry，并将数据存储到该entry的value当中；

5）如果想要使一个线程在ThreadLocal中存储多个数据，可以创建多个ThreadLocal变量供一个线程使用；
也可以在一个ThreadLocal的属于自己的entry中存放一个复杂类型的对象，比如Map、List等。

ThreadLocal也存在两个问题：

1）线程复用脏读问题，比如线程池重用Thread对象，那么对应的ThreadLocal中残留的数据可能被脏读，所以最好在使用完毕之后显示手动删除存入ThreadLocal中的数据；

2）内存泄漏问题，ThreadLocalMap的entry中的key都是ThreadLocal对象，而ThreadLocal对象是弱引
用，entry中的value又是强引用，所以当ThreadLocal被垃圾回收时，value不会被释放，同理最好在使用完毕之后显示手动删除存入ThreadLocal中的数据。

总的来说，ThreadLocal 适用于每个线程需要自己独立的实例且该实例需要在多个方法中被使用，也即变量在线程间隔离而在方法或类间共享的场景。另外，在分布式日志追踪这个场景下，并非必须使用 ThreadLocal ，其它方式完全可以实现同样的效果，只是 ThreadLocal 使得实现更简洁。

4.MDC的使用

作为区分来自不同源的交叉日志输出的工具。以某一请求唯一标识uuid为例，我们将从系统接受前端请求设置MDC、MDC在多线程边界的处理、MDC在类似于RPC协议（Dubbo）上游的传输、MDC在RPC协议下游的接收四个方面作出介绍。

4.1 MDC的获取与设置

追踪某一特定请求的业务日志，自然是在请求之前就把uuid获取并且设置到，通常情况下，可以使用Filter或者Interceptor在请求之前完成对uuid的设置。

请求唯一标识uuid为例，我们将从系统接受前端请求设置MDC、MDC在类似于RPC协议（Dubbo）上游的传输、MDC在RPC协议下游的接收、MDC在多线程边界的处理四个方面以及这三个方面中需要注意的问题作出介绍。

设置日志格式

在application.yml中增加如下配置：

1
2
3
logging:
  pattern:
    level: ' %X{uuid:-uuid} %X{user:-user} %5p'

获取并设置

情景一：前端在request的header里添加uuid字段

1）使用Filter

获取uuid，为MDC设置uuid，请求结束后清空MDC均在doFilter方法中。特别注意，每次请求之后一定要清空MDC，即MDC.clear()。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
    LOGGER.info("Set MDC ");
    HttpServletRequest httpServletRequest = (HttpServletRequest) servletRequest;
    // 获取MDC
    String uuid = httpServletRequest.getHeader(REQUEST_ID);
    // 设置MDC
    MDC.put(REQUEST_ID,uuid);
    try{
        filterChain.doFilter(servletRequest, servletResponse);
    }finally {
        // 一次请求之后，清空MDC
        MDC.clear();
    }
}

2）使用Interceptor

获取uuid和设置MDC都在preHandle方法里，清空MDC在postHandle方法里。Interceptor的preHandle、postHandle、afterCompletion的生效时间和顺序自行Google。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
public class MdcInterceptor extends HandlerInterceptorAdapter {

    private static final String REQUEST_ID = "uuid";

    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        // 获取uuid
        String uuid = request.getHeader(REQUEST_ID);
        // 设置MDC
        MDC.put(REQUEST_ID,uuid);
        return true;
    }

    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, @Nullable ModelAndView modelAndView) throws Exception {
        // 请求结束后，清空MDC
        MDC.clear();
    }

    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, @Nullable Exception ex) throws Exception {
    }

}

情景二：客户端程序为每个请求主动生成uuid，并将uuid添加到response的header里

情景一有一个缺陷，就是不通过前端访问某一接口，而是直接通过链接访问该接口，那么前端便不会传输uuid字段。该种场景便解决了这个问题。

首先，我们在后端生成uuid：

1
2
// 获取uuid
String uuid= UUID.randomUUID().toString();

之后MDC设置完成uuid之后，将uuid字段放入response的header里

1
response.addHeader("uuid",uuid);

其他步骤同情景一类似，通过这样，我们便可以为任何途径进来的请求赋予一个uuid。

4.2 MDC在多线程边界的处理

前文我们提到，MDC数据的存储是通过ThreadLocal实现的，ThreadLocal之和当前线程相关。也就是意味着，当我们使用多线程的时候，由主线程切换到其他线程时，MDC的数据是不能主动跨线程的。因为ThreadLocal是只存在于单个线程中，所以我们在使用多线程时，应该在主线程切换到其他线程的边界传输我们MDC的值并在新的线程内重新赋值。

下面我们借助一个例子来说明：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
public class MultithreadMdc {

    private static final Logger LOGGER = LoggerFactory.getLogger(MultithreadMdc.class);

    private ExecutorService executorService = Executors.newCachedThreadPool();

    public Map UpperCaseStrList(Map<String, String> map) {
        LOGGER.info("UpperCaseStrList Method start");
        LOGGER.info("map = {}", map);
        Map<String, Future> res = new HashMap<>();
        map.forEach((k, v) -> {
            res.put(k, executorService.submit(new StringCallable(v)));
        });
        LOGGER.info("res = {}", res);
        return res;
    }

    private class StringCallable implements Callable<Object> {

        private final String str;

        private final Map<String, String> mdcMap;

        public StringCallable(String str) {
            this.str = str;
            mdcMap = MDC.getCopyOfContextMap();
        }

        @Override
        public Object call() throws Exception {
            LOGGER.info("call method start");
            LOGGER.info("before setContextMap in this thread , Map of MDC is {}", MDC.getCopyOfContextMap());
            LOGGER.info("***************************");
            MDC.setContextMap(mdcMap);
            LOGGER.info("after setContextMap in this thread , Map of MDC is {}", MDC.getCopyOfContextMap());
            String res = str.toUpperCase();
            LOGGER.info("str = {} , toUpperCase , res = {}", str, res);
            LOGGER.info("after MDC clear in this thread , Map of MDC is {}", MDC.getCopyOfContextMap());
            return res;
        }
    }
}

上述MultithreadMdc 类中，方法UpperCaseStrList中使用了多线程，其主线程与其他线程的边界为内部类StringCallable，笔者在多线程传输MDC的方法为：

  1. 自定义类的私有变量

    1
    private final Map<String, String> mdcMap;

  2. 在类的构造函数初始化mdcMap的值

    1
    2
    3
    4
    public StringCallable(String str) {
                ······(其他初始化过程)
                mdcMap = MDC.getCopyOfContextMap();
            }

  3. 在新线程一开始便设置MDC在新线程的值

    1
    2
    3
    4
    5
    6
    7
    @Override
    public Object call() throws Exception {
                MDC.setContextMap(mdcMap);
                ······(其他业务逻辑)
                return res;
            }
        }

在第三步过程中，假如系统要进行相关RPC的调用，MDC在RPC协议间的传输在某种方法下(比如使用RpcContext传输)也需要在多线程的边界进行，因为RpcContext和MDC一样，同样是依赖于ThreadLocal实现的。具体传输方法请看下一小节（MDC在RPC协议上游的传输）的情景二。

4.3 MDC在RPC协议上游的传输

MDC中的数据在RPC协议上的传输，笔者认为有两种方法：

DTO属性

在数据传输的过程中，通过DTO（数据传输对象）将MDC的值传过去，例如一个DTO为RpcParam，其定义如下，我们可以将MDC.getCopyOfContextMap()的值 通过set方法放入HeaderParam的mdc变量里传输

1
2
3
4
5
6
7
8
9
10
11
12
13
public class RpcParam{
    private HeaderParam headerParam;
    private Map Body;

    //There is Getter and Setter Code
}
public class HeaderParam{
    private String id;
    private String url;
    private Map<String,String> mdc;

    //There is Getter and Setter Code
}

RpcContext

对于不用rpc协议，RpcContext的实现略有不同，本质同样是依赖于ThreadLocal进行线程数据隔离与方法共享。以Dubbo为例，我们可以在系统的边界使用RpcContext来承载MDC数据。

1
RpcContext.getContext().setAttachment("uuid",uuid);

值得注意的是，假如rpc请求是在多线程中请求，即系统边界是在多线程里，那么我们仅仅使用上述的代码是足够的。但是，当我们的客户端程序是单线程的，一定要在一次请求之后或者下一次请求之前清空RpcContext，重新设置，防止数据污染。

清空RpcContext：

1
RpcContext.getContext().clearAttachments();

注意：当系统进行RPC调用的步骤是在多线程中时，对应的MDC放到RpcContext的传输需要放在多线程中，以上节的MultithreadMdc.java举例，对应的第三步传输的代码为

1
2
3
4
5
6
7
8
@Override
public Object call() throws Exception {
            MDC.setContextMap(mdcMap);
            ······(其他业务逻辑)
            RpcContext.getContext().setAttachment("uuid",MDC.get("uuid"));
            return res;
        }
    }

4.4 MDC在RPC协议下游的接收

根据MDC在RPC协议上游的传输的两种方法，对应的MDC接收有以下两种：

DTO属性

下游获取到RpcParam后，使用get取得HeaderParam成员变量，进而在使用get方法获取HeaderParam的mdc变量，最后使用：

1
MDC.setContextMap(mdc);

RpcContext

使用RpcContext来获取：

1
RpcContext.getContext().getAttachment("uuid");

参考文献

MDC - Mapped Diagnostic Context 上下文诊断映射