MDC: A Better Way of Logging

Introduction

Nowadays, most real-world applications consist of a web application and REST service, i.e. deployed on a remote server. Web applications are built using a client application framework, while the REST service consists of a group of microservices. Unlike a traditional application where a page is loaded with a single request per page, a modern application consists of a single page (SPA) and needs multiple service requests to load. Each service request hops over multiple microservices to process the request. This poses a challenge in analyzing logs when multiple clients concurrently access the application.

Problem

In a traditional application, a separate thread from the thread pool processes a client request. Once the request is completed, the thread is returned to the thread pool. Typical logs generated in that case looks like this:

17:25:16,371 http-8080-3 INFO Service1.execute(77) | Handling request for service

17:25:16,430 http-8080-3 INFO Service1.execute(77) | Requesting data from database

17:25:16,479 http-8080-3 INFO Service1.execute(77) | Completed request

In case of multiple concurrent users accessing the application, a separate thread will process each request. This request will overlap and so the logs will be interleaved. Below are the log output:

17:25:16,371 http-8080-3 INFO Service1.execute(77) | Handling request for service

17:25:16,381 http-8080-6 INFO Service1.execute(77) | Handling request for service

17:25:16,430 http-8080-3 INFO Service1.execute(77) | Requesting data from database

17:25:16,479 http-8080-3 INFO Service1.execute(77) | Completed request

17:25:16,480 http-8080-6 INFO Service1.execute(77) | Requesting data from database

17:25:16,580 http-8080-6 INFO Service1.execute(77) | Completed request

In the above case, two users have logged in and are retrieving data from the database. If you inspect it carefully, it is easy to unravel which log statement belongs to which request by differentiating with thread ID. This thread-based correlation of logs is a useful technique to identify all the logs from a single request. However, with this technique, we could not differentiate which request belongs to which user. Now, things get even messier when multiple service hops are required to process a request or when multi-threading is implemented.  Consider the following example where two users log in and access Service1 concurrently. Service1 retrieves the data from the database and then calls Service2. Service 2 retrieves data from the database and returns the following:

public class Service1 {  

   private static final Logger LOGGER = Logger.getLogger(Service1.class);  

   public String getDataFromService1(String id){         

          LOGGER.info("Handling request for service 1");

          String (id);

          String (data1);

          LOGGER.info("Completed request");

          return data2;

   }  

   public String getDataFromDatabase(String data){

          LOGGER.info("Requesting data from database");

          String dataFromDatbase=connectToDatabaseAndRetriveData(data);

          LOGGER.info("Completed request");

          return dataFromDatbase;

   }

   public String callService2(String data){

          restServiceCallToService2(data);

   }

}

public class Service2 {

private static final Logger LOGGER = Logger.getLogger(Service2.class);  

   public String getDataFromService2(String id){         

          LOGGER.info("Handling request for service 2");

          String (id);        

          LOGGER.info("Completed request");

          return data1;

   } 

   public String getDataFromDatabase(String data){

          LOGGER.info("Requesting data from database");

          String dataFromDatbase=connectToDatabaseAndRetriveData(data);

          LOGGER.info("Completed request");

          return dataFromDatbase;
   }     

}

17:25:16,371 http-8080-3 INFO Service1.execute(77) | Handling request for service 1

17:25:16,372 http-8080-6 INFO Service1.execute(77) | Handling request for service 1

17:25:16,425 http-8080-6 INFO Service1.execute(112) | Requesting data from database

17:25:16,430 http-8080-3 INFO Service1.execute(112) | Requesting data from database

17:25:16,443 http-8080-3 INFO Service1.execute(120) | Completed request

17:25:16,479 http-8080-6 INFO Service1.execute(120) | Completed request

17:25:16,492 http-8080-7 INFO Service2.execute(50) | Handling request for service 2

17:25:16,500 http-8080-7 INFO Service2.execute(89) | Requesting data from database

17:25:16,512 http-8080-9 INFO Service2.execute(50) | Handling request for service 2

17:25:16,540 http-8080-9 INFO Service2.execute(89) | Requesting data from database

17:25:16,576 http-8080-7 INFO Service2.execute(113) | Completed request

17:25:16,580 http-8080-7 INFO Service2.execute(55) | Completed request

17:25:16,585 http-8080-9 INFO Service2.execute(113) | Completed request

17:25:16,600 http-8080-9 INFO Service2.execute(55) | Completed request

17:25:16,614 http-8080-3 INFO Service1.execute(90) | Completed request

17:25:16,640 http-8080-6 INFO Service1.execute(90) | Completed request

It is not clear from the above logs which thread ID belongs to which user and how the request has been processed. It is clearly visible that logs don’t contain all the information. Some additional information needs to be added in the logs.

Solution

 One of the approaches could be to generate a unique number when the request enters the service and print it with every log statement.  This will solve the problem of tracking the request across different servers. However, this would not distinguish between separate page loads. We also wanted to avoid the dependence on using the server-side state, if possible.

Another solution would be to print the user ID, session ID, and request ID for every log statement. Both session ID and request ID would be generated on the client side. Session ID should be unique for every session generated by the user. Whenever a user logs in, a unique session ID should be generated and maintained on the client side until the user logs out. It will help in tracking what the active user has performed. Request ID can be a sequential number concatenated with the session ID, which is unique for every request from the user. It will help in identifying a request in case there is a concurrent request from multiple users. Also, it is useful in tracking a request when processing a request requires multiple service hops. These identifiers (user id, session id, and request ID) are passed as an HTTP header with each request and, ultimately, appended to each log line

Implementation

