庆峰的博客

流水要争先，争的是滔滔不绝。

0%

SpringBoot-Mdc-Log

发表于 更新于 分类于
本文字数： 16k 阅读时长 ≈ 14 分钟

日常在开发过程中方便排查文件，需要在日志中输出一些关键内容。

MDC

在茫茫日志中定位需要的信息很费时，MDC 全称是 Mapped Diagnostic Context.一个线程安全的存放诊断日志的容器。

演示代码

HTTP处理演示

代码

实际上代码不需要这么麻烦,只需要调用MDC.put 就能将数据写入，但是实际开发过程中。通过手动编码的方式添加太低效了，这里在spring mvc的场景下使用用拦截器来处理数据注入操作。

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
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
/**
 * @author z201.coding@gmail.com
 **/
@RestController
@Slf4j
public class AppApplicationController {

    @RequestMapping(value = "")
    public Object index() {
        log.info("index");
        Map<String, Object> data = new HashMap<>();
        data.put("code", "200");
        return data;
    }

}


**
 * @author z201.coding@gamil.com
 */
@Order(Ordered.HIGHEST_PRECEDENCE + 8)
@ConditionalOnClass(WebMvcConfigurer.class)
@Slf4j
@Component
public class MdcTraceContextFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response,
                                    FilterChain filterChain) throws ServletException, IOException {
        String appTraceId = request.getHeader(MdcApiConstant.HTTP_HEADER_TRACE_ID);
        /**
         * 没有设置就设置下,设置了就直接返回。注意这里必须提前在拦截器中设置好，不然会失效。
         */
        if (StrUtil.isEmpty(appTraceId)) {
            appTraceId = MDC.get(MdcApiConstant.HTTP_HEADER_TRACE_ID);
            if (Strings.isEmpty(appTraceId)) {
                appTraceId = MdcTool.getInstance().currentTraceId();
            }
            request.setAttribute(MdcApiConstant.HTTP_HEADER_TRACE_ID, appTraceId);
        }
        MDC.put(MdcApiConstant.HTTP_HEADER_TRACE_ID, appTraceId);
        filterChain.doFilter(request, response);
    }
}


/**
 * @author z201.coding@gmail.com
 **/
public class MdcTool {

    private static class SingletonHolder {
        private static final MdcTool INSTANCE = new MdcTool();
    }
    private MdcTool (){}

    public static final MdcTool getInstance() {
        return SingletonHolder.INSTANCE;
    }

    public synchronized String currentTraceId() {
        ThreadLocalRandom random = ThreadLocalRandom.current();
        UUID uuid = new UUID(random.nextInt(), random.nextInt());
        StringBuilder st = new StringBuilder(uuid.toString().replace("-", "").toLowerCase());
        st.append(Instant.now().toEpochMilli());
        int i = 0;
        while (i < 3) {
            i++;
            st.append(ThreadLocalRandom.current().nextInt(2));
        }
        return st.toString();
    }
}

log配置文件

Log4j 或者 logback 在pattern表中修改表达式%X{AppTraceId} 这就是拦截去注入进去的数据key。

1
<pattern>[%t][%level][%file:%line][%X{AppTraceId}] %msg%n</pattern>
  • Console
1
2
culr http://localhost:9007/mdc/
[AppApplicationController.java:19][00000000299baa76ffffffffbd27659b1641811416723011] index

异步调用的

  • 在记录日志的时候，通常会使用MDC来存储每个线程的特有参数，以便更好的查询日志。
  • 但是Logback在最新的版本中因为性能问题，不会自动的将MDC的内存传给子线程。所以Logback建议在执行异步线程前
  • 先通过MDC.getCopyOfContextMap()方法将MDC内存获取出来，再传给线程。
  • 并在子线程的执行的最开始调用MDC.setContextMap(context)方法将父线程的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
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158

/**
 * 这是{@link ThreadPoolTaskExecutor}简单的改良，可以在每个任务之前设置子线程的MDC数据。
 * <p>
 * https://logback.qos.ch/manual/mdc.html
 *
 * @author z201.coding@gamil.com
 */
public class MdcThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {

