quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.73k stars 2.67k forks source link

[Hibernate Reactive Panache] Concurrent request - HR000069: Detected use of the reactive Session from a different Thread #41945

Open ZetalyAlexandre opened 3 months ago

ZetalyAlexandre commented 3 months ago

Describe the bug

Concurrent calls to the same api performing a delete in the database sometimes cause an anomaly “HR000069: Detected use of the reactive Session from a different Thread”. All calls are on different elements. This problem does not occur when requests are sequential.

Stacktrace example:

2024-07-17 10:29:06,501 ERROR [org.acm.hib.orm.pan.FruitResource] (vert.x-eventloop-thread-2) Failed to handle request: org.hibernate.HibernateException: java.lang.IllegalStateException: HR000069: Detected use of the reactive Se
ssion from a different Thread than the one which was used to open the reactive Session - this suggests an invalid integration; original thread [163]: 'vert.x-eventloop-thread-2' current Thread [162]: 'vert.x-eventloop-thread-1' 
        at org.hibernate.reactive.session.impl.ReactiveExceptionConverter.convert(ReactiveExceptionConverter.java:28)
        at org.hibernate.reactive.session.impl.ReactiveSessionImpl.lambda$doFlush$27(ReactiveSessionImpl.java:994)
        at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:934)
        at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:911)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
        at org.hibernate.reactive.util.async.impl.AsyncTrampoline$TrampolineInternal.unroll(AsyncTrampoline.java:131)
        at org.hibernate.reactive.util.async.impl.AsyncTrampoline$TrampolineInternal.lambda$unroll$0(AsyncTrampoline.java:126)
        at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
        at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
        at org.hibernate.reactive.persister.entity.mutation.ReactiveDeleteCoordinator.complete(ReactiveDeleteCoordinator.java:198)
        at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
        at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
        at io.vertx.core.Future.lambda$toCompletionStage$3(Future.java:536)
        at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141)
        at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:60)
        at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:211)
        at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23)
        at io.vertx.sqlclient.impl.QueryResultBuilder.tryComplete(QueryResultBuilder.java:88)
        at io.vertx.sqlclient.impl.QueryResultBuilder.tryComplete(QueryResultBuilder.java:32)
        at io.vertx.core.Promise.complete(Promise.java:66)
        at io.vertx.core.Promise.handle(Promise.java:51)
        at io.vertx.core.Promise.handle(Promise.java:29)
        at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141)
        at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:60)
        at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:211)
        at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23)
        at io.vertx.core.impl.future.PromiseImpl.onSuccess(PromiseImpl.java:49)
        at io.vertx.core.impl.future.PromiseImpl.handle(PromiseImpl.java:41)
        at io.vertx.sqlclient.impl.TransactionImpl.lambda$wrap$0(TransactionImpl.java:72)
        at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141)
        at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:54)
        at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:86)
        at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:184)
        at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:51)
        at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:211)
        at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23)
        at io.vertx.core.impl.future.PromiseImpl.onSuccess(PromiseImpl.java:49)
        at io.vertx.core.impl.future.PromiseImpl.handle(PromiseImpl.java:41)
        at io.vertx.core.impl.future.PromiseImpl.handle(PromiseImpl.java:23)
        at io.vertx.sqlclient.impl.command.CommandResponse.fire(CommandResponse.java:46)
        at io.vertx.sqlclient.impl.SocketConnectionBase.handleMessage(SocketConnectionBase.java:325)
        at io.vertx.pgclient.impl.PgSocketConnection.handleMessage(PgSocketConnection.java:118)
        at io.vertx.sqlclient.impl.SocketConnectionBase.lambda$init$0(SocketConnectionBase.java:138)
        at io.vertx.core.impl.EventLoopContext.emit(EventLoopContext.java:55)
        at io.vertx.core.impl.ContextBase.emit(ContextBase.java:297)
        at io.vertx.core.net.impl.NetSocketImpl.handleMessage(NetSocketImpl.java:378)
        at io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:159)
        at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:153)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
        at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
        at io.vertx.pgclient.impl.codec.PgEncoder.lambda$write$0(PgEncoder.java:100)
        at io.vertx.pgclient.impl.codec.PgCommandCodec.handleReadyForQuery(PgCommandCodec.java:139)
        at io.vertx.pgclient.impl.codec.PgDecoder.decodeReadyForQuery(PgDecoder.java:237)
        at io.vertx.pgclient.impl.codec.PgDecoder.channelRead(PgDecoder.java:96)
        at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
        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:840)
