MDC轻量化日志链路跟踪的若干种应用场景

"If debugging is the process of removing software bugs, then programming must be the process of putting them in." - Edsger Dijkstra

“如果调试是消除软件Bug的过程，那么编程就是产出Bug的过程。” —— 艾兹格·迪杰斯特拉

0x00 大纲

0x00 大纲
0x01 前言
0x02 应用场景
0x03 小结
0x04 附录

0x01 前言

当你的应用程序同时处理多个用户的请求时，你会看到日志文件或者控制台中的输出通常都是交错的，而非线性连续的。尤其是在分布式系统中，一个用户请求可能包含了若干次的服务节点调用，它的日志也因此变得碎片化，如果缺乏一个用于归类和关联的标识，就会导致这笔交易难以被跟踪和追查。

MDC(Mapped Diagnostic Context)是一种用于区分来自不同来源日志的工具。它的本质是一个由日志框架维护的Map存储结构，应用程序可以向其中写入键值对，并被日志框架访问。我们常用的日志门面SLF4J就对MDC的实现进行了抽象，由日志框架提供真正的实现。在SLF4J的文档中写道：

This class hides and serves as a substitute for the underlying logging system's MDC implementation.

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, BasicMDCAdapter will be used. For other systems, i.e. slf4j-simple and slf4j-nop, NOPMDCAdapter will be used.

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.

目前为止只有logback和log4j(log4j2)提供了较为完备的实现，其余日志框架下会使用SLF4J内部实现的BasicMDCAdapter或者NOPMDCAdapter.

0x02 应用场景

CLI 程序

以logback为例，我们创建一个简单的logback.xml配置文件：

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="false">
    <property name="log.pattern" value="[%thread][%level][%logger{42}][%X{traceId:--}] %msg%n%ex"/>

    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <pattern>${log.pattern}</pattern>
        </layout>
    </appender>

    <root level="INFO">
        <appender-ref ref="stdout"/>
    </root>
</configuration>

一个简单的类用于测试，我们用一个循环来模拟用户两个独立的请求：

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

public class Main {
    private static final Logger LOGGER = LoggerFactory.getLogger(Main.class);

    public static void main(String[] args) {
        for (int i = 0; i < 2; i++) {
            try {
                LOGGER.info("Empty MDC Before Putting Data.");
                MDC.put("traceId", UUID.randomUUID().toString());
                LOGGER.info("Hello MDC.");
                LOGGER.info("GoodBye MDC.");
                throw new RuntimeException("Test Exception");
            } catch (RuntimeException e) {
                LOGGER.error("Test MDC", e);
            } finally {
                MDC.clear();
                LOGGER.info("Empty MDC After Clearing Data.");
            }
        }
    }
}

运行之后，我们会得到类似这样的日志输出：

[main][INFO][com.example.Main][-] Empty MDC Before Putting Data.
[main][INFO][com.example.Main][9ed7cc12-3880-4a38-94d4-b7ba96f37234] Hello MDC.
[main][INFO][com.example.Main][9ed7cc12-3880-4a38-94d4-b7ba96f37234] GoodBye MDC.
[main][ERROR][com.example.Main][9ed7cc12-3880-4a38-94d4-b7ba96f37234] Test MDC
java.lang.RuntimeException: Test Exception
	at com.example.Main.main(Main.java:19)
[main][INFO][com.example.Main][-] Empty MDC After Clearing Data.
[main][INFO][com.example.Main][-] Empty MDC Before Putting Data.
[main][INFO][com.example.Main][ab94804a-4f9a-4474-ba23-98542884d0ea] Hello MDC.
[main][INFO][com.example.Main][ab94804a-4f9a-4474-ba23-98542884d0ea] GoodBye MDC.
[main][ERROR][com.example.Main][ab94804a-4f9a-4474-ba23-98542884d0ea] Test MDC
java.lang.RuntimeException: Test Exception
	at com.example.Main.main(Main.java:19)
[main][INFO][com.example.Main][-] Empty MDC After Clearing Data.

可以看到，两次请求的traceId是不一样的，这样就能在日志中将它们区分和识别开来。通常来说，最好在请求完成后对MDC中的数据进行清理，尤其是使用了线程池的情况，由于线程是复用的，除非对原来的键值进行了覆盖，否则它将保留上一次的值。

Web 应用（服务端）

在CLI程序中，我们可以用上面的写法来设置traceId，当时对于 Web 应用，由于Controller入口众多，不可能每个控制器都这样子写，可以使用拦截器实现公共逻辑，避免对Controller的方法造成污染。先增加一个简单的Controller，它有两个请求处理方法，一个同步，一个异步：

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
import java.util.Map;
import java.util.concurrent.Callable;

@RestController
public class MDCController {
    private static final Logger LOGGER = LoggerFactory.getLogger(MDCController.class);

    @Configuration
    public class WebMvcConfig implements WebMvcConfigurer {
        @Override
        public void addInterceptors(InterceptorRegistry registry) {
            registry.addInterceptor(new LogInterceptor()).addPathPatterns("/**");
        }
    }

    @GetMapping("/syncMDC")
    public String mdcSync() {
        LOGGER.info("sync MDC test.");
        return "syncMDC";
    }

    @GetMapping("/asyncMDC")
    public Callable<String> mdcAsync() {
        LOGGER.info("async MDC test.");
        Map<String, String> mdcMap = MDC.getCopyOfContextMap();
        return () -> {
            try {
                MDC.setContextMap(mdcMap);
                LOGGER.info("异步业务逻辑处理");
                return "asyncMDC";
            } finally {
                MDC.clear();
            }
        };
    }
}

然后是关键的MDC拦截器：

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.web.servlet.AsyncHandlerInterceptor;
import javax.servlet.DispatcherType;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.UUID;

/**
 * 日志增强拦截器，给输出日志加上链路跟踪号
 *
 * @author YanFaBu
 **/
public class LogInterceptor implements AsyncHandlerInterceptor {
    private static final Logger LOGGER = LoggerFactory.getLogger(LogInterceptor.class);

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        if (request.getDispatcherType() != DispatcherType.REQUEST) {
            // 非 DispatcherType.REQUEST 分发类型，尝试从 Attribute 获取 LOG_TRACE_ID
            MDC.put("traceId", (String) request.getAttribute("traceId"));
            LOGGER.info("preHandle Non DispatcherType.REQUEST type with DispatcherType {}", request.getDispatcherType());
            return true;
        }
        // 如果本次调用来自上游服务，那么尝试从请求头获取上游传递的 traceId
        String traceId = request.getHeader("traceId");
        if (traceId == null) {
            // 本服务节点是起始服务节点，设置 traceId
            traceId = UUID.randomUUID().toString();
        }
        MDC.put("traceId", traceId);
        // 异步处理会在内部进行 Request 转发，通过 Attribute 携带 traceId
        request.setAttribute("traceId", traceId);
        LOGGER.info("preHandle DispatcherType.REQUEST type with DispatcherType {}", request.getDispatcherType());
        return true;
    }

    @Override
    public void afterConcurrentHandlingStarted(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        // 清理 MDC
        LOGGER.info("afterConcurrentHandlingStarted Clearing MDC.");
        MDC.clear();
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception exception) {
        // 清理 MDC
        LOGGER.info("afterCompletion Clearing MDC with DispatcherType {}", request.getDispatcherType());
        MDC.clear();
    }
}

分别访问这两个Controller方法，应当看到类似这样的日志输出：

[http-nio-8080-exec-7][INFO][com.example.LogInterceptor][e828f77b-9c0d-42c5-83db-15f19153bf19] preHandle DispatcherType.REQUEST type with DispatcherType REQUEST
[http-nio-8080-exec-7][INFO][com.example.MDCController][e828f77b-9c0d-42c5-83db-15f19153bf19] sync MDC test.
[http-nio-8080-exec-7][INFO][com.example.LogInterceptor][e828f77b-9c0d-42c5-83db-15f19153bf19] afterCompletion Clearing MDC with DispatcherType REQUEST

[http-nio-8080-exec-8][INFO][com.example.LogInterceptor][7dc0878c-c014-44de-97d4-92108873a030] preHandle DispatcherType.REQUEST type with DispatcherType REQUEST
[http-nio-8080-exec-8][INFO][com.example.MDCController][7dc0878c-c014-44de-97d4-92108873a030] async MDC test.
[http-nio-8080-exec-8][INFO][com.example.LogInterceptor][7dc0878c-c014-44de-97d4-92108873a030] afterConcurrentHandlingStarted Clearing MDC.
[task-3][INFO][com.example.MDCController][7dc0878c-c014-44de-97d4-92108873a030] 异步业务逻辑处理
[http-nio-8080-exec-9][INFO][com.example.LogInterceptor][7dc0878c-c014-44de-97d4-92108873a030] preHandle Non DispatcherType.REQUEST type with DispatcherType ASYNC
[http-nio-8080-exec-9][INFO][com.example.LogInterceptor][7dc0878c-c014-44de-97d4-92108873a030] afterCompletion Clearing MDC with DispatcherType ASYNC

