Sunday 27 February 2022

Logback: MDC logging example

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

 

 

 

 

 

 

Previous                                                 Next                                                 Home

No comments:

Post a Comment