CDI request scope deactivation does not work on duplicated context

[michalvavrik]

Describe the bug

my use case:

Currently when gRPC extension is present, security events must be disabled or requests never reach gRPC server endpoint.

When I fire CDI event synchronously or asynchronously, I always get warning log message Request context already active when gRPC request started logged several times.

When CDI event is fired asynchronously and the CDI request context is activated, it should not be detectable by Arc.container.request().isActive(), because if other code re-use the same CDI request context that is also asynchronously deactivated by io.quarkus.arc.impl.EventImpl, than other code (like the gRPC one) will try to use deactivated context.

Expected behavior

CDI request scope deactivation actually deactivates request context.

Actual behavior

Request always goes here

quarkus/extensions/grpc/runtime/src/main/java/io/quarkus/grpc/runtime/supports/context/GrpcRequestContextGrpcInterceptor.java

Line 46 in 5290dc7

log.warn("Request context already active when gRPC request started");

.

How to Reproduce?

Reproducer:

quarkus create app --extensions=vertx-http
cd code-with-quarkus/

add

import io.quarkus.arc.Arc;
import io.quarkus.runtime.StartupEvent;
import io.vertx.ext.web.Router;
import jakarta.enterprise.event.Observes;

public class StartupObserver {

    void addRouter(@Observes StartupEvent event, Router router) {
        router.route().handler(routingContext -> {
            boolean activeBeforeActivation = Arc.container().requestContext().isActive();
            Arc.container().requestContext().activate();
            boolean activeAfterActivation = Arc.container().requestContext().isActive();
            Arc.container().requestContext().terminate();
            boolean activeAfterTermination = Arc.container().requestContext().isActive();
            routingContext.end("before activation: " + activeBeforeActivation
                    + " after activation: " + activeAfterActivation
            + " after termination: " + activeAfterTermination);
        });
    }

}

mvn quarkus:dev
curl -v http://localhost:8080/
response: 

before activation: false
after activation: true
after termination: true

Another Reproducer :

command mvn clean verify -DskipTests -f extensions/grpc/ && mvn clean test -f extensions/grpc/deployment/ -Dtest=GrpcAuthUsingSeparatePortTest

1. This reproducer only shows that Request context already active when gRPC request started message is logged, which should show that the request context is re-used even though started synchronously and terminated in finally clause.

quarkus/independent-projects/arc/runtime/src/main/java/io/quarkus/arc/impl/EventImpl.java

Line 330 in 08bff7a

requestContext.terminate();

diff --git a/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/CDIEventHandler.java b/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/CDIEventHandler.java
new file mode 100644
index 00000000000..a8b52d2c13f
--- /dev/null
+++ b/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/CDIEventHandler.java
@@ -0,0 +1,33 @@
+package io.quarkus.grpc.auth;
+
+import jakarta.enterprise.context.ApplicationScoped;
+import jakarta.enterprise.event.Event;
+import jakarta.enterprise.event.Observes;
+import jakarta.inject.Inject;
+
+import io.vertx.core.Handler;
+import io.vertx.ext.web.Router;
+import io.vertx.ext.web.RoutingContext;
+
+@ApplicationScoped
+public class CDIEventHandler {
+
+    @Inject
+    Event<Integer> event;
+
+    void init(@Observes Router router) {
+        router.route().order(-99).handler(new Handler<RoutingContext>() {
+            @Override
+            public void handle(RoutingContext routingContext) {
+                // IMPORTANT: if you comment out next line, the 'Request context already active when gRPC request started'
+                //            log message will never be logged
+                event.fire(1);
+                routingContext.next();
+            }
+        });
+    }
+
+    void consume1(@Observes Integer integer) {
+        System.out.println("Integer is " + integer);
+    }
+}
diff --git a/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthTestBase.java b/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthTestBase.java
index 3ec48c1ca6b..f17edc8897d 100644
--- a/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthTestBase.java
+++ b/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthTestBase.java
@@ -62,6 +62,7 @@ protected static QuarkusUnitTest createQuarkusUnitTest(String extraProperty) {
 
                     return ShrinkWrap.create(JavaArchive.class)
                             .addClasses(Service.class, BasicGrpcSecurityMechanism.class, BlockingHttpSecurityPolicy.class)
+                            .addClass(CDIEventHandler.class)
                             .addPackage(SecuredService.class.getPackage())
                             .add(new StringAsset(props), "application.properties");
                 });