Caused by: java.lang.IllegalStateException: HR000069: Detected use of the reactive Session from a different Thread than the one which was used to open the reactive Session - this suggests an invalid integration; original thread 
[163]: 'vert.x-eventloop-thread-2' current Thread [162]: 'vert.x-eventloop-thread-1'
        at org.hibernate.reactive.common.InternalStateAssertions.assertCurrentThreadMatches(InternalStateAssertions.java:46)
        at org.hibernate.reactive.session.impl.ReactiveSessionImpl.threadCheck(ReactiveSessionImpl.java:183)
        at org.hibernate.reactive.session.impl.ReactiveSessionImpl.checkOpen(ReactiveSessionImpl.java:1670)
        at org.hibernate.internal.AbstractSharedSessionContract.checkOpenOrWaitingForAutoClose(AbstractSharedSessionContract.java:447)
        at org.hibernate.internal.SessionImpl.checkOpenOrWaitingForAutoClose(SessionImpl.java:616)
        at org.hibernate.internal.SessigetPersistenceContext(SessionImpl.java:1825)
        at org.hibernate.reactive.event.impl.AbstractReactiveFlushingEventListener.lambda$performExecutions$0(AbstractReactiveFlushingEventListener.java:65)
        at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
        at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
        ... 74 more

Expected behavior

No exceptions should be thrown, all calls should work.

Actual behavior

An exception is sometimes raised with the following error message: “HR000069: Detected use of the reactive Session from a different Thread”.

How to Reproduce?

Project to reproduce: : hibernate-reactive-panache-quickstart.zip

I used the hibernate-reactive-panache-quickstart example. I've only added a “Remove all” button to the index.html file. This makes a call to the delete api, starting from the fruit list. There are no changes in the quarkus part.

JS function added:

$scope.removeAll = function() {
   $scope.fruits.forEach(fruit => $scope.remove(fruit));
}

Launch the project, access the page and use the “Remove all” option. The number of errors may vary

Output of uname -a or ver

No response

Output of java -version

openjdk version "17.0.9" 2023-10-17

Quarkus version or git rev

3.2.12.Final

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

Apache Maven 3.8.6 (84538c9988a25aec085021c365c560670ad80f63)

Additional information

No response

quarkus-bot[bot] commented 3 months ago

/cc @DavideD (hibernate-reactive), @FroMage (panache), @gavinking (hibernate-reactive), @loicmathieu (panache)

DavideD commented 3 months ago

Yes, this is a limitation we have at the moment. The Hibernate session does not support concurrent calls. We mention this in the Hibernate Reactive documentation: https://staging.hibernate.org/reactive/documentation/2.3/reference/html_single/#_sessions_and_vert_x_contexts

ZetalyAlexandre commented 3 months ago

On the backend, we do everything necessary to prevent this from happening. But when the calls come from multiple external calls (customer calls via the REST api), how can I avoid this kind of anomaly?

DavideD commented 3 months ago

You should have a different session for each request. Quarkus should take care of it.

What stopping you from adding a new access point in FruitResource?

    @DELETE
    public Uni<Response> deleteAll() {
        return Panache.withTransaction( () -> Panache.executeUpdate( "delete from Fruit" )
                .map( deleted -> Response
                        .ok( "Number of fruits deleted: " + deleted )
                        .build() ) );
    }

