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

Resteasy Reactive/Panache requests reactive Hibernate session from executor thread if request is large #31606

Closed
TwoFX opened this issue Mar 4, 2023 · 8 comments · Fixed by #31613
Assignees
Labels
area/rest kind/bug Something isn't working
Milestone

Comments

@TwoFX
Copy link
Contributor

TwoFX commented Mar 4, 2023

Describe the bug

I have a simple project which accepts some data via JSON through RESTEasy Reactive and saves it to the database using Hibernate Reactive with Panache. This works fine as long as the request object is small. However, if the request object is large (in my case, a few megabytes), then the request fails with HR000068: This method should exclusively be invoked from a Vert.x EventLoop thread; currently running on thread 'executor-thread-0' (see below for the full stack trace).

Expected behavior

The request should always finish successfully, regardless of the size of the request object.

Actual behavior

The request fails and returns a 500 status code. The following logging output is generated:

2023-03-04 16:57:10,768 ERROR [org.jbo.res.rea.ser.cor.RuntimeExceptionMapper] (executor-thread-0) An operation that needed be run on a Vert.x EventLoop thread was run on a worker pool thread. This likely means you need to annotate de.markushimmel.Resource#create(class de.markushimmel.RequestObject) with @io.smallrye.common.annotation.NonBlocking. Alternatively you can annotate the class de.markushimmel.Resource to make every method on the class run on a Vert.x EventLoop thread, or annotate your sub class of the jakarta.ws.rs.core.Application class to affect the entire application
2023-03-04 16:57:10,774 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-0) HTTP Request to /resource/create failed, error id: bf8e7471-cb50-4817-aeaf-eb549c080252-1: java.lang.IllegalStateException: HR000068: This method should exclusively be invoked from a Vert.x EventLoop thread; currently running on thread 'executor-thread-0'
        at org.hibernate.reactive.common.InternalStateAssertions.assertUseOnEventLoop(InternalStateAssertions.java:40)
        at org.hibernate.reactive.mutiny.impl.MutinySessionFactoryImpl.connection(MutinySessionFactoryImpl.java:177)
        at org.hibernate.reactive.mutiny.impl.MutinySessionFactoryImpl.lambda$openSession$0(MutinySessionFactoryImpl.java:111)
        at io.smallrye.context.impl.wrappers.SlowContextualSupplier.get(SlowContextualSupplier.java:21)
        at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage.subscribe(UniCreateFromCompletionStage.java:24)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniRunSubscribeOn.lambda$subscribe$0(UniRunSubscribeOn.java:27)
        at org.hibernate.reactive.context.impl.VertxContext.execute(VertxContext.java:90)
        at io.smallrye.mutiny.operators.uni.UniRunSubscribeOn.subscribe(UniRunSubscribeOn.java:25)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemConsume.subscribe(UniOnItemConsume.java:30)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemOrFailureFlatMap.subscribe(UniOnItemOrFailureFlatMap.java:27)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemOrFailureFlatMap.subscribe(UniOnItemOrFailureFlatMap.java:27)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.groups.UniSubscribe.withSubscriber(UniSubscribe.java:51)
        at io.smallrye.mutiny.groups.UniSubscribe.with(UniSubscribe.java:110)
        at io.smallrye.mutiny.groups.UniSubscribe.with(UniSubscribe.java:88)
        at org.jboss.resteasy.reactive.server.handlers.UniResponseHandler.handle(UniResponseHandler.java:19)
        at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:123)
        at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
        at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:1589)

2023-03-04 16:57:10,777 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (executor-thread-0) Request failed: java.lang.IllegalStateException: HR000068: This method should exclusively be invoked from a Vert.x EventLoop thread; currently running on thread 'executor-thread-0'
        at org.hibernate.reactive.common.InternalStateAssertions.assertUseOnEventLoop(InternalStateAssertions.java:40)
        at org.hibernate.reactive.mutiny.impl.MutinySessionFactoryImpl.connection(MutinySessionFactoryImpl.java:177)
        at org.hibernate.reactive.mutiny.impl.MutinySessionFactoryImpl.lambda$openSession$0(MutinySessionFactoryImpl.java:111)
        at io.smallrye.context.impl.wrappers.SlowContextualSupplier.get(SlowContextualSupplier.java:21)
        at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage.subscribe(UniCreateFromCompletionStage.java:24)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniRunSubscribeOn.lambda$subscribe$0(UniRunSubscribeOn.java:27)
        at org.hibernate.reactive.context.impl.VertxContext.execute(VertxContext.java:90)
        at io.smallrye.mutiny.operators.uni.UniRunSubscribeOn.subscribe(UniRunSubscribeOn.java:25)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemConsume.subscribe(UniOnItemConsume.java:30)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemOrFailureFlatMap.subscribe(UniOnItemOrFailureFlatMap.java:27)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemOrFailureFlatMap.subscribe(UniOnItemOrFailureFlatMap.java:27)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.groups.UniSubscribe.withSubscriber(UniSubscribe.java:51)
        at io.smallrye.mutiny.groups.UniSubscribe.with(UniSubscribe.java:110)
        at io.smallrye.mutiny.groups.UniSubscribe.with(UniSubscribe.java:88)
        at org.jboss.resteasy.reactive.server.handlers.UniResponseHandler.handle(UniResponseHandler.java:19)
        at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:123)
        at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
        at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:1589)

How to Reproduce?

Reproducer: https://github.com/TwoFX/resteasy-reactive-large-request-bug

Steps to reproduce:
Run ./mvnw verify. There are two tests, one for a request body of around 5000 bytes and one for a request body of around 5000000 bytes. The first test succeeds, and the second test fails.

Output of uname -a or ver

Linux markus-laptop 6.2.1-arch1-1 #1 SMP PREEMPT_DYNAMIC Sun, 26 Feb 2023 03:39:23 +0000 x86_64 GNU/Linux

Output of java -version

openjdk version "19.0.2" 2023-01-17
OpenJDK Runtime Environment (build 19.0.2+7)
OpenJDK 64-Bit Server VM (build 19.0.2+7, mixed mode)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

3.0.0.Alpha4

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

Apache Maven 3.8.6 (84538c9988a25aec085021c365c560670ad80f63)
Maven home: /home/markus/.m2/wrapper/dists/apache-maven-3.8.6-bin/67568434/apache-maven-3.8.6
Java version: 19.0.2, vendor: N/A, runtime: /usr/lib/jvm/java-19-openjdk
Default locale: en_US, platform encoding: UTF-8
OS name: "linux", version: "6.2.1-arch1-1", arch: "amd64", family: "unix"

Additional information

I have verified that the problem is NOT present in Quarkus 2.16.4.Final.

I tried to test the current main, but unfortunately after changing the group id and the version the reproducer fails to build. Maven gives the following error:

[WARNING] The POM for io.quarkus:quarkus-hibernate-reactive-panache:jar:999-20230217.022801-642 is invalid, transitive dependencies (if any) will not be available: 1 problem was encountered while building the effective model for io.quarkus:quarkus-hibernate-reactive-panache:999-SNAPSHOT
[ERROR] 'dependencies.dependency.version' for org.hibernate:hibernate-jpamodelgen-jakarta:jar is missing. @ 

I'm not sure what I'm doing wrong here. It would be very nice if someone could assist me with this, as this is currently preventing me from testing potential fixes.

I have digged into the bug a bit. The reason why we're on an executor thread in the first place is that the InputHandler does this if the request object is too large. Thus, for small request objects, we enter the UniResultHandler on a Vertx event loop thread, while for large request objects, we enter it on an executor thread.

