quarkus: Exceptions with Hibernate Reactive under load

Describe the bug

When using reactive panache and stressing the application with some tests, the application starts throwing exceptions:

2023-04-11 14:00:24,747 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (vert.x-eventloop-thread-6) Request failed: javax.persistence.PersistenceException: org.hibernate.HibernateException: java.util.concurrent.CompletionException: 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 [27]: 'vert.x-eventloop-thread-6' current Thread [23]: 'vert.x-eventloop-thread-2'
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181)
	at org.hibernate.reactive.session.impl.ReactiveExceptionConverter.convert(ReactiveExceptionConverter.java:31)
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl.lambda$firePersist$19(ReactiveSessionImpl.java:708)
	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 java.base/java.util.concurrent.CompletableFuture.uniAcceptNow(CompletableFuture.java:757)
	at java.base/java.util.concurrent.CompletableFuture.uniAcceptStage(CompletableFuture.java:735)
	at java.base/java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:2182)
	at java.base/java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:144)
	at org.hibernate.reactive.id.impl.BlockingIdentifierGenerator.lambda$generate$1(BlockingIdentifierGenerator.java:94)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at org.hibernate.reactive.id.impl.BlockingIdentifierGenerator.lambda$generate$0(BlockingIdentifierGenerator.java:87)
	at java.base/java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:718)
	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:384)
	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:100)
	at io.vertx.sqlclient.impl.QueryResultBuilder.tryComplete(QueryResultBuilder.java:34)
	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:163)
	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:292)
	at io.vertx.pgclient.impl.PgSocketConnection.handleMessage(PgSocketConnection.java:97)
	at io.vertx.sqlclient.impl.SocketConnectionBase.lambda$init$0(SocketConnectionBase.java:105)
	at io.vertx.core.impl.EventLoopContext.emit(EventLoopContext.java:55)
	at io.vertx.core.impl.ContextBase.emit(ContextBase.java:239)
	at io.vertx.core.net.impl.NetSocketImpl.handleMessage(NetSocketImpl.java:390)
	at io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:157)
	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:98)
	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:833)
Caused by: org.hibernate.HibernateException: java.util.concurrent.CompletionException: 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 [27]: 'vert.x-eventloop-thread-6' current Thread [23]: 'vert.x-eventloop-thread-2'
	... 77 more
Caused by: java.util.concurrent.CompletionException: 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 [27]: 'vert.x-eventloop-thread-6' current Thread [23]: 'vert.x-eventloop-thread-2'
	at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:315)
	at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1194)
	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309)
	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:144)
	at org.hibernate.reactive.event.impl.AbstractReactiveSaveEventListener.reactivePerformSaveOrReplicate(AbstractReactiveSaveEventListener.java:252)
	at org.hibernate.reactive.event.impl.AbstractReactiveSaveEventListener.lambda$reactivePerformSave$2(AbstractReactiveSaveEventListener.java:175)
	at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187)
	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309)
	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:144)
	at org.hibernate.reactive.event.impl.AbstractReactiveSaveEventListener.reactivePerformSave(AbstractReactiveSaveEventListener.java:175)
	at org.hibernate.reactive.event.impl.AbstractReactiveSaveEventListener.lambda$reactiveSaveWithGeneratedId$0(AbstractReactiveSaveEventListener.java:125)
	at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1150)
	... 73 more
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 [27]: 'vert.x-eventloop-thread-6' current Thread [23]: 'vert.x-eventloop-thread-2'
	at org.hibernate.reactive.common.InternalStateAssertions.assertCurrentThreadMatches(InternalStateAssertions.java:46)
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl.threadCheck(ReactiveSessionImpl.java:158)
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl.getReactiveActionQueue(ReactiveSessionImpl.java:168)
	at org.hibernate.reactive.event.impl.AbstractReactiveSaveEventListener.addInsertAction(AbstractReactiveSaveEventListener.java:343)
	at org.hibernate.reactive.event.impl.AbstractReactiveSaveEventListener.lambda$reactivePerformSaveOrReplicate$4(AbstractReactiveSaveEventListener.java:279)
	at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187)
	... 83 more

Expected behavior

Application runs without throwing exceptions.

Actual behavior

Application throws exceptions.

How to Reproduce?

Checkout this github.com repository:

git clone https://github.com/turing85/quarkus-reactive-stress-test.git
cd quarkus-reactive-stress-test

Deploy dependencies:

docker-compose --file local-deployment/docker-compose.yml up -d

Build the application, configure JMeter to use one thread:
```
./mvnw --define jmeter.threads=1 clean package
```
Create the database schema:
```
./mwnw flyway:migrate
```

Start the application:

java -jar target/quarkus-app/quarkus-run.jar

In a separate terminal, start the JMeter tests (we will call this terminal the test-terminal, and the terminal running the application the application-terminal):
```
./mvnw jmeter:jmeter
```

Observe that the tests finish without errors:

...
[INFO] summary =  10000 in 00:00:14 =  712.5/s Avg:     1 Min:     0 Max:   433 Err:     0 (0.00%)
...

