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

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

Closed
famod opened this issue Dec 2, 2022 · 19 comments · Fixed by #45670
Closed

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

famod opened this issue Dec 2, 2022 · 19 comments · Fixed by #45670
Labels
area/devmode kind/bug Something isn't working
Milestone

Comments

@famod
Copy link
Member

famod commented Dec 2, 2022

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 "<local2>" 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 "<local2>" 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: #29646 (comment)

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

@famod famod added the kind/bug Something isn't working label Dec 2, 2022
@gsmet
Copy link
Member

gsmet commented Dec 2, 2022

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

@geoand
Copy link
Contributor

geoand commented Dec 5, 2022

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

@mkouba
Copy link
Contributor

mkouba commented Dec 5, 2022

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
Copy link
Member Author

famod commented Dec 5, 2022

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

@mkouba
Copy link
Contributor

mkouba commented Dec 5, 2022

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

@famod
Copy link
Member Author

famod commented Dec 5, 2022

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
Copy link
Contributor

mkouba commented Dec 6, 2022

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
Copy link
Member Author

famod commented Dec 11, 2022

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

@mkouba
Copy link
Contributor

mkouba commented Dec 12, 2022

@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
Copy link
Member Author

famod commented Dec 13, 2022

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
Copy link
Member Author

famod commented Mar 22, 2023

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

@famod
Copy link
Member Author

famod commented Aug 8, 2023

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
Copy link
Member Author

famod commented Sep 6, 2023

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
Copy link
Member

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

@famod
Copy link
Member Author

famod commented Sep 16, 2024

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
Copy link
Contributor

geoand commented Sep 16, 2024

Thanks for checking

@famod
Copy link
Member Author

famod commented Sep 26, 2024

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
Copy link
Member Author

famod commented Sep 27, 2024

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.

@FroMage
Copy link
Member

FroMage commented Jan 10, 2025

I've another reproducer for this:

In quarkiverse/quarkus-renarde#266 a user reported an issue which happens when triggering multiple connections during a live reload.

Apparently, according to

we continue serving requests while a live reload is happening:
ClassLoader current = Thread.currentThread().getContextClassLoader();
VertxCoreRecorder.getVertx().get().getOrCreateContext().executeBlocking(new Callable<Boolean>() {
@Override
public Boolean call() {
//the blocking pool may have a stale TCCL
Thread.currentThread().setContextClassLoader(current);
boolean restart = false;
try {
DevConsoleManager.setDoingHttpInitiatedReload(true);
synchronized (this) {
if (nextUpdate < System.currentTimeMillis() || hotReplacementContext.isTest()) {
nextUpdate = System.currentTimeMillis() + HOT_REPLACEMENT_INTERVAL;
Object currentState = VertxHttpRecorder.getCurrentApplicationState();
try {
restart = hotReplacementContext.doScan(true);
} catch (Exception e) {
throw new IllegalStateException("Unable to perform live reload scanning", e);
}
if (currentState != VertxHttpRecorder.getCurrentApplicationState()) {
//its possible a Kafka message or some other source triggered a reload,
//so we could wait for the restart (due to the scan lock)
//but then fail to dispatch to the new application
restart = true;
}
}
}
if (hotReplacementContext.getDeploymentProblem() != null) {
throw new NoStackTraceException(hotReplacementContext.getDeploymentProblem());
}
if (restart) {
//close all connections on close, except for this one
//this prevents long-running requests such as SSE or websockets
//from holding onto the old deployment
Set<ConnectionBase> connections = new HashSet<>(openConnections);
for (ConnectionBase con : connections) {
if (con != connectionBase) {
con.close();
}
}
}
} finally {
DevConsoleManager.setDoingHttpInitiatedReload(false);
}
return restart;
}
}, false).onComplete(new Handler<AsyncResult<Boolean>>() {
@Override
public void handle(AsyncResult<Boolean> event) {
if (event.failed()) {
handleDeploymentProblem(routingContext, event.cause());
} else {
boolean restart = event.result();
if (restart) {
QuarkusExecutorFactory.reinitializeDevModeExecutor();
routingContext.request().headers().set(HEADER_NAME, "true");
VertxHttpRecorder.getRootHandler().handle(routingContext.request());
} else {
routingContext.next();
}
}
}
});

As such, what's happening is that the user makes a change, hits reload, but it's probably taking too long, so they hit reload again, and the second connection is served while the first is still handling the hot reload.

But midway during the request serving, the reload is happening and we're shutting down the Arc Container so the request fails with a really weird and confusing exception.

I could fix the symptom, but that's a waste of time because other applications would fail in different ways.

We could either make new connections (after the hot reload started) wait for the hot reload to be finished, or we could make them serve an error page mentioning that a hot reload is in progress. I suspect the first option is more user-friendly.

To reproduce:

  • Download https://github.com/gbourant/renarde-live-reload-bug
  • Start the app via mvn quarkus:dev
  • Open a browser at http://localhost:8080/hello
  • Edit HelloResource.java and change "Hello from Quarkus REST" (save the file)
  • Go back to the browser, press F5 so it will refresh BUT before it finishes the refresh/live-reload press again F5 fast. (If you just press once the F5 it works as expected)

This should be easy to reproduce with a hot reload test if we make sure the reload takes an artificially long time (not sure how, perhaps a 1s sleep during a custom build step, or a startup bean?).

@FroMage FroMage marked this as a duplicate of #45481 Jan 10, 2025
@quarkus-bot quarkus-bot bot added this to the 3.19 - main milestone Jan 18, 2025
@gsmet gsmet modified the milestones: 3.19 - main, 3.18.0 Jan 21, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/devmode kind/bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants