quarkus-bot[bot]
commented
1 month ago /cc @gwenneg (cache), @sberyozkin (security)
Open Malandril opened 1 month ago
quarkus-bot[bot]
commented
1 month ago /cc @gwenneg (cache), @sberyozkin (security)
mschorsch
commented
1 month ago @Malandril I think you have to activate the request context. See https://quarkus.io/guides/security-customization#security-identity-customization, search for ContextNotActiveException.
Malandril
commented
1 month ago @mschorsch I don't think that's the issue here, the blocking IdentityProvider already activates a request context, and the one using mutiny under a low load works perfectly fine, If the context was never active then no request would return correctly.
Adding a @ActivateRequestContext on the reactive code, does not fix the problems, under load the same issues arise.
michalvavrik
commented
2 weeks ago @Malandril this https://github.com/Malandril/quarkus-cache-bug/blob/main/src/main/java/org/acme/UserDatabaseIdentityProvider.java#L41 is that blocking version that works? can you point me to that reactive version that doesn't work? I'd need to see how you wrote it.
Malandril
commented
2 weeks ago @michalvavrik This not the blocking code that triggerrs the problem, its rather the reactive code in "LoginAttemptChecker" . https://github.com/Malandril/quarkus-cache-bug/blob/706a5aff3a9ef8d6b84398d1a01e36225899050d/src/main/java/org/acme/attempt/LoginAttemptChecker.java#L37
When swapping with the blocking code https://github.com/Malandril/quarkus-cache-bug/blob/706a5aff3a9ef8d6b84398d1a01e36225899050d/src/main/java/org/acme/attempt/LoginAttemptChecker.java#L49 The problem is fixed.
michalvavrik
commented
2 weeks ago @Malandril I have run your reproducer and yes, I can see issue with Hibernate (or cache?) but I think you made mistake when you called this issue Programmatic cache exceptions when used in a SecurityIdentityProvider because it looked for folk like it is a security issue and so it came to us but I don't know Hibernate internals :-) I cannot see issue in Quarkus Security there. Let me ping few people to have a look at this Hibernate / cache.
Hey @cescoffier please ping whoever looks into issues with cache and @RunOnVirtualThread.
Hey @yrodiere, if you adjust the reproducer with:
quarkus.http.auth.proactive=falseand annotate org.acme.GreetingResource with io.quarkus.security.Authenticated, then you can debug this like any other Hibernate code because then, it will 100 % come into activated CDI request context and it runs inside Quarkus REST ServerRestHandler. Yet, there I saw following issues that I cannot link to a bug in Quarkus Security:
2024-11-09 11:38:04,324 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-1) HTTP Request to /hello failed, error id: 1fe73ebf-0a6c-4bb8-ae74-8564ab95bd4c-1: java.util.ConcurrentModificationException
at java.base/java.util.HashMap.computeIfAbsent(HashMap.java:1229)
at io.quarkus.hibernate.orm.runtime.RequestScopedSessionHolder.getOrCreateSession(RequestScopedSessionHolder.java:21)
at io.quarkus.hibernate.orm.runtime.RequestScopedSessionHolder_ClientProxy.getOrCreateSession(Unknown Source)
at io.quarkus.hibernate.orm.runtime.session.TransactionScopedSession.acquireSession(TransactionScopedSession.java:105)
at io.quarkus.hibernate.orm.runtime.session.TransactionScopedSession.find(TransactionScopedSession.java:175)
at org.hibernate.engine.spi.SessionLazyDelegator.find(SessionLazyDelegator.java:825)
at org.hibernate.Session_OpdLahisOZ9nWRPXMsEFQmQU03A_Synthetic_ClientProxy.find(Unknown Source)
at io.quarkus.hibernate.orm.panache.common.runtime.AbstractJpaOperations.findById(AbstractJpaOperations.java:183)
at io.quarkus.hibernate.orm.panache.common.runtime.AbstractJpaOperations.findByIdOptional(AbstractJpaOperations.java:191)
at org.acme.db.UserRepository.findByIdOptional(UserRepository.java)
at org.acme.db.UserRepository.findByIdOptional(UserRepository.java)
at org.acme.db.UserRepository_ClientProxy.findByIdOptional(Unknown Source)
at org.acme.UserDatabaseIdentityProvider.authenticate(UserDatabaseIdentityProvider.java:55)
at org.acme.UserDatabaseIdentityProvider.lambda$authenticate$0(UserDatabaseIdentityProvider.java:50)
at io.quarkus.vertx.http.runtime.security.VertxBlockingSecurityExecutor$1$1.call(VertxBlockingSecurityExecutor.java:43)
at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$0(ContextImpl.java:178)
at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:270)
at io.vertx.core.impl.ContextImpl.lambda$internalExecuteBlocking$2(ContextImpl.java:210)
at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1495)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:1583)2024-11-09 11:38:04,424 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-0) HTTP Request to /hello failed, error id: 1fe73ebf-0a6c-4bb8-ae74-8564ab95bd4c-2: java.lang.IllegalStateException: Session/EntityManager is closed
at org.hibernate.internal.AbstractSharedSessionContract.checkOpen(AbstractSharedSessionContract.java:517)
at org.hibernate.engine.spi.SharedSessionContractImplementor.checkOpen(SharedSessionContractImplementor.java:186)
at org.hibernate.internal.AbstractSharedSessionContract.checkOpenOrWaitingForAutoClose(AbstractSharedSessionContract.java:535)
at org.hibernate.internal.SessionImpl.checkOpenOrWaitingForAutoClose(SessionImpl.java:622)
at org.hibernate.internal.SessionImpl.instantiate(SessionImpl.java:1481)
at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.instantiateEntity(EntityInitializerImpl.java:1146)
at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveEntityInstance(EntityInitializerImpl.java:1139)
at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveEntityInstance2(EntityInitializerImpl.java:1097)
at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveEntityInstance1(EntityInitializerImpl.java:1013)
at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveInstance(EntityInitializerImpl.java:928)
at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:528)
at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:424)
at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:94)
at org.hibernate.sql.results.internal.StandardRowReader.coordinateInitializers(StandardRowReader.java:235)
at org.hibernate.sql.results.internal.StandardRowReader.readRow(StandardRowReader.java:141)
at org.hibernate.sql.results.spi.ListResultsConsumer.readUnique(ListResultsConsumer.java:283)
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:195)
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:35)
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:224)
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:102)
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.executeQuery(JdbcSelectExecutor.java:91)
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:165)
at org.hibernate.loader.ast.internal.SingleIdLoadPlan.load(SingleIdLoadPlan.java:145)
at org.hibernate.loader.ast.internal.SingleIdEntityLoaderStandardImpl.load(SingleIdEntityLoaderStandardImpl.java:89)
at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:94)
at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:55)
at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.load(EntityBatchLoaderInPredicate.java:116)
at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:3777)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3766)
at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:604)
at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:590)
at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:206)
at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:245)
at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:110)
at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:69)
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1229)
at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1217)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.load(IdentifierLoadAccessImpl.java:210)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.doLoad(IdentifierLoadAccessImpl.java:161)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.lambda$load$1(IdentifierLoadAccessImpl.java:150)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.perform(IdentifierLoadAccessImpl.java:113)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.load(IdentifierLoadAccessImpl.java:150)
at org.hibernate.internal.SessionImpl.find(SessionImpl.java:2459)
at org.hibernate.internal.SessionImpl.find(SessionImpl.java:2425)
at io.quarkus.hibernate.orm.runtime.session.TransactionScopedSession.find(TransactionScopedSession.java:176)
at org.hibernate.engine.spi.SessionLazyDelegator.find(SessionLazyDelegator.java:825)
at org.hibernate.Session_OpdLahisOZ9nWRPXMsEFQmQU03A_Synthetic_ClientProxy.find(Unknown Source)
at io.quarkus.hibernate.orm.panache.common.runtime.AbstractJpaOperations.findById(AbstractJpaOperations.java:183)
at io.quarkus.hibernate.orm.panache.common.runtime.AbstractJpaOperations.findByIdOptional(AbstractJpaOperations.java:191)
at org.acme.db.UserRepository.findByIdOptional(UserRepository.java)
at org.acme.db.UserRepository.findByIdOptional(UserRepository.java)
at org.acme.db.UserRepository_ClientProxy.findByIdOptional(Unknown Source)
at org.acme.UserDatabaseIdentityProvider.authenticate(UserDatabaseIdentityProvider.java:55)
at org.acme.UserDatabaseIdentityProvider.lambda$authenticate$0(UserDatabaseIdentityProvider.java:50)
at io.quarkus.vertx.http.runtime.security.VertxBlockingSecurityExecutor$1$1.call(VertxBlockingSecurityExecutor.java:43)
at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$0(ContextImpl.java:178)
at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:270)
at io.vertx.core.impl.ContextImpl.lambda$internalExecuteBlocking$2(ContextImpl.java:210)
at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1521)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:1583)2024-11-09 11:38:19,577 INFO [org.hib.eve.int.DefaultLoadEventListener] (vert.x-worker-thread-77) HHH000327: Error performing load command: org.hibernate.sql.exec.ExecutionException: A problem occurred in the SQL executor : Error advancing (next) ResultSet position [ResultSet is closed]
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.makeExecutionException(JdbcValuesResultSetImpl.java:325)
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.advanceNext(JdbcValuesResultSetImpl.java:273)
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.processNext(JdbcValuesResultSetImpl.java:150)
at org.hibernate.sql.results.jdbc.internal.AbstractJdbcValues.next(AbstractJdbcValues.java:19)
at org.hibernate.sql.results.internal.RowProcessingStateStandardImpl.next(RowProcessingStateStandardImpl.java:99)
at org.hibernate.sql.results.spi.ListResultsConsumer.readUnique(ListResultsConsumer.java:282)
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:195)
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:35)
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:224)
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:102)
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.executeQuery(JdbcSelectExecutor.java:91)
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:165)
at org.hibernate.loader.ast.internal.SingleIdLoadPlan.load(SingleIdLoadPlan.java:145)
at org.hibernate.loader.ast.internal.SingleIdEntityLoaderStandardImpl.load(SingleIdEntityLoaderStandardImpl.java:89)
at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:94)
at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:55)
at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.load(EntityBatchLoaderInPredicate.java:116)
at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:3777)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3766)
at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:604)
at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:590)
at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:206)
at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:245)
at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:110)
at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:69)
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1229)
at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1217)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.load(IdentifierLoadAccessImpl.java:210)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.doLoad(IdentifierLoadAccessImpl.java:161)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.lambda$load$1(IdentifierLoadAccessImpl.java:150)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.perform(IdentifierLoadAccessImpl.java:113)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.load(IdentifierLoadAccessImpl.java:150)
at org.hibernate.internal.SessionImpl.find(SessionImpl.java:2459)
at org.hibernate.internal.SessionImpl.find(SessionImpl.java:2425)
at io.quarkus.hibernate.orm.runtime.session.TransactionScopedSession.find(TransactionScopedSession.java:176)
at org.hibernate.engine.spi.SessionLazyDelegator.find(SessionLazyDelegator.java:825)
at org.hibernate.Session_OpdLahisOZ9nWRPXMsEFQmQU03A_Synthetic_ClientProxy.find(Unknown Source)
at io.quarkus.hibernate.orm.panache.common.runtime.AbstractJpaOperations.findById(AbstractJpaOperations.java:183)
at io.quarkus.hibernate.orm.panache.common.runtime.AbstractJpaOperations.findByIdOptional(AbstractJpaOperations.java:191)
at org.acme.db.UserRepository.findByIdOptional(UserRepository.java)
at org.acme.db.UserRepository.findByIdOptional(UserRepository.java)
at org.acme.db.UserRepository_ClientProxy.findByIdOptional(Unknown Source)
at org.acme.UserDatabaseIdentityProvider.authenticate(UserDatabaseIdentityProvider.java:55)
at org.acme.UserDatabaseIdentityProvider.lambda$authenticate$0(UserDatabaseIdentityProvider.java:50)
at io.quarkus.vertx.http.runtime.security.VertxBlockingSecurityExecutor$1$1.call(VertxBlockingSecurityExecutor.java:43)
at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$0(ContextImpl.java:178)
at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:270)
at io.vertx.core.impl.ContextImpl.lambda$internalExecuteBlocking$2(ContextImpl.java:210)
at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1521)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: org.hibernate.exception.GenericJDBCException: Error advancing (next) ResultSet position [ResultSet is closed] [n/a]
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:63)
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.sql.results.jdbc.internal.JdbcValuesResultSetImpl.makeExecutionException(JdbcValuesResultSetImpl.java:314)
... 58 more
Caused by: java.sql.SQLException: ResultSet is closed
at io.agroal.pool.wrapper.ResultSetWrapper$1.invoke(ResultSetWrapper.java:54)
at jdk.proxy5/jdk.proxy5.$Proxy108.next(Unknown Source)
at io.agroal.pool.wrapper.ResultSetWrapper.next(ResultSetWrapper.java:90)
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.advanceNext(JdbcValuesResultSetImpl.java:270)
... 57 more2024-11-09 11:38:54,589 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-1) HTTP Request to /hello failed, error id: 1fe73ebf-0a6c-4bb8-ae74-8564ab95bd4c-10: java.lang.IllegalStateException: Illegal pop() with non-matching JdbcValuesSourceProcessingState
at org.hibernate.sql.results.spi.LoadContexts.deregister(LoadContexts.java:45)
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:223)
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:35)
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:224)
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:102)
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.executeQuery(JdbcSelectExecutor.java:91)
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:165)
at org.hibernate.loader.ast.internal.SingleIdLoadPlan.load(SingleIdLoadPlan.java:145)
at org.hibernate.loader.ast.internal.SingleIdEntityLoaderStandardImpl.load(SingleIdEntityLoaderStandardImpl.java:89)
at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:94)
at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:55)
at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.load(EntityBatchLoaderInPredicate.java:116)
at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:3777)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3766)
at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:604)
at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:590)
at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:206)
at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:245)
at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:110)
at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:69)
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1229)
at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1217)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.load(IdentifierLoadAccessImpl.java:210)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.doLoad(IdentifierLoadAccessImpl.java:161)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.lambda$load$1(IdentifierLoadAccessImpl.java:150)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.perform(IdentifierLoadAccessImpl.java:113)
at org.hibernate.loader.internal.IdentifierLoadAccessImpl.load(IdentifierLoadAccessImpl.java:150)
at org.hibernate.internal.SessionImpl.find(SessionImpl.java:2459)
at org.hibernate.internal.SessionImpl.find(SessionImpl.java:2425)
at io.quarkus.hibernate.orm.runtime.session.TransactionScopedSession.find(TransactionScopedSession.java:176)
at org.hibernate.engine.spi.SessionLazyDelegator.find(SessionLazyDelegator.java:825)
at org.hibernate.Session_OpdLahisOZ9nWRPXMsEFQmQU03A_Synthetic_ClientProxy.find(Unknown Source)
at io.quarkus.hibernate.orm.panache.common.runtime.AbstractJpaOperations.findById(AbstractJpaOperations.java:183)
at io.quarkus.hibernate.orm.panache.common.runtime.AbstractJpaOperations.findByIdOptional(AbstractJpaOperations.java:191)
at org.acme.db.UserRepository.findByIdOptional(UserRepository.java)
at org.acme.db.UserRepository.findByIdOptional(UserRepository.java)
at org.acme.db.UserRepository_ClientProxy.findByIdOptional(Unknown Source)
at org.acme.UserDatabaseIdentityProvider.authenticate(UserDatabaseIdentityProvider.java:55)
at org.acme.UserDatabaseIdentityProvider.lambda$authenticate$0(UserDatabaseIdentityProvider.java:50)
at io.quarkus.vertx.http.runtime.security.VertxBlockingSecurityExecutor$1$1.call(VertxBlockingSecurityExecutor.java:43)
at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$0(ContextImpl.java:178)
at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:270)
at io.vertx.core.impl.ContextImpl.lambda$internalExecuteBlocking$2(ContextImpl.java:210)
at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1521)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:1583)I will keep there area/security label, but as I said, unless I get more info, I don't think there is anything we can do in Quarkus Security. @sberyozkin please re-check if you want.
yrodiere
commented
1 week ago I can't have a closer look today, but I see multiple clues there may be invalid setup/usage involved.
SessionGiven this error:
2024-11-09 11:38:04,324 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-1) HTTP Request to /hello failed, error id: 1fe73ebf-0a6c-4bb8-ae74-8564ab95bd4c-1: java.util.ConcurrentModificationException
at java.base/java.util.HashMap.computeIfAbsent(HashMap.java:1229)
at io.quarkus.hibernate.orm.runtime.RequestScopedSessionHolder.getOrCreateSession(RequestScopedSessionHolder.java:21)... there seems to be multiple threads accessing (writing to?) this map, which is held in a request-scoped bean (RequestScopedSessionHolder), which we expect to be used from a single thread.
Hibernate ORM's Session in particular, and JPA's EntityManager in general, is not thread safe.
Outside of a transaction, there is one (and only one) Session/EntityManager per request scope, so you can't use the same request scope from multiple threads.
If you want to go multi-threaded, you need to open one transaction per thread: then each thread/transaction will use its own Session/EntityManager.
Hibernate ORM is blocking.
This code seemingly runs on the event loop, activates a request context, then calls Hibernate ORM somehow:
That's just incorrect:
EDIT: I noticed the runBlocking too late. You're already doing option 1, so it's fine.
Malandril
commented
1 week ago I can't have a closer look today, but I see multiple clues there may be invalid setup/usage involved.
Concurrent use of a
SessionGiven this error:
2024-11-09 11:38:04,324 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-1) HTTP Request to /hello failed, error id: 1fe73ebf-0a6c-4bb8-ae74-8564ab95bd4c-1: java.util.ConcurrentModificationException at java.base/java.util.HashMap.computeIfAbsent(HashMap.java:1229) at io.quarkus.hibernate.orm.runtime.RequestScopedSessionHolder.getOrCreateSession(RequestScopedSessionHolder.java:21)... there seems to be multiple threads accessing (writing to?) this map, which is held in a request-scoped bean (
RequestScopedSessionHolder), which we expect to be used from a single thread.Hibernate ORM's
Sessionin particular, and JPA'sEntityManagerin general, is not thread safe. Outside of a transaction, there is one (and only one)Session/EntityManagerper request scope, so you can't use the same request scope from multiple threads. If you want to go multi-threaded, you need to open one transaction per thread: then each thread/transaction will use its ownSession/EntityManager.
@yrodiere I think my reproducer is not minimal, i can probably reproduce an error, without any Hibernate, it happens more reliably with hibernate thats why I left it, i wanted to make sure the problem could be reproduced outside of my environment.
If I replace the whole hibernate class to simply return a QuarkusIdentity it throws :
jakarta.enterprise.context.ContextNotActiveException: RequestScoped context was not active when trying to obtain a bean instance for a client proxy of CLASS bean [class=io.quarkus.vertx.http.runtime.CurrentVertxRequest, id=0_6n6EmChCiiDdd8HelptG_A0AE]
- you can activate the request context for a specific method using the @ActivateRequestContext interceptor binding
at io.quarkus.arc.impl.ClientProxies.notActive(ClientProxies.java:70)
at io.quarkus.arc.impl.ClientProxies.getSingleContextDelegate(ClientProxies.java:30)
at io.quarkus.vertx.http.runtime.CurrentVertxRequest_ClientProxy.arc$delegate(Unknown Source)
at io.quarkus.vertx.http.runtime.CurrentVertxRequest_ClientProxy.setCurrent(Unknown Source)
at io.quarkus.resteasy.reactive.server.runtime.QuarkusCurrentRequest.set(QuarkusCurrentRequest.java:33)
at org.jboss.resteasy.reactive.server.core.CurrentRequestManager.set(CurrentRequestManager.java:12)
at org.jboss.resteasy.reactive.server.core.ResteasyReactiveRequestContext.handleRequestScopeActivation(ResteasyReactiveRequestContext.java:642)
at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.handleRequestScopeActivation(QuarkusResteasyReactiveRequestContext.java:39)
at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.requireCDIRequestScope(AbstractResteasyReactiveContext.java:264)
at org.jboss.resteasy.reactive.server.handlers.ResponseWriterHandler.handle(ResponseWriterHandler.java:27)
at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:147)
at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:147)
at io.quarkus.virtual.threads.ContextPreservingExecutorService$ContextPreservingRunnable.run(ContextPreservingExecutorService.java:45)
at java.base/java.util.concurrent.ThreadPerTaskExecutor$TaskRunner.run(ThreadPerTaskExecutor.java:314)
at java.base/java.lang.VirtualThread.run(VirtualThread.java:309)@Malandril I have run your reproducer and yes, I can see issue with Hibernate (or cache?) but I think you made mistake when you called this issue
Programmatic cache exceptions when used in a SecurityIdentityProviderbecause it looked for folk like it is a security issue and so it came to us but I don't know Hibernate internals :-) I cannot see issue in Quarkus Security there. Let me ping few people to have a look at this Hibernate / cache.
I named from the context in which I encountered the bug, we can rename the bug with a more appropriate name
Malandril
commented
1 week ago I updated the reproducer to the latest quarkus version and commented the hibernate code.
michalvavrik
commented
1 week ago I named from the context in which I encountered the bug, we can rename the bug with a more appropriate name
no worry, it was unnecessary note, I was just thinking aloud :-)
yrodiere
commented
1 week ago @yrodiere I think my reproducer is not minimal, i can probably reproduce an error, without any Hibernate, it happens more reliably with hibernate thats why I left it, i wanted to make sure the problem could be reproduced outside of my environment.
If I replace the whole hibernate class to simply return a QuarkusIdentity it throws :
Okay, I mistakenly thought from @michalvavrik's comment that it was related to Hibernate. It seems the problem really is related to the request scope then. Thanks for clarifying (and updating the reproducer!).
michalvavrik
commented
1 week ago Okay, I mistakenly thought from @michalvavrik's comment that it was related to Hibernate. It seems the problem really is related to the request scope then. Thanks for clarifying (and updating the reproducer!).
Hello @yrodiere ,
I have told you how to reproduce it when CDI request context is always active https://github.com/quarkusio/quarkus/issues/43572#issuecomment-2466169652. I am happy to help, but it is not clear to me if you tried it and how can I help?
If I replace the whole hibernate class to simply return a QuarkusIdentity it throws
that doesn't happen when you follow my suggestion; at least I didn't see it when I run it during the weekend.
michalvavrik
commented
1 week ago fyi @geoand there was stacktrace mentioned above next to this comment:
If I replace the whole hibernate class to simply return a QuarkusIdentity it throws
michalvavrik
commented
1 week ago to explained that @yrodiere , I thought it was smarter to postpone authentication till CDI request context is activated by Quarkus REST in a fashion that it always is, rather then activate it super early by user code and then deactive it, because I thought there was io.quarkus.virtual.threads.ContextPreservingExecutorService$ContextPreservingRunnable in action that I didn't know if works correctly when user does that. So I thought you may want to debug just Hibernate code. We can wait till the other exception is debugged.
michalvavrik
commented
1 week ago Anyway, I think it would be valuable to know whether you can reproduce it when you drop @RunOnVirtualThread. I had this reproducer in tmp dir so I would have to go through the whole process again ( clone, checkout what are deps and wrapper before I run it etc.). Please just try to drop it and report back whether problem is there without virtual threads as well. Thank you @Malandril
Malandril
commented
1 week ago I tested without virtual threads, and with a blocking endpoint the problem does not occur. However if use a reactive endpoint without virtual threads the problem reappears. I think the problem does not occur with a pure blocking function, because the throughput is limited by the worker pool size.
Reactive endpoint used:
@GET
@Produces(MediaType.TEXT_PLAIN)
public Uni<String> hello() throws InterruptedException {
// Helps with reproduction, reducing it, reduces the frequency
return Uni.createFrom().item("Hello from Quarkus REST").onItem().delayIt().by(Duration.ofSeconds(4));
}stacktrace:
jakarta.enterprise.context.ContextNotActiveException: RequestScoped context was not active when trying to obtain a bean instance for a client proxy of CLASS bean [class=io.quarkus.vertx.http.runtime.CurrentVertxRequest, id=0_6n6EmChCiiDdd8HelptG_A0AE]
- you can activate the request context for a specific method using the @ActivateRequestContext interceptor binding
at io.quarkus.arc.impl.ClientProxies.notActive(ClientProxies.java:70)
at io.quarkus.arc.impl.ClientProxies.getSingleContextDelegate(ClientProxies.java:30)
at io.quarkus.vertx.http.runtime.CurrentVertxRequest_ClientProxy.arc$delegate(Unknown Source)
at io.quarkus.vertx.http.runtime.CurrentVertxRequest_ClientProxy.setCurrent(Unknown Source)
at io.quarkus.resteasy.reactive.server.runtime.QuarkusCurrentRequest.set(QuarkusCurrentRequest.java:33)
at org.jboss.resteasy.reactive.server.core.CurrentRequestManager.set(CurrentRequestManager.java:12)
at org.jboss.resteasy.reactive.server.core.ResteasyReactiveRequestContext.handleRequestScopeActivation(ResteasyReactiveRequestContext.java:656)
at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.handleRequestScopeActivation(QuarkusResteasyReactiveRequestContext.java:39)
at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.requireCDIRequestScope(AbstractResteasyReactiveContext.java:264)
at org.jboss.resteasy.reactive.server.handlers.ResponseWriterHandler.handle(ResponseWriterHandler.java:27)
at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:147)
at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:147)
at org.jboss.resteasy.reactive.server.vertx.VertxResteasyReactiveRequestContext$1$1.handle(VertxResteasyReactiveRequestContext.java:84)
at org.jboss.resteasy.reactive.server.vertx.VertxResteasyReactiveRequestContext$1$1.handle(VertxResteasyReactiveRequestContext.java:81)
at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:270)
at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:252)
at io.vertx.core.impl.ContextInternal.lambda$runOnContext$0(ContextInternal.java:50)
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569)
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)Thanks. I can't see anything problematic regarding CDI request context on current main branch of the reproducer anymore. The stacktrace seems to me like there is a race and I am not sure where CDI request context activation / termination comes from (e.g. you consume security events async, but that should be run on new context) and I don't know Caffeine cache either. I'll have a look if noone else pick this up in few days. Hope someone else finds a time. Thank you for reporting this.
cescoffier
commented
1 week ago When using: return Uni.createFrom().item("Hello from Quarkus REST").onItem().delayIt().by(Duration.ofSeconds(4));, you are switching thread. The requesting context is likely lost.
Describe the bug
When using a programmatic cache in a reactive
SecurityIdentityProvidera heavy constant load causes issues in the reactive context, and the context is then in some invalide states and the following exception can be thrown.If you wrap your logic in a blocking context with
context.runBlockingthese problems do not occur.Expected behavior
Using a programmatic cache should not create errors in a
IdentityProviderand should not need to wrapped in a blocking context.Actual behavior
This creates some strange behaviour and exceptions such as
With a endpoint with hibernate the following also happens.
How to Reproduce?
Reproducer here https://github.com/Malandril/quarkus-cache-bug
run the dev mode with
./gradlew qDInstall k6 or use a the k6 docker image and run the script
k6 run -u 150 -d 60s k6.jsIt should trigger some exceptions. On my pc with 150 Vu i could reproduce it reliably.On the reproducer, if you uncommant the blocking code, and run with the blocking version, the bug does not appear.
Output of
uname -aorverNo response
Output of
java -version21
Quarkus version or git rev
3.15.1
Build tool (ie. output of
mvnw --versionorgradlew --version)gradle 8.8
Additional information
Could be related to #41081 and #39515