Access Log doesn't print Otel MDC (traceId, etc)

[hendratommy]

Describe the bug

I've installed quarkus-opentelemetry extension just as in the guide, however I notice that the Otel MDC key (traceId, etc) is null for access logs. This happens for both standard Vertx and Mutiny variant, even though the standard log can show traceId just fine.

Using JAX-RS the access log working correctly.

Expected behavior

The access log should print Otel MDC key for Vertx Web Router endpoint, just like JAX-RS.

2024-09-28 00:47:05,946 INFO  traceId=0af7651916cd43dd8448eb211c80319c, parentId=b7ad6b7169203331, spanId=47bc95d506a4d8e7, sampled=true Hello from Quarkus REST
2024-09-28 00:47:05,947 INFO  traceId=0af7651916cd43dd8448eb211c80319c, parentId=b7ad6b7169203331, spanId=47bc95d506a4d8e7, sampled=true "GET /hello HTTP/1.1 traceId=0af7651916cd43dd8448eb211c80319c spanId=47bc95d506a4d8e7"

Actual behavior

Using the following 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} %s%e%n
quarkus.http.access-log.enabled=true
quarkus.http.access-log.pattern="%r traceId=%{X,traceId} spanId=%{X,spanId}"
quarkus.otel.traces.exporter=none
quarkus.otel.metrics.exporter=none

Standard Vertx

I have defined the following routes:

@ApplicationScoped
public class Routes {
    @Inject
    Vertx vertx;
    @Inject
    WebClient client;

    public Handler<RoutingContext> handle(String msg) {
        return ctx -> {
            Log.info(msg);
            ctx.response().headers().set(HttpHeaders.CONTENT_TYPE, MediaType.TEXT_PLAIN);
            ctx.end(msg);
        };
    }

    public void sleep(RoutingContext ctx) {
        vertx.setTimer(1, v -> ctx.next());
    }

    public void init(@Observes Router router) {
        router.get("/message")
                .handler(handle("Message from Vertx"));

        router.get("/delayed-message")
                .handler(this::sleep)
                .handler(handle("Delayed message from Vertx"));

        router.get("/pokemon")
                .handler(this::sleep)
                .handler(ctx -> {
                    Log.info("Vertx Pokemon");
                    client.getAbs("https://pokeapi.co/api/v2/ability/1")
                            .send().onComplete(response -> {
                                ctx.response().headers().set(HttpHeaders.CONTENT_TYPE, MediaType.APPLICATION_JSON);
                                ctx.end(response.body());
                            }, ctx::fail);
                });
    }
}

Accessing each routes, produce logs:

2024-09-28 00:47:09,749 INFO  traceId=fb2e476334dc126a75164d893dca60a0, parentId=, spanId=1221c0a2ee69340a, sampled=true Message from Vertx
2024-09-28 00:47:09,751 INFO  traceId=, parentId=, spanId=, sampled= "GET /message HTTP/1.1 traceId=- spanId=-"
2024-09-28 00:47:12,496 INFO  traceId=4a0e0d719cd3ada1a25b80a57d51156b, parentId=, spanId=44122ab6d3c23193, sampled=true Delayed message from Vertx
2024-09-28 00:47:12,497 INFO  traceId=, parentId=, spanId=, sampled= "GET /delayed-message HTTP/1.1 traceId=- spanId=-"
2024-09-28 00:47:26,807 INFO  traceId=f3b88d6586cb1e9c696373a54284ab64, parentId=, spanId=94e34c7a5db63401, sampled=true Vertx Pokemon
2024-09-28 00:47:28,335 INFO  traceId=, parentId=, spanId=, sampled= "GET /pokemon HTTP/1.1 traceId=- spanId=-"

The logging from the code works fine, but none of the access logs works

Vertx Mutiny Variant

@ApplicationScoped
public class MutinyRoutes {
    @Inject
    WebClient client;

    public Consumer<RoutingContext> handle(String msg) {
        return ctx -> {
            Log.info(msg);
            ctx.response().headers().set(HttpHeaders.CONTENT_TYPE, MediaType.TEXT_PLAIN);
            ctx.endAndForget(msg);
        };
    }

    public void sleep(RoutingContext ctx) {
        Uni.createFrom().voidItem()
                .onItem().delayIt().by(Duration.ofMillis(1))
                .subscribe().with(v -> ctx.next());
    }

    public void init(@Observes Router router) {
        router.get("/mutiny/message")
                .handler(handle("Message from Mutiny Vertx"));

        router.get("/mutiny/delayed-message").handler(this::sleep).handler(handle("Delayed message from Mutiny Vertx"));

        router.get("/mutiny/pokemon")
                .handler(this::sleep)
                .handler(ctx -> {
                    Log.info("Mutiny Vertx Pokemon");
                    client.getAbs("https://pokeapi.co/api/v2/ability/1")
                            .send()
                            .subscribe().with(response -> {
                                ctx.response().headers().set(HttpHeaders.CONTENT_TYPE, MediaType.APPLICATION_JSON);
                                ctx.endAndForget(response.body());
                            }, ctx::fail);
                });
    }
}

The code is basically the same with standard Vertx, but accessing each endpoints gives me the following result:

