Qiita Teams that are logged in
You are not logged in to any team

Log in to Qiita Team
Community
OrganizationEventAdvent CalendarQiitadon (β)
Service
Qiita JobsQiita ZineQiita Blog
0
Help us understand the problem. What are the problem?

More than 1 year has passed since last update.

SpringWebFluxでMDCを使用するにはコンテキストを使うんだってさ

WebFluxとMDCの相性の悪さ

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

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

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

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

先駆者

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

本題

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

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

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

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

ざっくり何やってるのか

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

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

LogHelper.java
  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が有効なログを出力する)

LogHelper.java
  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をコンテキストに書き込む)

LogHelper.java
  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使ってることが無理やりなのかも?
いい方法あったら教えて下さい。
この記事は自ブログの書きなぐりを加筆修正、部分抜粋して掲載しました。

Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
0
Help us understand the problem. What are the problem?