Spring Boot ErrorController logging with Logback MDC

Question

(UPDATE: My question seems to be same as this one, but it has no effective answer.)

I'm trying logging on Spring Boot ErrorController, but it's logs don't have MDC value.

@Controller
@RequestMapping("/error")
@RequiredArgsConstructor
@Slf4j
public class MyErrorController implements ErrorController {

    private final ErrorAttributes errorAttributes;

    @Override
    public String getErrorPath() {
        return null;
    }

    @RequestMapping
    @ResponseBody
    public Map<String, String> error(final HttpServletRequest request) {
        final ServletWebRequest webRequest = new ServletWebRequest(request);
        final Throwable th = errorAttributes.getError(webRequest);

        if (th != null) {
            // **Logged without "requestId" value**
            log.error("MyErrorController", th);
        }

        return Map.of("result", "error");
    }
}

// http://logback.qos.ch/manual/mdc.html#autoMDC
public class MDCFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response,
        final FilterChain filterChain)
        throws ServletException, IOException {

        final String requestId = UUID.randomUUID().toString();

        MDC.put("requestId", requestId);

        try {
            filterChain.doFilter(request, response);
        } finally {
            MDC.remove("requestId");
        }
    }

}

@Configuration
public class MyConfig {

    @Bean
    public FilterRegistrationBean<MDCFilter> mdcFilter() {
        final FilterRegistrationBean<MDCFilter> bean = new FilterRegistrationBean<>();
        bean.setFilter(new MDCFilter());
        bean.addUrlPatterns("/*");
        bean.setOrder(Ordered.HIGHEST_PRECEDENCE);
        return bean;
    }
}

logback-spring.xml:

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <!-- encoders are assigned the type
         ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] requestId:%X{requestId} %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="debug">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

result(requestId value does not appear):

18:15:13.705 [http-nio-8080-exec-1] requestId: ERROR c.e.l.MyErrorController - MyErrorController
java.lang.RuntimeException: Error occured.
...

Here is complete code.

I think that I need to adapt MDCFilter before DispatcherServlet, but I don't know how to do it.

Answer 1

Remove MDC data on ServletRequestListener#requestDestroyed() instead of on Filter.

On Tomcat StandardHostValve fires RequestDestroyEvent after ErrorController executing.

            // Look for (and render if found) an application level error page
            if (response.isErrorReportRequired()) {
                // If an error has occurred that prevents further I/O, don't waste time
                // producing an error report that will never be read
                AtomicBoolean result = new AtomicBoolean(false);
                response.getCoyoteResponse().action(ActionCode.IS_IO_ALLOWED, result);
                if (result.get()) {
                    if (t != null) {
                        throwable(request, response, t); // *ErrorController is executed*
                    } else {
                        status(request, response);
                    }
                }
            }

            if (!request.isAsync() && !asyncAtStart) {
                context.fireRequestDestroyEvent(request.getRequest()); // *RequestDestroyEvent is fired*
            }

So, implement following:

public class MDCClearListener implements ServletRequestListener {

    @Override
    public void requestDestroyed(final ServletRequestEvent sre) {
        MDC.remove("requestId");
    }
}

    @Bean
    public ServletListenerRegistrationBean<MDCClearListener> mdcClearListener() {
        final ServletListenerRegistrationBean<MDCClearListener> bean = new ServletListenerRegistrationBean<>();
        bean.setListener(new MDCClearListener());
        bean.setOrder(Ordered.HIGHEST_PRECEDENCE);
        return bean;
    }

(Concrete code exists on solution branch.)

---

About related question's answer

This answer does not fit for me. Because:

The first way does not use ErrorController but @ExceptionHandler, so cannot catch exceptions thrown by Spring Security Filter. (Try answer/exceptionhandler-with-springsecurity branch code.)

The second way puts UUID on interceptor, so logged diffrent requestId between MyController and MyErrorController. This is not "request" id. (Try answer/interceptor branch code.)

Answer 2

Everything works as expected.

This is the logged line:

08:19:34.204 [http-nio-8080-exec-2] MY_MDC_VALUE DEBUG o.s.web.servlet.DispatcherServlet - Failed to complete request: java.lang.RuntimeException: Error occured.

What you've posted is the log from MyErroController

08:19:34.209 [http-nio-8080-exec-2]  ERROR c.e.l.MyErrorController - MyErrorController

And as you do call

MDC.clear();

the MDC is empty when this log statement is executed.