Source: wudashan.com/2018/02/15/Log-Request-In-MutiThread

01. Preface

When the existing network fails, we often need to obtain all logs in the request process for location. If the request is processed in only one thread, we can filter the log through the thread ID, but if the request contains asynchronous thread processing, it is difficult to rely on the thread ID alone.

The Huawei IoT platform provides the ability to receive the data reported by the equipment. When the data reaches the platform, the platform will carry out some complex business logic processing, such as data storage, rule engine, data push, command issuance, etc. Since there is no strong coupling between this logic, it is usually processed asynchronously. This article describes how to quickly filter out all business logs contained in a data submission request.

02. Text

The SLF4J log framework provides an MDC(Mapped Diagnostic Contexts) tool class. Google translates it into a mapped diagnostic context, which is difficult to understand literally. We can practice it first.

public class Main {

    private static final String KEY = "requestId";
    private static final Logger logger = LoggerFactory.getLogger(Main.class);
    
    public static void main(String[] args) {

        // Entry incoming request ID
        MDC.put(KEY, UUID.randomUUID().toString());
        
        // Print log
        logger.debug("log in main thread 1");
        logger.debug("log in main thread 2");
        logger.debug("log in main thread 3");

        // Exit removal request ID
        MDC.remove(KEY);

    }

}

We call the MDC.put() method at the entry of the main function to pass in the request ID, and the MDC.remove() method at the exit to remove the request ID. After configuring the log4j2.xml file, run the main function, and you can see the following log output on the console:

2018-02-17 13:19:52.606 {requestId=f97ea0fb-2a43-40f4-a3e8-711f776857d0} [main] DEBUG cn.wudashan.Main - log in main thread 1
2018-02-17 13:19:52.609 {requestId=f97ea0fb-2a43-40f4-a3e8-711f776857d0} [main] DEBUG cn.wudashan.Main - log in main thread 2
2018-02-17 13:19:52.609 {requestId=f97ea0fb-2a43-40f4-a3e8-711f776857d0} [main] DEBUG cn.wudashan.Main - log in main thread 3

It is obvious from the log that the curly braces contain the (mapped) request ID(requestId), which is actually the keyword (context) for us to locate (diagnose) the problem. With the MDC tool, as long as put() and remove() codes are implanted in the interface or section, we can quickly filter out all logs of a request through grep requestId=xxx *.log when locating problems in the current network.

03. Advanced

However, is the MDC tool really as convenient as we think? Back to the beginning, a request may involve multi-threaded asynchronous processing, so can it work normally in the multi-threaded asynchronous scenario? Talk is cheap, show me the code.

public class Main {

    private static final String KEY = "requestId";
    private static final Logger logger = LoggerFactory.getLogger(Main.class);

    public static void main(String[] args) {

        // Entry incoming request ID
        MDC.put(KEY, UUID.randomUUID().toString());

        // Main thread print < font style = "color: #1e6bb8; word wrap: break word; font weight: bold; border bottom: 1px solid" > log < / font >
        logger.debug("log in main thread");

        // Asynchronous thread printing < font style = "color: #1e6bb8; word wrap: break word; font weight: bold; border bottom: 1px solid" > log < / font >
        new Thread(new Runnable() {
            @Override
            public void run() {
                logger.debug("log in other thread");
            }
        }).start();

        // Exit removal request ID
        MDC.remove(KEY);

    }

}

In the code, we create a new asynchronous thread and print the log in the run() method of the anonymous object Runnable. Run the main function, and you can see the following log output on the console:

2018-02-17 14:05:43.487 {requestId=e6099c85-72be-4986-8a28-de6bb2e52b01} [main] DEBUG cn.wudashan.Main - log in main thread
2018-02-17 14:05:43.490 {} [Thread-1] DEBUG cn.wudashan.Main - log in other thread

Unfortunately, the request ID is not printed in the asynchronous thread. What's going on? To solve this problem, we must know the implementation principle of MDC. Due to limited space, we will not introduce it in detail here. The reason why MDC does not take effect in asynchronous threads is that the underlying layer uses ThreadLocal as the data structure. The request ID passed in by calling MDC.put() method is only valid in the current thread. Interested partners can go deep into the code details themselves.

