1, Introduction to MDC

MDC (Mapped Diagnostic Context) is a function provided by log4j, logback and log4j2 to facilitate logging under multi-threaded conditions. MDC can be regarded as a hash table bound to the current thread, and key value pairs can be added to it. The content contained in MDC can be accessed by code executed in the same thread. The child thread of the current thread inherits the contents of the MDC in its parent thread. When logging is required, you only need to obtain the required information from MDC. The content of MDC is saved by the program at an appropriate time. For a Web application, this data is usually saved at the beginning of the request being processed.

2, API description

• Clear() = > remove all MDC s
• Get (string key) = > get the value of the specified key in the MDC of the current thread
• Getcontext() = > get the MDC of the current thread
• Put (string key, object o) = > store the specified key value pair into the MDC of the current thread
• Remove (string key) = > delete the key value pair specified in the MDC of the current thread

3, Advantages

• The code is concise and the log style is unified. There is no need to spell traceid manually in log printing, that is, logger info("traceId:{} ", traceId)

4, Code implementation

4.1 the request has no child thread

4.1.1 implement log interceptor

@Component
public class LogInterceptor implements HandlerInterceptor {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
    System.out.println("Entry interceptor");
    //If there is an upper layer call, use the upper layer ID
    String traceId = request.getHeader(Constants.TRACE_ID);
    if (traceId == null) {
        traceId = TraceIdUtil.getTraceId();
    }

    MDC.put(Constants.TRACE_ID, traceId);
    return true;
}

@Override
public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView)
    throws Exception {
}

@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
    throws Exception {
    //Delete after call
    System.out.println("End of call");
    MDC.remove(Constants.TRACE_ID);
}
}

4.2.2 registered interceptors

@Configuration
public class MvcInterceptorConfig extends WebMvcConfigurationSupport {
@Autowired
private LogInterceptor logInterceptor;

@Override
protected void addInterceptors(InterceptorRegistry registry) {
    // Multiple interceptors form an interceptor chain
    // addPathPatterns is used to add interception rules, / * * means to intercept all requests
    // excludePathPatterns user exclusion interception
    registry.addInterceptor(logInterceptor).addPathPatterns("/**");
    super.addInterceptors(registry);
}
}

4.3.3 log output format setting

<property name="LOG_PATTERN_CONSOLE">
	[TRACEID:%X{traceId}] %clr{%d{HH:mm:ss.SSS}}{faint} %clr{%5p} %clr{[%15.15t]}{faint} %clr{%C{1.}(%M:%L)}{cyan} %clr{:}{faint} %m%n%xwEx
</property>

Note that the threadId in% X{traceId} should be the same as the key of MDC put in log interception

4.2 request with child thread

slf4j's MDC mechanism is internally implemented based on ThreadLocal. So we call MDC The request ID passed in by the put () method is only valid in the current thread. Therefore, the MDC data set in the main thread cannot be obtained in its child thread (thread pool).

Official recommendations

1) call MDC. before the parent thread creates a new child thread. The getcopyofcontextmap () method takes out the MDC content and passes it to the child thread

2) The child thread calls MDC before performing the operation The setcontextmap () method sets the MDC content of the parent thread to the child thread

Code implementation:

1) Use Aop to intercept requests, the same as above

2) log4j log configuration is the same as above

3) Decorator mode decorates sub threads in two ways

4.2.1 implementation mode 1 - Decorative Runnable

Use the decorator mode to decorate the Runnable interface, and create the MDCRunnable class to decorate the Runnable interface.

When creating the MDCRunnable class, save the MDC value of the current thread, and then execute the run() method

public class MDCRunnable implements Runnable{

private Runnable runnable;

/**
 * Saves the MDC value of the current main thread
 */
private final Map<String, String> mainMdcMap;

public MDCRunnable(Runnable runnable) {
    this.runnable = runnable;
    this.mainMdcMap = MDC.getCopyOfContextMap();
}

@Override
public void run() {
    // Assign the MDC value of the parent thread to the child thread
    for (Map.Entry<String, String> entry : mainMdcMap.entrySet()) {
        MDC.put(entry.getKey(), entry.getValue());
    }
    // Execute the decorated thread run method
    runnable.run();
    // Remove MDC value at the end of execution
    for (Map.Entry<String, String> entry : mainMdcMap.entrySet()) {
       MDC.remove(entry.getKey());
    }
  }
}