    /**
     * Pool where task threads take MDC from the submitting thread.
     */
    public static MdcThreadPoolTaskExecutor newWithInheritedMdc(int corePoolSize, int maximumPoolSize, long keepAliveTime,
                                                                TimeUnit unit, int queueCapacity, RejectedExecutionHandler rejectedExecutionHandler) {
        return new MdcThreadPoolTaskExecutor(corePoolSize, maximumPoolSize, keepAliveTime, unit, queueCapacity, rejectedExecutionHandler);
    }

    private MdcThreadPoolTaskExecutor(int corePoolSize, int maximumPoolSize,
                                      long keepAliveTime, TimeUnit unit, int queueCapacity, RejectedExecutionHandler rejectedExecutionHandler) {
        setCorePoolSize(corePoolSize);
        setMaxPoolSize(maximumPoolSize);
        setKeepAliveSeconds((int) unit.toSeconds(keepAliveTime));
        setQueueCapacity(queueCapacity);
        setRejectedExecutionHandler(rejectedExecutionHandler);
    }

    private Map<String, String> initMdcContext() {
        // 获取父线程MDC中的内容，必须在run方法之前，否则等异步线程执行的时候有可能MDC里面的值已经被清空了，这个时候就会返回null
        Map<String, String> context = MDC.getCopyOfContextMap();
        if (Validator.isNull(context)) {
            context = new HashMap<>();
        }
        if (CollectionUtil.isEmpty(context)) {
            // 防止线程没有链路信息,这里可以扩展
            context.put(MdcApiConstant.HTTP_HEADER_TRACE_ID, MdcTool.getInstance().currentTraceId());
        }
        return context;
    }

    /**
     * 所有线程都会委托给这个execute方法，在这个方法中我们把父线程的MDC内容赋值给子线程
     * https://logback.qos.ch/manual/mdc.html#managedThreads
     *
     * @param runnable
     */
    @Override
    public void execute(@NonNull Runnable runnable) {
        super.execute(() -> run(runnable, initMdcContext()));
    }

    /**
     * 异步提交
     *
     * @param task
     * @return
     */
    @NonNull
    @Override
    public Future<?> submit(@NonNull Runnable task) {
        return super.submit(() -> run(task, initMdcContext()));
    }

    /**
     * 异步提交
     *
     * @param task
     * @return
     */
    @NonNull
    @Override
    public <T> Future<T> submit(@NonNull Callable<T> task) {
        return super.submit(submit(task, initMdcContext()));
    }

    /**
     * 子线程委托的执行方法s
     *
     * @param runnable {@link Runnable}
     * @param context  父线程MDC内容
     */
    private void run(Runnable runnable, Map<String, String> context) {
        // 将父线程的MDC内容传给子线程
        if (context != null) {
            try {
                MDC.setContextMap(context);
            } catch (Exception e) {
                logger.error(e.getMessage(), e);
            }
        }
        try {
            // 执行异步操作
            runnable.run();
        } finally {
            // 清空MDC内容
            MDC.clear();
        }
    }

    private static <T> Callable<T> submit(final Callable<T> task, final Map<String, String> context) {
        return () -> {
            Map<String, String> previous = MDC.getCopyOfContextMap();
            if (context == null) {
                MDC.clear();
            } else {
                MDC.setContextMap(context);
            }
            try {
                return task.call();
            } finally {
                if (previous == null) {
                    MDC.clear();
                } else {
                    MDC.setContextMap(previous);
                }
            }
        };
    }
}

package cn.z201.mdc.log;

import java.util.concurrent.ThreadPoolExecutor;
import java.util.concurrent.TimeUnit;

/**
 * @author z201.coding@gmail.com
 **/
public class MdcThreadTaskUtils {

    private static MdcThreadPoolTaskExecutor taskExecutor = null;

