Quarkus のログにリクエストごとの ID を出力する

ログを眺めている時に、どこからどこまでが1つのリクエストの処理なのか分かりにくかったので、各ログに ID を出す方法を調べてみました。

Laravel の記事の Quarkus 版です。

失敗したアプローチ

最初に試した失敗した例について書いておきます。

リクエストフィルターで logger の MDC に ID を設定する方法です。

@Provider
public class ClassicRequestFilter  implements ContainerRequestFilter {
    private static final Logger log = Logger.getLogger(ClassicRequestFilter.class);

    @Override
    public void filter(ContainerRequestContext requestContext) throws IOException {
        var requestId = UUID.randomUUID();
        MDC.put("req.id", requestId);

        log.info(requestContext.getUriInfo().getRequestUri().toString());
    }
    
}
@Provider
public class ClassicResponseFilter implements ContainerResponseFilter {
    @Override
    public void filter(ContainerRequestContext requestContext, ContainerResponseContext responseContext)
            throws IOException {
        MDC.remove("req.id");
    }
}
quarkus.log.console.format=%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p id=%X{req.id} [%c{3.}] (%t) %s%e%n

この方法では1つ問題があります。MDC は ThreadLocal , つまりスレッドごとに情報を持つのですが、 Java は PHP と違いスレッドが再利用され他のリクエストに情報が受け継がれます。

imperative (reactive じゃない方) なら上記ソースでも問題ないのですが、 reactive の場合はリクエスト処理中に IO 待ちが発生すると待っている間に他のリクエストを処理します。あるスレッドにおいて、リクエスト1→リクエスト2→リクエスト1 のような順で処理されるケースがあるという事です。

reactive に対応するには

ドキュメントを読み漁ってみましたが、 Quarkus というよりもっと深い部分(Vert.x とか)の API を使用しなければならないような雰囲気を感じました。正直そこまでして実現するのは大変なので、もっと簡単な方法がないか調べたところ OpenTracing に行き当たりました。

本来の使い方ではないですが、トレースの単位で ID が発番されるという点でやりたいこととほぼ合致します。

pom.xml に以下の記述を追加し、

    <dependency>
      <groupId>io.quarkus</groupId>
      <artifactId>quarkus-smallrye-opentracing</artifactId>
    </dependency>

application.properties に以下の記述を追加すれば

quarkus.log.console.format=%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p traceId=%X{traceId}, parentId=%X{parentId}, spanId=%X{spanId}, sampled=%X{sampled} [%c{3.}] (%t) %s%e%n

以下のようなログが出ます。

2021-08-01 18:00:00,000 INFO  traceId=124e24f649c404fa, parentId=0, spanId=124e24f649c404fa, sampled=false [com.zu_.pla.qua.ext.run.ReactiveRequestFilter] (vert.x-eventloop-thread-7) http://localhost:8080/hello

これだけの用途のために OpenTracing を導入するのはもったいない気がしますが、なかなか勉強する理由を見つけられないでいた分散トレーシングを勉強するきっかけになりました。jaeger との連携も試してみようと思います。

コメントする

メールアドレスが公開されることはありません。 * が付いている欄は必須項目です

このサイトはスパムを低減するために Akismet を使っています。コメントデータの処理方法の詳細はこちらをご覧ください