Hello, everyone. I’m Chen

When a failure occurs, we often need to retrieve all logs from a request flow to locate it.

If the request is processed in only one thread, we can filter the log by thread ID, but if the request involves processing by asynchronous threads, the thread ID alone is insufficient.

Huawei IoT platform provides the capability to receive data reported by devices. After the data arrives on the platform, the platform performs complex service logic processing, such as data storage, rule engine, data push, and command delivery. Because there is no strong coupling between this logic, it is usually handled asynchronously. This article describes how to quickly filter out all service logs contained in a data report request.

1, the body

The SLF4J logging framework provides an MDC(Mapped Diagnostic Context) utility class, which Google translates as a Mapped Diagnostic context.

public class Main {

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

        // The entry passes in the request ID
        MDC.put(KEY, UUID.randomUUID().toString());
        
        // Prints logs
        logger.debug("log in main thread 1");
        logger.debug("log in main thread 2");
        logger.debug("log in main thread 3");

        // Exit remove request IDMDC.remove(KEY); }}Copy the code

We call the mdC.put () method at the entrance to main 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 and running the main function, 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
Copy the code

It is obvious from the log that the curly braces contain the (mapped) requestId (requestId), which is the key (context) that we used to locate (diagnose) the problem. With the MDC tool, you can use grep requestId= XXX *. Log to quickly filter out all logs of a request when faults are located on the live network by inserting put() and remove() codes on the interface or section.

2, advanced

However, are MDC tools as convenient as we think they are? Going back to where we started, a request might involve multi-threaded asynchronous processing, so does it still work in a 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) {

        // The entry passes in the request ID
        MDC.put(KEY, UUID.randomUUID().toString());

         
        logger.debug("log in main thread");

         
        new Thread(new Runnable() {
            @Override
            public void run(a) {
                logger.debug("log in other thread");
            }
        }).start();

        // Exit remove request IDMDC.remove(KEY); }}Copy the code

In the code we start an asynchronous thread and print the log in the run() method of the anonymous Runnable object. 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
Copy the code

Unfortunately, the request ID is not printed in asynchronous threads. What’s going on here?

To solve this problem, we need to understand how MDC works. The reason MDC doesn’t work in asynchronous threads is because the underlying data structure is ThreadLocal, and the request ID we pass in by calling mdC.put () is valid only for the current thread.

Those interested can delve into the code details for themselves.

Once we know how this works, we can solve this problem easily by writing a new MDCRunnable class that decorates the Runnable interface using decorator mode.

The MDC values of the current thread are saved when the MDCRunnable class is created, and then copied to the asynchronous thread when the run() method is executed.

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;
        // Save the MDC value of the current thread
        this.map = MDC.getCopyOfContextMap();
    }

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

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) {

        // The entry passes in the request ID
        MDC.put(KEY, UUID.randomUUID().toString());

         
        logger.debug("log in main thread");

         
        new Thread(new MDCRunnable(new Runnable() {
            @Override
            public void run(a) {
                logger.debug("log in other thread");
            }
        })).start();

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

Executing the main function outputs the following log:

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
Copy the code

Congratulations! As a result of our efforts, we finally have requestId prints in both asynchronous threads and thread pools!

3, summarize

This article showed you how to use the MDC tool to quickly filter all logs for a single request and to enable the MDC tool to work in asynchronous threads through the decorator pattern.

With MDC, and with AOP to embed requestId on all facets, you can filter out logs for arbitrary processes throughout the system.

The MDC tool greatly reduces the time for troubleshooting and improves the development efficiency during self-testing. During operation, maintenance (O&M), you can quickly collect related log information to speed up analysis.