diff --git a/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthUsingSeparatePortTest.java b/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthUsingSeparatePortTest.java
index f16d44b2da1..3b45ad0a62a 100644
--- a/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthUsingSeparatePortTest.java
+++ b/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthUsingSeparatePortTest.java
@@ -10,5 +10,4 @@ public class GrpcAuthUsingSeparatePortTest extends GrpcAuthTestBase {
     static final QuarkusUnitTest config = createQuarkusUnitTest("quarkus.grpc.server.use-separate-server=false\n" +
             "quarkus.grpc.clients.securityClient.host=localhost\n" +
             "quarkus.grpc.clients.securityClient.port=8081\n");
-
 }

3. this reproducer fails the test and when I put breakpoint (or logging) into io.quarkus.grpc.auth.GrpcAuthTestBase.Service#unaryCall it is never reached (or logged):

diff --git a/extensions/grpc/deployment/src/main/java/io/quarkus/grpc/deployment/GrpcServerProcessor.java b/extensions/grpc/deployment/src/main/java/io/quarkus/grpc/deployment/GrpcServerProcessor.java
index ccaf3d8231a..3ac910e56e5 100644
--- a/extensions/grpc/deployment/src/main/java/io/quarkus/grpc/deployment/GrpcServerProcessor.java
+++ b/extensions/grpc/deployment/src/main/java/io/quarkus/grpc/deployment/GrpcServerProcessor.java
@@ -45,7 +45,6 @@
 import io.quarkus.arc.deployment.BeanContainerBuildItem;
 import io.quarkus.arc.deployment.CustomScopeAnnotationsBuildItem;
 import io.quarkus.arc.deployment.RecorderBeanInitializedBuildItem;
-import io.quarkus.arc.deployment.SynthesisFinishedBuildItem;
 import io.quarkus.arc.deployment.SyntheticBeanBuildItem;
 import io.quarkus.arc.deployment.SyntheticBeansRuntimeInitBuildItem;
 import io.quarkus.arc.deployment.UnremovableBeanBuildItem;
@@ -53,7 +52,6 @@
 import io.quarkus.arc.processor.AnnotationsTransformer;
 import io.quarkus.arc.processor.BeanInfo;
 import io.quarkus.arc.processor.BuiltinScope;
-import io.quarkus.arc.processor.ObserverInfo;
 import io.quarkus.deployment.ApplicationArchive;
 import io.quarkus.deployment.Capabilities;
 import io.quarkus.deployment.Capability;
@@ -69,7 +67,6 @@
 import io.quarkus.deployment.builditem.ExtensionSslNativeSupportBuildItem;
 import io.quarkus.deployment.builditem.FeatureBuildItem;
 import io.quarkus.deployment.builditem.LaunchModeBuildItem;
-import io.quarkus.deployment.builditem.RuntimeConfigSetupCompleteBuildItem;
 import io.quarkus.deployment.builditem.ServiceStartBuildItem;
 import io.quarkus.deployment.builditem.ShutdownContextBuildItem;
 import io.quarkus.deployment.builditem.nativeimage.NativeImageResourceBuildItem;
@@ -93,7 +90,6 @@
 import io.quarkus.kubernetes.spi.KubernetesPortBuildItem;
 import io.quarkus.netty.deployment.MinNettyAllocatorMaxOrderBuildItem;
 import io.quarkus.runtime.LaunchMode;
-import io.quarkus.security.spi.runtime.SecurityEvent;
 import io.quarkus.smallrye.health.deployment.spi.HealthBuildItem;
 import io.quarkus.vertx.deployment.VertxBuildItem;
 import io.quarkus.vertx.http.deployment.VertxWebRouterBuildItem;
