How to trace logs across distributed applications/microservices in Spring Boot?

Logging is so critical to applications.

Good logging strategy can help you fix issues in production environment quickly and help you save time and money.

With the adoption of microservices , proper logging has got even more importance.

One of the difficulties in debugging microservices is that the flow of API requests are spread across different API’s and it is hard to trace the logs with respect to a particular request.

Also logs will not be printed in sequence in a live environment where there are a large number of concurrent hits.

To resolve this issue in Spring Boot you can make use of MDC (Mapped Diagnostic Context) provided by slf4j (available by default in Spring Boot applications)

At a high level , it just takes three major steps:

Step 1:

Generate a random request tracing id and put in MDC context (MDC is a class provided by slf4j) like this :

MDC.put("tracingId", UUID.randomUUID().toString());

This has to be done for every API request.

To avoid duplicating this across all requests , you can use Spring Handler Interceptor.

Step 2:

By default Spring Boot prints the logs in a predefined pattern.

You can override the pattern in application.properties by setting the property “logging.pattern.console”.

You just need to append the tracing id along with the other log messages using %X symbol

Here is an example:

logging.pattern.console = %d{yyyy-MM-dd HH:mm:ss.SSS} tracing ID: %X{tracingId}  [%t] %-5level %logger{36} - %msg %n

Step 3:

For every subsequent requests to other API’s send the tracing id in the HTTP header.

And in those API’s retrieve the tracing id from the header and put it in MDC context (MDC.put()).

This can be done the same way as before using Spring Boot Handler Interceptor.

Here are the steps in detail:

STEP 1: Generate a tracing Id

Let us assume there is a rest service named /firstService.

This service makes a call to another service named /secondService.

And the second service in turn calls another service named /thirdService.

These are three different distributed applications/microservices.

They all are developed by you and you have added enough logs in them.

The only problem you have is in tracing the logs as they are scattered all over the place.

As explained earlier , to resolve this , create a handler interceptor which intercepts all requests and generates a tracing ID for each request.

Here is the one I created for the FIRST service:

package com.spring.restclient;

import java.util.UUID;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.HandlerInterceptor;

@Component
public class LogInterceptor implements HandlerInterceptor {

	@Override
	public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
			throws Exception {
		
		MDC.put("tracingId", UUID.randomUUID().toString());
		return HandlerInterceptor.super.preHandle(request, response, handler);
	}

	@Override
	public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
			throws Exception {
		
		
		MDC.remove("tracingId");
		HandlerInterceptor.super.afterCompletion(request, response, handler, ex);
	}

}

Notice that a unique random id is generated using UUID class (from java.util package) and put in MDC context using MDC.put() method. This is done in the preHandle() method which is called before every HTTP request.

Once the request completes clear the key by using MDC.remove() method to be on the safer side.

Register the above handler interceptor for Spring to recognize it by creating a configuration class as below:

package com.spring.restclient;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;

@Component
public class InterceptorConfig implements WebMvcConfigurer{

	
	@Autowired
	private LogInterceptor logInterceptor;
	
	@Override
	public void addInterceptors(InterceptorRegistry registry) {
		registry.addInterceptor(logInterceptor);
	}

	
	
}

STEP 2: Print the tracing id in the logs

To print the tracing id in the logs configure the logging pattern using the keyword “logging.pattern.console” if you are printing to the console or “logging.pattern.file” if you printing to a log file. This needs to be done in application.properties file.

Here is a sample:

logging.pattern.console = %d{yyyy-MM-dd HH:mm:ss.SSS} tracing ID: %X{tracingId}  [%t] %-5level %logger{36} - %msg %n

Notice the tracing id printed after %X symbol (rest all are common messages printed in logs like date and time ,thread name, logger level ,logger name and the log message)

If you run the application after adding this you can see the tracing id printed in the logs.

Here is the ouput I got :

2020-10-27 21:10:49.587 tracing ID: 35047473-c97b-47ba-b4b2-009fca4335ad  [http-nio-8081-exec-3] INFO  c.spring.restclient.SampleRestClient - Starting first service  method 
 2020-10-27 21:10:49.593 tracing ID: 35047473-c97b-47ba-b4b2-009fca4335ad  [http-nio-8081-exec-3] INFO  c.spring.restclient.SampleRestClient - Invoking exchange method of rest template for first service 
 2020-10-27 21:10:49.625 tracing ID: 35047473-c97b-47ba-b4b2-009fca4335ad  [http-nio-8081-exec-3] INFO  c.spring.restclient.SampleRestClient - Returning response for first service 

Notice the tracing id 35047473-c97b-47ba-b4b2-009fca4335ad. This is generated for every request and is unique for each API request.

