Exceptions on dev mode reload (with multiple inbound requests?)

famod commented 1 year ago

Describe the bug

After changing a file, I often see one or more exceptions when hitting F5 in my UI (Vue.js SPA -> haproxy -> Quarkus). Those exceptions are mostly related to some NPEs in ArC, but I also had datasource issues like Stream closed.

For whatever reason, the SPA fires off two requests to the same endpoint, the second one apparently before waiting for the first one to finish.

Example exceptions (click me)

### OIDC ``` 2022-11-25 16:45:04,999 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-5) HTTP Request to %s failed, error id: %s [Error Occurred After Shutdown]: java.lang.RuntimeException: Error injecting io.quarkus.oidc.runtime.TenantConfigBean io.quarkus.oidc.runtime.DefaultTenantConfigResolver.tenantConfigBean at io.quarkus.oidc.runtime.DefaultTenantConfigResolver_Bean.create(Unknown Source) at io.quarkus.oidc.runtime.DefaultTenantConfigResolver_Bean.create(Unknown Source) at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:113) at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:37) at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:34) at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26) at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69) at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:34) at io.quarkus.arc.impl.ClientProxies.getApplicationScopedDelegate(ClientProxies.java:21) at io.quarkus.oidc.runtime.DefaultTenantConfigResolver_ClientProxy.arc$delegate(Unknown Source) at io.quarkus.oidc.runtime.DefaultTenantConfigResolver_ClientProxy.resolveConfig(Unknown Source) at io.quarkus.oidc.runtime.OidcAuthenticationMechanism.resolve(OidcAuthenticationMechanism.java:72) at io.quarkus.oidc.runtime.OidcAuthenticationMechanism.authenticate(OidcAuthenticationMechanism.java:44) at io.quarkus.oidc.runtime.OidcAuthenticationMechanism_ClientProxy.authenticate(Unknown Source) at io.quarkus.vertx.http.runtime.security.HttpAuthenticator.createSecurityIdentity(HttpAuthenticator.java:118) at io.quarkus.vertx.http.runtime.security.HttpAuthenticator.attemptAuthentication(HttpAuthenticator.java:97) at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2.handle(HttpSecurityRecorder.java:78) at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2.handle(HttpSecurityRecorder.java:60) at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284) at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:173) at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140) at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup.handleHotReplacementRequest(VertxHttpHotReplacementSetup.java:135) at io.quarkus.vertx.http.runtime.VertxHttpRecorder$11.handle(VertxHttpRecorder.java:510) at io.quarkus.vertx.http.runtime.VertxHttpRecorder$11.handle(VertxHttpRecorder.java:506) at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284) at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:173) at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140) at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:68) at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:37) at io.quarkus.vertx.http.runtime.VertxHttpRecorder$15.handle(VertxHttpRecorder.java:613) at io.quarkus.vertx.http.runtime.VertxHttpRecorder$15.handle(VertxHttpRecorder.java:596) at io.quarkus.vertx.http.runtime.VertxHttpRecorder$1.handle(VertxHttpRecorder.java:185) at io.quarkus.vertx.http.runtime.VertxHttpRecorder$1.handle(VertxHttpRecorder.java:160) at io.vertx.core.http.impl.Http1xServerRequestHandler.handle(Http1xServerRequestHandler.java:67) at io.vertx.core.http.impl.Http1xServerRequestHandler.handle(Http1xServerRequestHandler.java:30) at io.vertx.core.impl.EventLoopContext.emit(EventLoopContext.java:55) at io.vertx.core.impl.DuplicatedContext.emit(DuplicatedContext.java:158) at io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java:145) 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:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93) at io.netty.handler.codec.http.websocketx.extensions.WebSocketServerExtensionHandler.channelRead(WebSocketServerExtensionHandler.java:99) 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.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) 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.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:336) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:323) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:444) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:280) 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: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: java.lang.NullPointerException: Cannot invoke "io.quarkus.arc.ArcContainer.getActiveContext(java.lang.Class)" because "" is null at io.quarkus.oidc.runtime.TenantConfigBean_db1a9da4c1df4426bbea69cb152051caf53ae9c3_Synthetic_Bean.get(Unknown Source) at io.quarkus.oidc.runtime.TenantConfigBean_db1a9da4c1df4426bbea69cb152051caf53ae9c3_Synthetic_Bean.get(Unknown Source) ... 72 more ``` ### RR exception mapping ``` 17:06:36 ERROR [or.jb.re.re.co.co.AbstractResteasyReactiveContext] (executor-thread-5) Request failed [Error Occurred After Shutdown]: java.lang.NullPointerException: Cannot invoke "io.quarkus.arc.ArcContainer.getActiveContext(java.lang.Class)" because "" is null at someproject.api.exception.ApiExceptionMapper$GeneratedExceptionHandlerFor$Exception$OfMethod$mapToInternalServerError_Bean.get(Unknown Source) at someproject.api.exception.ApiExceptionMapper$GeneratedExceptionHandlerFor$Exception$OfMethod$mapToInternalServerError_Bean.get(Unknown Source) at io.quarkus.arc.impl.ArcContainerImpl.beanInstanceHandle(ArcContainerImpl.java:476) at io.quarkus.arc.impl.ArcContainerImpl.beanInstanceHandle(ArcContainerImpl.java:489) at io.quarkus.arc.impl.ArcContainerImpl$2.get(ArcContainerImpl.java:279) at io.quarkus.arc.impl.ArcContainerImpl$2.get(ArcContainerImpl.java:276) at io.quarkus.arc.runtime.BeanContainerImpl$1.create(BeanContainerImpl.java:46) at io.quarkus.resteasy.reactive.common.runtime.ArcBeanFactory.createInstance(ArcBeanFactory.java:27) at org.jboss.resteasy.reactive.server.core.RuntimeExceptionMapper.doGetExceptionMapper(RuntimeExceptionMapper.java:238) at org.jboss.resteasy.reactive.server.core.RuntimeExceptionMapper.getExceptionMapper(RuntimeExceptionMapper.java:217) at org.jboss.resteasy.reactive.server.core.RuntimeExceptionMapper.mapException(RuntimeExceptionMapper.java:79) at org.jboss.resteasy.reactive.server.core.ResteasyReactiveRequestContext.mapExceptionIfPresent(ResteasyReactiveRequestContext.java:334) at org.jboss.resteasy.reactive.server.handlers.ExceptionHandler.handle(ExceptionHandler.java:15) 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:833) ```

