Keycloak MySQL setup failed with error "Timeout after [300] seconds waiting for service container stability. Operation will roll back."

Question

I tried with 8.x and 10.x version of Keycloak, also with tried with Keycloak docker image but getting below issue, while configuring Keycloak with MySQL

12:27:16,047 DEBUG [org.keycloak.connections.jpa.updater.liquibase.conn.DefaultLiquibaseConnectionProvider] (ServerService Thread Pool -- 71) Foreign key constraint added to USER_GROUP_MEMBERSHIP (USER_ID)
12:27:17,356 DEBUG [org.keycloak.connections.jpa.updater.liquibase.conn.DefaultLiquibaseConnectionProvider] (ServerService Thread Pool -- 71) Primary key added to GROUP_ROLE_MAPPING (ROLE_ID, GROUP_ID)
12:27:18,637 DEBUG [org.keycloak.connections.jpa.updater.liquibase.conn.DefaultLiquibaseConnectionProvider] (ServerService Thread Pool -- 71) Foreign key constraint added to GROUP_ROLE_MAPPING (GROUP_ID)
12:27:19,384 ERROR [org.jboss.as.controller.management-operation] (Controller Boot Thread) WFLYCTL0348: Timeout after [300] seconds waiting for service container stability. Operation will roll back. Step that first updated the service container was 'add' at address '[
    ("core-service" => "management"),
    ("management-interface" => "http-interface")
]'
12:27:20,326 DEBUG [org.keycloak.connections.jpa.updater.liquibase.conn.DefaultLiquibaseConnectionProvider] (ServerService Thread Pool -- 71) Foreign key constraint added to GROUP_ROLE_MAPPING (ROLE_ID)
12:27:21,381 DEBUG [org.keycloak.connections.jpa.updater.liquibase.conn.DefaultLiquibaseConnectionProvider] (ServerService Thread Pool -- 71) Unique constraint added to REALM_DEFAULT_GROUPS(GROUP_ID)
12:27:23,153 DEBUG [org.keycloak.connections.jpa.updater.liquibase.conn.DefaultLiquibaseConnectionProvider] (ServerService Thread Pool -- 71) Foreign key constraint added to REALM_DEFAULT_GROUPS (REALM_ID)
12:27:24,389 ERROR [org.jboss.as.controller.management-operation] (Controller Boot Thread) WFLYCTL0190: Step handler org.jboss.as.server.DeployerChainAddHandler$FinalRuntimeStepHandler@2b5e08f5 for operation add-deployer-chains at address [] failed -- java.util.concurrent.TimeoutException: java.util.concurrent.TimeoutException
        at [email protected]//org.jboss.as.controller.OperationContextImpl.waitForRemovals(OperationContextImpl.java:523)
        at [email protected]//org.jboss.as.controller.AbstractOperationContext$Step.handleResult(AbstractOperationContext.java:1518)
        at [email protected]//org.jboss.as.controller.AbstractOperationContext$Step.finalizeInternal(AbstractOperationContext.java:1472)
        at [email protected]//org.jboss.as.controller.AbstractOperationContext$Step.finalizeStep(AbstractOperationContext.java:1445)
        at [email protected]//org.jboss.as.controller.AbstractOperationContext$Step.access$400(AbstractOperationContext.java:1319)
        at [email protected]//org.jboss.as.controller.AbstractOperationContext.executeResultHandlerPhase(AbstractOperationContext.java:876)
        at [email protected]//org.jboss.as.controller.AbstractOperationContext.processStages(AbstractOperationContext.java:726)
        at [email protected]//org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:467)
        at [email protected]//org.jboss.as.controller.OperationContextImpl.executeOperation(OperationContextImpl.java:1413)
        at [email protected]//org.jboss.as.controller.ModelControllerImpl.boot(ModelControllerImpl.java:527)
        at [email protected]//org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:515)
        at [email protected]//org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:477)
        at [email protected]//org.jboss.as.server.ServerService.boot(ServerService.java:448)
        at [email protected]//org.jboss.as.server.ServerService.boot(ServerService.java:401)
        at [email protected]//org.jboss.as.controller.AbstractControllerService$1.run(AbstractControllerService.java:416)
        at java.base/java.lang.Thread.run(Thread.java:834)

