Preserve custom MDC attributes during exception-handling in Spring Boot

Question

Short Version (With Enough Details)

How to preserve the MDC attribute added in a doFilter() method of a javax.servlet.Filter implementation ...

public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
    try {
        MDC.put("token", MyToken.random()); // add the MDC attribute related to the current request processing
        chain.doFilter(request, response); // send the request to other filters and the Controller
    } finally {
        MDC.clear(); // MDC attribute must be removed so future tasks executed on the same thread would not log invalid information
    }
}

... during exception handling if an exception occurs in another filter or in the Controller (the call to chain.doFilter(...)).

Currently, if an exception occurs: the finally block would be executed, clearing the MDC, and then the exception would be thrown out of the filter. All the logs during the exception handling will not contain the MDC attribute.

Long Version (Overly Detailed)

I have a simple Filter implementation to intercept all requests. It only creates a random string of characters (a token) to be included in all logs related to processing the request.

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class RequestFilter implements Filter {
    @Override
    public void init(FilterConfig filterConfig) {
    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        try {
            MDC.put("token", MyToken.random());
            chain.doFilter(request, response);
        } finally {
            MDC.clear();
        }
    }

    @Override
    public void destroy() {
    }
}

The sequence of events would be:

1. The request is received.
2. My doFilter() is called, adding the random token to MDC.
3. The request is processed by calling chain.doFilter().
4. Whatever happens (processing finished, error occurred), the MDC is cleared of the random token in the finally block.

The problem is that if an error occurs and it is processed (e.g. by a custom ErrorController implementation), the related logs do not include the token:

[2019.03.13 15:00:14.535] token:308...8bf [DEBUG] 8124 [https-jsse-nio-8443-exec-7] o.s.w.s.DispatcherServlet                  : GET "/resource", parameters={}
[2019.03.13 15:00:14.551] token:308...8bf [DEBUG] 8124 [https-jsse-nio-8443-exec-7] o.s.w.s.DispatcherServlet                  : Completed 400 BAD_REQUEST
[2019.03.13 15:00:14.551] token:          [DEBUG] 8124 [https-jsse-nio-8443-exec-7] o.s.w.s.DispatcherServlet                  : "ERROR" dispatch for GET "/error", parameters={}
[2019.03.13 15:00:14.551] token:          [DEBUG] 8124 [https-jsse-nio-8443-exec-7] o.s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public org.springframework.http.ResponseEntity myproj.CustomErrorController.handleError(javax.servlet.http.HttpServletRequest)
[2019.03.13 15:00:14.551] token:          [ERROR] 8124 [https-jsse-nio-8443-exec-7] m.CustomErrorController                    : HTTP Error: Bad Request (400)
[2019.03.13 15:00:14.551] token:          [DEBUG] 8124 [https-jsse-nio-8443-exec-7] o.s.w.s.DispatcherServlet                  : Exiting from "ERROR" dispatch, status 400

The finally block is executed when the exception is thrown from the Controller which handles it, resulting in clearing the MDC.

Error handling (including the custom ErrorController) is executed after this, which means there is no more token in the related logs.

How can I add a custom token to all the logs related to the entire processing of the request from receiving it until sending a response, including error handling? I want the MDC to be cleared after a response has been sent by the thread, as the last action. The MDC should be cleared regardless of what happens (successful response, exception thrown during error handling, etc).

With multiple clients using the Rest service simultaneously, logs can get really messed up. Having a unique token attached to each log produced during the entire handling process of a certain request would greatly simplify debugging.

Answer 1

It seems to work well that clearing MDC on ServletRequestListener#requestDestroyed(), instead of on Filter.

(Here is concrete example.)

Answer 2

There are two ways to define mechanism for generating token for requests.

The first way is to define a filter and wrap the DispatcherServlet like this:

import org.slf4j.MDC;
import org.springframework.stereotype.Component;

import java.io.IOException;
import java.util.UUID;

import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.annotation.WebFilter;

@Component
@WebFilter
public class RequestFilter implements Filter {

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        try {
            MDC.put("token", UUID.randomUUID().toString());
            chain.doFilter(request, response);
        } finally {
            MDC.clear();
        }
    }

}

and change mapping url for DispatcherServlet in application.properties

server.servlet.context-path=/api
spring.mvc.servlet.path=/

That way is applicable if you can change url mapping for DispatcherServlet, and you should have default exception handler definition like this:

@ExceptionHandler({ Exception.class })
public void handleException(Exception e) {
   log.error("Error: ", e);
}

otherwise can be logs without token in console. If the above conditions do not apply, use the second method.

The second way is to use the Interceptor, the configuration is as follows:

public class MDCInterceptor implements HandlerInterceptor {

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

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        MDC.clear();
    }
}

And add interceptor in configuration

@Configuration
public class WebMvcConfiguration implements WebMvcConfigurer {

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(new MDCInterceptor());
    }
}

Above configuration has MDC.clear() in postHandle method, because after exception the afterCompletion method is executed immediately and will clear the MDC. The second method covers all cases of adding a token to log messages.

Answer 3

you can use ServletRequestListener instead,

for example:

import org.slf4j.MDC;
import org.springframework.stereotype.Component;

import javax.servlet.ServletRequestEvent;
import javax.servlet.ServletRequestListener;
import java.util.UUID;

@Component
public class MyServletRequestListener implements ServletRequestListener {

    @Override
    public void requestInitialized(ServletRequestEvent requestEvent) {
        MDC.put("token", UUID.randomUUID().toString());
    }

    @Override
    public void requestDestroyed(ServletRequestEvent requestEvent) {
        MDC.clear();
    }
}

Answer 4

A standard servlet filter is executed around any servlet, including Spring's DispatcherServlet (see, for example, here) but your filter is a Spring component. Since it doesn't use any Spring bean you can easily convert it to a plain filter, that is a filter configured in the web.xml as described in the page I linked.