Expected behavior

No request should be processed while dev mode is being restarted.

Actual behavior

It seems that the first request triggers the reload and before that is finished, the second request catches Quarkus in an inconsistent state.

How to Reproduce?

Update: https://github.com/quarkusio/quarkus/issues/29646#issuecomment-2378025724

Output of `uname -a` or `ver`

No response

Output of `java -version`

No response

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.14.2

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

No response

Additional information

No response

gsmet commented 1 year ago

@geoand @mkouba @Ladicek might be something for you? We probably need to have proper locks?

geoand commented 1 year ago

I thought we already put connections on hold while restarting the application

mkouba commented 1 year ago

Hm, the actual restart should be performed during invocation of HotReplacementContext.doScan() in the synchronized block but it could probably happen that the second request holds onto the old deployment and fails with the NPE before the connection is closed here?

For whatever reason, the SPA fires off two requests to the same endpoint, the second one apparently before waiting for the first one to finish.

Is it the SPA or the haproxy?

famod commented 1 year ago

It's the SPA and my UI colleague says it's fine. Dunno, bit fishy.

mkouba commented 1 year ago

I know that it's probably difficult but could you try to build a simple reproducer app?

famod commented 1 year ago

I quickly tried hammering hibernate-orm-quickstart and two OIDC quickstarts with hey but wasn't able to provoke this issue. I might be wrong, but maybe those quickstarts are tearing down Quarkus too quickly (because they are too small).

mkouba commented 1 year ago

I quickly tried hammering hibernate-orm-quickstart and two OIDC quickstarts with hey but wasn't able to provoke this issue. I might be wrong, but maybe those quickstarts are tearing down Quarkus too quickly (because they are too small).

You can try to add some Thread.sleep()-like logic in the app init to prolong the scanning part.

famod commented 1 year ago

@mkouba "app init"? Where would you put it exactly? Thanks!

mkouba commented 1 year ago

@mkouba "app init"? Where would you put it exactly? Thanks!

Maybe a StartupEvent observer? And likewise a ShutdownEvent could be used to prolong the tear down phase.

famod commented 1 year ago

Ok, vanilla app level events then (I thought you were after some more extension-level kind of delay).

I played around with sleep in @PreDestroy but that didn't really cut it.