Knowing the principle, it is easy to solve this problem. We can use the decorator pattern to write a new MDCRunnable class to decorate the Runnable interface. Save the MDC value of the current thread when creating the MDCRunnable class, and copy the saved MDC value to the asynchronous thread when executing the run() method. The code implementation is as follows:

public class MDCRunnable implements Runnable {

    private final Runnable runnable;

    private final Map<String, String> map;

    public MDCRunnable(Runnable runnable) {
        this.runnable = runnable;
        // Saves the MDC value of the current thread
        this.map = MDC.getCopyOfContextMap();
    }

    @Override
    public void run() {
        // Pass in the saved MDC value
        for (Map.Entry<String, String> entry : map.entrySet()) {
            MDC.put(entry.getKey(), entry.getValue());
        }
        // Decorator mode, execute the run method
        runnable.run();
        // Remove saved MDC values
        for (Map.Entry<String, String> entry : map.entrySet()) {
            MDC.remove(entry.getKey());
        }
    }
    
}

Next, we need to decorate the Runnable implementation class created in the main function:

public class Main {

    private static final String KEY = "requestId";
    private static final Logger logger = LoggerFactory.getLogger(Main.class);
    private static final ExecutorService EXECUTOR = Executors.newSingleThreadExecutor();

    public static void main(String[] args) {

        // Entry incoming request ID
        MDC.put(KEY, UUID.randomUUID().toString());

        // Main thread print < font style = "color: #1e6bb8; word wrap: break word; font weight: bold; border bottom: 1px solid" > log < / font >
        logger.debug("log in main thread");

        // Asynchronous thread prints < font style = "color: #1e6bb8; word wrap: break word; font weight: bold; border bottom: 1px solid" > log < / font >, and decorates Runnable with MDCRunnable
        new Thread(new MDCRunnable(new Runnable() {
            @Override
            public void run() {
                logger.debug("log in other thread");
            }
        })).start();

        // The asynchronous thread pool prints logs and decorates the Runnable with MDCRunnable
        EXECUTOR.execute(new MDCRunnable(new Runnable() {
            @Override
            public void run() {
                logger.debug("log in other thread pool");
            }
        }));
        EXECUTOR.shutdown();

        // Exit removal request ID
        MDC.remove(KEY);

    }

}

Executing the main function will output the following logs:

2018-03-04 23:44:05.343 {requestId=5ee2a117-e090-41d8-977b-cef5dea09d34} [main] DEBUG cn.wudashan.Main - log in main thread
2018-03-04 23:44:05.346 {requestId=5ee2a117-e090-41d8-977b-cef5dea09d34} [Thread-1] DEBUG cn.wudashan.Main - log in other thread
2018-03-04 23:44:05.347 {requestId=5ee2a117-e090-41d8-977b-cef5dea09d34} [pool-2-thread-1] DEBUG cn.wudashan.Main - log in other thread pool

Congratulations! After our efforts, the requestId is finally printed in both asynchronous threads and thread pools!

04. Summary

This article describes how to use MDC tool to quickly filter all logs of a request, and make MDC tool effective in asynchronous threads through decorator mode. With MDC, you can filter out the logs of any process of the whole system by implanting requestId into all aspects through AOP technology.

Using MDC tools in the development self-test stage can greatly save the time of locating problems and improve the development efficiency; In the operation and maintenance stage, relevant log information can be quickly collected to speed up the analysis.

Recent hot article recommendations:

1.1000 + Java interview questions and answers (2021 latest version)

2.Stop playing if/ else on the full screen. Try the strategy mode. It's really fragrant!!

3.what the fuck! What is the new syntax of xx ≠ null in Java?

4.Spring Boot 2.6 was officially released, a wave of new features..

5.Java development manual (Songshan version) is the latest release. Download it quickly!

Feel good, don't forget to like + forward!