WebFluxとMDCの相性の悪さ

Springで一般的に利用されているSpring WebMVCであればこの問題に遭遇することはない。

WebFluxとWebMVCで大きく異なっているのはリクエスト・レスポンスを処理する際のスレッドの扱いにある。
WebFluxで使用されるEventLoopThreadはSpringMVCと異なり、1リクエストを複数のスレッドで処理する。

ところが、MDCの実装はLocalThreadに依存している。つまり、MDCを実行したスレッドにはMDCの情報があるが、そうでないスレッドではMDCの情報が存在せず、ログに出ない。

本番リリースギリギリでこの事象を踏み抜いてしまった私が、その調査結果をここに記す。

先駆者

• Line公式アカウントのチャットシステムにおけるSpringおよびWebFluxの活用事例
• Passing Context with Spring WebFlux

上記２つでは、このテーマよりも一歩高度な、WebFluxでMDCを複数アプリケーション間で伝播させる方法について述べている。これは別記事で掘り下げたい。

本題

答えは次の記事に掲示されており、
- Logging with Context in Spring WebFlux (Part II)

コンテキストという機能と、logOnNext,logOnError, putの３つのメソッドにある。
ちなみに、ここで言うコンテキスト(Context)とはReactorの文脈である。ドキュメントとしてもReactorに記載があるのこれを参照してほしい。

簡単に言うと、コンテキストとは、「リアクティブな環境下でデータを伝播させることのできる」仕組みであり、これを利用することでMDCをまともに機能させることができる。
(データの伝播にはサブスクリプション伝播メカニズムというのが関わってるらしく、この先までは自分は理解していない。が、上記のドキュメント9.8.2でそれっぽい解説が書かれているぞ！)

このままではあまり記事としての価値が薄いのでそれぞれのメソッドを掘り下げておく。

ざっくり何やってるのか

• LogHelper.javaではpublic static final String CONTEXT_MAP = "context-map";という定義がされている。
• logOnNextやlogOnErrorはコンテキストを定数CONTEXT_MAPのKey値で参照する。コンテキストはMapのようなI/Fをしているので、それでValueを拾っている。それをMDCに突っ込んでログを出力し、動作し終わるとMDCをクリアする。
• putはコンテキストに定数CONTEXT_MAPで書き込みを行っている。

logOnNext(正常時にMDCが有効なログを出力する)

  public static <T> Consumer<Signal<T>> logOnNext(
    Consumer<T> log) {
    return signal -> {
      if (signal.getType() != SignalType.ON_NEXT) return;
      Optional<Map<String, String>> maybeContextMap
        = signal.getContext().getOrEmpty(CONTEXT_MAP);
      if (maybeContextMap.isEmpty()) {
        log.accept(signal.get());
      } else {
        MDC.setContextMap(maybeContextMap.get());
        try {
          log.accept(signal.get());
        } finally {
          MDC.clear();
        }
      }
    };

logOnNextはWebFluxのdoOnEachメソッドと組み合わせて使用する。
signal.getType() != SignalType.ON_NEXT がミソであり、このメソッドは異常系の呼び出しの際には反応しない。あくまで正常にデータが伝播したときに発火してログを出す。

logOnError(異常時にMDCが有効なログを出力する)

  public static <T> Consumer<Signal<T>> logOnError(
    Consumer<Throwable> log) {
    return signal -> {
      if (!signal.isOnError()) return;
      Optional<Map<String, String>> maybeContextMap
        = signal.getContext().getOrEmpty(CONTEXT_MAP);
      if (maybeContextMap.isEmpty()) {
        log.accept(signal.getThrowable());
      } else {
        MDC.setContextMap(maybeContextMap.get());
        try {
          log.accept(signal.getThrowable());
        } finally {
          MDC.clear();
        }
      }
    };
  }

logOnErrorも、大枠はlogOnNextと大差ない。しかし、参照するシグナルが変わっており、こちらはエラーシグナルに反応してログを出す。
つまり、メソッドの終端でlogOnXXXを使った場合、正常に終わればErrorは呼ばれないし、異常に終わればNextは呼ばれない。

put(MDCをコンテキストに書き込む)

  public static Function<Context, Context> put(String key, String value) {
    return ctx -> {
      Optional<Map<String, String>> maybeContextMap =
        ctx.getOrEmpty(CONTEXT_MAP);
      if (maybeContextMap.isPresent()) {
        maybeContextMap.get().put(key, value);
        return ctx;
      } else {
        Map<String, String> ctxMap = new HashMap<>();
        ctxMap.put(key, value);
        return ctx.put(CONTEXT_MAP, ctxMap);
      }
    };

putの役割は単純明快で、コンテキストにデータを保存するだけのものだ。
利用方法だが、下記のように行う。

.subscriberContext(put("hogehogeId", response.getHogehogeId().toString()))

subscriberContextは、ドキュメントを見る限り一連の処理におけるコンテキストを生成するもののようだ。putは定数CONTEXTを拾って追加し、新しくコンテキストを返すので、データの伝播のチェーン内では延々とMDCに値を突っ込める。

おわり

そもそもリアクティブな環境でMDC使ってることが無理やりなのかも？
いい方法あったら教えて下さい。
この記事は自ブログの書きなぐりを加筆修正、部分抜粋して掲載しました。