famod commented 1 year ago

FTR, this still happens with 2.16.5. I'll try to continue with my reproducer efforts.

famod commented 1 year ago

Still happens with 3.2.3, e.g.:

023-08-08 21:08:22,561 INFO [io.qua.dep.dev.RuntimeUpdatesProcessor] (vert.x-worker-thread-2) Restarting quarkus due to changes in EhbaApplicationController.class.
2023-08-08 21:08:22,675 WARN [org.hib.eng.jdb.spi.SqlExceptionHelper] (executor-thread-9) SQL Error: 0, SQLState: null
2023-08-08 21:08:22,676 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (executor-thread-9) This pool is closed and does not handle any more connections! [Error Occurred After Shutdown]
2023-08-08 21:08:22,681 INFO  (,) [io.quarkus] (Quarkus Main Thread) register-server stopped in 0.118s
2023-08-08 21:08:22,682 WARN  [foo.bar.reg.api.exc.ApiExceptionMapper] (executor-thread-9) internal exception: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection [This pool is closed and does not handle any more connections!] [n/a]
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:61)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:108)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:94)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:116)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:143)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:51)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:150)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:177)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:152)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.lambda$list$0(JdbcSelectExecutorStandardImpl.java:102)
    at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.executeQuery(DeferredResultSetAccess.java:226)
    at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.getResultSet(DeferredResultSetAccess.java:163)
    at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.advanceNext(JdbcValuesResultSetImpl.java:254)
    at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.processNext(JdbcValuesResultSetImpl.java:134)
    at org.hibernate.sql.results.jdbc.internal.AbstractJdbcValues.next(AbstractJdbcValues.java:19)
    at org.hibernate.sql.results.internal.RowProcessingStateStandardImpl.next(RowProcessingStateStandardImpl.java:66)
    at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:198)
    at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:361)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:168)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.list(JdbcSelectExecutorStandardImpl.java:93)
    at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:31)
    at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.lambda$new$0(ConcreteSqmSelectQueryPlan.java:110)
    at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.withCacheableSqmInterpretation(ConcreteSqmSelectQueryPlan.java:303)
    at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.performList(ConcreteSqmSelectQueryPlan.java:244)
    at org.hibernate.query.sqm.internal.QuerySqmImpl.doList(QuerySqmImpl.java:518)
    at org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:367)
    at org.hibernate.query.spi.AbstractSelectionQuery.getSingleResult(AbstractSelectionQuery.java:473)
    at io.quarkus.hibernate.orm.panache.common.runtime.CommonPanacheQueryImpl.singleResult(CommonPanacheQueryImpl.java:309)
    at io.quarkus.hibernate.orm.panache.runtime.PanacheQueryImpl.singleResult(PanacheQueryImpl.java:169)
    at de.tsystems.mms.nrwegbr.register.core.persistence.AccountRepository_0d33e07eee18a3c454bf8e3f7bdea8f00bc5e373Impl.findByUserName(Unknown Source)
    at de.tsystems.mms.nrwegbr.register.api.permission.ExtractJwtToken$Interceptor.intercept(ExtractJwtToken.java:94)
