Get the traceId into the access logs

[brunobat]

Fixes #43570

The problem is created at the end of the request, when the OTel related data is removed from the VertxMDC context here:

quarkus/extensions/opentelemetry/runtime/src/main/java/io/quarkus/opentelemetry/runtime/OpenTelemetryUtil.java

Line 110 in c65d7ac

public static void clearMDCData(io.vertx.core.Context vertxContext) {

Before the RequestDoneHandler is executed in the access log.

This is just a dirty way to do it. I don't think we should touch the lifecycle, therefore, caching the value for later seems sensible enough.
We could also consider to store that data in the QuarkusRequestWrapper.

[brunobat]

This happens because on JAX-RS we are writing to log and then closing. With Mutiny, the context is cleared right before the access log and then re-set again with the right data.

[geoand]

Thanks for this @brunobat.

I can't say I understand the fix TBH, so a few more details on how and why it works would be nice.

Also reading

This happens because on JAX-RS we are writing to log and then closing

I still don't understand why the problem does not manifest with Quarkus REST.

[brunobat]

I've done an analysis on the stack traces when using Mutiny and JAX-RS when creating the access log line and when we clear the MDC context to understand where's the divergence.

When using vert.x, we go from here:
https://github.com/eclipse-vertx/vert.x/blob/5d427de6fbee5d264d08e54085e23366ae65befe/src/main/java/io/vertx/core/http/impl/Http1xServerResponse.java#L421

https://github.com/eclipse-vertx/vert.x/blob/5d427de6fbee5d264d08e54085e23366ae65befe/src/main/java/io/vertx/core/http/impl/Http1xServerResponse.java#L448

And this causes the span to end and the MDC context to be cleared.

When using JAX-RS the stack trace uses a different method and the span is not ended before the log whiting
https://github.com/eclipse-vertx/vert.x/blob/5d427de6fbee5d264d08e54085e23366ae65befe/src/main/java/io/vertx/core/http/impl/Http1xServerResponse.java#L427

The entire stack traces (sorry, not public): https://docs.google.com/spreadsheets/d/16bZi3o7uThUFfZo9A-bHqeTE4tC4qLB34L6BZ9zmOwo/edit?usp=sharing

I can also see changes (main branch is different) in the Http1xServerResponse::end() method used in the Mutiny path... I wonder if this is not an issue with Vert.x itself. Will try to see what happened there.

[brunobat]

This was what changed in the meantime:

• Released on Vert.x 5.0: https://github.com/eclipse-vertx/vert.x/pull/4809/files#diff-72aed77ae9b30c07cd30e9005bfc3e1d65131d6fa1bbf0c0093ef876a25daa82R397 -> I bet this is the problem. It's now calling this code: https://github.com/eclipse-vertx/vert.x/pull/4809/files#diff-6066745d72c6f938f3c9b5b7f76471ede6d87c6372f30f2e104e62d083637e4aR230

• Released on Vert.x 5.1: https://github.com/eclipse-vertx/vert.x/pull/5591/files#diff-c733741b8b97fc2664a99b7f2349e31aab112efa2e417fd09b055850c3f0b599R402