keycloak: Failed to obtain JDBC connection with built-in H2 in start-dev
Before reporting an issue
- I have searched existing issues
- 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
About this issue
- Original URL
- State: closed
- Created a year ago
- Reactions: 2
- Comments: 45 (15 by maintainers)
I was scratching my head about this, it happened after I updated the laptop which comes with Windows 11. Oddly enough, it works fine in Widows Sandbox!!
The solution that worked with me is to run it with --db-pool-initial-size 10 like:
kc.bat start-dev --db-pool-initial-size 10Same thing on windows 11 JDK 17
We had an success with replacing the affected
io.agroal.agroal-pool-1.16.jarwithio.agroal.agroal-pool-1.15.jar, cavemen style. Just replace the JAR file in the Keycloak installation, and rename it toio.agroal.agroal-pool-1.16.jarso it is correctly picked up on the ClassPath.It’s an ugly hack, and honestly I’m not really sure why it even works, but it does.
here it is:
It seems that deactivating the “Windows features” “WWW-Services” and “Web management tools” helps.
I have had the same problem with windows 11, Solved the problem by
updating keyloak.conf in conf directory
steps I have followed
and edit the keycloak.conf file in conf directory uncomment below lines add relevant parameters.
# The database vendor. db=postgres
# The username of the database user. db-username=john
# The password of the database user. db-password=john123
# The full database JDBC URL. If not provided, a default URL is set based on the selected database vendor. db-url=jdbc:postgresql://localhost:5432/keycloak
@Toami79
You’re supposed to do one or the other, but not both. For me the downgrade worked for Keycloak 20.0.5 with OpenJDK 19.0.2 on Windows hosts
Hello,
Sorry if it’s not appropriate but i had a similar issue with Keycloak on a Windows Server 2019, and maybe it will help. On my side i’m authenticating my users against Oracle, using a custom user federation provider (a Java JDBC connector). My Oracle database and Keycloak are located on the same machine.
My Keycloak failed with the same error message about the IOException on keycloak.mv.db. I spent a lot of time trying to fix this issue, when i decided to check it this issue wasn’t an effect border from another problem. I decided to check my Oracle Listener log: C:\Oracle\diag\tnslsnr\FR1PSWBLD15\listener\trace\listener.log
Here is what i observed when Keycloak starts and then fails:
15-JUN-2023 10:06:49 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=FR1PSWBLD15$))(SERVICE_NAME=local)(CONNECTION_ID=Fy2Hm9IhT0SR1VF0L6BrdA==)) * (ADDRESS=(PROTOCOL=tcp)(HOST=169.254.93.185%21)(PORT=54985)) * establish * local * 0The problem here is that 169.254.93.185 is not my server physical LAN address, but is an Hyper-V virtual network card.
I decided to uninstall Hyper-V from my server. Once the server restarted, i restarted Keycloak and checked my Listener.log. Here is what i observed wen Keycloak started this time, without any failure:
15-JUN-2023 10:32:06 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=FR1PSWBLD15$))(SERVICE_NAME=local)(CONNECTION_ID=xImvBR+dRrGFkDW3vakWdQ==)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.21.16.230)(PORT=60215)) * establish * local * 0This time, i could see the correct IP address, and fixed my Keycloak issue. My conclusion is that this IOException with the keycloak.mv.db was a side effect and Hyper-V was the problem, as the JDBC connector was unable to connect to the database.
I hope this can help people who can be stuck with this issue. Regards
@luke-sensei Could you please paste the full log message with exception that you received specifically with 21.0.2?
@hmlnarik So I tried to reproduce this on my Mac OS Ventura 13.2.1 2019 Intel MacBook Pro. I started KC 20.0.3 distribution using
kc.sh start-devten times each using Java17 GraalVM and Java19 Graalvm without problems. Then I let Keycloak run on Java19 for several hours using it occasionally in between to log in users also activating event persistence so there was some background activity on the database. Also without any problems. So I cannot reproduce this issue.@jblachly Are you using OpenJDK? I could also try with that…
@sschu additonally, the fact that it can fail on startup as logged above suggests it’s unrelated to pool connection exhaustion .
I’ll do some load testing tonight on the latest MacOSX 12.
Regarding question about JDK, I am using OpenJDK 19 installed through homebrew.