Java使用MDC实现日志追踪

Java, Spring Boot / 作者： / / 发表评论 / Java, LogbackMDCAdapter, MDC, MDCAdapter, MDC全局链路追踪实现, MDC原理, MDC源码解读, 使用MDC实现日志追踪, 全局链路追踪, 多线程日志追踪, 实现日志追踪, 日志追踪

在目前的微服务体系中，服务应用多，调用链复杂，相应的排查问题的难度也随之上升。当应用发生异常时，我们需要快速定位问题日志，这就需要我们对请求链路进行追踪，在请求到达系统时产生一个能够标识整个请求生命周期的ID。

一、MDC简介

MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能，也可以说是一种轻量级的日志跟踪工具。可以粗略的理解成是一个线程安全的存放诊断日志的容器。

logback官方链接：http://logback.qos.ch/manual/mdc.html

二、MDC快速入门

先看看MDC 基本的 API 的用法，如下例子根据官方案例改编。

1、代码示例

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import java.util.UUID;

/**
 * MDC快速入门示例
 */public class SimpleMDC {

    private static final Logger logger = LoggerFactory.getLogger(SimpleMDC.class);
    public static final String REQ_ID = "REQ_ID";

    public static void main(String[] args) {
        MDC.put(REQ_ID, UUID.randomUUID().toString());
        logger.info("开始调用服务A，进行业务处理");
        logger.info("业务处理完毕，可以释放空间了，避免内存泄露");
        MDC.remove(REQ_ID);
        logger.info("REQ_ID 还有吗？{}", MDC.get(REQ_ID) != null);
    }
}

2、logback配置

接下来配置 logback.xml，通过 %X{REQ_ID} 来打印 REQ_ID 的信息，logback.xml 文件内容如下：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>[%t] [%X{REQ_ID}] - %m%n</Pattern>
        </layout>
    </appender>
    <root level="debug">
        <appender-ref ref="CONSOLE"/>
    </root>
</configuration>

3、引入依赖包

<dependencies>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>1.7.7</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-core</artifactId>
        <version>1.2.3</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-access</artifactId>
        <version>1.2.3</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>1.2.3</version>
    </dependency>
</dependencies>

4、运行效果

程序跑起来，输出截图如下：

Java使用MDC实现日志追踪插图

5、结果分析

根据输出结果分析，能够得到两条结论：

  • 第一：如图中红色圈住部分所示，当 logback 内置的日志字段不能满足业务需求时，便可以借助 MDC 机制，将业务上想要输出的信息，通过 logback 给打印出来；
  • 第二：如蓝色圈住部分所示，当调用 MDC.remove(Key) 后，便可将业务字段从 MDC 中删除，日志中就不再打印请求 ID 啦；

三、MDC原理

通过快速入门的程序，得知 MDC 的值与线程是绑定在一起的，不同线程互不影响，MDC 背后到底是怎么实现的呢？原理如下：

  • a）MDC 提供的 put 方法，可以将一个 K-V 的键值对放到容器中，并且能保证同一个线程内，Key 是唯一的，不同的线程 MDC 的值互不影响；
  • b）在 logback.xml 中，在 layout 中可以通过声明 %X{REQ_ID} 来输出 MDC 中 REQ_ID 的信息；
  • c）MDC 提供的 remove 方法，可以清除 MDC 中指定 key 对应的键值对信息。

四、MDC源码解读

解读源码之前，要提提 SLF4J，全称是 Simple Logging Facade for Java，翻译过来就是「一套简单的日志门面」。是为了让研发人员在项目中切换日志组件的方便，特意抽象出的一层。

1、SLF4J

项目开发中经常这么定义日志对象：

Logger logger = LoggerFactory.getLogger(SimpleMDC.class)

其中 Logger 就来自于 SLF4J 的规范包，项目中一旦这样定义 Logger，在底层就可以无缝切换 logback、log4j 等日志组件啦，这或许就是 Java 为什么要提倡要面向接口编程的好处。

