Recently, I was going through application logs to find the root cause of a production issue. My application was a microservice that serves HTTP requests. I was having a hard time trying to read the flow of an HTTP request. At the time of development, I thought I could track the request flow, if required, through the Thread ID that is printed in logs.  But now I realize something more is required in logs to track the flow, such as a flow id or correlation id with each log statement. 

In this article, we will be talking about the Mapped Diagnostic Context (MDC) to improve application logging. The idea of MDC is to provide a way for feeding information (e.g. flow id) to the framework where logging actually happens.

I am attaching code snippets to show how to use MDC in a Spring Boot application.

First, we will be creating a request interceptor. This interceptor will check request headers first to see if a correlation id exists. If not, then it will create a new correlation id. Then it will put the correlation id into the MDC and remove it after the request completes. The idea behind checking for the correlation id in headers is that if the request is coming from another microservice then same correlation id should be used for logging.

import org.apache.commons.lang.StringUtils;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.UUID;

@Component
public class CorrelationInterceptor extends HandlerInterceptorAdapter {

    private static final String CORRELATION_ID_HEADER_NAME = "X-Correlation-Id";
    private static final String CORRELATION_ID_LOG_VAR_NAME = "correlationId";

    @Override
    public boolean preHandle(final HttpServletRequest request, final HttpServletResponse response,
                             final Object handler) throws Exception {
        final String correlationId = getCorrelationIdFromHeader(request);
        MDC.put(CORRELATION_ID_LOG_VAR_NAME, correlationId);
        return true;
    }

    @Override
    public void afterCompletion(final HttpServletRequest request, final HttpServletResponse response,
                                final Object handler, final Exception ex) throws Exception {
        MDC.remove(CORRELATION_ID_LOG_VAR_NAME);
    }

    private String getCorrelationIdFromHeader(final HttpServletRequest request) {
        String correlationId = request.getHeader(CORRELATION_ID_HEADER_NAME);
        if (StringUtils.isBlank(correlationId)) {
            correlationId = generateUniqueCorrelationId();
        }
        return correlationId;
    }

    private String generateUniqueCorrelationId() {
        return UUID.randomUUID().toString();
    }
}

Also, we will be configuring the logback-spring.xml file to print the correlation id in the logs. You need to change the pattern tag in the appender, and add %X{correlationId}to it. The X conversion character outputs the MDC associated with the thread issuing the logging request. So it will print the value of field correlationId.

<pattern>%d{dd-MM-yyyy HH:mm:ss.SSS} %thread %X{correlationId} [%-5level] %class{0} - %msg%n</pattern>

The benifit of populating the correlation id in interceptor is that you do not need to change your business logic. If your application is not HTTP based then you can use spring AOP to populate MDC as shown below. Whenever a function of an Authorization Service is invoked, the @Before aspect will populate the correlation id in MDC and after the function been executed, the @After aspect will remove it.

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.slf4j.MDC;
import org.springframework.context.annotation.Configuration;

import java.util.UUID;

@Aspect
@Configuration
public class CorelationIdAspect {
    private static final String CORRELATION_ID_HEADER_NAME = "X-Correlation-Id";
    private static final String CORRELATION_ID_LOG_VAR_NAME = "correlationId";


    @Before(value = "execution(* com.gaurav.services.AuthorizationService.*(..))")
    public void before(JoinPoint joinPoint) {
        final String correlationId = generateUniqueCorrelationId();
        MDC.put(CORRELATION_ID_LOG_VAR_NAME, correlationId);
    }

    @After(value = "execution(* com.gaurav.services.AuthorizationService.*(..))")
    public void afterReturning(JoinPoint joinPoint) {
        MDC.remove(CORRELATION_ID_LOG_VAR_NAME);
    }

    private String generateUniqueCorrelationId() {
        return UUID.randomUUID().toString();
    }
}