Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Hibernate Reactive with Stage API throws ContextNotActiveException on flush #14812

Closed
yrodiere opened this issue Feb 4, 2021 · 10 comments · Fixed by #18262
Closed

Hibernate Reactive with Stage API throws ContextNotActiveException on flush #14812

yrodiere opened this issue Feb 4, 2021 · 10 comments · Fixed by #18262

Comments

@yrodiere
Copy link
Member

yrodiere commented Feb 4, 2021

Describe the bug

The code below throws a ContextNotActiveException (see also reproducer below). Switching to the Mutiny API makes the problem disappear.

    @Inject
    Stage.Session session;

    @Test
    @ActivateRequestContext
    public void test() {
        DefaultEntity entity = new DefaultEntity("default");

        DefaultEntity retrievedEntity = session.withTransaction(tx -> session.persist(entity))
                .thenCompose($ -> session.withTransaction(tx -> session.clear().find(DefaultEntity.class, entity.getId())))
                .toCompletableFuture().join();

        assertThat(retrievedEntity)
                .isNotSameAs(entity)
                .returns(entity.getName(), DefaultEntity::getName);
    }

Stack trace:

java.util.concurrent.CompletionException: javax.enterprise.context.ContextNotActiveException
        at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314)
        at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319)
        at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1081)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
        at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073)
        at org.hibernate.reactive.pool.impl.Handlers.lambda$toCompletionStage$0(Handlers.java:26)
        at io.vertx.sqlclient.impl.SqlResultHandler.complete(SqlResultHandler.java:98)
        at io.vertx.sqlclient.impl.SqlResultHandler.handle(SqlResultHandler.java:87)
        at io.vertx.sqlclient.impl.SqlResultHandler.handle(SqlResultHandler.java:33)
        at io.vertx.sqlclient.impl.SocketConnectionBase.handleMessage(SocketConnectionBase.java:241)
        at io.vertx.sqlclient.impl.SocketConnectionBase.lambda$init$0(SocketConnectionBase.java:88)
        at io.vertx.core.net.impl.NetSocketImpl.lambda$new$2(NetSocketImpl.java:101)
        at io.vertx.core.streams.impl.InboundBuffer.handleEvent(InboundBuffer.java:237)
        at io.vertx.core.streams.impl.InboundBuffer.write(InboundBuffer.java:127)
        at io.vertx.core.net.impl.NetSocketImpl.handleMessage(NetSocketImpl.java:357)
        at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:366)
        at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:43)
        at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:229)
        at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:163)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
        at io.vertx.pgclient.impl.codec.PgEncoder.lambda$write$0(PgEncoder.java:78)
        at io.vertx.pgclient.impl.codec.PgCommandCodec.handleReadyForQuery(PgCommandCodec.java:138)
        at io.vertx.pgclient.impl.codec.PgDecoder.decodeReadyForQuery(PgDecoder.java:226)
        at io.vertx.pgclient.impl.codec.PgDecoder.channelRead(PgDecoder.java:86)
        at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: javax.enterprise.context.ContextNotActiveException
        at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:40)
        at io.quarkus.hibernate.reactive.runtime.ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_ClientProxy.arc$delegate(ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_ClientProxy.zig:61)
        at io.quarkus.hibernate.reactive.runtime.ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_ClientProxy.flush(ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_ClientProxy.zig:187)
        at io.quarkus.hibernate.reactive.singlepersistenceunit.SinglePersistenceUnitCdiStageSessionTest.lambda$test$1(SinglePersistenceUnitCdiStageSessionTest.java:33)
        at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072)
        ... 41 more

Expected behavior
I would expect the Mutiny API and the Stage API to behave similarly. Maybe the code is wrong, but in that case both APIs should throw an exception?

Actual behavior
(Describe the actual behavior clearly and concisely.)

To Reproduce

See this branch where I added two tests: one with the Mutiny API and another with the Stage API. The Munity test passes, but the Stage one fails.

Configuration
N/A

Screenshots
N/A

Environment (please complete the following information):

  • Output of uname -a or ver: Linux yrodiere.redhat 5.10.8-100.fc32.x86_64 #1 SMP Sun Jan 17 19:52:43 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
  • Output of java -version:
openjdk version "11.0.9" 2020-10-20
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.9+11)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.9+11, mixed mode)
  • GraalVM version (if different from Java): the one built in Quarkus
  • Quarkus version or git rev: 63db661
  • Build tool (ie. output of mvnw --version or gradlew --version):
Apache Maven 3.6.3 (cecedd343002696d0abb50b32b541b8a6ba2883f)
Maven home: /home/yrodiere/.m2/wrapper/dists/apache-maven-3.6.3-bin/1iopthnavndlasol9gbrbg6bf2/apache-maven-3.6.3
Java version: 11.0.9, vendor: AdoptOpenJDK, runtime: /home/yrodiere/tools/java/jdk-11.0.9+11
Default locale: en_US, platform encoding: UTF-8
OS name: "linux", version: "5.10.8-100.fc32.x86_64", arch: "amd64", family: "unix"

Additional context
N/A

@yrodiere yrodiere added the kind/bug Something isn't working label Feb 4, 2021
@ghost
Copy link

ghost commented Feb 4, 2021

/cc @DavideD, @Sanne, @gavinking

@yrodiere
Copy link
Member Author

yrodiere commented Feb 4, 2021