注意到异步请求处理中的线程号的变化，请求受理-业务处理-请求应答历经了3个不同的线程，凡是跨线程的处理逻辑，必然需要对MDC的传递进行处理，否则链路跟踪会丢失。网上看到过很多例子，都忽略了对DispatcherType的处理，这样就会导致异步请求中，有一部分日志会失去追踪，导致最终排查问题时链路不完整。通过Attribute传递不是唯一的方式，也可以借助其他上下文来传递。

Web 应用（客户端）

OkHttp 同步请求

import okhttp3.OkHttpClient;
import okhttp3.Request;
import okhttp3.Response;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

import java.io.IOException;
import java.util.Objects;
import java.util.UUID;

public class Client {
    private static final Logger LOGGER = LoggerFactory.getLogger(LogInterceptor.class);

    public static void main(String[] args) throws IOException {
        okHttpSync();
    }

    public static void okHttpSync() throws IOException {
        try {
            String traceId = UUID.randomUUID().toString();
            MDC.put("traceId", traceId);
            LOGGER.info("okHttpSync request syncMDC");
            OkHttpClient client = new OkHttpClient().newBuilder()
                    .build();
            Request request = new Request.Builder()
                    .url("http://localhost:8080/syncMDC")
                    .method("GET", null)
                    .addHeader("traceId", traceId)
                    .build();
            try (Response response = client.newCall(request).execute()) {
                LOGGER.info("okHttpSync response：{}", Objects.requireNonNull(response.body()).string());
            }
        } finally {
            MDC.clear();
        }
    }
}

OkHttp 异步请求

import okhttp3.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import java.io.IOException;
import java.util.Map;
import java.util.Objects;
import java.util.UUID;

public class Client {
    private static final Logger LOGGER = LoggerFactory.getLogger(LogInterceptor.class);

    public static void main(String[] args) {
        okHttpAsync();
    }

    public static void okHttpAsync() {
        try {
            String traceId = UUID.randomUUID().toString();
            MDC.put("traceId", traceId);
            LOGGER.info("okHttpAsync request syncMDC");
            OkHttpClient client = new OkHttpClient().newBuilder()
                    .build();
            Request request = new Request.Builder()
                    .url("http://localhost:8080/syncMDC")
                    .method("GET", null)
                    .addHeader("traceId", traceId)
                    .build();
            Map<String, String> mdcMap = MDC.getCopyOfContextMap();
            client.newCall(request).enqueue(new Callback() {
                @Override
                public void onFailure(Call call, IOException e) {
                    try {
                        MDC.setContextMap(mdcMap);
                        LOGGER.error("okHttpAsync error", e);
                    } finally {
                        MDC.clear();
                    }
                }

                @Override
                public void onResponse(Call call, Response response) throws IOException {
                    try {
                        MDC.setContextMap(mdcMap);
                        LOGGER.info("okHttpAsync response：{}", Objects.requireNonNull(response.body()).string());
                    } finally {
                        MDC.clear();
                    }
                }
            });
        } finally {
            MDC.clear();
        }
    }
}

顺利的话，在客户端应该会得到类似下面的日志输出（注意线程名称的变化）：

[main][INFO][com.example.Client][53924455-0fcd-442b-a5aa-aaa33005d299] okHttpSync request syncMDC
[main][INFO][com.example.Client][53924455-0fcd-442b-a5aa-aaa33005d299] okHttpSync response：syncMDC