2024-09-28 01:22:37,677 INFO  traceId=9b8d5773720ed39f5009c9e3270edf9f, parentId=, spanId=8c4b6c4b1f9c60c2, sampled=true Message from Mutiny Vertx
2024-09-28 01:22:37,679 INFO  traceId=, parentId=, spanId=, sampled= "GET /mutiny/message HTTP/1.1 traceId=- spanId=-"
2024-09-28 01:22:42,977 INFO  traceId=c39dcb22cd3408670b965e8fbf917cb6, parentId=, spanId=7e603a6a1d177b3d, sampled=true Delayed message from Mutiny Vertx
2024-09-28 01:22:42,978 INFO  traceId=c39dcb22cd3408670b965e8fbf917cb6, parentId=, spanId=7e603a6a1d177b3d, sampled=true "GET /mutiny/delayed-message HTTP/1.1 traceId=c39dcb22cd3408670b965e8fbf917cb6 spanId=7e603a6a1d177b3d"
2024-09-28 01:22:45,582 INFO  traceId=de4c61216c8f0ea56cdee36c21b9bf30, parentId=, spanId=5a68e3bc3466cca3, sampled=true Mutiny Vertx Pokemon
2024-09-28 01:22:45,659 INFO  traceId=, parentId=, spanId=, sampled= "GET /mutiny/pokemon HTTP/1.1 traceId=- spanId=-"

Notes that for the /delayed-message endpoint both standard log and access log are displaying Otel MDC correctly, seems like delaying the execution is working somehow. However the /pokemon which is also using delay doesn't print any Otel MDC in the access log.

How to Reproduce?

I made a small project to reproduce this issue:
https://github.com/hendratommy/vertx-otel-accesslog-issue

Output of uname -a or ver

arwin MacBook-Pro.local 23.6.0 Darwin Kernel Version 23.6.0: Mon Jul 29 21:13:00 PDT 2024; root:xnu-10063.141.2~1/RELEASE_X86_64 x86_64

Output of java -version

openjdk version "21.0.4" 2024-07-16 LTS OpenJDK Runtime Environment Temurin-21.0.4+7 (build 21.0.4+7-LTS) OpenJDK 64-Bit Server VM Temurin-21.0.4+7 (build 21.0.4+7-LTS, mixed mode)

Quarkus version or git rev

3.15.1

Build tool (ie. output of mvnw --version or gradlew --version)

ApacheMaven 3.9.8 (36645f6c9b5079805ea5009217e36f2cffd34256)

Additional information

No response

[quarkus-bot]

/cc @brunobat (opentelemetry,tracing), @radcortez (opentelemetry,tracing)

[gsmet]

@brunobat do you have this one on your radar?

[brunobat]

It has never been implemented for access logs.
Adding it to the backlog.
How urgent is this?

[famod]

Doesn't say much about the urgency but the lack of tracing infos in access log did not make my life easier over there: #42636 (reply in thread)

[stefvanderweldevolksbanknl]

We would also like this.

[danielsoro]

I'll work on it, can you assign it to me @brunobat?

[brunobat]

Thanks @danielsoro. The task is yours.

[brunobat]

@danielsoro Any update on this?

[danielsoro]

@danielsoro Any update on this?

Sorry for the delay; I needed to be out for a time, but I'm coming back for now. I already have something but it is still not finished, as we already discussed, the logic here for the access_log should change a bit. We should inject it into the vertex context when the request arrives, so when we've injected the start span/trace/etc, this information will be available in the context and possibly be retrieved into the AccessLog Processor.

I'm having an issue building quarkus on my Mac, because the protobuf plugin is trying to execute a .exe, not sure why... but it is really weird.

[INFO] Compiling 3 proto file(s) to /Users/dcunha/git/java/quarkus/extensions/grpc/stubs/target/generated-sources/protobuf/grpc-java
[ERROR] PROTOC FAILED: /Users/dcunha/git/java/quarkus/extensions/grpc/stubs/target/protoc-plugins/protoc-gen-grpc-java-1.69.0-osx-aarch_64.exe: program not found or is not executable
Please specify a program using absolute path or make sure the program is available in your PATH system variable
--grpc-java_out: protoc-gen-grpc-java: Plugin failed with status code 1.

[ERROR] /Users/dcunha/git/java/quarkus/extensions/grpc/stubs/src/main/proto/health/v1/health.proto [0:0]: /Users/dcunha/git/java/quarkus/extensions/grpc/stubs/target/protoc-plugins/protoc-gen-grpc-java-1.69.0-osx-aarch_64.exe: program not found or is not executable
Please specify a program using absolute path or make sure the program is available in your PATH system variable
--grpc-java_out: protoc-gen-grpc-java: Plugin failed with status code 1.

[ERROR] /Users/dcunha/git/java/quarkus/extensions/grpc/stubs/src/main/proto/reflection/v1/reflection.proto [0:0]: /Users/dcunha/git/java/quarkus/extensions/grpc/stubs/target/protoc-plugins/protoc-gen-grpc-java-1.69.0-osx-aarch_64.exe: program not found or is not executable
Please specify a program using absolute path or make sure the program is available in your PATH system variable
--grpc-java_out: protoc-gen-grpc-java: Plugin failed with status code 1.

[ERROR] /Users/dcunha/git/java/quarkus/extensions/grpc/stubs/src/main/proto/reflection/v1alpha/reflection.proto [0:0]: /Users/dcunha/git/java/quarkus/extensions/grpc/stubs/target/protoc-plugins/protoc-gen-grpc-java-1.69.0-osx-aarch_64.exe: program not found or is not executable
Please specify a program using absolute path or make sure the program is available in your PATH system variable
--grpc-java_out: protoc-gen-grpc-java: Plugin failed with status code 1.

[brunobat]

I Had this problem at some point but I can't remember how I fixed it.
Try a git clean to remove obsolete stuff.
Maybe @alesj remembers how to fix this.

[danielsoro]

rosetta is required to make it work... that was the issue:

 softwareupdate --install-rosetta --agree-to-license