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.

Magnum

Your code seems ok to me. As per your filter configuration, your MDC gets cleared after everything has been done. All the dispatcher servlet handling happens-before your "finally" block gets executed. So, logically your trace-id should get printed in all logs. Could you please add a logline in the "finally" block to understand in which order MDC is getting cleared? If I am correct, your logline would be printed at the last indicating somewhere else in your code, MDC is cleared as well. – Neurotic

@MukulBansal I am going to look into this later today and update the question. I now believe that the above might be achievable by adding a custom filter to Spring Security, specifying the explicit order in configuration. Then the MDC gets set and cleared by a filter much closer to the start of the execution chain, possibly also wrapping the exception handling. But I am not sure, maybe the effect is exactly the same and exception handling always takes place last after other filters have been exited. – Magnum

Looking at the source of FilterChainProxy your filter might have been added to the security filter chain (a virtual chain). That could explain the log output. – Endosperm

Answer 1

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();
    }
}

Mendie

Answer 2

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

(Here is concrete example.)

Granniah

Answer 3

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.

Margarita

The Interceptor method won't work. The exception bubbles up and then a "fake" request re-enters the filter/interceptor chain without all of the information that the original request had. – Circumfuse

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.

Streamy

Would a HandlerInterceptor be simpler or even possible? Add the MDC attribute in preHandle() and remove it in afterCompletion()? – Magnum

I'm afraid that any Spring MVC component is managed (i.e. wrapped) by DispatcherServlet but your use case needs something that wraps servlets, that is a standard filter. – Streamy

@anddero: any feedback? Have you tried the standard filter solution? – Streamy

Not yet, I will get back to it as soon as I can thought, thanks! – Magnum

@Streamy can you provide an updated link to a "standard filter" example or documentation. The link you provided in your answer doesn't seem to work for me. I'm also trying to accomplish what the OP is but I'm not sure I'm implementing the right kind of filter. – Soaring

@DaveC Now I have linked an Oracle paper, however any "servlet filters primer" should be good. – Streamy

@Streamy thank you! I implemented a class which extended Filter in my kotlin spring project and still didn't see MDC values coming through. – Soaring

@DaveC Have you configured it in web.xml? Is the server executing it for each request? – Streamy

@Streamy I didn't implement in web.xml. I registered it as a bean. It was intercepting every request. – Soaring

@DaveC As I already said: "I'm afraid that any Spring MVC component is managed (i.e. wrapped) by DispatcherServlet but your use case needs something that wraps servlets, that is a standard filter". The OP hasn't given feedback anymore about this suggestion so you could be the first to give it a try. – Streamy