Now, (but, as noted above, I haven't tested any of this), my guess is that the first commit with this problem is 47b10ae. Since then, the Uni subscription created by Panache.withTransaction uses a different Executor. In Quarkus 2, it is AbstractJpaOperations::executeInVertxEventLoop (see here). In Quarkus 3, it is the org.hibernate.reactive.context.impl.VertxContext (see here).

Now, it turns out that VertxContext::execute doesn't actually always execute the runnable on a Vertx event loop thread, as you can see in the else branch. I don't understand any of this well enough to know whether this is intentional or not -- perhaps, the line runnable.run() (line 90) should actually be currentContext.executeInContext( x -> runnable.run() ). So it is actually possible that this isn't a problem with Quarkus, but with Hibernate Reactive. Again, as I mentioned, I haven't tried this potential fix because I can't get Quarkus to build properly locally.

I would very much like to contribute a fix for this myself if possible, I only need some feedback if my analysis is correct and some assistance with the "POM is invalid" problem described above.

@TwoFX TwoFX added the kind/bug Something isn't working label Mar 4, 2023
@quarkus-bot
Copy link

quarkus-bot bot commented Mar 4, 2023

/cc @DavideD (hibernate-reactive), @FroMage (panache,resteasy-reactive), @Sanne (hibernate-reactive), @Sgitario (resteasy-reactive), @gavinking (hibernate-reactive), @geoand (resteasy-reactive), @loicmathieu (panache), @stuartwdouglas (resteasy-reactive)

@geoand
Copy link
Contributor

geoand commented Mar 6, 2023

What's going on here is that because you are sending a large payload that needs to be built up in memory, Quarkus is automatically switching the handling of the request to a worker thread.

You can tune this property by setting quarkus.resteay-reactive.input-buffer-size

@geoand
Copy link
Contributor

geoand commented Mar 6, 2023

Let me check and see however if there is an easy way to fix the issue

@TwoFX
Copy link
Contributor Author

TwoFX commented Mar 6, 2023

Let me check and see however if there is an easy way to fix the issue

Thanks for looking into it. Just to make sure you're not doing any unnecessary work, have you read my analysis in the "Additional information" section? This suggests that the problem might be in Hibernate Reactive rather than RESTEasy Reactive.

@geoand
Copy link
Contributor

geoand commented Mar 6, 2023

I have yes, thanks for that!

There may be in an issue in HR, but there is definitely an issue on RR as well which I want to address :)

@geoand
Copy link
Contributor

geoand commented Mar 6, 2023

I am pretty sure that #31613 fixes the whole problem, although I can't test the reproducer because currently Hibernate Reactive is temporarily disabled in the main branch (which is also why you could not try your fix).

geoand added a commit to geoand/quarkus that referenced this issue Mar 6, 2023
@Sanne
Copy link
Member

Sanne commented Mar 6, 2023

hi @TwoFX - what a great bugreport, thanks!

So, yes Hibernate Reactive is currently disabled in main - we're working on it and hoping to re-enable the module soon, even if only as early preview with some limitations.

The assertions in Hibernate Reactive are important; it can't work correctly when it's not run on the actual event-loop as that's were the responses from the database are delivered and we need to process them in well defined order; I'm surprised that Resteasy Reactive/Panache requests were allowed to occasionally fallback to a different model: this requirement is double-checked by Hibernate Reactive as it's otherwise tricky to debug, but similar event ordering problems could potentially affect other components too - just harder to notice.

@geoand
Copy link
Contributor

geoand commented Mar 6, 2023

I'm surprised that Resteasy Reactive/Panache requests were allowed to occasionally fallback to a different model

This was an oversight that should be fixed by the PR :)

geoand added a commit to geoand/quarkus that referenced this issue Mar 6, 2023
geoand added a commit to geoand/quarkus that referenced this issue Mar 6, 2023
geoand added a commit to geoand/quarkus that referenced this issue Mar 7, 2023
geoand added a commit to geoand/quarkus that referenced this issue Mar 7, 2023
geoand added a commit to geoand/quarkus that referenced this issue Mar 7, 2023
geoand added a commit that referenced this issue Mar 7, 2023
Ensure large payloads don't affect the invoking thread of a Resource Method
@quarkus-bot quarkus-bot bot added this to the 3.0 - main milestone Mar 7, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/rest kind/bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants