Random ContextNotActiveException in a Series of Outgoing Rest Calls from a ManagedExecutor Thread

[mrickly]

Describe the bug

• We delegate the execution of outgoing rest calls to a ManagedExecutor thread.
• We make sure to remove the context: @ManagedExecutorConfig(cleared = ThreadContext.ALL_REMAINING, propagated = {}).
• The thread performs outgoing rest calls.
• Before each call, we activate the request context, intercept the rest client method and access the CurrentIdentityAssociation to set an identity, which requires an active RequestContext. When the client method returns, we reset the CurrentIdentityAssociation to the original identity (which is anonymous) and again requires an active RequestContext.
• After a random number of outgoing calls, resetting the identity fails with a ContextNotActiveException.

Expected behavior

• ContextNotActiveException should never happen at this location, because the RequestContext should not be shared with any other thread.

Actual behavior

• After a random number of outgoing calls, resetting the identity fails with a ContextNotActiveException.

How to Reproduce?

Reproducer: See attached zip file: requestcontext-issue-reproducer

How to reproduce:

• Create maven project in IntelliJ from .zip file.
• Execute the test. The test will succeed after 15 seconds (Thread sleep in test, waiting for async thread to finish).
• In the log, you will see the ContextNotActiveException appearing, within the first 30 calls probably (100 calls to wiremock in total, each one takes 100 ms by wiremock configuration).

requestcontext-issue-reproducer.zip

Output of uname -a or ver

No response

Output of java -version

openjdk 21.0.5 2024-10-15 LTS

Quarkus version or git rev

3.17.5

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

Maven 3.9.6

Additional information

Amazingly, if I comment the following lines, then the exception does not appear:

#quarkus.log.category."io.quarkus.arc.requestContext".min-level=TRACE
#quarkus.log.category."io.quarkus.arc.requestContext".level=TRACE

My explanation for this bizarre behaviour is that there is a race condition somewhere and that the additional logging changes the timing and the outcome of the race.

Possibly related to #43372: The reproducer has neither grpc nor kafka, but the real application causing issues uses grpc indirectly via otlp traces exporter.

[quarkus-bot]

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