[main][INFO][com.example.Client][5cb52293-c8ac-4bc5-87fc-dbeb1e727eba] okHttpAsync request syncMDC
[OkHttp http://localhost:8080/...][INFO][com.example.Client][5cb52293-c8ac-4bc5-87fc-dbeb1e727eba] okHttpAsync response：syncMDC

在服务端对应的日志如下，可以看到traceId是一致的（如果不一致或者没有看到traceId，应该检查下上一章提到的拦截器是否有被正确实现）：

[http-nio-8080-exec-2][INFO][com.example.LogInterceptor][53924455-0fcd-442b-a5aa-aaa33005d299] preHandle DispatcherType.REQUEST type with DispatcherType REQUEST
[http-nio-8080-exec-2][INFO][com.example.MDCController][53924455-0fcd-442b-a5aa-aaa33005d299] sync MDC test.
[http-nio-8080-exec-2][INFO][com.example.LogInterceptor][53924455-0fcd-442b-a5aa-aaa33005d299] afterCompletion Clearing MDC with DispatcherType REQUEST

[http-nio-8080-exec-3][INFO][com.example.LogInterceptor][5cb52293-c8ac-4bc5-87fc-dbeb1e727eba] preHandle DispatcherType.REQUEST type with DispatcherType REQUEST
[http-nio-8080-exec-3][INFO][com.example.MDCController][5cb52293-c8ac-4bc5-87fc-dbeb1e727eba] sync MDC test.
[http-nio-8080-exec-3][INFO][com.example.LogInterceptor][5cb52293-c8ac-4bc5-87fc-dbeb1e727eba] afterCompletion Clearing MDC with DispatcherType REQUEST

处理思路都是通过HTTP Header携带traceId到下游服务，让下游服务可以跟踪来源。注意异步请求时，请求处理和应答处理回调线程不在同一个线程，需要对MDC的传递进行处理，否则链路跟踪会丢失。其他的客户端，如HttpClient、Unirest等 HTTP 请求库原理与之相似，这里就不一一列举了。

Spring WebClient

与OkHttp异步调用类似，注意要在Mono或者Flux的subscribe方法中传递MDC上下文。其实WebClient中有Context传递的概念，但是这块资料比较少，异步非阻塞的代码又看得头痛，暂时不想去研究了。下面的代码出于演示目的使用，请勿直接使用：

import okhttp3.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.web.reactive.function.client.WebClient;

import java.io.IOException;
import java.util.Map;
import java.util.Objects;
import java.util.UUID;
import java.util.concurrent.CountDownLatch;

public class Client {
    private static final Logger LOGGER = LoggerFactory.getLogger(LogInterceptor.class);

    public static void main(String[] args) throws InterruptedException {
        webClient();
    }

    public static void webClient() throws InterruptedException {
        String traceId = UUID.randomUUID().toString();
        MDC.put("traceId", traceId);
        LOGGER.info("webClient request syncMDC");
        WebClient client = WebClient.create("http://localhost:8080/syncMDC");
        Map<String, String> mdcMap = MDC.getCopyOfContextMap();
        CountDownLatch latch = new CountDownLatch(1);
        client.get()
                .uri("/")
                .retrieve()
                .bodyToMono(String.class)
                .subscribe(result -> {
                    try {
                        MDC.setContextMap(mdcMap);
                        LOGGER.info("webClient response：{}", result);
                    } finally {
                        MDC.clear();
                        latch.countDown();
                    }
                }, throwable -> {
                    try {
                        MDC.setContextMap(mdcMap);
                        LOGGER.error("webClient error", throwable);
                    } finally {
                        MDC.clear();
                    }
                });
        latch.await();
    }
}

输出日志如下，注意线程的变化：

[main][INFO][com.example.Client][8c984fa8-e3cd-4914-875e-ba333d31c7a9] webClient request syncMDC
[reactor-http-nio-2][INFO][com.example.Client][8c984fa8-e3cd-4914-875e-ba333d31c7a9] webClient response：syncMDC

Dubbo 服务

与 HTTP 调用类似，基于Dubbo的 RPC 调用也是可以跟踪的，利用Dubbo的Filter和SPI注册机制，我们可以增加自己的过滤器实现日志链路跟踪：

import org.apache.dubbo.common.extension.Activate;
import org.apache.dubbo.rpc.*;
import org.slf4j.MDC;
import java.util.UUID;

/**
 * 服务链路跟踪过滤器
 */
@Activate
public class RpcTraceFilter implements Filter {
    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        RpcContext context = RpcContext.getContext();
        boolean shouldRemove = false;
        if (context.isProviderSide()) {
            // 获取消费端设置的参数
            String traceId = context.getAttachment("traceId");
            if (traceId == null || traceId.isEmpty()) {
                traceId = MDC.get("traceId");
                if (traceId == null || traceId.isEmpty()) {
                    traceId = UUID.randomUUID().toString();
                    shouldRemove = true;
                }
            }
            // 设置 traceId
            MDC.put("traceId", traceId);
            // 继续设置下游参数，供在提供方里面作为消费端时，其他服务提供方使用这些参数
            context.setAttachment("traceId", traceId);
        } else if (context.isConsumerSide()) {
            // 如果连续调用多个服务，则会使用同个线程里之前设置的traceId
            String traceId = MDC.get("traceId");
            if (traceId == null || traceId.isEmpty()) {
                traceId = UUID.randomUUID().toString();
                // 设置 traceId
                MDC.put("traceId", traceId);
                shouldRemove = true;
            }
            // 设置传递到提供端的参数
            context.setAttachment("traceId", traceId);
        }
        try {
            return invoker.invoke(invocation);
        } finally {
            // 调用完成后移除MDC属性
            if (shouldRemove) {
                MDC.clear();
            }
        }
    }
}

