m1h43l
February 7, 2023, 8:48am
1
I am getting a timeout when using the dev-file database configuration. Can I set the timeout in any way?
2023-02-07 09:09:50,524 WARN [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator] (JPA Startup Thread: keycloak-default) HHH000342: Could not obtain connection to query metadata: java.sql.SQLException: Acquisition timeout while waiting for new connection
at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:320)
at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:248)
at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
at io.quarkus.hibernate.orm.runtime.customized.QuarkusConnectionProvider.getConnection(QuarkusConnectionProvider.java:23)
at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess.obtainConnection(JdbcEnvironmentInitiator.java:181)
at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:68)
at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:35)
at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.initiateService(StandardServiceRegistryImpl.java:101)
at org.hibernate.service.internal.AbstractServiceRegistryImpl.createService(AbstractServiceRegistryImpl.java:263)
at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:237)
at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:214)
at org.hibernate.engine.jdbc.internal.JdbcServicesImpl.configure(JdbcServicesImpl.java:51)
at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.configureService(StandardServiceRegistryImpl.java:107)
at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:246)
at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:214)
at org.hibernate.boot.internal.SessionFactoryOptionsBuilder.<init>(SessionFactoryOptionsBuilder.java:272)
at io.quarkus.hibernate.orm.runtime.recording.PrevalidatedQuarkusMetadata.buildSessionFactoryOptionsBuilder(PrevalidatedQuarkusMetadata.java:68)
at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:72)
at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:72)
at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:165)
at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:66)
at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.util.concurrent.TimeoutException
at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:296)
... 23 more
See this github issue:
opened 02:10PM - 13 Jan 23 UTC
closed 12:08PM - 27 Mar 23 UTC
kind/bug
area/storage
team/store
### Before reporting an issue
- [X] I have searched existing issues
- [X] I … have reproduced the issue with the latest release
### Area
core
### Describe the bug
I have been testing Keycloak 20.0.3 on MacOS X 12.6.2 after previously using versions 18 and 19 for many months without problem. Keycloak 20 can enter some sort of invalid state whereby database connections, even to the local H2 file store, seem to be intermittently unavailable.
Additionally, this problem can manifest immediately at startup, even with a fresh (deleted) data directory, and immediately after a system reboot (so not expecting tons of file handles in use etc.)
For example, startup with `start-dev` will sometimes start just fine, while other times fail. This particular time (i.e. for the trace below), I managed to capture a startup failure with `export`, which I was doing in order to try to reset my instance database. However, startup failures with `start-dev` have the same top of callstack failures.
```
james ~/src/keycloak-20.0.2/bin $ ./kc.sh export --file ~/Downloads/vv-dev-users.json --realm vv-dev
2023-01-13 07:20:49,342 INFO [org.keycloak.quarkus.runtime.hostname.DefaultHostnameProvider] (main) Hostname settings: Base URL: <unset>, Hostname: <request>, Strict HTTPS: false, Path: <request>, Strict BackChannel: false, Admin URL: <unset>, Admin: <request>, Port: -1, Proxied: false
2023-01-13 07:20:50,158 WARN [io.quarkus.agroal.runtime.DataSources] (main) Datasource <default> enables XA but transaction recovery is not enabled. Please enable transaction recovery by setting quarkus.transaction-manager.enable-recovery=true, otherwise data may be lost if the application is terminated abruptly
2023-01-13 07:20:50,440 WARN [org.infinispan.PERSISTENCE] (keycloak-cache-init) ISPN000554: jboss-marshalling is deprecated and planned for removal
2023-01-13 07:20:50,468 WARN [org.infinispan.CONFIG] (keycloak-cache-init) ISPN000569: Unable to persist Infinispan internal caches as no global state enabled
2023-01-13 07:20:50,489 INFO [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
2023-01-13 07:20:50,602 INFO [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000128: Infinispan version: Infinispan 'Triskaidekaphobia' 13.0.10.Final
2023-01-13 07:20:55,243 WARN [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator] (JPA Startup Thread: keycloak-default) HHH000342: Could not obtain connection to query metadata: java.sql.SQLException: Acquisition timeout while waiting for new connection
at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:320)
at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:248)
at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
at io.quarkus.hibernate.orm.runtime.customized.QuarkusConnectionProvider.getConnection(QuarkusConnectionProvider.java:23)
at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess.obtainConnection(JdbcEnvironmentInitiator.java:181)
at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:68)
at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:35)
at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.initiateService(StandardServiceRegistryImpl.java:101)
at org.hibernate.service.internal.AbstractServiceRegistryImpl.createService(AbstractServiceRegistryImpl.java:263)
at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:237)
at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:214)
at org.hibernate.engine.jdbc.internal.JdbcServicesImpl.configure(JdbcServicesImpl.java:51)
at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.configureService(StandardServiceRegistryImpl.java:107)
at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:246)
at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:214)
at org.hibernate.boot.internal.SessionFactoryOptionsBuilder.<init>(SessionFactoryOptionsBuilder.java:272)
at io.quarkus.hibernate.orm.runtime.recording.PrevalidatedQuarkusMetadata.buildSessionFactoryOptionsBuilder(PrevalidatedQuarkusMetadata.java:68)
at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:72)
at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:72)
at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:165)
at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:66)
at java.base/java.lang.Thread.run(Thread.java:1589)
Caused by: java.util.concurrent.TimeoutException
at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:296)
... 23 more
2023-01-13 07:20:55,446 INFO [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: node_903739, Site name: null
2023-01-13 07:21:00,592 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: Failed to start server in (import_export) mode
2023-01-13 07:21:00,592 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: Failed to obtain JDBC connection
2023-01-13 07:21:00,592 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: Acquisition timeout while waiting for new connection
2023-01-13 07:21:00,592 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) For more details run the same command passing the '--verbose' option. Also you can use '--help' to see the details about the usage of the particular command.
```
These exceptions can also happen while Keycloak is running, idle in the background. I got a series of these overnight, every 70-90 minutes, although yesterday evening while developing (and API calling token endpoints) much, much more frequently.
```
2023-01-13 04:49:41,962 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Timer-0) SQL Error: 0, SQLState: null
2023-01-13 04:49:41,965 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Timer-0) Acquisition timeout while waiting for new connection
2023-01-13 04:49:41,967 ERROR [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-0) Failed to run scheduled task ClearExpiredAdminEvents: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:111)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:2122)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2059)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2037)
at org.hibernate.loader.Loader.scroll(Loader.java:2945)
at org.hibernate.loader.hql.QueryLoader.scroll(QueryLoader.java:610)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.scroll(QueryTranslatorImpl.java:452)
at org.hibernate.engine.query.spi.HQLQueryPlan.performScroll(HQLQueryPlan.java:353)
at org.hibernate.internal.SessionImpl.scroll(SessionImpl.java:1601)
at org.hibernate.query.internal.AbstractProducedQuery.doScroll(AbstractProducedQuery.java:1588)
at org.hibernate.query.internal.AbstractProducedQuery.scroll(AbstractProducedQuery.java:1574)
at org.hibernate.query.internal.AbstractProducedQuery.stream(AbstractProducedQuery.java:1598)
at org.hibernate.query.Query.getResultStream(Query.java:1140)
at org.keycloak.events.jpa.JpaEventStoreProvider.clearExpiredAdminEvents(JpaEventStoreProvider.java:283)
at org.keycloak.events.jpa.JpaEventStoreProviderFactory.invalidate(JpaEventStoreProviderFactory.java:69)
at org.keycloak.services.DefaultKeycloakSessionFactory.lambda$invalidate$0(DefaultKeycloakSessionFactory.java:368)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:179)
at java.base/java.util.HashMap$ValueSpliterator.forEachRemaining(HashMap.java:1787)
at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762)
at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:276)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
at java.base/java.util.HashMap$ValueSpliterator.forEachRemaining(HashMap.java:1787)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
at org.keycloak.services.DefaultKeycloakSessionFactory.invalidate(DefaultKeycloakSessionFactory.java:368)
at org.keycloak.services.DefaultKeycloakSession.invalidate(DefaultKeycloakSession.java:123)
at org.keycloak.services.scheduled.ClearExpiredAdminEvents.run(ClearExpiredAdminEvents.java:35)
at org.keycloak.services.scheduled.ClusterAwareScheduledTaskRunner$1.call(ClusterAwareScheduledTaskRunner.java:58)
at org.keycloak.services.scheduled.ClusterAwareScheduledTaskRunner$1.call(ClusterAwareScheduledTaskRunner.java:54)
at org.keycloak.cluster.infinispan.InfinispanClusterProvider.executeIfNotExecuted(InfinispanClusterProvider.java:78)
at org.keycloak.services.scheduled.ClusterAwareScheduledTaskRunner.runTask(ClusterAwareScheduledTaskRunner.java:54)
at org.keycloak.services.scheduled.ScheduledTaskRunner.run(ScheduledTaskRunner.java:54)
at org.keycloak.timer.basic.BasicTimerProvider$1.run(BasicTimerProvider.java:53)
at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
at java.base/java.util.TimerThread.run(Timer.java:516)
Caused by: java.sql.SQLException: Acquisition timeout while waiting for new connection
at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:320)
at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:248)
at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
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:108)
... 45 more
Caused by: java.util.concurrent.TimeoutException
at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:296)
... 50 more
2023-01-13 04:49:46,976 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Timer-0) SQL Error: 0, SQLState: null
2023-01-13 04:49:46,977 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Timer-0) Acquisition timeout while waiting for new connection
2023-01-13 04:49:46,978 ERROR [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-0) Failed to run scheduled task ClearExpiredClientInitialAccessTokens: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181)
at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1705)
at org.keycloak.models.jpa.JpaRealmProvider.removeExpiredClientInitialAccess(JpaRealmProvider.java:1044)
at org.keycloak.models.cache.infinispan.RealmCacheSession.removeExpiredClientInitialAccess(RealmCacheSession.java:1400)
at org.keycloak.services.scheduled.ClearExpiredClientInitialAccessTokens.run(ClearExpiredClientInitialAccessTokens.java:30)
at org.keycloak.services.scheduled.ClusterAwareScheduledTaskRunner$1.call(ClusterAwareScheduledTaskRunner.java:58)
at org.keycloak.services.scheduled.ClusterAwareScheduledTaskRunner$1.call(ClusterAwareScheduledTaskRunner.java:54)
at org.keycloak.cluster.infinispan.InfinispanClusterProvider.executeIfNotExecuted(InfinispanClusterProvider.java:78)
at org.keycloak.services.scheduled.ClusterAwareScheduledTaskRunner.runTask(ClusterAwareScheduledTaskRunner.java:54)
at org.keycloak.services.scheduled.ScheduledTaskRunner.run(ScheduledTaskRunner.java:54)
at org.keycloak.timer.basic.BasicTimerProvider$1.run(BasicTimerProvider.java:53)
at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
at java.base/java.util.TimerThread.run(Timer.java:516)
Caused by: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:111)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$1.doPrepare(StatementPreparerImpl.java:90)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareStatement(StatementPreparerImpl.java:81)
at org.hibernate.hql.internal.ast.exec.BasicExecutor.doExecute(BasicExecutor.java:68)
at org.hibernate.hql.internal.ast.exec.BasicExecutor.execute(BasicExecutor.java:50)
at org.hibernate.hql.internal.ast.exec.DeleteExecutor.execute(DeleteExecutor.java:177)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:458)
at org.hibernate.engine.query.spi.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:377)
at org.hibernate.internal.SessionImpl.executeUpdate(SessionImpl.java:1483)
at org.hibernate.query.internal.AbstractProducedQuery.doExecuteUpdate(AbstractProducedQuery.java:1714)
at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1696)
... 11 more
Caused by: java.sql.SQLException: Acquisition timeout while waiting for new connection
at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:320)
at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:248)
at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
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:108)
... 24 more
Caused by: java.util.concurrent.TimeoutException
at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:296)
... 29 more
2023-01-13 04:49:48,125 WARN [io.agroal.pool] (agroal-11) Datasource '<default>': IO Exception: "/Users/james/src/keycloak-20.0.2/data/h2/keycloakdb.mv.db" [90028-214]
```
### Version
20.0.3
### Expected behavior
No difficulty connecting to a "Pool" that is really just a local filesystem H2 database
### Actual behavior
Exceptions on startup; Exceptions even when idle.
### How to Reproduce?
Unclear; ~~possibly local database became corrupted~~
happens with fresh installation of 20.0.3
### Anything else?
_No response_
If this looks like what’s happening to you, please chime in there with your system configuration and specs.