0

(Stack Overflowとのマルチポストになります)

Spring Boot の ログ出力情報としてリクエスト単位で固有の値を共通的に付与したいと考えています。
この目的のため、Logback MDCを利用しリファレンスの例7.5を参考にして後述のように実装しました。

この実装では、Spring MVCの通常のcontrollerなどでは想定通り所望の情報(今回の実装ではrequestIdの値)が付与されてログ出力されるのですが、 ErrorContoller 実装クラスのログ出力では付与されませんでした。

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

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

@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");
    }
}
// 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">
        <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>

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

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

(完全なコードはこちら)


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

2 件の回答 2

1

処理を追ってみたところ、ErrorControllerは、TomcatのStandardHostValve#invoke()から実行されていました。
次の引用箇所の throwable(request, response, t); から呼ばれています。

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

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


このイベントを受け取るには ServletRequestListenerを実装し登録します:

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

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

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.
...

(完全なコードは同じリポジトリのsolutionブランチにあります)


類似の質問として質問文に記載しているものに新たに回答が付いていたのでこちらについて評価します。
結論としては、あまり適切な方法ではないと考えます。

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

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

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

answer/interceptor ブランチで試すことができます。

0

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

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

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

この質問に回答するには、ログインする必要があります。

求めていた回答ではありませんか? のタグが付いた他の質問を参照する。