    /**
     * demo
     *         ThreadTaskUtils.run(() -> run());
     *         FutureTask<String> futureTask = new FutureTask<String>(() -> call());
     *         ThreadTaskUtils.run(futureTask);
     */
    static {
        /**
         * 核心线程数 5
         * 最大线程数 50
         * 队列最大长度 1000
         * 线程池维护线程所允许的空闲时间(单位秒) 120
         * 线程池对拒绝任务(无线程可用)的处理策略 ThreadPoolExecutor.CallerRunsPolicy策略 ,调用者的线程会执行该任务,如果执行器已关闭,则丢弃. 120
         */
    }
    public static void run(Runnable runnable) {
        if (null == taskExecutor) {
            taskExecutor = MdcThreadPoolTaskExecutor.newWithInheritedMdc(5, 50, 1000, TimeUnit.SECONDS, 120, new ThreadPoolExecutor.AbortPolicy());
            taskExecutor.initialize();
        }
        taskExecutor.execute(runnable);
    }
}



线程次调用演示

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
package cn.z201.mdc.log;

import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Disabled;
import org.junit.jupiter.api.MethodOrderer;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.TestMethodOrder;
import org.junit.jupiter.api.extension.ExtendWith;
import org.springframework.boot.test.autoconfigure.web.servlet.AutoConfigureMockMvc;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.test.context.junit.jupiter.SpringExtension;

import java.util.concurrent.CountDownLatch;


@Slf4j
@ExtendWith(SpringExtension.class)
@SpringBootTest(classes = AppApplication.class, webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT)
@AutoConfigureMockMvc
// 指定单元测试方法顺序
@TestMethodOrder(MethodOrderer.OrderAnnotation.class)
public class AppApplicationTest {

    @Test
    @Disabled
    public void testMdcTask(){
        MdcThreadTaskUtils.run(()->{
            log.info("");
        });
        int count = 10;
        CountDownLatch countDownLatch = new CountDownLatch(count);
        for (int i = 0; i < count; i++) {
            MdcThreadTaskUtils.run(()->{
                log.info("{}",Thread.currentThread().getId());
                countDownLatch.countDown();
            });
        }
        countDownLatch.countDown();
    }

}
  • Console
1
2
3
4
5
6
7
8
9
10
11
[MdcThreadPoolTaskExecutor-1][INFO][0000000044c1a93a000000000224a6b71641812254518111] 
[MdcThreadPoolTaskExecutor-2][INFO][ffffffffd75119fd0000000030ef630d1641812254519101] 34
[MdcThreadPoolTaskExecutor-3][INFO][0000000066a8e5c8ffffffffd68aed601641812254519001] 35
[MdcThreadPoolTaskExecutor-4][INFO][0000000066ee68fdfffffffff577e4281641812254519111] 36
[MdcThreadPoolTaskExecutor-3][INFO][ffffffffa217a73300000000725bf6351641812254519000] 35
[MdcThreadPoolTaskExecutor-5][INFO][00000000320b6d0a000000003af12e701641812254519011] 37
[MdcThreadPoolTaskExecutor-3][INFO][000000006b4901b6ffffffffebbf10d91641812254519110] 35
[MdcThreadPoolTaskExecutor-1][INFO][000000002b61782800000000157d2c1e1641812254519100] 33
[MdcThreadPoolTaskExecutor-5][INFO][00000000586b86f7ffffffffc5581f661641812254520000] 37
[MdcThreadPoolTaskExecutor-1][INFO][ffffffff930e3437ffffffffa425c03b1641812254520011] 33
[MdcThreadPoolTaskExecutor-2][INFO][000000001a75d2e7fffffffff55857f91641812254520010] 34
  • 成功防止异步操作丢失了log标记信息。

SpringAsync方法

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
 @Bean
    public AsyncTaskExecutor taskExecutor() {
        ThreadPoolTaskExecutor executor =
          MdcThreadPoolTaskExecutor.newWithInheritedMdc(8, 32, 2, TimeUnit.MINUTES, 1000, new ThreadPoolExecutor.AbortPolicy());
        executor.setThreadNamePrefix("def-Executor ");
        return executor;
    }

@RestController
@Slf4j
public class AppApplicationController {

    @Async
    @RequestMapping(value = "")
    public Object index() {
        log.info("index");
        Map<String, Object> data = new HashMap<>();
        data.put("code", "200");
        return data;
    }

}
  • Console