caused by: java.sql.SQLException: This pool is closed and does not handle any more connections!
    at io.agroal.pool.ConnectionPool.beforeAcquire(ConnectionPool.java:209)
    at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:235)
    at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
    at io.opentelemetry.instrumentation.jdbc.datasource.OpenTelemetryDataSource.wrapCall(OpenTelemetryDataSource.java:137)
    at io.opentelemetry.instrumentation.jdbc.datasource.OpenTelemetryDataSource.getConnection(OpenTelemetryDataSource.java:77)
    at io.quarkus.hibernate.orm.runtime.customized.QuarkusConnectionProvider.getConnection(QuarkusConnectionProvider.java:23)
    at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:113)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:143)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:51)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:150)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:177)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:152)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.lambda$list$0(JdbcSelectExecutorStandardImpl.java:102)
    at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.executeQuery(DeferredResultSetAccess.java:226)
    at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.getResultSet(DeferredResultSetAccess.java:163)
    at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.advanceNext(JdbcValuesResultSetImpl.java:254)
    at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.processNext(JdbcValuesResultSetImpl.java:134)
    at org.hibernate.sql.results.jdbc.internal.AbstractJdbcValues.next(AbstractJdbcValues.java:19)
    at org.hibernate.sql.results.internal.RowProcessingStateStandardImpl.next(RowProcessingStateStandardImpl.java:66)
    at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:198)
    at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:361)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:168)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.list(JdbcSelectExecutorStandardImpl.java:93)
    at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:31)
    at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.lambda$new$0(ConcreteSqmSelectQueryPlan.java:110)
    at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.withCacheableSqmInterpretation(ConcreteSqmSelectQueryPlan.java:303)
    at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.performList(ConcreteSqmSelectQueryPlan.java:244)
    at org.hibernate.query.sqm.internal.QuerySqmImpl.doList(QuerySqmImpl.java:518)
    at org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:367)
    at org.hibernate.query.spi.AbstractSelectionQuery.getSingleResult(AbstractSelectionQuery.java:473)
    at io.quarkus.hibernate.orm.panache.common.runtime.CommonPanacheQueryImpl.singleResult(CommonPanacheQueryImpl.java:309)
    at io.quarkus.hibernate.orm.panache.runtime.PanacheQueryImpl.singleResult(PanacheQueryImpl.java:169)
    at foo.bar.register.core.persistence.AccountRepository_0d33e07eee18a3c454bf8e3f7bdea8f00bc5e373Impl.findByUserName(Unknown Source)
    at foo.bar.register.api.permission.ExtractJwtToken$Interceptor.in(ExtractJwtToken.java:94)

and then after the restart:

2023-08-08 21:08:44,862 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (vert.x-worker-thread-2) Live reload took more than 4 seconds, you may want to enable instrumentation based reload (quarkus.live-reload.instrumentation=true). This allows small changes to take effect without restarting Quarkus.
2023-08-08 21:08:44,886 WARN  [io.qua.ope.run.QuarkusContextStorage] (vert.x-eventloop-thread-4) Context in storage not the expected context, Scope.close was not called correctly
2023-08-08 21:08:44,983 WARN  [foo.bar.reg.api.exc.ApiExceptionMapper] (executor-thread-1) internal exception: java.io.IOException: java.nio.channels.ClosedChannelException
    at org.jboss.resteasy.reactive.server.vertx.VertxInputStream$VertxBlockingInput.readBlocking(VertxInputStream.java:255)
    at org.jboss.resteasy.reactive.server.vertx.VertxInputStream.readIntoBuffer(VertxInputStream.java:122)
    at org.jboss.resteasy.reactive.server.vertx.VertxInputStream.read(VertxInputStream.java:84)
    at com.fasterxml.jackson.core.json.ByteSourceJsonBootstrapper.ensureLoaded(ByteSourceJsonBootstrapper.java:539)
    at com.fasterxml.jackson.core.json.ByteSourceJsonBootstrapper.detectEncoding(ByteSourceJsonBootstrapper.java:133)
    at com.fasterxml.jackson.core.json.ByteSourceJsonBootstrapper.constructParser(ByteSourceJsonBootstrapper.java:256)
    at com.fasterxml.jackson.core.JsonFactory._createParser(JsonFactory.java:1744)
    at com.fasterxml.jackson.core.JsonFactory.createParser(JsonFactory.java:1143)
    at com.fasterxml.jackson.databind.ObjectReader.createParser(ObjectReader.java:1103)
    at com.fasterxml.jackson.databind.ObjectReader.readValue(ObjectReader.java:1481)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.ServerJacksonMessageBodyReader.doReadFrom(ServerJacksonMessageBodyReader.java:87)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.ServerJacksonMessageBodyReader.readFrom(ServerJacksonMessageBodyReader.java:38)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.ServerJacksonMessageBodyReader.readFrom(ServerJacksonMessageBodyReader.java:77)
    at org.jboss.resteasy.reactive.server.handlers.RequestDeserializeHandler.readFrom(RequestDeserializeHandler.java:126)
    at org.jboss.resteasy.reactive.server.handlers.RequestDeserializeHandler.handle(RequestDeserializeHandler.java:84)
    at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:135)
    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:2513)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
    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:833)