Switch back to the application-terminal, stop it, and rebuild the application, configure JMeter to use 4 threads, start the application:
```
./mvnw --define jmeter.threads=4 clean package
java -jar target/quarkus-app/quarkus-run.jar
```
Back to the test-terminal, re-execute the JMeter tests:
```
./mvnw jmeter:jmeter
```

Observe that there are errors in the tests:

...
[INFO] summary =  40000 in 00:00:13 = 3034.4/s Avg:     1 Min:     0 Max:   482 Err:   927 (2.32%)
...

Find the stack trace mentioned above in the logs of the application-terminal
In the test-terminal, Run the wrk-tests, with 1 thread and 1 connection:
```
wrk/run.sh 1 1 30s
```
Observe that the tests finish without erros:
```
...
Non-2xx responses: 0 (0.00%)
...
```
Re-run the tests, with 1 thread and 2 connections:
```
wrk/run.sh 1 2 30s
```
Immediately switch back to the application-terminal and observe that, for some time, exceptions are thrown and then, the exceptions stop
When the tests finish, switch back to the test-terminal, observe the (relatively low) error rate:
```
...
Non-2xx responses: 242 (0.12%)
...
```
Re-run the wrk-tests, with 4 connections:
```
wrk/run.sh 1 4 30s
```
Immediately switch back to the application-terminal, observe that the application prints stack traces constantly
When the tests are finished, switch back to the test-terminal and observe the significantly higher error rate:
```
...
Non-2xx responses: 6597 (2.46%)
...
```

Output of `uname -a` or `ver`

Linux <redacted> 5.15.0-52-generic #58-Ubuntu SMP Thu Oct 13 08:03:55 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

Output of `java -version`

openjdk version "17.0.5" 2022-10-18
OpenJDK Runtime Environment Temurin-17.0.5+8 (build 17.0.5+8)
OpenJDK 64-Bit Server VM Temurin-17.0.5+8 (build 17.0.5+8, mixed mode, sharing)

GraalVM version (if different from Java)

GraalVM Mandrel, Version 22.3.1.0-java17

Quarkus version or git rev

2.16.6.Final 3.0.0.CR2

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

Apache Maven 3.8.7 (b89d5959fcde851dcb1c8946a785a163f14e1e29)
Maven home: /home/marco/.m2/wrapper/dists/apache-maven-3.8.7-bin/678cc9d4/apache-maven-3.8.7
Java version: 17.0.5, vendor: Eclipse Adoptium, runtime: /opt/java/mandrel/22.3.0.1-java17
Default locale: en_US, platform encoding: UTF-8
OS name: "linux", version: "5.15.0-52-generic", arch: "amd64", family: "unix"

Additional information

The errors disappear when we export QUARKUS_VERTX_EVENT_LOOPS_POOL_SIZE=1
The issue is similar to #23324, but in the case presented, no emitter is involved
The code for quarkus 3 is on branch quarkus-3 (github.com)
The behaviour is also observabiel when the app is compiled natively, for both 2.x and 3.x
Relevant quarkusio.zupipchat.com discussion

About this issue

Original URL
State: closed
Created a year ago
Comments: 17 (14 by maintainers)

Commits related to this issue

chore(deps): update all non-major dependencies (mulk/quarkus-googlecloud-jsonlogging!15) This MR contains the following updates: | Package | Type | Update | Change | |---|---|---|---| | [io.quarkus:... — committed to benkard/quarkus-googlecloud-jsonlogging by deleted user a year ago

Most upvoted comments

@turing85 I had a better look, you’re right the sequence is declared correctly (starting from 51 wasn’t necessary) and there’s indeed a problem in the ReactiveGeneratorWrapper. Tracking as https://github.com/hibernate/hibernate-reactive/issues/1587

Sanne on Apr 13, 2023

Thanks, we can see the error related to the IllegalState. Still working on it

DavideD on Apr 12, 2023

Have now merged a fix in Hibernate Reactive, we’ll release it soon and upgrade Quarkus.

https://github.com/hibernate/hibernate-reactive/pull/1608

Sanne on Apr 23, 2023

I’ve been working on this with @DavideD and our conclusion is that the task is being switched on a different thread by vert.x - which is entirely valid to do as it attempts to load balance different contexts on different threads, but the assertions we introduced in Hibernate Reactive are too strict as they don’t deal with this case.

You can experiment with this by disabling the assertions; we had foreseen some level of risk when introducing them so there’s a safeguard: set the system property org.hibernate.reactive.common.InternalStateAssertions.ENFORCE=false

https://github.com/Sanne/hibernate-reactive/blob/f5f693bae3d938eff1f473e75c363b89ad8df18e/hibernate-reactive-core/src/main/java/org/hibernate/reactive/common/InternalStateAssertions.java#L28-L30

My conclusions from this is that I was mistaken in enforcing this assertion as there’s some valid scenarious in which the thread switch is legal - at the time we were working to spot mistakes in Quarkus integration in which the thread switch was not intended.

On the other hand, I’m puzzled by the fact that we DID NEVER see this thread switch happen under other load tests (e.g. the Techempower benchmark - we’ve been runnig that extensively), while it’s trivial to reproduce with this one. I’d love to investigate further and figure out why it wasn’t being triggered on our other tests.

Sanne on Apr 12, 2023