在需要用到的服务模块的resource/META-INF/dubbo/org.apache.dubbo.rpc.Filter文件中注册过滤器（注意路径和名称不能错）：

rpcTraceFilter=com.example.RpcTraceFilter

SpringBoot的application.properties中增加配置（为了简单验证，这里没有使用注册中心。如果你想更严谨地测试，建议在本地启动两个独立的工程，并使用ZooKeeper进行服务注册）：

dubbo.application.name=MDCExample
dubbo.scan.base-packages=com.example
dubbo.registry.address=N/A
# dubbo filter
dubbo.consumer.filter=rpcTraceFilter
dubbo.provider.filter=rpcTraceFilter

增加一个简单的Dubbo服务：

import org.apache.dubbo.config.annotation.DubboService;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@DubboService
public class RpcService implements IRpcService {
    private static final Logger LOGGER = LoggerFactory.getLogger(RpcService.class);

    public String mdcRpc() {
        LOGGER.info("Calling RPC service.");
        return "mdcRpc";
    }
}

在Controller中增加一个方法，进行验证：

import org.apache.dubbo.config.annotation.DubboReference;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;

import java.util.Map;
import java.util.concurrent.Callable;

@RestController
public class MDCController {
    // ......（省略前面的代码）
    @DubboReference
    private IRpcService rpcService;

    @GetMapping("/mdcRpc")
    public String mdcRpc() {
        LOGGER.info("rpc MDC test.");
        return rpcService.mdcRpc();
    }
}

访问Controller方法，应该能得到类似下面的输出：

[http-nio-8080-exec-1][INFO][com.example.LogInterceptor][f003f750-2044-41ae-a041-8a76eb0c415b] preHandle DispatcherType.REQUEST type with DispatcherType REQUEST
[http-nio-8080-exec-1][INFO][com.example.MDCController][f003f750-2044-41ae-a041-8a76eb0c415b] rpc MDC test.
[http-nio-8080-exec-1][INFO][com.example.RpcService][f003f750-2044-41ae-a041-8a76eb0c415b] Calling RPC service.
[http-nio-8080-exec-1][INFO][com.example.LogInterceptor][f003f750-2044-41ae-a041-8a76eb0c415b] afterCompletion Clearing MDC with DispatcherType REQUEST

线程池

前面提到过跨线程调用时，需要自己处理MDC上下文的传递，如果是单个线程，可以手工进行处理，但如果是线程池，似乎就不能这么干了。线程池种类繁多，处理方式也有细微差别，这里不可能全部列举，以Spring项目中常用的 ThreadPoolTaskExecutor为例，我们可以利用它提供的setTaskDecorator方法对任务进行装饰：

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.context.annotation.Bean;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
import java.util.Map;
import java.util.UUID;

public class MDCExecutor {
    private static final Logger LOGGER = LoggerFactory.getLogger(MDCExecutor.class);
    public static void main(String[] args) {
        MDC.put("traceId", UUID.randomUUID().toString());
        ThreadPoolTaskExecutor executor = asyncTaskExecutor();
        executor.initialize();
        executor.submit(() -> LOGGER.info("MDC Executor"));
        executor.shutdown();
    }
    @Bean
    public static ThreadPoolTaskExecutor asyncTaskExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setTaskDecorator(task -> {
            Map<String, String> mdcMap = MDC.getCopyOfContextMap();
            return () -> {
                try {
                    if (mdcMap != null) {
                        MDC.setContextMap(mdcMap);
                    }
                    task.run();
                } finally {
                    MDC.clear();
                }
            };
        });
        return executor;
    }
}