caused by: java.nio.channels.ClosedChannelException
    at org.jboss.resteasy.reactive.server.vertx.VertxInputStream$VertxBlockingInput.<init>(VertxInputStream.java:183)
    at org.jboss.resteasy.reactive.server.vertx.VertxInputStream.<init>(VertxInputStream.java:38)
    at org.jboss.resteasy.reactive.server.vertx.VertxResteasyReactiveRequestContext.createInputStream(VertxResteasyReactiveRequestContext.java:243)
    at org.jboss.resteasy.reactive.server.core.ResteasyReactiveRequestContext.getInputStream(ResteasyReactiveRequestContext.java:717)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.ServerJacksonMessageBodyReader.readFrom(ServerJacksonMessageBodyReader.java:77)
    at org.jboss.resteasy.reactive.server.handlers.RequestDeserializeHandler.readFrom(RequestDeserializeHandler.java:126)
    at org.jboss.resteasy.reactive.server.handlers.RequestDeserializeHandler.handle(RequestDeserializeHandler.java:84)
    at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:135)
    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:2513)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
    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:833)

Next F5 is ok.

famod commented 1 year ago

3.3.2, bit different:

[io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-7) HTTP Request to /application/ehba/list-ca failed, error id: e8b6ca4b-4ccf-4eaf-9612-2a00561ae1d3-1 [Error Occurred After Shutdown]: java.lang.IllegalStateException: No CDI container is available
    at io.quarkus.arc.impl.ArcCDIProvider.getCDI(ArcCDIProvider.java:29)
    at jakarta.enterprise.inject.spi.CDI.getCDIProvider(CDI.java:78)
    at jakarta.enterprise.inject.spi.CDI.current(CDI.java:65)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$HttpAuthenticationHandler.setPathMatchingPolicy(HttpSecurityRecorder.java:375)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$AbstractAuthenticationHandler.handle(HttpSecurityRecorder.java:400)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$AbstractAuthenticationHandler.handle(HttpSecurityRecorder.java:385)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup.handleHotReplacementRequest(VertxHttpHotReplacementSetup.java:135)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$5.handle(VertxHttpRecorder.java:435)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$5.handle(VertxHttpRecorder.java:431)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:68)
    at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:37)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$2.handle(HttpServerCommonHandlers.java:82)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$2.handle(HttpServerCommonHandlers.java:65)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$1.handle(VertxHttpRecorder.java:176)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$1.handle(VertxHttpRecorder.java:152)
    at io.vertx.core.impl.EventLoopContext.emit(EventLoopContext.java:55)
    at io.vertx.core.impl.DuplicatedContext.emit(DuplicatedContext.java:158)
    at io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java:167)
    at io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:158)
    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.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
    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.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:333)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:454)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
    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)

Postremus commented 11 months ago

Also facing the last one @famod posted "No CDI container is available". On 3.2.6.Final.

famod commented 2 weeks ago