通过 org.slf4j.MDC 的源码，可以很清楚的知道 MDC 主要是通过 MDCAdapter 来完成 put、get、remove 等操作。

Java使用MDC实现日志追踪插图2

不出所料 MDCAdapter 也是个接口。在 Java 的世界里，应该都知道定义接口的目的：就是为了定义规范，让子类去实现。

2、MDCAdapter

MDCAdapter 就和 JDBC 的规范类似，专门用于定义操作规范。JDBC 是为了定义数据库操作规范，让数据库厂商（MySQL、DB2、Oracle 等）去实现；而 MDCAdapter 则是让具体的日志组件（logback、log4j等）去实现。

public interface MDCAdapter {
    // 获取当前线程MDC上下文中指定key的值
    void put(String var1, String var2);
// 往当前线程MDC上下文中
    String get(String var1);
// 移除当前线程MDC上下文中指定key的键值
    void remove(String var1);
// 清空MDC上下文
    void clear();
// 获取MDC上下文
    Map<String, String> getCopyOfContextMap();
// 设置MDC上下文呢
    void setContextMap(Map<String, String> var1);
}
Java使用MDC实现日志追踪插图4

3、MDCAdapter接口的实现类

MDCAdapter 接口的实现类，有 NOPMDCAdapter、BasicMDCAdapter、LogbackMDCAdapter 以及 Log4jMDCAdapter 等等几种，其中 log4j 使用的是 Log4jMDCAdapter，而 Logback 使用的是 LogbackMDCAdapter。

Java使用MDC实现日志追踪插图6

4、LogbackMDCAdapter

1）LogbackMDCAdapter的源码

public class LogbackMDCAdapter implements MDCAdapter {
    final ThreadLocal<Map<String, String>> copyOnThreadLocal = new ThreadLocal();
    private static final int WRITE_OPERATION = 1;
    private static final int MAP_COPY_OPERATION = 2;
    final ThreadLocal<Integer> lastOperation = new ThreadLocal();

    public LogbackMDCAdapter() {
    }
    ...
}

可以看到LogbackMDC声明了类型为ThreadLocal的map。ThreadLocal 提供了线程本地的实例。它与普通变量的区别在于，每个使用该变量的线程都会初始化一个完全独立的实例副本，也就是说ThreadLocal变量在线程之间隔离而在方法或类间能够共享。

2）LogbackMDCAdapter中的put()

public void put(String key, String val) throws IllegalArgumentException {
    if (key == null) {
        throw new IllegalArgumentException("key cannot be null");
    } else {
        Map<String, String> oldMap = (Map)this.copyOnThreadLocal.get();
        Integer lastOp = this.getAndSetLastOperation(1);
        if (!this.wasLastOpReadOrNull(lastOp) && oldMap != null) {
            oldMap.put(key, val);
        } else {
            Map<String, String> newMap = this.duplicateAndInsertNewMap(oldMap);
            newMap.put(key, val);
        }
    }
}

校验并把键值设值到ThreadLocal的容器中

3）duplicateAndInsertNewMap()

private Map<String, String> duplicateAndInsertNewMap(Map<String, String> oldMap) {
    Map<String, String> newMap = Collections.synchronizedMap(new HashMap());

    if (oldMap != null) {
        synchronized(oldMap) {
            newMap.putAll(oldMap);
        }
    }

    this.copyOnThreadLocal.set(newMap);
    return newMap;
}

创建线程安全的HashMap作为容器，并放到ThreadLocal中

4）完整代码

Java使用MDC实现日志追踪插图8

通过图中标注 1、2 的代码，可以清晰的知道 MDC 底层最终使用的是 ThreadLocal 来进行的实现：

  • a）ThreadLocal 很多地方叫做线程本地变量，也有些地方叫做线程本地存储。
  • b）ThreadLocal 的作用是提供线程内的局部变量，这种变量在线程的生命周期内起作用，减少同一个线程内多个函数或者组件之间一些公共变量的传递的复杂度。
  • c）ThreadLocal 使用场景为用来解决数据库连接、Session 管理等。