One of the ways to implement this is to pass the userId , sessionId  , and requestId explicitly to each and every log statements, which is a tedious and repetitive task. An example is demonstrated below: 

LOGGER.info(“UserId:”+userId+” Session Id:”+sessionId+” Requestid:”+requestId+ "Handling request for service 1" );

This is not the most elegant way of implementation since there is a lot of hard coding to do for every log statement.

Another solution is to use mapped diagnostic context (MDC). The MDC provides a simple key/value mechanism to capture small amounts of custom diagnostic data. Since it's built into the logging framework, it's really easy to add values from the MDC to each log line. MDC is supported by log4j, log4j2, and SL4J/logback.

MDC allows us to fill a map-like structure with pieces of information that are accessible to the appender when the log message is actually written. The MDC structure is internally attached to the executing thread in the same way a ThreadLocal variable would be.

The high-level idea is:

• At the start of the thread, fill MDC with pieces of information that are required  to make available to the log appender
• Log the message

MDC also provides an API to remove any information that is added to MDC. The salient parts of the MDC class are shown below. Please refer to the MDC javadocs for a complete list of methods:

public class MDC {
//Put a context value as identified by key
//into the current thread's context map.
public static void put(String key, String val);

//Get the context identified by the key parameter.
public static String get(String key);

//Remove the context identified by the key parameter.
public static void remove(String key);

//Clear all entries in the MDC.
public static void clear();
}

The MDC class only contains static methods. It lets the developer place information in a diagnostic context, which can be subsequently retrieved by the logging components. If the logging component is configured appropriately, it will automatically retrieve this information from the thread context and include in each log entry. The MDC manages contextual information on a per-thread basis; any child thread does not automatically inherit a copy of the mapped diagnostic context of its parent.

While implementing microservices, the best practice to add information to the MDC is in the interceptor layer. This is the single place where the call to service passes through.

The example listed below implements a HandlerInterceptorAdapter interface. In the overridden method,preHandle, it reads from the HTTP request header,  UserId, sessionId , and RequestId  and adds it to the MDC.

publicclass ServiceInterceptor extends HandlerInterceptorAdapter {

    /**

     * The Logger for the Class.

     */

    privatefinalstatic Logger LOGGER = Logger.getLogger(ServiceInterceptor.class);   

    @Override

    publicboolean preHandle(HttpServletRequest request, HttpServletResponse response, Object object) throws Exception {

       MDC.put("userId", request.getHeader("UserId"));

        MDC.put("sessionId ", request.getHeader("SessionId"));

        MDC.put("requestId", request.getHeader("RequestId"));

}

The pattern of the appender should also be changed in order to retrieve the variables stored in the MDC.  %X is the key in this layout pattern. It is used to output the MDC associated with the thread, which generates the logging event. The X conversion character is followed by the key for the map placed between braces, as in %X{userId}  where userId  is the key. The value in the MDC corresponding to the key will be the output.

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> 
<layout>
<Pattern>%X{userId} %X{sessionId} %X{requestId} - %m%n</Pattern>
</layout> 
</appender>

We re-run the same code by changing the appender and adding the interceptor. In conclusion, the following logs were generated:

17:53:25,496 http-8080-20 INFO Service1.execute(77)    U1001          a55ceb00b7641432 a55ceb00b7641432_1     Handling request for service 1

17:53:25,497 http-8080-26 INFO Service1.execute(77)    U1002          dr5677mnj389234k          dr5677mnj389234k_1     Handling request for service 1

17:53:25,550 http-8080-26 INFO Service1.execute(112) U1002          dr5677mnj389234k          dr5677mnj389234k_1     Requesting data from database

17:53:25,555 http-8080-20 INFO Service1.execute(112) U1001          a55ceb00b7641432         a55ceb00b7641432_1     Requesting data from database

17:53:25,568 http-8080-20 INFO Service1.execute(120) U1001          a55ceb00b7641432         a55ceb00b7641432_1     Completed request

17:53:25,584 http-8080-26 INFO Service1.execute(120) U1002          dr5677mnj389234k          dr5677mnj389234k_1     Completed request

17:53:25,617 http-8080-27 INFO Service2.execute(50)    U1001          a55ceb00b7641432         a55ceb00b7641432_1     Handling request for service 2

17:53:25,615 http-8080-27 INFO Service2.execute(89)    U1001          a55ceb00b7641432         a55ceb00b7641432_1     Requesting data from database

17:53:25,637 http-8080-29 INFO Service2.execute(50)    U1002          dr5677mnj389234k          dr5677mnj389234k_1     Handling request for service 2

17:53:25,665 http-8080-29 INFO Service2.execute(89)    U1002          dr5677mnj389234k          dr5677mnj389234k_1     Requesting data from database

17:53:25,701 http-8080-27 INFO Service2.execute(113) U1001          a55ceb00b7641432         a55ceb00b7641432_1     Completed request

17:53:25,705 http-8080-27 INFO Service2.execute(55)    U1001          a55ceb00b7641432         a55ceb00b7641432_1     Completed request

17:53:25,710 http-8080-29 INFO Service2.execute(113) U1002          dr5677mnj389234k          dr5677mnj389234k_1     Completed request

17:53:25,725 http-8080-29 INFO Service2.execute(55)    U1012          dr5677mnj389234k          dr5677mnj389234k_1     Completed request

17:53:25,739 http-8080-20 INFO Service1.execute(90)    U1001          a55ceb00b7641432         a55ceb00b7641432_1     Completed request

17:53:25,765 http-8080-26 INFO Service1.execute(90)    U1002          dr5677mnj389234k          dr5677mnj389234k_1     Completed request.