PS: You should be able to write this:

   @DELETE
   public Uni<Response> deleteAll() {
       return Panache.withTransaction(Fruit::deleteAll)
               .map(deleted -> Response.ok("Number of fruits deleted: " + deleted).build());
   }

But I've found this bug: https://github.com/quarkusio/quarkus/issues/41967

ZetalyAlexandre commented 3 months ago

I've done more test and I do not have this issue when I try to mass update or mass create. So it's very much linked to delete only. Nothing prevent me to add a "mass" delete endpoint. We've already found a workaround for our particular application. Unit deletions by several users are rare in our application, so this shouldn't be a problem for the time being.

I was just afraid that this case could also arise with mass creation or modification, which doesn't seem to be the case.

ZetalyAlexandre commented 3 months ago

It seems that I do not have the issue if I replace:

    @DELETE
    @Path("{id}")
    public Uni<Response> delete(Long id) {
        return Panache.withTransaction(() -> Fruit.deleteById(id))
                .map(deleted -> deleted
                        ? Response.ok().status(NO_CONTENT).build()
                        : Response.ok().status(NOT_FOUND).build());
    }

by

    @DELETE
    @Path("{id}")
    public Uni<Response> delete(Long id) {
        return Panache.withTransaction(() -> Panache.executeUpdate("delete from Fruit where id=?1", id))
                .map(deleted -> deleted > 0
                        ? Response.ok().status(NO_CONTENT).build()
                        : Response.ok().status(NOT_FOUND).build());
    }
DavideD commented 3 months ago

If the session is not re-created each time, it can definitely happen in all situations, even if you don't see any error now. Simply because the Session is not designed to be used in parallel.

Maybe I was a bit too quick in looking at this issue, though. I will have a second look.

That said, I think that adding a new Rest point to FruitResource is a better solution because it will keep all the actual logic in one place.

DavideD commented 3 months ago

OK, nevermind, it doesn't seem like it's using the same session, so it's something else that's causing the error

DavideD commented 3 months ago

I was just afraid that this case could also arise with mass creation or modification, which doesn't seem to be the case.

I suppose it could happen, I don't see why this should be deletion specific. The error is related to when the session is open/used. Sadly, I don't have the time right now to look into this.

The same error happens using hibernate reactive without Panache, so it could be a bug in Quarkus or Hibernate Reactive. I will have another look at it as soon as I have time, if nobody else is going to work on it.

I'm also not familiar with AngularJS in this situation, maybe somebody else can chime in?

ZetalyAlexandre commented 3 months ago

This is very strange, as I've done the following tests (one call per create/update/delete, all done with concurrency):

This only happens when using “Fruit.deleteById(id)” with only 5 simultaneous requests, but has never happened for the others...

I'll let you work on it. Thanks for your responsiveness.

MaximeGil commented 2 months ago

Hello,

@DavideD Do you think it's related to this old Zulip discussion ? https://quarkusio.zulipchat.com/#narrow/stream/187030-users/topic/Reactive.20exception.20.22Detected.20use.20of.20the.20reactive.2E.2E.22/near/380321402

That's why I had to downgrade in 2.x in the past. I didn't want to take any chances, despite all our tests before going live. However, this problem is very important to me because it happened again today...

DavideD commented 2 months ago

I'm not sure, but thanks for reminding me. I will check for sure.

Can you give me some details about your use case?

The Hibernate ORM upgrades are taking me longer than I've anticipated, but I hope I can get back to check these bugs soon

Dougniel commented 1 month ago

I had a similar problem, same error but while inserting with ~20 concurrent request with about 1000k records each within 5 entities

I analyzed a heap dump with VisualVM and found that one instance of ReactiveSessionImpl was still open even though there was no activity at that time. Looking a bit more I found this code that seams a bit sneaky (singleton with an instance variable holding a session..). So I disabled hibernate.order_inserts that I had activated it previously for 20% speed gain and I d'ont have this issue anymore

FroMage commented 1 month ago

@DavideD this looks like a good code suspect, no?

DavideD commented 1 month ago

Could be. As soon as I have finished something else I will have a better look