Discussed with @DavideD (https://hibernate.zulipchat.com/#narrow/stream/205413-hibernate-reactive-dev/topic/Flush.20with.20stage.20API.20in.20Quarkus). He'll have a look when he has some time.

yrodiere added a commit to yrodiere/quarkus that referenced this issue Feb 4, 2021
See quarkusio#14812

Signed-off-by: Yoann Rodière <yoann@hibernate.org>
@Sanne
Copy link
Member

Sanne commented Feb 4, 2021

FWIW, I have a different error; perhaps this is the underlying cause?

java.lang.AssertionError: This needs to be run on the Vert.x event loop

	at org.hibernate.reactive.session.impl.ReactiveSessionImpl.<init>(ReactiveSessionImpl.java:129)
	at org.hibernate.reactive.stage.impl.StageSessionFactoryImpl.openSession(StageSessionFactoryImpl.java:63)
	at io.quarkus.hibernate.reactive.runtime.ReactiveSessionProducer.createStageSession(ReactiveSessionProducer.java:25)
	at io.quarkus.hibernate.reactive.runtime.ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_Bean.create(ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_Bean.zig:259)
	at io.quarkus.hibernate.reactive.runtime.ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_Bean.create(ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_Bean.zig:297)
	at io.quarkus.arc.impl.RequestContext.getIfActive(RequestContext.java:68)
	at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:33)
	at io.quarkus.hibernate.reactive.runtime.ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_ClientProxy.arc$delegate(ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_ClientProxy.zig:61)
	at io.quarkus.hibernate.reactive.runtime.ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_ClientProxy.withTransaction(ReactiveSessionProducer_ProducerMethod_createStageSession_f9b8f611ead14dce89da7dfa2d7630a8afb9b0b9_ClientProxy.zig:1042)
	at io.quarkus.hibernate.reactive.singlepersistenceunit.SinglePersistenceUnitCdiStageSessionTest.test(SinglePersistenceUnitCdiStageSessionTest.java:34)
	at io.quarkus.hibernate.reactive.singlepersistenceunit.SinglePersistenceUnitCdiStageSessionTest_Subclass.test$$superaccessor1(SinglePersistenceUnitCdiStageSessionTest_Subclass.zig:189)
	at io.quarkus.hibernate.reactive.singlepersistenceunit.SinglePersistenceUnitCdiStageSessionTest_Subclass$$function$$1.apply(SinglePersistenceUnitCdiStageSessionTest_Subclass$$function$$1.zig:29)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
	at io.quarkus.arc.impl.ActivateRequestContextInterceptor.aroundInvoke(ActivateRequestContextInterceptor.java:24)
	at io.quarkus.arc.impl.ActivateRequestContextInterceptor_Bean.intercept(ActivateRequestContextInterceptor_Bean.zig:275)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
	at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
	at io.quarkus.hibernate.reactive.singlepersistenceunit.SinglePersistenceUnitCdiStageSessionTest_Subclass.test(SinglePersistenceUnitCdiStageSessionTest_Subclass.zig:147)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)

@yrodiere
Copy link
Member Author

yrodiere commented Feb 4, 2021

@Sanne That's weird, I don't have this error...

Anyway. I thought withTransaction() was supposed to move execution to the event loop?

@DavideD
Copy link
Contributor

DavideD commented Feb 4, 2021

@Sanne That's weird, I don't have this error...

Same for me. And when I debug, everything seems in the right Thread

@CurtisBaldwinson
Copy link

I spent days despairing over reactive services not working in Quarkus tests. They only worked if called starting from the controller via RestAssured or other such rest simulator.

Eventually I got lucky and was able to inject a Mutiny.SessionFactory into the test:

    @Inject
    Mutiny.SessionFactory mutinySessionFactory;

And inside the test method itself, wrap it in a withSession:

        mutinySessionFactory.withSession(mutinySession ->
                Multi.createFrom()
                        .iterable(rootAccounts)
                        .call(thisAccount -> accountService.createAccount(thisAccount))
                        .collectItems().asList()
        ).subscribeAsCompletionStage().join();

@yrodiere
Copy link
Member Author

yrodiere commented Feb 5, 2021

(Note: I edited the first line, it was misleading)

I suspect that injected sessions can only work properly when accessed from the original thread that activated the request context (be it the test thread or the VertX even loop thread).

When we call session.withTransaction($ -> session.persist(entity)), here is what I think is happening:

  • On the original non-vertx thread T1, session.withTransaction is called.
    • This creates a delegate session S1 in the request scope of T1.
    • This then calls S1.withTransaction(...), which triggers the following call.
  • On another vertx thread T2, session.persist is called.
    • This attempts to create another delegate session S2 in the request scope of T2. However, the request scope is not active in this thread, so we get an exception.

With Mutiny however, it seems all the calls are performed in the original thread T1. I don't know why. This works, but I think it may be wrong, since I believe everything should be executed in the VertX event loop?

@DavideD could this possibly be what's happening? Maybe something similar?

gsmet pushed a commit to gsmet/quarkus that referenced this issue Feb 8, 2021
See quarkusio#14812

Signed-off-by: Yoann Rodière <yoann@hibernate.org>
(cherry picked from commit 675c417)
@stuartwdouglas
Copy link
Member

It sounds like Mutiny is propagating the request scope but the CompletionStage API is not.

@yrodiere
Copy link
Member Author

yrodiere commented Feb 9, 2021 via email

@cescoffier
Copy link
Member

Mutiny has built-in propagation. CompletionStage does not have that.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants