In this post, I am going to explain how to use Mapped Diagnostic Context (MDC) to improve application logs.
Let me explain simple HelloWorld application first.
HelloWorld.java
package com.sample.app;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
public class HelloWorld {
private static Logger logger = LoggerFactory.getLogger(HelloWorld.class);
public static void main(String[] args) {
Logger logger = LoggerFactory.getLogger(HelloWorld.class);
MDC.put("transactionId", "AAddd-1223-W");
logger.trace("Trace message");
logger.debug("Debug message");
logger.info("Info message");
logger.warn("Warning message");
logger.error("Error message");
}
}
MDC.put("transactionId", "AAddd-1223-W");
Attaching a transactionId to MDC
How can I print the information in MDC while logging?
In logback.xml <pattern> element follow below syntax to access the value associated with the key MDC_KEY_NAME.
%X{MDC_KEY_NAME}
logback.xml
<configuration scan="true" scanPeriod="15 seconds">
<appender name="STDOUT"
class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%X{transactionId} %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n
</pattern>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="STDOUT" />
</root>
</configuration>
When you ran HelloWorld application, you will see below messages in console.
AAddd-1223-W 10:51:46.430 [main] INFO com.sample.app.HelloWorld - Info message AAddd-1223-W 10:51:46.432 [main] WARN com.sample.app.HelloWorld - Warning message AAddd-1223-W 10:51:46.432 [main] ERROR com.sample.app.HelloWorld - Error message
As you see above output, a transactionId ‘AAddd-1223-W’ is attached to every logger.
Where can I use this MDC?
When you are working in multi-threaded environment or client-server applications, your application needs to server parallel requests and which leads to interleaved log messages.
Let us see how clumsy the log messages without context.
MDCDemo.java
package com.sample.app;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class MDCDemo {
private static Logger logger = LoggerFactory.getLogger(MDCDemo.class);
private static void sleep(int noOfSeconds) {
try {
TimeUnit.SECONDS.sleep(noOfSeconds);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
static class MyTask implements Runnable {
@Override
public void run() {
logger.info("Started processing the request");
sleep(1);
logger.info("Got user details");
sleep(1);
logger.info("order placed");
sleep(1);
logger.info("Sent notification to the user");
}
}
public static void main(String args[]) {
ExecutorService executor = Executors.newFixedThreadPool(3);
for (int i = 0; i < 5; i++) {
executor.submit(new MyTask());
}
executor.shutdown();
}
}
Sample Output
15:55:42.898 INFO com.sample.app.MDCDemo - Started processing the request 15:55:42.898 INFO com.sample.app.MDCDemo - Started processing the request 15:55:42.898 INFO com.sample.app.MDCDemo - Started processing the request 15:55:43.901 INFO com.sample.app.MDCDemo - Got user details 15:55:43.901 INFO com.sample.app.MDCDemo - Got user details 15:55:43.901 INFO com.sample.app.MDCDemo - Got user details 15:55:44.903 INFO com.sample.app.MDCDemo - order placed 15:55:44.903 INFO com.sample.app.MDCDemo - order placed 15:55:44.903 INFO com.sample.app.MDCDemo - order placed 15:55:45.903 INFO com.sample.app.MDCDemo - Sent notification to the user 15:55:45.903 INFO com.sample.app.MDCDemo - Sent notification to the user 15:55:45.903 INFO com.sample.app.MDCDemo - Sent notification to the user 15:55:45.903 INFO com.sample.app.MDCDemo - Started processing the request 15:55:45.903 INFO com.sample.app.MDCDemo - Started processing the request 15:55:46.905 INFO com.sample.app.MDCDemo - Got user details 15:55:46.905 INFO com.sample.app.MDCDemo - Got user details 15:55:47.910 INFO com.sample.app.MDCDemo - order placed 15:55:47.910 INFO com.sample.app.MDCDemo - order placed 15:55:48.913 INFO com.sample.app.MDCDemo - Sent notification to the user 15:55:48.913 INFO com.sample.app.MDCDemo - Sent notification to the user
Let’s improvise logging using MDC.
Let me attach some unique identifier to the task using MDC.
MDC.put("transactionId", "MyTask-" + counter.getAndIncrement());
Refer the transactionId in appender encoder pattern.
<appender name="STDOUT"
class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%X{transactionId} %d{HH:mm:ss.SSS} %-5level %logger{36} -
%msg%n
</pattern>
</encoder>
</appender>
Find the below working application.
Create logback.xml file under src/main/resources folder.
logback.xml
<configuration scan="true" scanPeriod="15 seconds">
<appender name="STDOUT"
class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%X{transactionId} %d{HH:mm:ss.SSS} %-5level %logger{36} -
%msg%n
</pattern>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="STDOUT" />
</root>
</configuration>
Define MDCDemo class.
MDCDemo.java
package com.sample.app;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
public class MDCDemo {
private static Logger logger = LoggerFactory.getLogger(MDCDemo.class);
private static void sleep(int noOfSeconds) {
try {
TimeUnit.SECONDS.sleep(noOfSeconds);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
static class MyTask implements Runnable {
private static AtomicInteger counter = new AtomicInteger(1);
@Override
public void run() {
MDC.put("transactionId", "MyTask-" + counter.getAndIncrement());
logger.info("Started processing the request");
sleep(1);
logger.info("Got user details");
sleep(1);
logger.info("order placed");
sleep(1);
logger.info("Sent notification to the user");
}
}
public static void main(String args[]) {
ExecutorService executor = Executors.newFixedThreadPool(3);
for (int i = 0; i < 5; i++) {
executor.submit(new MyTask());
}
executor.shutdown();
}
}
Output
As you see the output, MyTask-* is added to every log message.
You can download complete working application from below link.
https://github.com/harikrishna553/java-libs/tree/master/logback/mdc-logging-demo
No comments:
Post a Comment