12:27:24,391 ERROR [org.jboss.as.controller.client] (Controller Boot Thread) WFLYCTL0190: Step handler org.jboss.as.server.DeployerChainAddHandler$FinalRuntimeStepHandler@2b5e08f5 for operation add-deployer-chains at address [] failed -- java.util.concurrent.TimeoutException

By increasing timeout using command

$ bin/standalone.sh -Djboss.as.management.blocking.timeout=3600

It failed with error below

17:26:32,383 INFO  [org.keycloak.connections.jpa.updater.liquibase.LiquibaseJpaUpdaterProvider] (ServerService Thread Pool -- 68) Initializing database schema. Using changelog META-INF/jpa-changelog-master.xml
17:31:25,854 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000101:84ae906:5ee761e5:f in state  RUN
17:31:25,870 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000101:84ae906:5ee761e5:f
17:31:27,355 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000101:84ae906:5ee761e5:12 in state  RUN
17:31:27,356 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000101:84ae906:5ee761e5:12
17:31:31,222 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000101:84ae906:5ee761e5:15 in state  RUN
17:31:31,225 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000101:84ae906:5ee761e5:15 invoked while multiple threads active within it.
17:31:31,250 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffff7f000101:84ae906:5ee761e5:15 completed with multiple threads - thread ServerService Thread Pool -- 68 was in progress with java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
java.net.SocketInputStream.read(SocketInputStream.java:171)
java.net.SocketInputStream.read(SocketInputStream.java:141)
com.mysql.cj.protocol.ReadAheadInputStream.fill(ReadAheadInputStream.java:107)
com.mysql.cj.protocol.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:150)
com.mysql.cj.protocol.ReadAheadInputStream.read(ReadAheadInputStream.java:180)
java.io.FilterInputStream.read(FilterInputStream.java:133)
com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64)
com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)
com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)
com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54)
com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44)
com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:533)
com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:703)
com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:642)
com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:941)
com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:887)
com.mysql.cj.NativeSession.execSQL(NativeSession.java:1073)
com.mysql.cj.jdbc.StatementImpl.executeInternal(StatementImpl.java:724)
com.mysql.cj.jdbc.StatementImpl.execute(StatementImpl.java:648)
org.jboss.jca.adapters.jdbc.WrappedStatement.execute(WrappedStatement.java:198)
liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:307)
liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:55)
liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:113)
liquibase.database.AbstractJdbcDatabase.execute(AbstractJdbcDatabase.java:1277)
liquibase.database.AbstractJdbcDatabase.executeStatements(AbstractJdbcDatabase.java:1259)
liquibase.changelog.ChangeSet.execute(ChangeSet.java:582)
liquibase.changelog.visitor.UpdateVisitor.visit(UpdateVisitor.java:51)
liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:79)
liquibase.Liquibase.update(Liquibase.java:214)
liquibase.Liquibase.update(Liquibase.java:192)
liquibase.Liquibase.update(Liquibase.java:188)
org.keycloak.connections.jpa.updater.liquibase.LiquibaseJpaUpdaterProvider.updateChangeSet(LiquibaseJpaUpdaterProvider.java:182)
org.keycloak.connections.jpa.updater.liquibase.LiquibaseJpaUpdaterProvider.update(LiquibaseJpaUpdaterProvider.java:102)
org.keycloak.connections.jpa.updater.liquibase.LiquibaseJpaUpdaterProvider.update(LiquibaseJpaUpdaterProvider.java:81)
org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory$2.run(DefaultJpaConnectionProviderFactory.java:341)
org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:227)
org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory.update(DefaultJpaConnectionProviderFactory.java:334)
org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory.migration(DefaultJpaConnectionProviderFactory.java:306)
org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory.lambda$lazyInit$0(DefaultJpaConnectionProviderFactory.java:182)
org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory$$Lambda$802/938288417.run(Unknown Source)
org.keycloak.models.utils.KeycloakModelUtils.suspendJtaTransaction(KeycloakModelUtils.java:682)
org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory.lazyInit(DefaultJpaConnectionProviderFactory.java:133)
org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory.create(DefaultJpaConnectionProviderFactory.java:81)
org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory.create(DefaultJpaConnectionProviderFactory.java:59)
org.keycloak.services.DefaultKeycloakSession.getProvider(DefaultKeycloakSession.java:204)
org.keycloak.models.jpa.JpaRealmProviderFactory.create(JpaRealmProviderFactory.java:51)
org.keycloak.models.jpa.JpaRealmProviderFactory.create(JpaRealmProviderFactory.java:33)
org.keycloak.services.DefaultKeycloakSession.getProvider(DefaultKeycloakSession.java:204)
org.keycloak.services.DefaultKeycloakSession.realmLocalStorage(DefaultKeycloakSession.java:157)
org.keycloak.models.cache.infinispan.RealmCacheSession.getRealmDelegate(RealmCacheSession.java:148)
org.keycloak.models.cache.infinispan.RealmCacheSession.getMigrationModel(RealmCacheSession.java:141)
org.keycloak.migration.MigrationModelManager.migrate(MigrationModelManager.java:97)
org.keycloak.services.resources.KeycloakApplication.migrateModel(KeycloakApplication.java:244)
org.keycloak.services.resources.KeycloakApplication.migrateAndBootstrap(KeycloakApplication.java:185)
org.keycloak.services.resources.KeycloakApplication$1.run(KeycloakApplication.java:147)
org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:227)
org.keycloak.services.resources.KeycloakApplication.startup(KeycloakApplication.java:138)
org.keycloak.services.resources.KeycloakApplication$$Lambda$778/1366630785.run(Unknown Source)
org.keycloak.provider.wildfly.WildflyPlatform.onStartup(WildflyPlatform.java:29)
org.keycloak.services.resources.KeycloakApplication.<init>(KeycloakApplication.java:125)
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
java.lang.reflect.Constructor.newInstance(Constructor.java:423)
org.jboss.resteasy.core.ConstructorInjectorImpl.construct(ConstructorInjectorImpl.java:152)
org.jboss.resteasy.spi.ResteasyProviderFactory.createProviderInstance(ResteasyProviderFactory.java:2805)
org.jboss.resteasy.spi.ResteasyDeployment.createApplication(ResteasyDeployment.java:369)
org.jboss.resteasy.spi.ResteasyDeployment.startInternal(ResteasyDeployment.java:281)
org.jboss.resteasy.spi.ResteasyDeployment.start(ResteasyDeployment.java:92)
org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.init(ServletContainerDispatcher.java:119)
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.init(HttpServletDispatcher.java:36)
io.undertow.servlet.core.LifecyleInterceptorInvocation.proceed(LifecyleInterceptorInvocation.java:117)
org.wildfly.extension.undertow.security.RunAsLifecycleInterceptor.init(RunAsLifecycleInterceptor.java:78)
io.undertow.servlet.core.LifecyleInterceptorInvocation.proceed(LifecyleInterceptorInvocation.java:103)
io.undertow.servlet.core.ManagedServlet$DefaultInstanceStrategy.start(ManagedServlet.java:305)
io.undertow.servlet.core.ManagedServlet.createServlet(ManagedServlet.java:145)
io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:585)
io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:556)
io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:42)
io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction$$Lambda$734/2095679667.call(Unknown Source)
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1541)
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$735/1593765930.call(Unknown Source)
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1541)
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$735/1593765930.call(Unknown Source)
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1541)
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$735/1593765930.call(Unknown Source)
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1541)
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$735/1593765930.call(Unknown Source)
io.undertow.servlet.core.DeploymentManagerImpl.start(DeploymentManagerImpl.java:598)
org.wildfly.extension.undertow.deployment.UndertowDeploymentService.startContext(UndertowDeploymentService.java:97)
org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:78)
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
java.util.concurrent.FutureTask.run(FutureTask.java:266)
org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
java.lang.Thread.run(Thread.java:748)
org.jboss.threads.JBossThread.run(JBossThread.java:485)

