Upgrade from 14 to 25 fails during Migration

We are upgrading from Keycloak 14 to Keycloak 25.0.6.
Our setup contains approximately around 300+ realms.

Upgrade stops/fails after approximately 4 min consistently while the migration is going on.

I have included following properties in the JAVA_OPTS of the k8s sts we are using.

-Dquarkus.transaction-manager.default-transaction-timeout=3600
-Dkeycloak.migration.batch-enabled=true
-Dkeycloak.migration.batch-size=1000

I have also added the ENV variable ‘QUARKUS_TRANSACTION_MANAGER_DEFAULT_TRANSACTION_TIMEOUT=3600’ just to make sure the timeout property is picked up.

Logs does not show any errors. Just the warning messages. See sample logs below.

I am not sure what I am missing here.

I even tried deleting all the ‘http challenge’ flow from the database directly to save time. It skips removing ‘http challenge’ during migration. However, it still fails the same way after 4 min. I am pretty sure this is related to some timeout and I am not able to find that info.

Please advise if I missed anything.

Thanks

Appending additional Java properties to JAVA_OPTS
2024-11-12 15:09:44,188 DEBUG [org.keycloak.quarkus.runtime.configuration.mappers.PropertyMappers] (main) Duplicated mappers for key 'KC_HOSTNAME_ADMIN'. Used the first found.
2024-11-12 15:09:44,189 DEBUG [org.keycloak.quarkus.runtime.configuration.mappers.PropertyMappers] (main) Duplicated mappers for key 'KC_HOSTNAME_STRICT'. Used the first found.
2024-11-12 15:09:44,287 DEBUG [org.keycloak.quarkus.runtime.configuration.mappers.PropertyMappers] (main) Duplicated mappers for key 'kc.hostname-strict'. Used the first found.
2024-11-12 15:09:44,288 DEBUG [org.keycloak.quarkus.runtime.configuration.mappers.PropertyMappers] (main) Duplicated mappers for key 'kc.hostname-strict'. Used the first found.
2024-11-12 15:09:44,442 INFO  [org.keycloak.common.Profile] (main) Preview features enabled: token-exchange:v1
2024-11-12 15:09:44,470 DEBUG [org.keycloak.quarkus.runtime.configuration.mappers.PropertyMappers] (main) Duplicated mappers for key 'kc.dir'. Used the first found.
2024-11-12 15:09:44,470 DEBUG [org.keycloak.quarkus.runtime.configuration.mappers.PropertyMappers] (main) Duplicated mappers for key 'kc.dir'. Used the first found.
2024-11-12 15:09:44,471 DEBUG [org.keycloak.quarkus.runtime.configuration.mappers.PropertyMappers] (main) Duplicated mappers for key 'kc.dir'. Used the first found.
2024-11-12 15:09:44,471 DEBUG [org.keycloak.quarkus.runtime.configuration.mappers.PropertyMappers] (main) Duplicated mappers for key 'kc.dir'. Used the first found.
2024-11-12 15:09:44,471 DEBUG [org.keycloak.quarkus.runtime.configuration.mappers.PropertyMappers] (main) Duplicated mappers for key 'kc.dir'. Used the first found.
2024-11-12 15:09:44,472 DEBUG [org.keycloak.quarkus.runtime.configuration.mappers.PropertyMappers] (main) Duplicated mappers for key 'kc.dir'. Used the first found.
2024-11-12 15:09:44,501 WARN  [org.keycloak.quarkus.runtime.cli.Picocli] (main) The following used options or option values are DEPRECATED and will be removed or their behaviour changed in a future release:
	- https-trust-store-password: Use the System Truststore instead, see the docs for details.
	- https-trust-store-type: Use the System Truststore instead, see the docs for details.
	- https-trust-store-file: Use the System Truststore instead, see the docs for details.
Consult the Release Notes for details.
2024-11-12 15:09:44,708 INFO  [org.keycloak.common.Profile] (main) Preview features enabled: token-exchange:v1
2024-11-12 15:09:45,068 DEBUG [org.keycloak.crypto.def.DefaultCryptoProvider] (main) Loaded org.bouncycastle.jce.provider.BouncyCastleProvider security provider
2024-11-12 15:09:45,068 DEBUG [org.keycloak.common.crypto.CryptoIntegration] (main) Using the crypto provider: org.keycloak.crypto.def.DefaultCryptoProvider
2024-11-12 15:09:45,305 DEBUG [org.keycloak.connections.jpa.updater.liquibase.lock.LiquibaseDBLockProviderFactory] (main) Liquibase lock provider configured with lockWaitTime: 900 seconds
2024-11-12 15:09:45,314 DEBUG [org.keycloak.models.sessions.infinispan.InfinispanStickySessionEncoderProviderFactory] (main) Should attach route to the sticky session cookie: true
2024-11-12 15:09:45,316 DEBUG [org.keycloak.keys.infinispan.InfinispanPublicKeyStorageProviderFactory] (main) minTimeBetweenRequests is 10 maxCacheTime is 86400
2024-11-12 15:09:45,317 DEBUG [org.keycloak.scripting.DefaultScriptingProviderFactory] (main) Enable script engine cache: true
2024-11-12 15:09:45,879 DEBUG [org.keycloak.truststore.FileTruststoreProviderFactory] (main) File truststore provider initialized: /usr/lib/jvm/java-21-openjdk-21.0.5.0.10-3.el9.x86_64/lib/security/cacerts, Truststore type: pkcs12
2024-11-12 15:09:45,882 DEBUG [org.keycloak.protocol.oidc.OIDCWellKnownProviderFactory] (main) Include Client Scopes in OIDC Well-known endpoint: true
2024-11-12 15:09:45,882 DEBUG [org.keycloak.protocol.oidc.OIDCWellKnownProviderFactory] (main) Include Client Scopes in OIDC Well-known endpoint: true
2024-11-12 15:09:48,504 INFO  [io.agroal.pool] (JPA Startup Thread) Datasource '<default>': Initial size smaller than min. Connections will be created when necessary
2024-11-12 15:09:48,908 INFO  [org.infinispan.CONTAINER] (Thread-5) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
2024-11-12 15:09:49,184 WARN  [org.jgroups.stack.Configurator] (Thread-5) JGRP000014: ThreadPool.thread_dumps_threshold has been deprecated: ignored
2024-11-12 15:09:49,209 INFO  [org.infinispan.CLUSTER] (Thread-5) ISPN000078: Starting JGroups channel `ISPN` with stack `kubernetes`
2024-11-12 15:09:49,211 INFO  [org.jgroups.JChannel] (Thread-5) local_addr: [REMOVED FOR SECURITY], name: keycloak-s5-0-59385
2024-11-12 15:09:49,224 INFO  [org.jgroups.protocols.FD_SOCK2] (Thread-5) server listening on *.57800
2024-11-12 15:09:50,169 DEBUG [org.keycloak.services.resources.KeycloakApplication] (main) PlatformProvider: org.keycloak.quarkus.runtime.integration.QuarkusPlatform
2024-11-12 15:09:51,233 INFO  [org.jgroups.protocols.pbcast.GMS] (Thread-5) keycloak-s5-0-59385: no members discovered after 2003 ms: creating cluster as coordinator
2024-11-12 15:09:51,242 INFO  [org.infinispan.CLUSTER] (Thread-5) ISPN000094: Received new cluster view for channel ISPN: [keycloak-s5-0-59385|0] (1) [keycloak-s5-0-59385]
2024-11-12 15:09:51,302 INFO  [org.infinispan.CLUSTER] (Thread-5) ISPN000079: Channel `ISPN` local address is `keycloak-s5-0-59385`, physical addresses are `[REMOVED FOR SECURITY]`
2024-11-12 15:09:51,776 DEBUG [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Using container managed Infinispan cache container, lookup=DefaultCacheManager keycloak-s5-0-59385
2024-11-12 15:09:51,777 INFO  [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: keycloak-s5-0-59385, Site name: null
2024-11-12 15:09:51,779 DEBUG [org.keycloak.models.sessions.infinispan.InfinispanSingleUseObjectProviderFactory] (main) Not having remote stores. Using basic cache 'actionTokens' for single-use cache of token
2024-11-12 15:09:51,783 INFO  [org.keycloak.broker.provider.AbstractIdentityProviderMapper] (main) Registering class org.keycloak.broker.provider.mappersync.ConfigSyncEventListener
2024-11-12 15:09:51,841 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.database.QuarkusJpaConnectionProviderFactory] (main) Database info: {[REMOVED FOR SECURITY]}
2024-11-12 15:09:51,910 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusJpaUpdaterProvider] (main) Validating if database is updated
2024-11-12 15:09:51,996 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusLiquibaseConnectionProvider] (main) Using changelog file META-INF/jpa-changelog-master.xml and changelogTableName DATABASECHANGELOG
2024-11-12 15:09:53,098 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusJpaUpdaterProvider] (main) Validation failed. Database is not up-to-date for changelog META-INF/jpa-changelog-master.xml
2024-11-12 15:09:53,146 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusLiquibaseConnectionProvider] (main) Using changelog file META-INF/jpa-changelog-master.xml and changelogTableName DATABASECHANGELOG
2024-11-12 15:09:53,150 DEBUG [org.keycloak.connections.jpa.updater.liquibase.lock.LiquibaseDBLockProvider] (main) Going to lock namespace=DATABASE
2024-11-12 15:09:53,250 DEBUG [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Initialized record in the database lock table
2024-11-12 15:09:53,250 DEBUG [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Trying to lock database
2024-11-12 15:09:53,252 DEBUG [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockDatabaseChangeLogGenerator] (main) SQL command for pessimistic lock: SELECT ID FROM keycloak_s5_demo1.DATABASECHANGELOGLOCK WHERE ID=1 FOR UPDATE
2024-11-12 15:09:53,273 DEBUG [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Successfully acquired database lock
2024-11-12 15:09:53,274 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusJpaUpdaterProvider] (main) Starting database update
2024-11-12 15:09:53,292 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusLiquibaseConnectionProvider] (main) Using changelog file META-INF/jpa-changelog-master.xml and changelogTableName DATABASECHANGELOG
2024-11-12 15:09:53,703 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusJpaUpdaterProvider] (main) Updating database from 21.1.0-19404-2 to 25.0.0-28861-index-creation. Using changelog META-INF/jpa-changelog-master.xml
2024-11-12 15:10:11,714 WARN  [liquibase.executor.jvm.JdbcExecutor] (main) 'utf8' is currently an alias for the character set UTF8MB3, but will be an alias for UTF8MB4 in a future release. Please consider using UTF8MB4 in order to be unambiguous.
2024-11-12 15:10:12,198 WARN  [liquibase.executor.jvm.JdbcExecutor] (main) 'utf8' is currently an alias for the character set UTF8MB3, but will be an alias for UTF8MB4 in a future release. Please consider using UTF8MB4 in order to be unambiguous.
2024-11-12 15:10:12,384 WARN  [liquibase.executor.jvm.JdbcExecutor] (main) 'utf8' is currently an alias for the character set UTF8MB3, but will be an alias for UTF8MB4 in a future release. Please consider using UTF8MB4 in order to be unambiguous.
2024-11-12 15:10:12,573 WARN  [liquibase.executor.jvm.JdbcExecutor] (main) 'utf8' is currently an alias for the character set UTF8MB3, but will be an alias for UTF8MB4 in a future release. Please consider using UTF8MB4 in order to be unambiguous.
2024-11-12 15:10:12,649 WARN  [liquibase.executor.jvm.JdbcExecutor] (main) 'utf8' is currently an alias for the character set UTF8MB3, but will be an alias for UTF8MB4 in a future release. Please consider using UTF8MB4 in order to be unambiguous.