五、MDC能干什么

MDC 的应用场景其实蛮多的，下面简单列举几个：

  • a）在 WEB 应用中，如果想在日志中输出请求用户 IP 地址、请求 URL、统计耗时等等，MDC 基本都能支撑；
  • b）在 WEB 应用中，如果能画出用户的请求到响应整个过程，势必会快速定位生产问题，那么借助 MDC 来保存用户请求时产生的 reqId，当请求完成后，再将这个 reqId 进行移除，这么一来通过 grep reqId 就能轻松 get 整个请求流程的日志轨迹；
  • c）在微服务盛行的当下，链路跟踪是个难题，而借助 MDC 去埋点，巧妙实现链路跟踪应该不是问题。

六、多线程使用MDC追踪日志

1、背景

多线程情况下，子线程的sl4j打印日志缺少traceId等信息，导致定位问题不方便

2、解决方案

  • 1、打印日志时添加用户ID、trackId等信息，缺点是每个日志都要手动添加
  • 2、使用mdc直接拷贝父线程值

3、代码实现

// 新建线程时：
Map<String, String> mdcContextMap = MDC.getCopyOfContextMap()

// 将mdcContextMap作为参数传给子线程
// 子线程运行时：
if(null != mdcContextMap){
    MDC.setContextMap(mdcContextMap);
}

// 销毁线程时
MDC.clear();

4、参考

import org.slf4j.MDC;

import java.util.Map;
import java.util.concurrent.*;

