SpringWebFluxでMDCを使用する

2020-02-02T20:08:08

SpringWebFluxでMDCを使用する

この記事は下記に加筆修正版があります
-> ログ出力の話
-> アプリケーション間伝播の話(まだ)

WebFluxとMDCの相性の悪さ

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

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

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

では、SpringWebFluxとMDCを併用する方法がないのか、と言えばそうではない。下記のStackOverFlowではいくつかの解決方法が述べられている

https://stackoverflow.com/questions/58104396/logback-mdc-on-netty-or-any-other-non-blocking-io-server

この中で回答者の一人が下記のように述べている。

Basically you need to somehow tie the traceId to the request/connection, and each time you start processing for that connection, set the traceId in the MDC for the current thread.

つまり、Threadでなにか処理、終端をするたびにMDCを作成・クリアするような仕組みが必要になる。

ざっと調べたところLINEの発表や、

Spring界隈では有名であろうブログに記載があった。

https://ndportmann.com/passing-context-with-spring-webflux/

コンテキストを利用する

上述したLINEやブログの内容には、トレースIDやリクエスト情報を複数のアプリケーションに渡って伝播する方法が述べられている。
この中で共通して利用されているのがコンテキストである。

コンテキストを使ってロギングする方法について国内の情報は乏しいが、英語圏ではいくらかの情報が出てくる例えば下記である

https://blog.pragmatists.com/unobvious-traps-of-spring-webflux-16924a0d76d5

また具体的な方法として、Kotlinであるが下記記事が引用されている

https://www.novatec-gmbh.de/en/blog/how-can-the-mdc-context-be-used-in-the-reactive-spring-applications/

ここでいうContextとはReactorの話であるので、ドキュメントとしてはReactorを参照するのが正しいようだ。

https://projectreactor.io/docs/core/release/reference/#context

具体的な話

コンテキストとは、MDCに変わり、リアクティブな環境下においてもコンテキストを保存できるようにしたReactorの仕組みであることが上記の記事で説明されている。

すなわち、コンテキストから情報を取り出してMDCに保存し、処理の終了とともにMDCをクリアすることで、MVCとほぼかわらずlogbackを使ったロギングができるということだ。

実装方法

例示その1 複数アプリケーション間でのコンテキストの伝播

最初に上げたブログには具体的なコードが載っている。
一つは、下記のようなコードである。

import org.springframework.core.Ordered;
import org.springframework.core.annotation.Order;
import org.springframework.http.HttpHeaders;
import org.springframework.http.server.reactive.ServerHttpRequest;
import org.springframework.http.server.reactive.ServerHttpResponse;
import org.springframework.stereotype.Component;
import org.springframework.web.server.ServerWebExchange;
import org.springframework.web.server.WebFilter;
import org.springframework.web.server.WebFilterChain;
import reactor.core.publisher.Mono;
import reactor.util.context.Context;

import java.util.Map;

import static java.util.stream.Collectors.toMap;
import static jp.co.example.helper.LogHelper.*;

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class MdcHeaderFilter implements WebFilter {
  private static final String MDC_HEADER_PREFIX = "X-MDC-";

  @Override
  public Mono<Void> filter(
    ServerWebExchange ex,
    WebFilterChain chain) {
    ex.getResponse().beforeCommit(
      () -> addContextToHttpResponseHeaders(ex.getResponse())
    );

    return chain.filter(ex)
      .subscriberContext(
        ctx -> addRequestHeadersToContext(ex.getRequest(), ctx)
      );
  }

  private Context addRequestHeadersToContext(
    final ServerHttpRequest request,
    final Context context) {

    final Map<String, String> contextMap = request
      .getHeaders().toSingleValueMap().entrySet()
      .stream()
      .filter(x -> x.getKey().startsWith(MDC_HEADER_PREFIX))
      .collect(
        toMap(v -> v.getKey().substring(MDC_HEADER_PREFIX.length()),
          Map.Entry::getValue
        )
      );

    // 例えばCookieをいれたければこうすればよい
    String cookie = request.getCookies().containsKey("EXAMPLE") ?
      request.getCookies().getFirst("EXAMPLE").getValue() : "none";
    contextMap.put("example-cookie", cookie);

    return context.put(CONTEXT_MAP, contextMap);
  }

  private Mono<Void> addContextToHttpResponseHeaders(
    final ServerHttpResponse res) {

    return Mono.subscriberContext().doOnNext(ctx -> {
      if (!ctx.hasKey(CONTEXT_MAP)) return;

      final HttpHeaders headers = res.getHeaders();
      ctx.<Map<String, String>>get(CONTEXT_MAP).forEach(
        (key, value) -> headers.add(MDC_HEADER_PREFIX + key, value)
      );
    }).then();
  }
}

このコードの目的は、早い話が掲題の通り、複数アプリケーション間でのコンテキストの伝播である。

すなわち、MDC_HEADER_PREFIX に指定されている X-MDC-プレフィックスがついたヘッダーをWebFilterですべてCONTEXT_MAPコンテキストに格納しているものである。

また、レスポンスを返すときにはCONTEXT_MAPからMDC_HEADER_PREFIXをつけてヘッダーに乗せている。こうすることで、この実装がなされたアプリケーション間ではコンテキストデータのやり取りが可能になる。

例示その2 コンテキストデータをMDCで扱う

そもそも本稿の目的はこっちである。

件のブログではlogOnNext, logOnError, putの3つのヘルパーが記載されている。

import org.slf4j.MDC;
import reactor.core.publisher.Signal;
import reactor.core.publisher.SignalType;
import reactor.util.context.Context;

import java.util.HashMap;
import java.util.Map;
import java.util.Optional;
import java.util.function.Consumer;
import java.util.function.Function;

public final class LogHelper {
  public static final String CONTEXT_MAP = "context-map";

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

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

  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

まずはputヘルパーである。
これが行なっていることはコンテキストへのデータの格納である。

利用方法は難しくなく、対象の処理に対し下記のように利用する。
.subscriberContext(put("hogehogeId", response.getHogehogeId().toString()))

subscriberContextはサブスクライブ時に参照されるため、早期にコンテキストにデータを格納可能である

logOnNext, logOnError

logOnNext, logOnErrorはそれぞれ、コンテキストを利用したログ出力をサポートするヘルパーである。

例えば下記のように扱う

.doOnEach(logOnNext(s -> log.info("begin: inputFrom")))

.doOnEach(logOnError(throwable -> log.info("入力フォーム表示で例外.", throwable)))

それぞれ、ヘルパー関数内でSignalというデータを参照しており、logOnNextは正常時に、logOnErrorは異常時にのみ実行される用になっている。

これらのヘルパーはMDCへの登録、MDCのクリアを行なっているため安全に利用可能である。