keycloak: TimeoutException in ConnectionPool.handlerFromSharedCache

After fixing #16448, some users still experience TimeoutException in ConnectionPool.handlerFromSharedCache.

This is a tracker issue for https://issues.redhat.com/browse/AG-204. A reference for Quarkus issue may be added once known.

This issue is currently blocked on the aforementioned AG-204 issue.

C:\Users\***\keycloak-21.0.2>bin\kc start-dev
2023-04-13 10:16:57,717 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-04-13 10:16:59,194 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-04-13 10:17:01,858 WARN  [org.infinispan.CONFIG] (keycloak-cache-init) ISPN000569: Unable to persist Infinispan internal caches as no global state enabled
2023-04-13 10:17:01,890 WARN  [org.infinispan.PERSISTENCE] (keycloak-cache-init) ISPN000554: jboss-marshalling is deprecated and planned for removal
2023-04-13 10:17:01,921 INFO  [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
2023-04-13 10:17:04,366 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:321)
        at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:249)
        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:834)
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:298)
        ... 23 more

2023-04-13 10:17:06,653 WARN  [io.agroal.pool] (agroal-11) Datasource '<default>': IO Exception: "C:/Users/***/keycloak-21.0.2/data/h2/keycloakdb.mv.db" [90028-214]
2023-04-13 10:17:06,668 WARN  [io.agroal.pool] (agroal-11) Datasource '<default>': Error opening database: "Sleep interrupted" [8000-214]
2023-04-13 10:17:06,842 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: Failed to start server in (development) mode
2023-04-13 10:17:06,842 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: Failed to obtain JDBC connection
2023-04-13 10:17:06,842 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: Error opening database: "Sleep interrupted" [8000-214]
2023-04-13 10:17:06,842 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: sleep interrupted
2023-04-13 10:17:06,842 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.

_Originally posted by @luke-sensei in https://github.com/keycloak/keycloak/issues/16448#issuecomment-1506550481_

About this issue

Original URL
State: open
Created a year ago
Comments: 24 (11 by maintainers)

Most upvoted comments

@stefan-rink , I changed the wifi network adapter priority and it worked for me! Thank you very much!

jtokuda7 on Oct 19, 2023

We are running Keycloak version 21.1.1 (image quay.io/keycloak/keycloak:21.1.1)on our staging environment using a PostgreSQL db on a K8S cluster and we regularly see the same exceptions as described in this issue.

In production we are running Keycloak 19.0.2 using a similar setup without a problem.

jgoelen on May 12, 2023

Hi, i hope this helps shedding some light on the root cause: This seems to be a network configuration problem. For us, keycloak works when started on a machine without VPN , but does NOT work when having our company VPN active.

We are trying to use KeyCloak with the H2 Database (i.e. using kc.bat start-dev).

With VPN we are getting a very similar callstack as noted on top of this issue. We are using Keycloak 20.0.3 with openjdk-19-0.2, on Windows 10 21H2. (Sorry, i am reluctant to give out the make of VPN we are using, in order to not disclose details of our company network…)

We have no clue yet, what the difference may be. I inspected the windows event logs to no avail. We didn’t try to use KC with a different ‘real’ database so far. But it starts always when using “db=dev-mem”.

ThomasSteinkamp on May 8, 2023

@kami619 - I’m seeing “the database system is shutting down” which is valid error message after a system-under-test reset when the Keycloak restart was faster than the PostgreSQL shutdown. The global lock might then wait for some time for the database to come up again. I don’t see a TimeoutException in your log snippet, therefore I consider it unrelated.

ahus1 on Apr 22, 2023