对于其他线程池，通用的思路是覆写其submit或者execute方法来实现MDC传递，比如我们下面提到的定时任务调度线程池。

定时任务

除了Controller和 RPC 接口发起的调用，最常见的就是定时任务了。如果是定时任务作为业务发起源，可以在任务调度的时候对MDC进行处理。这块处理比较复杂，暂时没有找到比较优雅的切入点：

增加一个实现RunnableScheduledFuture接口的DecoratedFuture类：

import org.slf4j.MDC;
import java.util.Map;
import java.util.Optional;
import java.util.UUID;
import java.util.concurrent.*;

class DecoratedFuture<V> implements RunnableScheduledFuture<V> {
    Runnable runnable;
    Callable<V> callable;
    final RunnableScheduledFuture<V> task;

    public DecoratedFuture(Runnable r, RunnableScheduledFuture<V> task) {
        this.task = task;
        runnable = r;
    }

    public DecoratedFuture(Callable<V> c, RunnableScheduledFuture<V> task) {
        this.task = task;
        callable = c;
    }

    @Override
    public boolean isPeriodic() {
        return task.isPeriodic();
    }

    @Override
    public void run() {
        try {
            Map<String, String> mdcMap = MDC.getCopyOfContextMap();
            Optional.ofNullable(mdcMap).ifPresent(MDC::setContextMap);
            String traceId = MDC.get("traceId");
            if (traceId == null || traceId.isEmpty()) {
                traceId = UUID.randomUUID().toString();
            }
            MDC.put("traceId", traceId);
            task.run();
        } finally {
            MDC.clear();
        }
    }

    @Override
    public boolean cancel(boolean mayInterruptIfRunning) {
        return task.cancel(mayInterruptIfRunning);
    }

    @Override
    public boolean isCancelled() {
        return task.isCancelled();
    }

    @Override
    public boolean isDone() {
        return task.isDone();
    }

    @Override
    public V get() throws InterruptedException, ExecutionException {
        return task.get();
    }

    @Override
    public V get(long timeout, TimeUnit unit) throws InterruptedException, ExecutionException, TimeoutException {
        return task.get(timeout, unit);
    }

    @Override
    public long getDelay(TimeUnit unit) {
        return task.getDelay(unit);
    }

    @Override
    public int compareTo(Delayed o) {
        return task.compareTo(o);
    }

    @Override
    public int hashCode() {
        return task.hashCode();
    }

    @Override
    public boolean equals(Object o) {
        if (this == o) {
            return true;
        }
        if (o == null || getClass() != o.getClass()) {
            return false;
        }
        DecoratedFuture<?> that = (DecoratedFuture<?>) o;
        return this.task.equals(that.task);
    }

    public Runnable getRunnable() {
        return runnable;
    }

    public RunnableScheduledFuture<V> getTask() {
        return task;
    }

    public Callable<V> getCallable() {
        return callable;
    }
}

增加一个实现ThreadPoolTaskScheduler接口的DecoratedThreadPoolTaskScheduler类：

import org.slf4j.MDC;
import org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler;
import java.time.Duration;
import java.time.Instant;
import java.util.Map;
import java.util.Optional;
import java.util.concurrent.RejectedExecutionHandler;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.ScheduledFuture;
import java.util.concurrent.ThreadFactory;

class DecoratedThreadPoolTaskScheduler extends ThreadPoolTaskScheduler {
    private static final long serialVersionUID = 1L;

    static Runnable withTraceId(Runnable task) {
        Map<String,String> mdcMap = MDC.getCopyOfContextMap();
        return ()-> {
            try {
                Optional.ofNullable(mdcMap).ifPresent(MDC::setContextMap);
                task.run();
            } finally {
                MDC.clear();
            }
        };
    }

    @Override
    protected ScheduledExecutorService createExecutor(int poolSize, ThreadFactory threadFactory, RejectedExecutionHandler rejectedExecutionHandler) {
        return new DecoratedScheduledThreadPoolExecutor(poolSize, threadFactory, rejectedExecutionHandler);
    }
    
    @Override
    public ScheduledFuture<?> schedule(Runnable task, Instant startTime) {
        return super.schedule(withTraceId(task), startTime);
    }
    