@@ -796,36 +792,4 @@ void initGrpcSecurityInterceptor(List<BindableServiceBuildItem> bindables, Capab
         }
     }
 
-    @Record(RUNTIME_INIT)
-    @Consume(RuntimeConfigSetupCompleteBuildItem.class)
-    @BuildStep
-    void validateSecurityEventsNotObserved(SynthesisFinishedBuildItem synthesisFinished,
-            Capabilities capabilities,
-            GrpcSecurityRecorder recorder,
-            BeanArchiveIndexBuildItem indexBuildItem) {
-        if (!capabilities.isPresent(Capability.SECURITY)) {
-            return;
-        }
-
-        // collect all SecurityEvent classes
-        Set<DotName> knownSecurityEventClasses = new HashSet<>();
-        knownSecurityEventClasses.add(DotName.createSimple(SecurityEvent.class));
-        indexBuildItem
-                .getIndex()
-                .getAllKnownImplementors(SecurityEvent.class)
-                .stream()
-                .map(ClassInfo::name)
-                .forEach(knownSecurityEventClasses::add);
-
-        // find at least one CDI observer and validate security events are disabled
-        knownClasses: for (DotName knownSecurityEventClass : knownSecurityEventClasses) {
-            for (ObserverInfo observer : synthesisFinished.getObservers()) {
-                if (observer.getObservedType().name().equals(knownSecurityEventClass)) {
-                    recorder.validateSecurityEventsDisabled(knownSecurityEventClass.toString());
-                    break knownClasses;
-                }
-            }
-        }
-    }
-
 }
diff --git a/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthTestBase.java b/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthTestBase.java
index 3ec48c1ca6b..faadc5b9fdc 100644
--- a/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthTestBase.java
+++ b/extensions/grpc/deployment/src/test/java/io/quarkus/grpc/auth/GrpcAuthTestBase.java
@@ -61,6 +61,7 @@ protected static QuarkusUnitTest createQuarkusUnitTest(String extraProperty) {
                     }
 
                     return ShrinkWrap.create(JavaArchive.class)
+                            .addClass(SecurityEventObserver.class)
                             .addClasses(Service.class, BasicGrpcSecurityMechanism.class, BlockingHttpSecurityPolicy.class)
                             .addPackage(SecuredService.class.getPackage())
                             .add(new StringAsset(props), "application.properties");

And now, you need to ask yourself how do I know it is also related to synchronous events here - you can just comment out this line,

quarkus/extensions/security/runtime-spi/src/main/java/io/quarkus/security/spi/runtime/SecurityEventHelper.java

Line 72 in 08bff7a

securityEvent.fireAsync(event);

build Security extension and re-run test with a same result.

Output of uname -a or ver

Fedora 38

Output of java -version

OpenJDK Runtime Environment Temurin-17.0.7+7

Quarkus version or git rev

999-SNAPSHOT

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

Apache Maven 3.9.3

Additional information

No response

[quarkus-bot]

/cc @Ladicek (arc), @alesj (grpc), @cescoffier (grpc), @geoand (kubernetes), @iocanel (kubernetes), @manovotn (arc), @mkouba (arc)

[michalvavrik]

cc @sberyozkin related to #37472

[michalvavrik]

Hello @cescoffier @mkouba @Ladicek @manovotn I had a look into this and I found out that CDI request scope is never activated which is for some reason expected

quarkus/extensions/vertx/runtime/src/main/java/io/quarkus/vertx/runtime/VertxCurrentContextFactory.java

Line 59 in 7d15333

// context.removeLocal(LOCAL_KEY);

I have updated this issue description with brand new reproducer and I propose to drop that line completely. I'll try to drop it, create test and see what Quarkus CI has to say, but I am pretty sure the PR will be rejected. Why is it implemented this way? I'd like to be able to terminate CDI request context even on duplicated context as well.

[michalvavrik]

