MDC propagation works with ManagedExecutor, but not with ThreadContext

vladykin commented 1 month ago

Describe the bug

MDC propagation works inconsistently between ManagedExecutor and ThreadContext.

Expected behavior

One would expect that ThreadContext provides the same propagation features as ManagedExecutor, but for custom thread pools and CompletableFutures.

Actual behavior

ThreadContext doesn't propagate MDC.

How to Reproduce?

Here is the reproducer:

package org.acme;

import jakarta.inject.Inject;
import jakarta.ws.rs.GET;
import jakarta.ws.rs.Path;
import jakarta.ws.rs.Produces;
import jakarta.ws.rs.core.MediaType;
import java.util.concurrent.Executors;
import org.eclipse.microprofile.context.ManagedExecutor;
import org.eclipse.microprofile.context.ThreadContext;
import org.jboss.logging.MDC;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@Path("/hello")
public class GreetingResource {

    private static final Logger log = LoggerFactory.getLogger(GreetingResource.class);

    @Inject
    ManagedExecutor executor;

    @Inject
    ThreadContext threadContext;

    @GET
    @Produces(MediaType.TEXT_PLAIN)
    public String hello() {
        MDC.put("foo", "bar");
        executor.execute(() -> {
            log.info("ManagedExecutor");
        });
        Executors.newSingleThreadExecutor().execute(threadContext.contextualRunnable(() -> {
            log.info("ThreadContext.contextualRunnable");
        }));
        threadContext.withContextCapture(CompletableFuture.completedFuture(null))
            .thenRunAsync(() -> {
                log.info("ThreadContext.withContextCapture");
            }, Executors.newSingleThreadExecutor());
        return "Hello from Quarkus REST";
    }
}

Output is:

22:33:56 INFO  [or.ac.GreetingResource] (executor-thread-2) {foo=bar} ManagedExecutor
22:33:56 INFO  [or.ac.GreetingResource] (pool-16-thread-1) {} ThreadContext.contextualRunnable
22:33:56 INFO  [or.ac.GreetingResource] (pool-17-thread-1) {} ThreadContext.withContextCapture

Output of `uname -a` or `ver`

No response

Output of `java -version`

openjdk version "17.0.11" 2024-04-16 LTS

Quarkus version or git rev

3.12.3

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

Apache Maven 3.9.6

Additional information

https://quarkus.io/guides/logging#use-mdc-to-add-contextual-log-information doesn't mention ThreadContext, while it mentions ManagedExecutor. So, no promises made in the docs are violated. But still feels like a bug. ThreadContext is useful when ManagedExecutor is not flexible enough, or when one needs to deal with CompletionStages.

Some people suggest implementing a custom ThreadContextProvider, e.g. https://stackoverflow.com/questions/65039035/manual-context-propagation-in-quarkus-native-mode/65040601 or https://github.com/quarkusio/quarkus/issues/22724#issuecomment-1138752879

Is this the official recommendation to make MDC work? Or can it be considered a bug and fixed in the future versions of Quarkus?

quarkus-bot[bot] commented 1 month ago

/cc @FroMage (context-propagation), @manovotn (context-propagation)

manovotn commented 1 month ago

Some people suggest implementing a custom ThreadContextProvider

That is a standard way of extending the MP context propagation model with custom contexts so at least as a workaround, that should work.

I don't know much about how we implement MDC propagation but from a quick glance it seems like it's done through vert.x duplicate context and I guess that doesn't fit well with ThreadContextProvider? CC @cescoffier and @luneo7 who might know more

FroMage commented 1 month ago

Yeah, looks like related to the role duplication in context propagation between the vert.x context and MP/CP. I suspect a similar solution to how Arc propagates its contexts might be required. I know Arc uses Vert.x to store its context, but I suspect it also has support for MP/CP, right ?

vladykin commented 1 month ago

If it helps, here is what I found in Quarkus sources:

jboss-threads-specific ContextHandler taking care of propagating the Vert.x Context (and MDC is part of that Context)
ArcContextProvider - ThreadContextProvider propagating Arc context, although it doesn't directly reference anything from Vert.x

manovotn commented 1 month ago

Yeah, looks like related to the role duplication in context propagation between the vert.x context and MP/CP. I suspect a similar solution to how Arc propagates its contexts might be required. I know Arc uses Vert.x to store its context, but I suspect it also has support for MP/CP, right ?

Yea there is https://github.com/quarkusio/quarkus/blob/master/extensions/arc/runtime/src/main/java/io/quarkus/arc/runtime/context/ArcContextProvider

And the cdi req context is stored in a way that vertx can use it as well. I am currently on pto so maybe @mkouba can provide more details.

mkouba commented 1 month ago

Yeah, looks like related to the role duplication in context propagation between the vert.x context and MP/CP. I suspect a similar solution to how Arc propagates its contexts might be required. I know Arc uses Vert.x to store its context, but I suspect it also has support for MP/CP, right ?

Yea there is https://github.com/quarkusio/quarkus/blob/master/extensions/arc/runtime/src/main/java/io/quarkus/arc/runtime/context/ArcContextProvider

And the cdi req context is stored in a way that vertx can use it as well. I am currently on pto so maybe @mkouba can provide more details.

So the ArcContextProvider delegates to the io.quarkus.arc.impl.RequestContext which is backed by a pluggable abstraction (io.quarkus.arc.CurrentContext) and if quarkus-vertx is present then the Vert.x duplicated context is used. In other words, if quarkus-vertx is present then ArcContextProvider does nothing in most cases but there's also a threadlocal fallback (used if the Vertx context is not available).

quarkusio / quarkus