17:31:31,252 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000101:84ae906:5ee761e5:15 aborting with 1 threads active!
17:31:31,252 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000101:84ae906:5ee761e5:15
17:31:31,514 WARN  [com.arjuna.ats.arjuna] (ServerService Thread Pool -- 68) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000101:84ae906:5ee761e5:15
17:31:31,516 WARN  [com.arjuna.ats.arjuna] (ServerService Thread Pool -- 68) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000101:84ae906:5ee761e5:12
17:31:31,517 WARN  [com.arjuna.ats.arjuna] (ServerService Thread Pool -- 68) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000101:84ae906:5ee761e5:f
17:31:31,518 FATAL [org.keycloak.services] (ServerService Thread Pool -- 68) java.lang.RuntimeException: Failed to update database
17:31:31,520 INFO  [org.jboss.as.server] (Thread-2) WFLYSRV0220: Server shutdown has been requested via an OS signal
17:31:32,024 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 75) WFLYCLINF0003: Stopped sessions cache from keycloak container
17:31:32,038 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-6) WFLYSRV0028: Stopped deployment keycloak-server.war (runtime-name: keycloak-server.war) in 490ms
17:31:32,068 ERROR [org.jboss.as.controller.management-operation] (Controller Boot Thread) WFLYCTL0013: Operation ("add") failed - address: ([("subsystem" => "microprofile-metrics-smallrye")]): java.lang.NullPointerException
        at org.wildfly.extension.microprofile.metrics.MicroProfileMetricsSubsystemAdd$2.execute(MicroProfileMetricsSubsystemAdd.java:86)
        at org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:999)
        at org.jboss.as.controller.AbstractOperationContext.processStages(AbstractOperationContext.java:743)
        at org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:467)
        at org.jboss.as.controller.OperationContextImpl.executeOperation(OperationContextImpl.java:1413)
        at org.jboss.as.controller.ModelControllerImpl.boot(ModelControllerImpl.java:527)
        at org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:515)
        at org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:477)
        at org.jboss.as.server.ServerService.boot(ServerService.java:448)
        at org.jboss.as.server.ServerService.boot(ServerService.java:401)
        at org.jboss.as.controller.AbstractControllerService$1.run(AbstractControllerService.java:416)
        at java.lang.Thread.run(Thread.java:748)

