

([Stack Overflowとのマルチポスト](https://stackoverflow.com/q/66865224/4506703)になります)

Spring Boot の ログ出力情報としてリクエスト単位で固有の値を共通的に付与したいと考えています。  
この目的のため、Logback
MDCを利用し[リファレンスの例7.5](http://logback.qos.ch/manual/mdc_ja.html#autoMDC)を参考にして後述のように実装しました。

この実装では、Spring
MVCの通常のcontrollerなどでは想定通り所望の情報(今回の実装では`requestId`の値)が付与されてログ出力されるのですが、
[`ErrorContoller`](https://docs.spring.io/spring-
boot/docs/2.4.4/reference/htmlsingle/#boot-features-error-handling)
実装クラスのログ出力では付与されませんでした。

`ErrorController`に実装した処理が実行されるのは`MDCFilter`を抜けてからだ(`MDC.remove()`が実行された後だからだ)、という原因は理解できるのですが、ではどのように実装すれば良いのか、というのがわかりません。

(`DispatcherServlet`よりも先に`MDCFilter`が適用されるようにすれば良いように思われたのですが、その実現方法がわかりませんでした。)

[code]

    @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) {
                // ここで出力したログにMDCの値(requestId)が付与されない
                log.error("MyErrorController", th);
            }
    
            return Map.of("result", "error");
        }
    }
    
[/code]

[code]

    // 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");
            }
        }
    
    }
    
[/code]

[code]

    @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;
        }
    }
    
[/code]

`logback-spring.xml`:

[code]

    <configuration>
        <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
            <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>
    
[/code]

実行結果("`requestId:`" の後ろにUUIDが出力されて欲しいが、そうなっていない):

[code]

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

([完全なコードはこちら](https://github.com/yukihane/logging-with-mdc-demo))

* * *

類似の質問として次のようなものを見つけました(が、明確な回答は寄せられていないようでした):

  * [Preserve custom MDC attributes during exception-handling in Spring Boot](https://stackoverflow.com/q/55146885/4506703) \- Stack Overflow
  * [How can I make the MDC available during logging in a spring controller advice?](https://stackoverflow.com/q/44257548/4506703) \- Stack Overflow


CC BY-SA 4.0
2021-03-30T17:06:18.170
74991
2023-09-30T08:02:50.360
2021-03-31T01:51:38.257
2808
2808
question
spring-boot tomcat logging
Spring Boot ErrorController のログに Logback MDC の情報を付与したい


「`remove`せず放置する」というのも対策のひとつとして考えられるかと思います。

有効でなくなった情報を保持したままにする、というのは確かにあまり行儀は良くないですが、実際のところ、今回ユーザリクエストを処理したスレッドは近い将来また別のユーザリクエストを処理するために再利用されるでしょう。  
そのタイミングで有効な情報で上書きされるため、実害はまず発生しないと思われます。

リクエストの都度MDCをクリアする必要があるかの質問はこちらにありました。検討の参考になるかもしれません:

  * [Do we need clear MDC after HTTP request in Spring](https://stackoverflow.com/q/42414643/4506703) \- Stack Overflow


CC BY-SA 4.0
2021-03-30T21:05:18.377
74993
2021-03-30T21:05:18.377
2808
74991
answer


処理を追ってみたところ、`ErrorController`は、Tomcatの[`StandardHostValve#invoke()`](https://github.com/apache/tomcat/blob/9.0.44/java/org/apache/catalina/core/StandardHostValve.java#L169-L186)から実行されていました。  
次の引用箇所の `throwable(request, response, t);` から呼ばれています。

[code]

    final class StandardHostValve extends ValveBase {
    ...
        @Override
        public final void invoke(Request request, Response response)
            throws IOException, ServletException {
    ...
                // 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 が呼ばれる**
                        } else {
                            status(request, response);
                        }
                    }
                }
    
                if (!request.isAsync() && !asyncAtStart) {
                    context.fireRequestDestroyEvent(request.getRequest());
                }
    ...
        }
    ...
    }
    
[/code]

その処理の後、`context.fireRequestDestroyEvent(request.getRequest());`が呼ばれているのが見て取れます。  
このイベントを拾って MDC をクリアすれば良さそうです。

* * *

このイベントを受け取るには
[`ServletRequestListener`](https://spring.pleiades.io/specifications/platform/8/apidocs/javax/servlet/servletrequestlistener#requestDestroyed-
javax.servlet.ServletRequestEvent-)を実装し登録します:

[code]

    public class MDCClearListener implements ServletRequestListener {
    
        @Override
        public void requestDestroyed(final ServletRequestEvent sre) {
            MDC.remove("requestId");
        }
    }
    
[/code]

[code]

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

上記の実装を行って実行したところ、所望の結果を得ることができました("`requestId:`"の後にUUIDが出力されている):

[code]

    22:09:19.294 [http-nio-8080-exec-1] requestId:82debc7b-5834-49d1-aba7-738c8b50d581 ERROR c.e.l.MyErrorController - MyErrorController
    java.lang.RuntimeException: Error occured.
    ...
    
[/code]

(完全なコードは同じリポジトリの[`solution`ブランチ](https://github.com/yukihane/logging-with-mdc-
demo/tree/solution)にあります)

* * *

類似の質問として質問文に記載しているものに[新たに回答](https://stackoverflow.com/a/66913638/4506703)が付いていたのでこちらについて評価します。  
結論としては、あまり適切な方法ではないと考えます。

まず、1つめの方法として挙げらているのは、
`ErrorController`でなく`@ExceptionHandler`によってエラーをハンドリングする方法です。  
これは、Spring MVCのエラーハンドリングを行う場合には利用可能ですが、それ以外、例えばSpring Securityはハンドリングできません。  
[`answer/exceptionhandler-with-springsecurity`
ブランチ](https://github.com/yukihane/logging-with-mdc-
demo/tree/answer/exceptionhandler-with-springsecurity)で挙動を試すことができます。

なお、この辺りのエラーハンドリングの機構についてはこちらで解説されている方がいらっしゃいます:

  * [SpringBootの例外ハンドリング](https://qiita.com/haseesah/items/6b0f0fcfe681734e2617) \- Qiita

2つめの方法はインターセプタを用いる方法です。  
この方法を採用すると、Controller呼び出しの都度MDCが上書きされます。つまり、`MyErrorController`で出力されるIDは、それまでの処理に振られていたIDと変わってしまい、"リクエストID"では無くなってしまっています(同じリクエストでも異なるUUIDが振られてしまう)。

[`answer/interceptor` ブランチ](https://github.com/yukihane/logging-with-mdc-
demo/tree/answer/interceptor)で試すことができます。


CC BY-SA 4.0
2021-04-01T13:26:41.107
75031
2021-04-03T02:52:04.297
2021-04-03T02:52:04.297
2808
2808
74991
answer