Example source code address:
https://github.com/wudashan/slf4j-mdc-muti-thread

preface

When faults occur on the live network, you often need to obtain all logs in the request process for locating faults. 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.

The body of the

public class Main { private static final String KEY = "requestId"; private static final Logger logger = LoggerFactory.getLogger(Main.class); Public static void main(String[] args) {// static void main(String[] args) {mdc.put (KEY, uuid.randomuuid ().toString()); Logger. debug("log in main thread 1"); logger.debug("log in main thread 2"); logger.debug("log in main thread 3"); // Egress remove request ID mdc.remove (KEY); }}Copy the code

2018-02-17 13:19:52.606 {requestId= f97eA0FB-2A43-40F4-a3E8-711f776857d0} [main] DEBUG cn. Wudashan Thread 1 2018-02-17 13:19:52.609 {requestId= f97eA0FB-2A43-40F4-a3E8-711f776857d0} [main] DEBUG cn. Wudashan 2018-02-17 13:19:52.609 {requestId= f97eA0FB-2A43-40F4-a3E8-711f776857d0} [main] DEBUG cn. Wudashan log in main thread 3Copy the code

The 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) {// static void main(String[] args) {mdc.put (KEY, uuid.randomuuid ().toString()); Logger. debug("log in main thread"); New Thread(new Runnable() {@override public void run() {logger.debug("log in other Thread "); } }).start(); // Egress remove request ID mdc.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 [2018-02-17 14:05:43.490 {} [thread-1] DEBUG cn. WudashanCopy 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 current thread's MDC value this.map = mdC.getCopyofContextMap (); } @override public void run() {// Pass 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 saved MDC values 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) {// static void main(String[] args) {mdc.put (KEY, uuid.randomuuid ().toString()); Logger. debug("log in main thread"); // The asynchronous thread prints a log, Runnable new Thread(new MDCRunnable(new Runnable() {@override public void run() {logger.debug("log in other thread"); } })).start(); // The asynchronous thread pool prints logs, Execute (new MDCRunnable(new Runnable() {@override public void run() {logger.debug("log ")  in other thread pool"); }})); EXECUTOR.shutdown(); // Egress remove request ID mdc.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 Thread 2018-03-04 23:44:05.346 {requestId= 5EE2A117-E090-41D8-977b-cEF5DEA09D34} [THREAD-1] DEBUG cn. Wudashan 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 poolCopy the code

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

conclusion