ログを眺めている時に、どこからどこまでが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
この方法では１つ問題があります。MDC は ThreadLocal , つまりスレッドごとに情報を持つのですが、 Java は PHP と違いスレッドが再利用され他のリクエストに情報が受け継がれます。
imperative (reactive じゃない方) なら上記ソースでも問題ないのですが、 reactive の場合はリクエスト処理中に IO 待ちが発生すると待っている間に他のリクエストを処理します。あるスレッドにおいて、リクエスト１→リクエスト２→リクエスト１ のような順で処理されるケースがあるという事です。
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 との連携も試してみようと思います。