STEP 3: Pass the tracing Id to other APIs in HTTP header

As earlier mentioned , the first service /firstservice calls another service /secondservice.

While doing so it sets the tracing Id in the header as shown in below code:

package com.spring.restclient;

import java.util.Map;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.http.HttpEntity;
import org.springframework.http.HttpHeaders;
import org.springframework.http.HttpMethod;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.client.RestTemplate;

@RestController
public class SampleRestClient {

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

	@GetMapping("/firstservice")
	public Map<String, String> test() {

		logger.info("Starting first service  method");
		String url = "http://localhost:8080/secondservice";

		RestTemplate template = new RestTemplate();

		logger.info("Invoking exchange method of rest template for first service");
		
		HttpHeaders headers = new HttpHeaders();
		headers.add("tracingId", MDC.get("tracingId"));
		HttpEntity requestEntity = new HttpEntity<>(headers);
		
		
		ResponseEntity<Map> response = template.exchange(url, HttpMethod.GET, requestEntity, Map.class);

		logger.info("Returning response for first service");

		return response.getBody();
	}
}

And the /secondservice API retrieves this tracing Id from the header and puts it in MDC context in the same way as done in Step 1.

Here is the LogInterceptor of the second service:

package com.spring.restservice;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.HandlerInterceptor;

@Component
public class LogInterceptor implements HandlerInterceptor {

	@Override
	public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
			throws Exception {

		String tracingId = request.getHeader("tracingId");
		MDC.put("tracingId", tracingId);
		return HandlerInterceptor.super.preHandle(request, response, handler);
	}

	@Override
	public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
			throws Exception {

		MDC.remove("tracingId");
		HandlerInterceptor.super.afterCompletion(request, response, handler, ex);
	}

}

In preHandle() method tracing Id is obtained from the header . Register this interceptor in a Configuration file as done before. Also set the “logging.pattern.console” in application.properties file in the same way as done for the first service.

The below logs got printed on invoking the /firstservice (which calls this /secondservice)

2020-10-27 21:10:49.603 tracing ID: 35047473-c97b-47ba-b4b2-009fca4335ad  [http-nio-8080-exec-2] INFO  c.s.restservice.SampleRestController - Starting secondservice  
 2020-10-27 21:10:49.608 tracing ID: 35047473-c97b-47ba-b4b2-009fca4335ad  [http-nio-8080-exec-2] INFO  c.s.restservice.SampleRestController - Invoking exchange method of rest template for second service 
 2020-10-27 21:10:49.620 tracing ID: 35047473-c97b-47ba-b4b2-009fca4335ad  [http-nio-8080-exec-2] INFO  c.s.restservice.SampleRestController - Returning response for second service 

Notice that the tracing Id is the same.

The same process is repeated for the third service.

Here is the log printed by the third service:

2020-10-27 21:10:49.615 tracing ID: 35047473-c97b-47ba-b4b2-009fca4335ad  [http-nio-8082-exec-2] INFO  c.e.thirdservice.ThirdController - Started third service  
 2020-10-27 21:10:49.615 tracing ID: 35047473-c97b-47ba-b4b2-009fca4335ad  [http-nio-8082-exec-2] INFO  c.e.thirdservice.ThirdController - Returning response  

Again the tracing id is the same.

Here is the request I made through postman :

Here is the Controller classes of the second and third APIs:

Second service:

package com.spring.restservice;

import java.util.Map;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.http.HttpEntity;
import org.springframework.http.HttpHeaders;
import org.springframework.http.HttpMethod;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.client.RestTemplate;

@RestController
public class SampleRestController {

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

	@GetMapping("/secondservice")
	public Map<String, String> restService() {

		logger.info("Starting secondservice ");
		String url = "http://localhost:8082/thirdservice";

		RestTemplate template = new RestTemplate();
		HttpHeaders headers = new HttpHeaders();
		headers.add("tracingId", MDC.get("tracingId"));
		HttpEntity requestEntity = new HttpEntity<>(headers);

		logger.info("Invoking exchange method of rest template for second service");
		ResponseEntity<Map> response = template.exchange(url, HttpMethod.GET, requestEntity, Map.class);

		logger.info("Returning response for second service");

		return response.getBody();

	}
}

Third service:

package com.example.thirdservice;

import java.util.HashMap;
import java.util.Map;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class ThirdController {

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

	@GetMapping("/thirdservice")
	public Map<String, String> thirdservice() {

		logger.info("Started third service");

		Map<String, String> map = new HashMap<>();
		map.put("message", "This is the third controller responding!");

		logger.info("Returning response");
		return map;
	}
}

That’s it!

2 thoughts

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s