I debugged RESTEasy Classic and I think there is another underlying issue that makes things happen only because deactivation is not actually happening (due to this bug), I'll leave experts to deal with it. Please also check how many times request context in io.quarkus.arc.runtime.context.ArcContextProvider.NullContextSnapshot is activated / deactivated when running mvn clean verify -f integration-tests/smallrye-jwt-token-propagation/ -Dtest-containers -Dstart-containers -Dtest=OidcTokenPropagationTest#testEchoUserNameWithAccessTokenPropagation -Dmaven.surefire.debug and there are other examples (see CI of my closed PR). I can't tell if there is a good reason for such behavior, I'll leave it on you.

[michalvavrik]

Adjusted labels because this is the Arc bug - Jakarta CDI 4.0 specification in 2.5.5.2. Activating Built In Contexts subsection Activating a Request Context says that @ActivateRequestContext is supposed to deactive request context upon method completion, which is not happening.

[mkouba]

Adjusted labels because this is the Arc bug - Jakarta CDI 4.0 specification in 2.5.5.2. Activating Built In Contexts subsection Activating a Request Context says that @ActivateRequestContext is supposed to deactive request context upon method completion, which is not happening.

Keep in mind that the @ActivateRequestContext interceptor only deactivates the request context if it was activated by this interceptor before the intercepted method was invoked. In other words, it does not deactivate the request context if it was already active.

I did not look into the details of this issue though. Does the method return an async type, e.g. Uni? ArC has some special handling of for async types (which is not standardized by the way).

[michalvavrik]

I appreciate you read my comment @mkouba , this is not urgent at all, but I was wondering if you know about it :-)

Keep in mind that the @ActivateRequestContext interceptor only deactivates the request context if it was activated by this interceptor before the intercepted method was invoked. In other words, it does not deactivate the request context if it was already active.

I used @ActivateRequestContext interceptor as I could find it in spec, but I didn't see there Arc.container().requestContext().terminate(), only found mention of deactivating request context. It happens with or without the interceptor, only requirement is to be on duplicated context, which is IMO common case when processing HTTP requests in Vert.x HTTP extension.

I re-tested it yesterday after #37982 got merged and I still can reproduce it.

I did not look into the details of this issue though. Does the method return an async type, e.g. Uni? ArC has some special handling of for async types (which is not standardized by the way).

This also happens when something is returned in a synchronous way. io.quarkus.arc.impl.RequestContext#isActive returns true when current context state is not null, which is always true once the request scope has been activated, because it is not removed here io.quarkus.vertx.runtime.VertxCurrentContextFactory.VertxCurrentContext#remove. Destroy works, deactivation does not.

That said, I tried to fix it and it is really complex in scenarios like RESTEasy Classic, there can be something I'm missing. I just think deactivation should work, otherwise it's misleading operation.

[manovotn]

I have updated this issue description with brand new reproducer and I propose to drop that line completely. I'll try to drop it, create test and see what Quarkus CI has to say, but I am pretty sure the PR will be rejected. Why is it implemented this way? I'd like to be able to terminate CDI request context even on duplicated context as well.

I tried looking into history to see why we chose to never remove req. context state from the vertx duplicated context and the only link I found was this comment... which sadly doesn't tell me much.
But I agree it's awkward because you are then left with context that is active but its ContextState is actually invalid 🤔

Maybe requestContext().isActive() should also check for validity of the underlying ContextState?
I'll keep digging a bit more...

When CDI event is fired asynchronously and the CDI request context is activated, it should not be detectable by Arc.container.request().isActive()

Note that Arc.container().requestContext() may return different context based on where you invoke that from. So from within an async observer of that event, you should see it active, but from the thread that fired the even, that depends on whether it was previously active or not. And both of these contexts will have different underlying ContextState.

[michalvavrik]

Note that Arc.container().requestContext() may return different context based on where you invoke that from. So from within an async observer of that event, you should see it active, but from the thread that fired the even, that depends on whether it was previously active or not. And both of these contexts will have different underlying ContextState.

Got it, thank you.