/**
 * A SLF4J MDC-compatible {@link ThreadPoolExecutor}.
 * <p/>
 * In general, MDC is used to store diagnostic information (e.g. a user's session id) in per-thread variables, to facilitate
 * logging. However, although MDC data is passed to thread children, this doesn't work when threads are reused in a
 * thread pool. This is a drop-in replacement for {@link ThreadPoolExecutor} sets MDC data before each task appropriately.
 * <p/>
 */public class MdcThreadPoolExecutor extends ThreadPoolExecutor {

    final private boolean useFixedContext;
    final private Map<String, Object> fixedContext;

    /**
     * Pool where task threads take MDC from the submitting thread.
     */    public static MdcThreadPoolExecutor newWithInheritedMdc(int corePoolSize, int maximumPoolSize, long keepAliveTime,
                                                            TimeUnit unit, BlockingQueue<Runnable> workQueue) {
        return new MdcThreadPoolExecutor(null, corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
    }

    /**
     * Pool where task threads take fixed MDC from the thread that creates the pool.
     */    @SuppressWarnings("unchecked")
    public static MdcThreadPoolExecutor newWithCurrentMdc(int corePoolSize, int maximumPoolSize, long keepAliveTime,
                                                          TimeUnit unit, BlockingQueue<Runnable> workQueue) {
        return new MdcThreadPoolExecutor(MDC.getCopyOfContextMap(), corePoolSize, maximumPoolSize, keepAliveTime, unit,
                workQueue);
    }

    /**
     * Pool where task threads always have a specified, fixed MDC.
     */    public static MdcThreadPoolExecutor newWithFixedMdc(Map<String, Object> fixedContext, int corePoolSize,
                                                        int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                                        BlockingQueue<Runnable> workQueue) {
        return new MdcThreadPoolExecutor(fixedContext, corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
    }

    private MdcThreadPoolExecutor(Map<String, Object> fixedContext, int corePoolSize, int maximumPoolSize,
                                  long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue) {
        super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
        this.fixedContext = fixedContext;
        useFixedContext = (fixedContext != null);
    }

    @SuppressWarnings("unchecked")
    private Map<String, Object> getContextForTask() {
        return useFixedContext ? fixedContext : MDC.getCopyOfContextMap();
    }

    /**
     * All executions will have MDC injected. {@code ThreadPoolExecutor}'s submission methods ({@code submit()} etc.)
     * all delegate to this.
     */    @Override
    public void execute(Runnable command) {
        super.execute(wrap(command, getContextForTask()));
    }

    public static Runnable wrap(final Runnable runnable, final Map<String, Object> context) {
        return new Runnable() {
            @Override
            public void run() {
                Map previous = MDC.getCopyOfContextMap();
                if (context == null) {
                    MDC.clear();
                } else {
                    MDC.setContextMap(context);
                }
                try {
                    runnable.run();
                } finally {
                    if (previous == null) {
                        MDC.clear();
                    } else {
                        MDC.setContextMap(previous);
                    }
                }
            }
        };
    }
}

七、MDC全局链路追踪实现

1、声明过滤器对请求拦截

@Configuration
public class FilterConfig {
    @Bean
    public FilterRegistrationBean registFilter() {
        FilterRegistrationBean registration = new FilterRegistrationBean();
        registration.setFilter(new DyeFilter());
        registration.addUrlPatterns("/*");
        registration.setName("DyeFilter");
        registration.setOrder(1);
        return registration;
    }
}

2、构建上下文对象，并赋值到MDC

@WebFilter(filterName = "DyeFilter")
public class DyeFilter implements Filter {

    @Override
    public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws ServletException, IOException {
        HttpServletRequest request = (HttpServletRequest) req;
        initGlobalContext(request);
        try {
            chain.doFilter(req, resp);
        } finally {
            ContextUtil.clearContext();
        }
    }

    private static void initGlobalContext(HttpServletRequest servletRequest) {
        GlobalContext context = new GlobalContext();
        String contextStr = servletRequest.getHeader(ContextConstant.REQUEST_CONTEXT);
        if (!StringUtils.isEmpty(contextStr)){
            context = JSON.parseObject(contextStr,GlobalContext.class);
        }else{
            context.setTraceId(UUID.randomUUID().toString());
            context.setClientIp(IpUtil.getClientAddress(servletRequest));
        }
        ContextUtil.setCurrentContext(context);
    }

    @Override
    public void init(FilterConfig config){
    }

    @Override
    public void destroy() {
    }
}

3、构建GlobalContext

在业务入口构建GlobalContext，在后续的调用链中，将从请求头中获取构建好的GlobalContext

public class ContextUtil {
    private static ThreadLocal<GlobalContext> currentThreadLocal = ThreadLocal.withInitial(GlobalContext::new);

    public static void setCurrentContext(GlobalContext context) {
        currentThreadLocal.set(context);
        String traceId = context.getTraceId();
        if (traceId != null && traceId.length() > 0 && MDC.get(ContextConstant.TRACK_ID) == null) {
            MDC.put(ContextConstant.TRACK_ID, traceId);
        }
    }

    public static GlobalContext getCurrentContext() {
       return currentThreadLocal.get();
    }

    public static void clearContext() {
        MDC.clear();
        currentThreadLocal.remove();
    }
}

4、获取GlobalContext，并通过请求头透传

public class FeignConfig {
    @Bean
    public RequestInterceptor header(){
        return this::setRequestHeader;
    }
    private void setRequestHeader(RequestTemplate requestTemplate){
        GlobalContext context = ContextUtil.getCurrentContext();
        if (context!=null){
            requestTemplate.header(ContextConstant.REQUEST_CONTEXT, JSONParser.quote(JSON.toJSONString(context)));
        }
    }
}

这里只举例通过Feign调用的方式，服务之间调用还有很多种，主要思路就是把GlobalContext透传到下一个服务

5、在logback配置文件中配置MDC容器中的变量%X{trackId}

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %X{trackId} [%15.15t] %class{39}.%method[%L] : %m%n</pattern>
        <!-- 控制台也要使用UTF-8，不要使用GBK，否则会中文乱码 -->
        <charset>UTF-8</charset>
    </encoder>
</appender>
打赏微海报分享

相关文章

发表评论