Still an issue in Quarkus 3.14.4. Trace looks a bit different now, but still OIDC in the mix:

ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-4) HTTP Request to /foo/bar failed, error id: a6e7350d-25f5-4b03-8a34-35d043a59d7c-3 [Error Occurred After Shutdown]: java.lang.IllegalArgumentException
    at io.quarkus.arc.impl.ArcContainerImpl.unwrap(ArcContainerImpl.java:996)
    at io.quarkus.arc.impl.ArcContainerImpl.instance(ArcContainerImpl.java:1031)
    at io.quarkus.arc.impl.Instances.resolveBeans(Instances.java:40)
    at io.quarkus.arc.impl.Instances.resolveBeans(Instances.java:36)
    at io.quarkus.arc.impl.InstanceImpl.resolve(InstanceImpl.java:339)
    at io.quarkus.arc.impl.InstanceImpl.<init>(InstanceImpl.java:169)
    at io.quarkus.arc.impl.InstanceImpl.forInjection(InstanceImpl.java:130)
    at io.quarkus.arc.impl.InstanceProvider.get(InstanceProvider.java:42)
    at io.quarkus.arc.impl.InstanceProvider.get(InstanceProvider.java:18)
    at io.quarkus.oidc.runtime.DefaultTenantConfigResolver_Bean.doCreate(Unknown Source)
    at io.quarkus.oidc.runtime.DefaultTenantConfigResolver_Bean.create(Unknown Source)
    at io.quarkus.oidc.runtime.DefaultTenantConfigResolver_Bean.create(Unknown Source)
    at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:119)
    at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:38)
    at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:35)
    at io.quarkus.arc.generator.Default_jakarta_enterprise_context_ApplicationScoped_ContextInstances.c204(Unknown Source)
    at io.quarkus.arc.generator.Default_jakarta_enterprise_context_ApplicationScoped_ContextInstances.computeIfAbsent(Unknown Source)
    at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:35)
    at io.quarkus.arc.impl.ClientProxies.getApplicationScopedDelegate(ClientProxies.java:21)
    at io.quarkus.oidc.runtime.DefaultTenantConfigResolver_ClientProxy.arc$delegate(Unknown Source)
    at io.quarkus.oidc.runtime.DefaultTenantConfigResolver_ClientProxy.resolveConfig(Unknown Source)
    at io.quarkus.oidc.runtime.OidcAuthenticationMechanism.resolve(OidcAuthenticationMechanism.java:81)
    at io.quarkus.oidc.runtime.OidcAuthenticationMechanism.authenticate(OidcAuthenticationMechanism.java:47)
    at io.quarkus.oidc.runtime.OidcAuthenticationMechanism_ClientProxy.authenticate(Unknown Source)
    at io.quarkus.vertx.http.runtime.security.HttpAuthenticator.createSecurityIdentity(HttpAuthenticator.java:223)
    at io.quarkus.vertx.http.runtime.security.HttpAuthenticator.attemptAuthentication(HttpAuthenticator.java:181)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$AuthenticationHandler.handle(HttpSecurityRecorder.java:284)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$AuthenticationHandler.handle(HttpSecurityRecorder.java:233)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1285)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
    at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup.handleHotReplacementRequest(VertxHttpHotReplacementSetup.java:144)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$HotReplacementRoutingContextHandler.handle(VertxHttpRecorder.java:1662)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$HotReplacementRoutingContextHandler.handle(VertxHttpRecorder.java:1652)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1285)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
    at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:68)
    at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:37)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$2.handle(HttpServerCommonHandlers.java:86)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$2.handle(HttpServerCommonHandlers.java:69)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$1.handle(VertxHttpRecorder.java:182)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$1.handle(VertxHttpRecorder.java:158)
    at io.vertx.core.impl.ContextImpl.emit(ContextImpl.java:328)
    at io.vertx.core.impl.DuplicatedContext.emit(DuplicatedContext.java:164)
    at io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java:174)
    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.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:289)
    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.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
    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:1407)
    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:918)
    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:994)
    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:1583)

/cc @sberyozkin

PS: Haven't had any time to try harder with a reproducer, unfortunately.

geoand commented 2 weeks ago

Thanks for checking

famod commented 1 week ago

So I was able to reproduce this!

clone quarkus-quickstarts (I used main@3.15.1)
cd security-openid-connect-client-quickstart

apply:


diff --git a/security-openid-connect-client-quickstart/src/main/java/org/acme/security/openid/connect/client/FrontendResource.java b/security-openid-connect-client-quickstart/src/main/java/org/acme/security/openid/connect/client/FrontendResource.java
index cf87223f6..d60ebb0b4 100644
--- a/security-openid-connect-client-quickstart/src/main/java/org/acme/security/openid/connect/client/FrontendResource.java
+++ b/security-openid-connect-client-quickstart/src/main/java/org/acme/security/openid/connect/client/FrontendResource.java
@@ -47,7 +47,10 @@ public class FrontendResource {
 @Produces("text/plain")
 public Uni<String> getUserNameWithOidcClientTokenHeaderParam() {
    return tokenHelper.getTokens(oidcClientCreator.getOidcClient()).onItem()

.transformToUni(tokens -> restClientWithTokenHeaderParam.getUserName("Bearer " + tokens.getAccessToken()));
.transformToUni(tokens -> {
System.out.println("AccessToken: " + tokens.getAccessToken());
return restClientWithTokenHeaderParam.getUserName("Bearer " + tokens.getAccessToken());
}); }

@GET
./mvnw quarkus:dev
curl http://localhost:8080/frontend/user-name-with-oidc-client-token-header-param
copy access token from the console (after "AccessToken: ", e.g. eyJhbGciOiJSU...)
make an arbitrary change to any file to trigger reload on next request
hey -H "Authorization: Bearer <insert token here>" http://localhost:8080/protected/userName (or use any other tool to send multiple concurrent requests)

/cc @sberyozkin

famod commented 6 days ago

I'm under the impression that oidc is only a victim of a timing issue (?) in VertxHttpHotReplacementSetup or HotReplacementRoutingContextHandler, but I might be very wrong here since I'm not familiar with the code involved.

quarkusio / quarkus