Test: use MDCRunnable instead of Runnable

@PostMapping("/test")
public String test(@RequestBody String str){
    log.info("get into test Request method");
    SmsThreadPoolUtil.getInstance().execute(new MDCRunnable(new Runnable() {
        @Override
        public void run() {
            log.info("Sub thread 1 executes the task");
        }
    }));
    executorService.execute(new MDCRunnable(new Runnable() {
        @Override
        public void run() {
            log.info("Sub thread 2 executes the task");
        }
    }));

    log.info("test End of method execution");
    return str;
}

[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.857 DEBUG [nio-9999-exec-1] o.s.c.l.LogFormatUtils(traceDebug:91) : Read "application/json;charset=UTF-8" to ["{
    "str":"11111111"
}"]
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.863  INFO [nio-9999-exec-1] c.t.c.TestController(test:41) : get into test Request method
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.865  INFO [pool-3-thread-1] c.t.c.TestController$1(run:45) : Sub thread 1 executes the task
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.865  INFO [nio-9999-exec-1] c.t.c.TestController(test:55) : test End of method execution
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.865  INFO [pool-2-thread-1] c.t.c.TestController$2(run:51) : Sub thread 2 executes the task
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.871 DEBUG [nio-9999-exec-1] o.s.w.s.m.m.a.AbstractMessageConverterMethodProcessor(writeWithMessageConverters:268) : Using 'text/plain', given [*/*] and supported [text/plain, */*, application/json, application/*+json]
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.872 DEBUG [nio-9999-exec-1] o.s.c.l.LogFormatUtils(traceDebug:91) : Writing ["{
    "str":"11111111"
}"]

4.2.2 implementation mode 2 - decorative thread pool

public class MDCThreadPoolExecutor extends ThreadPoolExecutor {
public MDCThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue) {
    super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
}

public MDCThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                    BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory) {
    super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory);
}

public MDCThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                    BlockingQueue<Runnable> workQueue, RejectedExecutionHandler handler) {
    super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, handler);
}

public MDCThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                    BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory,
                                    RejectedExecutionHandler handler) {
    super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
}

@Override
public void execute(final Runnable runnable) {
    // The content in the MDC of the parent thread must be obtained before the run method. Otherwise, when the asynchronous thread executes, the value in the MDC may have been cleared, and null will be returned at this time
    final Map<String, String> context = MDC.getCopyOfContextMap();
    super.execute(new Runnable() {
        @Override
        public void run() {
            // Pass the MDC content of the parent thread to the child thread
            MDC.setContextMap(context);
            try {
                // Perform asynchronous operations
                runnable.run();
            } finally {
                // Empty MDC content
                MDC.clear();
            }
        }
    });
  }
}

Test: replace ThreadPoolExecutor with MDCThreadPoolExecutor

public class SmsThreadPoolUtil {
	//Define type
	private static ThreadPoolExecutor pool=new MDCThreadPoolExecutor(10, 20,
			10, TimeUnit.SECONDS, new LinkedBlockingDeque<Runnable>(10000), new RejectedPoolUtils());
	
	public static ThreadPoolExecutor getInstance() {
		return pool;
	}
}

@Service
@Slf4j
public class RejectedPoolUtils implements RejectedExecutionHandler{
	@Override
	public void rejectedExecution(Runnable r, ThreadPoolExecutor executor) {
		log.info("Maximum number of queues reached");
	}
}

@PostMapping("/test")
public String test(@RequestBody String str){
    log.info("get into test Request method");
    SmsThreadPoolUtil.getInstance().execute(new Runnable() {
        @Override
        public void run() {
            log.info("Sub thread 1 executes the task");
        }
    });
    log.info("test End of method execution");
    return str;
}