SpringのWebアプリで、ログインユーザをlogに出力する方法として、
Interceptor+MDCを使う際、HandlerInterceptor ではなく、
AsyncHandlerInterceptor を使いましょうという話。

logでカスタム情報を表示する

Logbackを使うと以下のような感じでログフォーマットを指定できる。

logback.xml

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss,SSS} %X{userid} %level %msg%n</pattern>
        </encoder>
    </appender>

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

この時、ログレベルや時間のようなもの以外にカスタムで値を設定することができる。

InterceptorでMDCを設定

以下はuseridをカスタムで設定するサンプル。

MdcInterceptor.java

package com.sample.interceptor;

import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.HandlerInterceptor;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

@Component
public class MdcInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        MDC.put("userid", "sample-user");
        log.info("begin");
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        log.info("end");
        MDC.clear();
    }
}

log

2021-04-03 06:07:04 sample-user INFO begin
2021-04-03 06:07:04 sample-user INFO end

上記のMDCはスレッドごとに設定される。
そのため、スレッドプールを使うアプリケーションでは、
ちゃんとクリアしないと関係ない処理のlogで設定した内容が出力される。

HandlerInterceptorの注意点

HandlerInterceptor を使ってMDCを設定するサンプルはググると割と出てきたが、
ちょっとした罠がある。
HandlerInterceptor は非同期処理を実行した場合、
そのスレッドで postHandle や afterCompletion が実行されない。
そのため、以下のような流れで処理が行われてスレッドAの MDC がクリアされず、
他の処理でスレッドAを使った時に過去に設定したユーザ情報がある。

スレッドAで preHandle が実行される。
非同期スレッドBで preHandle が実行される。
非同期スレッドBで afterCompletion が実行される。

改めて読んだら、ちゃんとドキュメントに書いてあった。

非同期処理のシナリオでは、メインスレッドが postHandle および afterCompletion コールバックをレンダリングまたは呼び出さずに終了する間、ハンドラーは別のスレッドで実行される場合があります。ハンドラーの同時実行が完了すると、モデルのレンダリングを続行するためにリクエストがディスパッチされ、この契約のすべてのメソッドが再度呼び出されます。その他のオプションと詳細については、org.springframework.web.servlet.AsyncHandlerInterceptor を参照してください

そういう訳で HandlerInterceptor ではなく、
AsyncHandlerInterceptor で書いておいたほうが無難である。

MdcInterceptor.java

package com.sample.interceptor;

import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.AsyncHandlerInterceptor;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

@Component
public class MdcInterceptor implements AsyncHandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        MDC.put("userid", "sample-user");
        log.info("begin");
        return true;
    }

    @Override
    public void afterConcurrentHandlingStarted(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        log.info("end");
        MDC.clear();
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        log.info("end");
        MDC.clear();
    }
}

MDCを使う時HandlerInterceptorを使うのはやめた方が良い

logでカスタム情報を表示する

InterceptorでMDCを設定

HandlerInterceptorの注意点