Structured logging in logback using MDC

General Use Case

When any application fails in production then it is necessary is to track how the execution went. For this the standard approach is to add logs. Logs can be helpful in tracking how the execution went but tracking the execution becomes more difficult in multithreaded applications. The logs start to get jumbled for various threads. We can obviously start naming our threads and add the thread names in the logs but sometimes we need more information for tracking our business logic.

An Example

A simple example would be a web application. Suppose in an e-commerce application User “Rohan” is browsing the product “Shampoo”. Then a error occurs and we find that Rohan was browsing Shampoo. Now to understand how execution went we need to find all logs for when Rohan was browsing shampoo. The question is how do we proceed with finding all the logs?

Ad hoc solution

When this error occurs sometimes we realize that our logs don’t enough information to filter out all the logs for the situation easily so we go to our code and add

[code]
log.info("Username " + username + ",product " + product + " <REST OF LOG>" );
[/code]

Then we run again and notice that someone missed one log so we need to add this to that log.info or log.debug. Also in future whenever we add new log we need to remember to add this information to that log also. It becomes tedious and error-prone.

Better Solution – MDC

We can use MDC to solve this problem. This provides us with the ability to add this key value pair information to whole blocks of code.

An example application is present on github if you want a simple running application faster.

We can have classes like below

[code]
public class Log {

private static Logger logger = LoggerFactory.getLogger(Log.class);

public static void main(String[] args) {
try {
MDC.put("username", "Rohan");
logger.debug("Rohan logs in");
new Log2().main();
} finally {
MDC.remove("username");
}
}

}

public class Log2 {

Logger logger = LoggerFactory.getLogger(Log2.class);

public void main() {
try {
MDC.put("product", "Shampoo");
logger.info("staring at the screen");

} finally {
MDC.remove("product");
}
logger.info("browsing done");
}

}

[/code]

When we are starting a new block we use MDC.put to put the key value pair for the log to use from that point onwards. And in finally block we remove the key from MDC.

The key-value remains for all logs in the current thread. We can create another class and we will get the key value pair in our logs there also as long as the thread remains the same.

A sample run of the above can produce something like this

[code]
14:33:49.127 [username=Rohan] [main] DEBUG dummy.Log – Rohan logs in
14:33:49.129 [product=Shampoo, username=Rohan] [main] INFO dummy.Log2 – staring at the screen
14:33:49.129 [username=Rohan] [main] INFO dummy.Log2 – browsing done
[/code]

When a user logs in (in Log class) we put the username in MDC. So as long as the user is logged in all logs will have the user’s name like in the above example have username=Rohan as long as the application is running. Then when we go to some other functionality we can put another key-value pair for filtering those particular logs. In the above example we place product=Shampoo in the logs.

So we can filter all logs for Rohan or all logs when he was browsing Shampoo. And this is much cleaner approach then appending the information in the logs one-by-one.

But how do we decide how this information will be shown in the logs. Like all logging solutions we have a format string which we can use for this.

For the current situation we are using logback for our logging so we have the information in our example with the format

[code]
<pattern>%d{HH:mm:ss.SSS} [%X] [%thread] %-5level %logger{36} – %msg%n</pattern>
[/code]

Here the main part is %X. This gives us the map present in MDC.

MDC has helped us a lot when a lot of devs are working on QA environment and someone needs to test an API. The logs are running and we need to find how a particular API is working. We have been using MDC so we can filter out separate logs via the request ID.

Hope this helps.