1
[def-Executor 1][INFO][ffffffffd62f558600000000385223a51641814195289011] index
  • 还有其它场景的用法，比如内部服务调用的时候，就可以单独将数封住在请求中传递到下个服务，只需要在下一个服务中的拦截器中获取在设置到当前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
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62

/**
 * As of SLF4J version 1.7.14, StaticMDCBinder classes shipping in various bindings
 * come with a getSingleton() method. Previously only a public field called SINGLETON 
 * was available.
 * 
 * @return MDCAdapter
 * @throws NoClassDefFoundError in case no binding is available
 * @since 1.7.14
 */
private static MDCAdapter bwCompatibleGetMDCAdapterFromBinder() throws NoClassDefFoundError {
    try {
        return StaticMDCBinder.getSingleton().getMDCA();
    } catch (NoSuchMethodError nsme) {
        // binding is probably a version of SLF4J older than 1.7.14
        return StaticMDCBinder.SINGLETON.getMDCA();
    }
}

static {
    try {
        mdcAdapter = bwCompatibleGetMDCAdapterFromBinder();
    } catch (NoClassDefFoundError ncde) {
        mdcAdapter = new NOPMDCAdapter();
        String msg = ncde.getMessage();
        if (msg != null && msg.contains("StaticMDCBinder")) {
            Util.report("Failed to load class \"org.slf4j.impl.StaticMDCBinder\".");
            Util.report("Defaulting to no-operation MDCAdapter implementation.");
            Util.report("See " + NO_STATIC_MDC_BINDER_URL + " for further details.");
        } else {
            throw ncde;
        }
    } catch (Exception e) {
        // we should never get here
        Util.report("MDC binding unsuccessful.", e);
    }
}

/**
 * Put a diagnostic context value (the <code>val</code> parameter) as identified with the
 * <code>key</code> parameter into the current thread's diagnostic context map. The
 * <code>key</code> parameter cannot be null. The <code>val</code> parameter
 * can be null only if the underlying implementation supports it.
 * 
 * <p>
 * This method delegates all work to the MDC of the underlying logging system.
 *
 * @param key non-null key 
 * @param val value to put in the map
 * 
 * @throws IllegalArgumentException
 *           in case the "key" parameter is null
 */
public static void put(String key, String val) throws IllegalArgumentException {
    if (key == null) {
        throw new IllegalArgumentException("key parameter cannot be null");
    }
    if (mdcAdapter == null) {
        throw new IllegalStateException("MDCAdapter cannot be null. See also " + NULL_MDCA_URL);
    }
    mdcAdapter.put(key, val);
}
  • 静态代码初始化mdcAdapter,mdcAdapter是个接口，可以理解为规范，会有不同的实现类。

  • 项目中使用的是logback所以，实际使用的是LogbackMDCAdapter。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
// The internal map is copied so as

 // We wish to avoid unnecessarily copying of the map. To ensure
 // efficient/timely copying, we have a variable keeping track of the last
 // operation. A copy is necessary on 'put' or 'remove' but only if the last
 // operation was a 'get'. Get operations never necessitate a copy nor
 // successive 'put/remove' operations, only a get followed by a 'put/remove'
 // requires copying the map.
 // See http://jira.qos.ch/browse/LOGBACK-620 for the original discussion.

 // We no longer use CopyOnInheritThreadLocal in order to solve LBCLASSIC-183
 // Initially the contents of the thread local in parent and child threads
 // reference the same map. However, as soon as a thread invokes the put()
 // method, the maps diverge as they should.
 final ThreadLocal<Map<String, String>> copyOnThreadLocal = new ThreadLocal<Map<String, String>>();

 private static final int WRITE_OPERATION = 1;
 private static final int MAP_COPY_OPERATION = 2;

 // keeps track of the last operation performed
 final ThreadLocal<Integer> lastOperation = new ThreadLocal<Integer>();

  • 真想大白，实际上维护了一个ThreadLocal

  • 这里需要注意有一个NOPMDCAdapter ，注意要是适配不支持上下文的日志系统。比如JDK14中的NOP。

END