UPDATE SUMMARY
Run:                         21
Previously run:             113
Filtered out:                 0
-------------------------------
Total change sets:          134

2024-11-12 15:10:17,060 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusJpaUpdaterProvider] (main) Completed database update for changelog META-INF/jpa-changelog-master.xml
2024-11-12 15:10:17,061 DEBUG [org.keycloak.connections.jpa.updater.liquibase.lock.LiquibaseDBLockProvider] (main) Going to release database lock namespace=DATABASE
2024-11-12 15:10:17,061 DEBUG [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Going to release database lock
2024-11-12 15:10:17,132 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (main) new JtaTransactionWrapper
2024-11-12 15:10:17,132 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (main) was existing? false
2024-11-12 15:10:17,140 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.database.QuarkusJpaConnectionProviderFactory] (main) Calling migrateModel
2024-11-12 15:10:17,505 DEBUG [org.keycloak.storage.datastore.DefaultMigrationManager] (main) Migrating older model to 22.0.0
2024-11-12 15:10:17,508 DEBUG [org.keycloak.cluster.infinispan.CrossDCAwareCacheFactory] (main) No configured remoteStore available. Cross-DC scenario is not used
2024-11-12 15:10:17,539 DEBUG [org.keycloak.cluster.infinispan.InfinispanClusterProviderFactory] (main) Initialized cluster startup time to Tue Nov 12 15:09:45 GMT 2024
2024-11-12 15:10:17,544 DEBUG [org.keycloak.cluster.infinispan.InfinispanNotificationsManager] (main) Added listener for infinispan cache: work
2024-11-12 15:10:17,546 DEBUG [org.keycloak.models.cache.infinispan.InfinispanCacheRealmProviderFactory] (main) Registered cluster listeners
2024-11-12 15:10:19,671 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.GroupConfigPropertyByPathSynchronizer@31daef26 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@1f59def1
2024-11-12 15:10:19,671 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.RoleConfigPropertyByClientIdSynchronizer@8968fe8 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@1f59def1
2024-11-12 15:10:19,671 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.RoleConfigPropertyByRoleNameSynchronizer@38a36f64 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@1f59def1
2024-11-12 15:10:20,886 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.GroupConfigPropertyByPathSynchronizer@31daef26 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@544364ba
2024-11-12 15:10:20,886 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.RoleConfigPropertyByClientIdSynchronizer@8968fe8 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@544364ba
2024-11-12 15:10:20,886 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.RoleConfigPropertyByRoleNameSynchronizer@38a36f64 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@544364ba
2024-11-12 15:10:21,429 DEBUG [org.keycloak.migration.migrators.MigrateTo22_0_0] (main) Removed 'http challenge' authentication flow in realm 'test-1'
2024-11-12 15:10:23,027 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.GroupConfigPropertyByPathSynchronizer@31daef26 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@60a4f677
2024-11-12 15:10:23,027 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.RoleConfigPropertyByClientIdSynchronizer@8968fe8 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@60a4f677
2024-11-12 15:10:23,027 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.RoleConfigPropertyByRoleNameSynchronizer@38a36f64 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@60a4f677
2024-11-12 15:10:23,534 DEBUG [org.keycloak.migration.migrators.MigrateTo22_0_0] (main) Removed 'http challenge' authentication flow in realm 'test-2'
.
.
.
.
.
2024-11-12 15:14:10,721 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.GroupConfigPropertyByPathSynchronizer@31daef26 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@1c67763c
2024-11-12 15:14:10,721 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.RoleConfigPropertyByClientIdSynchronizer@8968fe8 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@1c67763c
2024-11-12 15:14:10,721 DEBUG [org.keycloak.broker.provider.mappersync.ConfigSyncEventListener] (main) Synchronizer org.keycloak.broker.provider.mappersync.RoleConfigPropertyByRoleNameSynchronizer@38a36f64 does not match event: org.keycloak.models.cache.infinispan.RealmCacheSession$3@1c67763c
2024-11-12 15:14:11,494 DEBUG [org.keycloak.migration.migrators.MigrateTo22_0_0] (main) Removed 'http challenge' authentication flow in realm 'sep-2'
2024-11-12 15:14:12,810 INFO  [org.infinispan.CLUSTER] (Thread-12) ISPN000080: Disconnecting JGroups channel `ISPN`
2024-11-12 15:14:12,849 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (main) JtaTransactionWrapper rollback
2024-11-12 15:14:12,854 WARN  [io.agroal.pool] (main) Datasource '<default>': JDBC resources leaked: 2 ResultSet(s) and 2 Statement(s)
2024-11-12 15:14:12,936 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (main) JtaTransactionWrapper end
2024-11-12 15:14:12,938 DEBUG [org.keycloak.quarkus.runtime.storage.legacy.infinispan.CacheManagerFactory] (main) Shutdown embedded cache manager
2024-11-12 15:14:12,938 INFO  [com.arjuna.ats.jbossatx] (main) ARJUNA032014: Stopping transaction recovery manager

There is a lot of features and changes from 14 to 25. I am suggesting you to update it step by step following Keycloak migration guide:
https://www.keycloak.org/docs/latest/upgrading/#migrating-to-16-0-0
from 14 to 16
16 to 17 …

Update:
This issue was due to the pod crashing after 5 min. After increasing the “initialDelaySeconds” of livenessProbe and readinessProbe, it wait for the upgrade to complete. Such an unexpected mistake!

Thanks @djordje for your response. But in my case, I was able to successfully upgrade from 14 to 25 without any issues.

1 Like