17:31:32,081 ERROR [org.jboss.as.server] (ServerService Thread Pool -- 55) WFLYSRV0022: Deploy of deployment "keycloak-server.war" was rolled back with no failure message
17:31:32,132 INFO  [org.jboss.as] (MSC service thread 1-5) WFLYSRV0050: Keycloak 10.0.1 (WildFly Core 11.1.1.Final) stopped in 584ms

I am looking for solution like:

1. If I could get initial DDL & DML of Keycloak
2. If Keycloak could continue from where it failed
3. If timeout could be increased. In this case, I tried below command but it not work

docker run -p 8080:8080 -e KEYCLOAK_USER=admin -e KEYCLOAK_PASSWORD=password -e DB_VENDOR=mysql -e DB_DATABASE=keycloak -e DB_USER=keycloak -e DB_PASSWORD=keycloak -e DB_ADDR=mysql -e ROOT_LOGLEVEL=DEBUG -e JAVA_OPTIONS="-Djboss.as.management.blocking.timeout=900" -e KEYCLOAK_LOGLEVEL=DEBUG --link=mysql jboss/keycloak

Answer 1

I ran into this issue today, after my Keycloak instance suddenly stopped working.

I took a look at my underlying PostgreSQL database and retrieved the locks. And what I saw, was that a Liquibase lock was not released.

So I used this commmand to search for open activities inside the PostgreSQL DB:

SELECT pid, state, username, query, query_start
FROM pg_stat_activity
WHERE pid in (
  select pid from pg_locks l
  join pg_class t on l.relation = t.oid
  where t.relkind = 'r'
);

which returned the following:

pid | state  | usename  |                                query                                 |          query_start
-----+--------+----------+----------------------------------------------------------------------+-------------------------------
  32 | active | keycloak | SELECT ID FROM public.databasechangeloglock WHERE ID=1000 FOR UPDATE | 2020-10-11 14:21:07.396058+00
 354 | active | keycloak | SELECT ID FROM public.databasechangeloglock WHERE ID=1000 FOR UPDATE | 2020-10-11 19:42:06.636659+00

Those database locks come from Liquibase which is used by Keycloak to upgrade your data structure/definition. Those locks were not released while upgrading the schema.

After dropping the table, the service now works again.

DROP TABLE databasechangeloglock;

In my case neither increasing the blocking timeout nor adding a default timeout to the transaction manager worked.

<coordinator-environment default-timeout="600" .../> # did not work
...
JAVA_TOOLS_OPTS: "-Djboss.as.management.blocking.timeout=3600" # did not work

Answer 2

Seems that your keycloak tried to update schema during startup and it took too much time, so wildfly broke Keycloak deployment by timeout. Try to add following property to wildfly:

${KEYCLOAK_HOME}/bin/standalone.sh -Djboss.as.management.blocking.timeout=3600