    @Override
    public ScheduledFuture<?> scheduleAtFixedRate(Runnable task, Instant startTime, Duration period) {
        return super.scheduleAtFixedRate(withTraceId(task), startTime, period);
    }
    
    @Override
    public ScheduledFuture<?> scheduleAtFixedRate(Runnable task, Duration period) {
        return super.scheduleAtFixedRate(withTraceId(task), period);
    }
    
    @Override
    public ScheduledFuture<?> scheduleWithFixedDelay(Runnable task, Instant startTime, Duration delay) {
        return super.scheduleWithFixedDelay(withTraceId(task), startTime, delay);
    }
    
    @Override
    public ScheduledFuture<?> scheduleWithFixedDelay(Runnable task, Duration delay) {
        return super.scheduleWithFixedDelay(withTraceId(task), delay);
    }
}

增加一个继承ScheduledThreadPoolExecutor类的DecoratedScheduledThreadPoolExecutor类，覆写它的两个decorateTask方法：

import java.util.concurrent.*;

class DecoratedScheduledThreadPoolExecutor extends ScheduledThreadPoolExecutor {
    public DecoratedScheduledThreadPoolExecutor(int poolSize, ThreadFactory threadFactory, RejectedExecutionHandler rejectedExecutionHandler) {
        super(poolSize, threadFactory, rejectedExecutionHandler);
    }

    @Override
    protected <V> RunnableScheduledFuture<V> decorateTask(Runnable runnable, RunnableScheduledFuture<V> task) {
        return new DecoratedFuture<>(runnable, task);
    }

    @Override
    protected <V> RunnableScheduledFuture<V> decorateTask(Callable<V> callable, RunnableScheduledFuture<V> task) {
        return new DecoratedFuture<>(callable, task);
    }
}

在定时任务Configuration中，创建DecoratedThreadPoolTaskScheduler作为调度线程池：

import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.scheduling.annotation.EnableAsync;
import org.springframework.scheduling.annotation.EnableScheduling;
import org.springframework.scheduling.annotation.SchedulingConfigurer;
import org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler;
import org.springframework.scheduling.config.ScheduledTaskRegistrar;

/**
 * 定时调度配置
 */
@Configuration
@EnableAsync
@EnableScheduling
public class SchedulingConfiguration implements SchedulingConfigurer {
    public static final String TASK_SCHEDULER = "taskScheduler";

    @Override
    public void configureTasks(ScheduledTaskRegistrar taskRegistrar) {
        taskRegistrar.setTaskScheduler(taskScheduler());
    }

    @Bean(TASK_SCHEDULER)
    public ThreadPoolTaskScheduler taskScheduler() {
        return new DecoratedThreadPoolTaskScheduler();
    }
}

添加一个简单定时任务：

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.scheduling.annotation.Scheduled;

@SpringBootApplication
public class App {
    private static final Logger LOGGER = LoggerFactory.getLogger(App.class);
    public static void main(String[] args) {
        SpringApplication.run(App.class, args);
    }

    @Scheduled(fixedDelay = 1500)
    public void cronTaskConfigRefresh() {
        LOGGER.info("MDC task scheduler.");
    }
}

可以看到类似下面的输出，说明就成功了：

[taskScheduler-1][INFO][com.example.App][0959d1a6-4680-4a95-a29b-b62694f0d348] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][8f034b1e-db40-44cb-9fc2-986eb8f0da6d] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][02428e88-53f8-4151-aba0-86e069c96462] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][fcd5d925-95e0-4e28-aa68-39e765668dde] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][b8ed50c6-0d6d-40c0-b170-976717fe7d22] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][9d173a26-41d4-43dc-beae-731a9f267288] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][0257c93a-9bec-40b7-9447-5a938bd2ce5f] MDC task scheduler.

0x03 小结

在实际项目中，通过灵活组合上面的若干种手段，就可以实现轻量化的日志链路跟踪，在大部分情况下基本上已经够用了，当然你也可以引入SkyWalking或ZipKin等探针框架，它们提供的功能也更全面更丰富。如何选择，需要根据具体项目自行权衡。

0x04 附录

样例工程下载

原文链接：https://www.cnblogs.com/mylibs/p/using-mdc-to-trace-log.html

本站文章如无特殊说明，均为本站原创，如若转载，请注明出处：MDC轻量化日志链路跟踪的若干种应用场景 - Python技术站