quarkus
quarkus copied to clipboard
quarkusio
First Request to Reactive SQL fail
Describe the bug at first time that request an concurrency reactive sql client, it fail. But the second time it work fine
Expected behavior that also works fine the first time
Actual behavior after the application startup and receives the first request to a method with reactive sql concurrent calls, the connection fail.
To Reproduce In a Reactive SQL Cient Application with resteasy,reactive-pg-client,resteasy-mutiny extensions
- create a methos like this:
var query = findAll();
var list = query.page(Page.of(1, 10)).list();
var total = query.count();
return Uni.combine().all().unis(list, total).asTuple().onItem().transform((tuple) -> {
return PageResponse.newBuilder().setElements(tuple.getItem1()).setTotalCount(tuple.getItem2()).build();
});
- statup quarkus
- genered an request
- this will fail on the line "var total = query.count();"
The error is:
Caused by: java.lang.IllegalStateException: session is currently connecting to database
at org.hibernate.reactive.pool.impl.ProxyConnection.withConnection(ProxyConnection.java:52)
at org.hibernate.reactive.pool.impl.ProxyConnection.selectJdbc(ProxyConnection.java:109)
at org.hibernate.reactive.loader.ReactiveLoader.executeReactiveQueryStatement(ReactiveLoader.java:106)
at org.hibernate.reactive.loader.ReactiveLoader.doReactiveQueryAndInitializeNonLazyCollections(ReactiveLoader.java:63)
at org.hibernate.reactive.loader.CachingReactiveLoader.doReactiveList(CachingReactiveLoader.java:62)
at org.hibernate.reactive.loader.CachingReactiveLoader.reactiveListIgnoreQueryCache(CachingReactiveLoader.java:80)
at org.hibernate.reactive.loader.hql.impl.ReactiveQueryLoader.reactiveList(ReactiveQueryLoader.java:113)
at org.hibernate.reactive.loader.hql.impl.ReactiveQueryLoader.reactiveList(ReactiveQueryLoader.java:87)
at org.hibernate.reactive.session.impl.ReactiveQueryTranslatorImpl.reactiveList(ReactiveQueryTranslatorImpl.java:122)
at org.hibernate.reactive.session.impl.ReactiveHQLQueryPlan.performReactiveList(ReactiveHQLQueryPlan.java:114)
at org.hibernate.reactive.session.impl.ReactiveSessionImpl.lambda$reactiveList$6(ReactiveSessionImpl.java:389)
at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1106)
at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2235)
at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:143)
at org.hibernate.reactive.session.impl.ReactiveSessionImpl.reactiveList(ReactiveSessionImpl.java:389)
at org.hibernate.reactive.session.impl.ReactiveQueryImpl.doReactiveList(ReactiveQueryImpl.java:133)
at org.hibernate.reactive.session.impl.ReactiveQueryImpl.getReactiveResultList(ReactiveQueryImpl.java:109)
at org.hibernate.reactive.session.impl.ReactiveQueryImpl.getReactiveSingleResult(ReactiveQueryImpl.java:84)
at org.hibernate.reactive.mutiny.impl.MutinyQueryImpl.getSingleResult(MutinyQueryImpl.java:168)
at io.quarkus.hibernate.reactive.panache.common.runtime.CommonPanacheQueryImpl.lambda$count$3(CommonPanacheQueryImpl.java:204)
at io.quarkus.hibernate.reactive.panache.common.runtime.CommonPanacheQueryImpl.applyFilters(CommonPanacheQueryImpl.java:323)
at io.quarkus.hibernate.reactive.panache.common.runtime.CommonPanacheQueryImpl.count(CommonPanacheQueryImpl.java:204)
at io.quarkus.hibernate.reactive.panache.runtime.PanacheQueryImpl.count(PanacheQueryImpl.java:144)
at com.example.template.repository.reactive.panache.CotPanacheRepository.getPage(CotPanacheRepository.java:46)
at com.example.template.repository.reactive.panache.CotPanacheRepository_ClientProxy.getPage(CotPanacheRepository_ClientProxy.zig:1614)
at com.example.template.core.impl.CotCoreImpl.getPage(CotCoreImpl.java:37)
at com.example.template.core.impl.CotCoreImpl_ClientProxy.getPage(CotCoreImpl_ClientProxy.zig:349)
at com.example.template.api.CotApi.getPage(CotApi.java:48)
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)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:643)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:507)
... 25 more
Environment (please complete the following information):
- Output of
uname -aorver: Linux 5.3.18-lp152.60-default x86_64 x86_64 x86_64 GNU/Linux - Output of
java -version: OpenJDK 64-Bit Server VM Corretto-11.0.10.9.1 (build 11.0.10+9-LTS, mixed mode) - GraalVM version (if different from Java):
- Quarkus version or git rev: 1.10.5, 1.11.0 and 1.11.1
- Build tool (ie. output of
mvnw --versionorgradlew --version): 3.6.3
not yet, but it is easy to reproduce. Only make two concurrent reactive request to database (postgresql 13 in my case), startup the application and execute a reactive service. If you wish i could create a demo test repo
If you wish i could create a demo test repo
That would be great and save me a lot of time
This looks like the same issue as others have reported: not using a transaction and/or not delegating to the right thread.
IMO it's Panache Reactive which should not allow this usage and throw a better exception.
This looks like the same issue as others have reported: not using a transaction and/or not delegating to the right thread.
I think so, but I prefer to check with the test case
(I don't know for sure and will let @DavideD reprodice and confirm, I'm just suspecting this might be the case since I see RestEasy being used in the stacktrace)
in repository example is even worse, since it gives error in all requests :(
2021-02-01 11:59:08,151 ERROR [org.hib.rea.errors] (vert.x-eventloop-thread-23) could not execute query: java.util.concurrent.CompletionException: java.lang.IllegalStateException: Session/EntityManager is closed
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.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:792)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:475)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378)
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:829)
Caused by: java.lang.IllegalStateException: Session/EntityManager is closed
at org.hibernate.internal.AbstractSharedSessionContract.checkOpen(AbstractSharedSessionContract.java:375)
at org.hibernate.engine.spi.SharedSessionContractImplementor.checkOpen(SharedSessionContractImplementor.java:148)
at org.hibernate.reactive.session.impl.ReactiveSessionImpl.checkOpen(ReactiveSessionImpl.java:1394)
at org.hibernate.internal.AbstractSharedSessionContract.checkOpenOrWaitingForAutoClose(AbstractSharedSessionContract.java:381)
at org.hibernate.internal.SessionImpl.getEntityUsingInterceptor(SessionImpl.java:563)
at org.hibernate.loader.Loader.getRow(Loader.java:1609)
at org.hibernate.loader.Loader.getRowFromResultSet(Loader.java:740)
at org.hibernate.loader.Loader.getRowsFromResultSet(Loader.java:1039)
at org.hibernate.reactive.loader.hql.impl.ReactiveQueryLoader.getRowsFromResultSet(ReactiveQueryLoader.java:203)
at org.hibernate.reactive.loader.ReactiveLoaderBasedResultSetProcessor.reactiveExtractResults(ReactiveLoaderBasedResultSetProcessor.java:73)
at org.hibernate.reactive.loader.hql.impl.ReactiveQueryLoader$1.reactiveExtractResults(ReactiveQueryLoader.java:69)
at org.hibernate.reactive.loader.ReactiveLoader.reactiveProcessResultSet(ReactiveLoader.java:123)
at org.hibernate.reactive.loader.ReactiveLoader.lambda$doReactiveQueryAndInitializeNonLazyCollections$0(ReactiveLoader.java:71)
at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072)
... 39 more
Process finished with exit code 137 (interrupted by signal 9: SIGKILL)
please note that just created a service called hello/first. It does not have initial concurrency. Now, if service "hello/first" is executed at first and then execute "hello" service, then no error is present
Yes, this is the problem @Sanne was talking about. When I run the test I have the following exception:
021-02-01 17:25:34,176 ERROR [org.jbo.res.res.i18n] (executor-thread-5) RESTEASY002020: Unhandled asynchronous exception, sending back 500: org.jboss.resteasy.spi.ApplicationException: java.lang.AssertionError: This needs to be run on the Vert.x event loop
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:183)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:643)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:507)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:457)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:459)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:419)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:393)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:68)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:138)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.access$000(VertxRequestHandler.java:41)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:93)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2415)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
at java.base/java.lang.Thread.run(Thread.java:832)
at org.jboss.threads.JBossThread.run(JBossThread.java:501)
Caused by: 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.mutiny.impl.MutinySessionFactoryImpl.openSession(MutinySessionFactoryImpl.java:67)
at io.quarkus.hibernate.reactive.runtime.ReactiveSessionProducer.createMutinySession(ReactiveSessionProducer.java:32)
You say that the problem is resteasy? even if concurrent panache reactive code work fine with just before execute a call to non-concurrent panache code? Note: an unit test only to repository layer also fails
This will work if you wrap everything in a transaction:
public Uni<PageResponse<Entity>> getPage() {
return Panache.withTransaction(() -> {
var query = this.findAll();
var list = query.page( Page.of( 1, 10 ) ).list();
var total = query.count();
return Uni.combine().all().unis(list, total).asTuple().onItem().transform((tuple) ->
PageResponse.<Entity>newBuilder()
.setElements(tuple.getItem1())
.setTotalCount(tuple.getItem2())
.build() );
});
}
Ok, i will use this way. But i still think there are an issue in somewhere. Maybe in future releases no longer have to use transaction in this case. In any case, thank you very much!!!
You say that the problem is resteasy? even if concurrent panache reactive code work fine with just before execute a call to non-concurrent panache code?
Well it's not RESTEasy's fault, but a limitation of our current integration: it's expected to run all Hibernate Reactive code within a reactive context - which at this time means within the same Vert.x eventloop as the vert.x SQL client which it's using underneath.
Failing to run it on the right thread will produce such obscure errors; we certainly need to fix this.
N.B. if you run you reproducer as a test it will fail, as there are assertions which explicitly check for this code to be run on the right thread. One way we could fix this is to promote such assertions to hard requirements - haven't done so yet as we were exploring options, and trying to figure if there was a way to allow this without being that restrictive.
Now, after calling a simple request to panache reactive, all subsequent concurrent request to database work fine! I do not know how initialization connections works in panache reactive, but from the behavior and the error "Session/EntityManager is closed" all this looks like initialization connections trouble in hibernete reactive. Isn't it?
but anyway, thanks for helping me and giving me a solution to my issue
I do not know how initialization connections works in panache reactive, but from the behavior and the error "Session/EntityManager is closed" all this looks like initialization connections trouble in hibernete reactive. Isn't it?
The code is fine but a single Session is not designed to be threadsafe; a consequence of running this on the wrong thread is that both your original thread and the Vert.x thread make state changes, leading likely to illegal state (and complex to diagnose issues).
So we need to ensure all operations are being scheduled on the right thread.
So, I'm a bit puzzled by the state of this issue. What is wrong and what can we fix?
It looks like we're getting cryptic exceptions such as java.lang.IllegalStateException: session is currently connecting to database which is a totally bogus error message which does not at all reflect what's going on.
I was sorta believing that the issue was that we were invoking an operation on a worker thread which is forbidden, but I tried it in resteasy-reactive and got the same issue on an IO thread.
So let's ask this very clearly @Sanne @DavideD @gavinking:
- what operations can I do on the reactive session without a transaction?
- is there a different outcome depending on which thread is calling the operation? As in: should be it a worker thread or an IO thread?
- who is going to fix the error message? I could fix it in the Panache layer when I access a reactive session: I can check the current thread, not sure if I can check if there's a current transaction, though (how?). But, won't this affect even users of the reactive session without the Panache layer? If yes, then that error check belongs in the HR quarkus extension, or the HR session itself, no?
what operations can I do on the reactive session without a transaction?
I don't think in this case the problem is the lack of a transaction, I think the issue get solved because when one calls withTransaction the block of code runs in the right Vert.x context. As far as I know one could do some reads without a transaction. What happens when we call Panache.withTransaction?
is there a different outcome depending on which thread is calling the operation? As in: should be it a worker thread or an IO thread?
In Hibernate Reactive we check two things:
- The thread must be an eventLoopThread using
io.vertx.core.ContextContext.isOnEventLoopThread() - The thread that has created the session is the same thread that is now doing the operation
I don't know if this answer your question.
who is going to fix the error message? I could fix it in the Panache layer when I access a reactive session: I can check the current thread, not sure if I can check if there's a current transaction, though (how?). But, won't this affect even users of the reactive session without the Panache layer? If yes, then that error check belongs in the HR quarkus extension, or the HR session itself, no?
We probably need to have better error messages on the Hibernate Reactive side. But first we need to understand a bit better why this is happening
I didn't have much time to investigate this issue further, but I should be able to get back to it soon
@FroMage please see org.hibernate.reactive.common.InternalStateAssertions : it expects a system property to be set to enable the assertions that Davide is mentioning.
I had hopes to enable these assertions by default, but I wasn't able to do so as it would break Panache apparently. That's precisely the issue I asked you about some months ago, but then you had been drafted to work on other things... I hope you could make Panache work now with the checks enabled?
As you can see it can be quite confusing when those assertions don't hold.
BTW the system property is set for the integration tests using Hibernate Reactive which don't use Panache; see:
- integration-tests/hibernate-reactive-postgresql/pom.xml
- integration-tests/hibernate-reactive-db2/pom.xml
- integration-tests/hibernate-reactive-mysql/pom.xml
Well, it's not just setting up the assertion checks, right? If we want to make this work transparently for Panache, we need to start switching to the right thread behind the scenes if required, right?
@FroMage right, I need you to patch Panache Reactive to run things on the right thread. Enabling the assertions should help you to verify being on the right track - and when you're done I'll patch Hibernate Reactive to enable the assertions by default.
What we need is all Quarkus integration tests (including those using Panache) to be able to pass with those assertions enabled.
cc/ @DavideD @gavinking
I was talking to @FroMage about some other stuff and he suggested this was a problem that we would need to solve before doing anything else, so I volunteered to have a look to provide a fresh pair of eyes.
Disclaimer: I don't know much about HR, so my conclusions might be entirely mistaken.
First of all, I used the reproducer, but switched to RESTEasy Reactive in order to ensure that no threading issues exist during the request handling. Using that, I was consistently able to reproduce:
2021-05-11 13:23:21,961 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (vert.x-eventloop-thread-35) Request failed: java.lang.IllegalStateException: session is currently connecting to database
when hitting http://localhost:8080/hello. This was the case for both the supplied version of Quarkus and Quarkus from main.
Following a debugging session, I believe that the problem is simply that the operations performed by the application (Repository#getPage) are happening concurrently (due to the use of Uni.combine()) which leads to the fact that the first operation has not finished obtaining and setting the connection when the second operation requests a connection - this leads to the error we see (which AFAICT, is not bogus).
The reason the problem goes away when the operations of Repository#getPage are wrapped in Panache.withTransaction is because by the time the actual operations try to obtain that connection, the connection has already been set by virtue of the transaction being started (which of course entails that the connection was obtained)
@geoand sure that helps but there's a deeper issue if we don't guarantee all mutations-executing code is not run on the expected thread. So another key difference is that withTransaction creates a block of code which can be entirely and sequentially be run on the right worker, as HR will do.