Database errors when upgrading from 18 to 19.0.2 #14557

colbiJavier · 2022-09-23T07:21:12Z

colbiJavier
Sep 23, 2022

I have keycloak 18 running using MS-SQL database. Everything is working fine, but wanted to upgrade to the latest versions for the new update email verification feature.

I followed the directions and when I start the server I get a series of database errors. I tried starting the server with --spi-connections-jpa-default-migration-strategy=update and the --spi-connections-jpa-default-migration-strategy=manual and neither worked. I also tried running kc.sh build --db=mssql --transaction-xa-enabled=false first and it didn't make a difference. I can see on the database server that queries are being made, so I'm lost on what else to check or what may be causing the issue.

# /opt/keycloak/bin/kc.sh start --spi-connections-jpa-default-migration-strategy=update
2022-09-22 18:47:24,163 INFO  [org.keycloak.quarkus.runtime.hostname.DefaultHostnameProvider] (main) Hostname settings: Base URL: <unset>, Hostname: login.domain.net, Strict HTTPS: true, Path: <request>, Strict BackChannel: false, Admin URL: <unset>, Admin: <request>, Port: -1, Proxied: false
2022-09-22 18:47:25,824 INFO  [org.keycloak.common.crypto.CryptoIntegration] (main) Detected crypto provider: org.keycloak.crypto.def.DefaultCryptoProvider
2022-09-22 18:47:28,514 WARN  [org.infinispan.CONFIG] (keycloak-cache-init) ISPN000569: Unable to persist Infinispan internal caches as no global state enabled
2022-09-22 18:47:28,530 WARN  [org.infinispan.PERSISTENCE] (keycloak-cache-init) ISPN000554: jboss-marshalling is deprecated and planned for removal
2022-09-22 18:47:28,591 INFO  [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
2022-09-22 18:47:29,085 INFO  [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000128: Infinispan version: Infinispan 'Triskaidekaphobia' 13.0.9.Final
2022-09-22 18:47:29,303 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000078: Starting JGroups channel `ISPN`
2022-09-22 18:47:29,304 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000088: Unable to use any JGroups configuration mechanisms provided in properties {}. Using default JGroups configuration!
2022-09-22 18:47:29,412 WARN  [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the send buffer of socket MulticastSocket was set to 1.00MB, but the OS only allocated 212.99KB
2022-09-22 18:47:29,412 WARN  [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the receive buffer of socket MulticastSocket was set to 20.00MB, but the OS only allocated 212.99KB
2022-09-22 18:47:29,413 WARN  [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the send buffer of socket MulticastSocket was set to 1.00MB, but the OS only allocated 212.99KB
2022-09-22 18:47:29,413 WARN  [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the receive buffer of socket MulticastSocket was set to 25.00MB, but the OS only allocated 212.99KB
2022-09-22 18:47:31,429 INFO  [org.jgroups.protocols.pbcast.GMS] (keycloak-cache-init) qbkey01-61047: no members discovered after 2003 ms: creating cluster as coordinator
2022-09-22 18:47:31,440 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000094: Received new cluster view for channel ISPN: [qbkey01-61047|0] (1) [qbkey01-61047]
2022-09-22 18:47:31,447 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000079: Channel `ISPN` local address is `qbkey01-61047`, physical addresses are `[192.168.210.90:33645]`
2022-09-22 18:47:32,273 INFO  [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: qbkey01-61047, Site name: null
2022-09-22 18:47:36,983 INFO  [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusJpaUpdaterProvider] (main) Updating database. Using changelog META-INF/jpa-changelog-master.xml
2022-09-22 18:47:38,182 WARN  [com.arjuna.ats.jta] (main) ARJUNA016061: TransactionImple.enlistResource - XAResource.start returned: XAException.XAER_RMERR for < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffff7f000101:a423:632cadc9:0, node_name=quarkus, branch_uid=0:ffff7f000101:a423:632cadc9:3f, subordinatenodename=null, eis_name=0 >: javax.transaction.xa.XAException: com.microsoft.sqlserver.jdbc.SQLServerException: Failed to create the XA control connection. Error: "The connection is closed."
        at com.microsoft.sqlserver.jdbc.SQLServerXAResource.DTC_XA_Interface(SQLServerXAResource.java:738)
        at com.microsoft.sqlserver.jdbc.SQLServerXAResource.start(SQLServerXAResource.java:772)
        at io.agroal.narayana.BaseXAResource.start(BaseXAResource.java:150)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:661)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:422)
        at io.agroal.narayana.NarayanaTransactionIntegration.associate(NarayanaTransactionIntegration.java:93)
        at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:245)
        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)
        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.doQuery(Loader.java:956)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:357)
        at org.hibernate.loader.Loader.doList(Loader.java:2868)
        at org.hibernate.loader.Loader.doList(Loader.java:2850)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2682)
        at org.hibernate.loader.Loader.list(Loader.java:2677)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:540)
        at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:400)
        at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219)
        at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1454)
        at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1649)
        at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1617)
        at org.hibernate.query.Query.getResultList(Query.java:165)
        at org.keycloak.models.jpa.MigrationModelAdapter.init(MigrationModelAdapter.java:59)
        at org.keycloak.models.jpa.MigrationModelAdapter.<init>(MigrationModelAdapter.java:42)
        at org.keycloak.models.jpa.JpaRealmProvider.getMigrationModel(JpaRealmProvider.java:93)
        at org.keycloak.storage.datastore.LegacyMigrationManager.migrate(LegacyMigrationManager.java:119)
        at org.keycloak.migration.MigrationModelManager.migrate(MigrationModelManager.java:33)
        at org.keycloak.quarkus.runtime.storage.legacy.database.LegacyJpaConnectionProviderFactory.migrateModel(LegacyJpaConnectionProviderFactory.java:219)
        at org.keycloak.quarkus.runtime.storage.legacy.database.LegacyJpaConnectionProviderFactory.initSchema(LegacyJpaConnectionProviderFactory.java:213)
        at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:250)
        at org.keycloak.quarkus.runtime.storage.legacy.database.LegacyJpaConnectionProviderFactory.postInit(LegacyJpaConnectionProviderFactory.java:138)
        at org.keycloak.quarkus.runtime.integration.QuarkusKeycloakSessionFactory.init(QuarkusKeycloakSessionFactory.java:96)
        at org.keycloak.quarkus.runtime.integration.jaxrs.QuarkusKeycloakApplication.startup(QuarkusKeycloakApplication.java:42)
        at org.keycloak.quarkus.runtime.integration.QuarkusLifecycleObserver.onStartupEvent(QuarkusLifecycleObserver.java:37)
        at org.keycloak.quarkus.runtime.integration.QuarkusLifecycleObserver_Observer_onStartupEvent_b0e82415b143738dc1f986a5fa4668e83d0a5dea.notify(Unknown Source)
        at io.quarkus.arc.impl.EventImpl$Notifier.notifyObservers(EventImpl.java:320)
        at io.quarkus.arc.impl.EventImpl$Notifier.notify(EventImpl.java:302)
        at io.quarkus.arc.impl.EventImpl.fire(EventImpl.java:73)
        at io.quarkus.arc.runtime.ArcRecorder.fireLifecycleEvent(ArcRecorder.java:128)
        at io.quarkus.arc.runtime.ArcRecorder.handleLifecycleEvents(ArcRecorder.java:97)
        at io.quarkus.deployment.steps.LifecycleEventsBuildStep$startupEvent1144526294.deploy_0(Unknown Source)
        at io.quarkus.deployment.steps.LifecycleEventsBuildStep$startupEvent1144526294.deploy(Unknown Source)
        at io.quarkus.runner.ApplicationImpl.doStart(Unknown Source)
        at io.quarkus.runtime.Application.start(Application.java:101)
        at io.quarkus.runtime.ApplicationLifecycleManager.run(ApplicationLifecycleManager.java:103)
        at io.quarkus.runtime.Quarkus.run(Quarkus.java:67)
        at org.keycloak.quarkus.runtime.KeycloakMain.start(KeycloakMain.java:103)
        at org.keycloak.quarkus.runtime.cli.command.AbstractStartCommand.run(AbstractStartCommand.java:37)
        at picocli.CommandLine.executeUserObject(CommandLine.java:1939)
        at picocli.CommandLine.access$1300(CommandLine.java:145)
        at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2358)
        at picocli.CommandLine$RunLast.handle(CommandLine.java:2352)
        at picocli.CommandLine$RunLast.handle(CommandLine.java:2314)
        at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2179)
        at picocli.CommandLine$RunLast.execute(CommandLine.java:2316)
        at picocli.CommandLine.execute(CommandLine.java:2078)
        at org.keycloak.quarkus.runtime.cli.Picocli.parseAndRun(Picocli.java:93)
        at org.keycloak.quarkus.runtime.KeycloakMain.main(KeycloakMain.java:89)
        at
8000
 java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at io.quarkus.bootstrap.runner.QuarkusEntryPoint.doRun(QuarkusEntryPoint.java:60)
        at io.quarkus.bootstrap.runner.QuarkusEntryPoint.main(QuarkusEntryPoint.java:31)

2022-09-22 18:47:38,194 WARN  [com.arjuna.ats.jta] (main) ARJUNA016138: Failed to enlist XA resource io.agroal.narayana.BaseXAResource@3220833f: javax.transaction.SystemException: TransactionImple.enlistResource - XAResource.start ARJUNA016054: could not register transaction: < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffff7f000101:a423:632cadc9:0, node_name=quarkus, branch_uid=0:ffff7f000101:a423:632cadc9:3f, subordinatenodename=null, eis_name=0 >
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:714)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:422)
        at io.agroal.narayana.NarayanaTransactionIntegration.associate(NarayanaTransactionIntegration.java:93)
        at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:245)
        at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
        ....

2022-09-22 18:47:38,344 WARN  [io.agroal.pool] (main) Datasource '<default>': Closing open connection after completion
2022-09-22 18:47:38,583 WARN  [com.arjuna.ats.jta] (main) ARJUNA016061: TransactionImple.enlistResource - XAResource.start returned: XAException.XAER_RMERR for < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffff7f000101:a423:632cadc9:42, node_name=quarkus, branch_uid=0:ffff7f000101:a423:632cadc9:81, subordinatenodename=null, eis_name=0 >: javax.transaction.xa.XAException: com.microsoft.sqlserver.jdbc.SQLServerException: Failed to create the XA control connection. Error: "The connection is closed."
        at com.microsoft.sqlserver.jdbc.SQLServerXAResource.DTC_XA_Interface(SQLServerXAResource.java:738)
        at com.microsoft.sqlserver.jdbc.SQLServerXAResource.start(SQLServerXAResource.java:772)
        at io.agroal.narayana.BaseXAResource.start(BaseXAResource.java:150)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:661)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:422)
        at io.agroal.narayana.NarayanaTransactionIntegration.associate(NarayanaTransactionIntegration.java:93)
        at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:245)
        at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
        ....


2022-09-22 18:47:38,584 WARN  [com.arjuna.ats.jta] (main) ARJUNA016138: Failed to enlist XA resource io.agroal.narayana.BaseXAResource@6158113e: javax.transaction.SystemException: TransactionImple.enlistResource - XAResource.start ARJUNA016054: could not register transaction: < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffff7f000101:a423:632cadc9:42, node_name=quarkus, branch_uid=0:ffff7f000101:a423:632cadc9:81, subordinatenodename=null, eis_name=0 >
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:714)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:422)
        at io.agroal.narayana.NarayanaTransactionIntegration.associate(NarayanaTransactionIntegration.java:93)
        at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:245)
        at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
        ....

2022-09-22 18:47:39,285 WARN  [io.agroal.pool] (main) Datasource '<default>': Closing open connection after completion
2022-09-22 18:47:39,577 WARN  [com.arjuna.ats.jta] (main) ARJUNA016061: TransactionImple.enlistResource - XAResource.start returned: XAException.XAER_RMERR for < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffff7f000101:a423:632cadc9:8a, node_name=quarkus, branch_uid=0:ffff7f000101:a423:632cadc9:c9, subordinatenodename=null, eis_name=0 >: javax.transaction.xa.XAException: com.microsoft.sqlserver.jdbc.SQLServerException: Failed to create the XA control connection. Error: "The connection is closed."
        at com.microsoft.sqlserver.jdbc.SQLServerXAResource.DTC_XA_Interface(SQLServerXAResource.java:738)
        at com.microsoft.sqlserver.jdbc.SQLServerXAResource.start(SQLServerXAResource.java:772)
        at io.agroal.narayana.BaseXAResource.start(BaseXAResource.java:150)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:661)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:422)
        at io.agroal.narayana.NarayanaTransactionIntegration.associate(NarayanaTransactionIntegration.java:93)
        at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:245)
        at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
        ....

2022-09-22 18:47:39,578 WARN  [com.arjuna.ats.jta] (main) ARJUNA016138: Failed to enlist XA resource io.agroal.narayana.BaseXAResource@37922937: javax.transaction.SystemException: TransactionImple.enlistResource - XAResource.start ARJUNA016054: could not register transaction: < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffff7f000101:a423:632cadc9:8a, node_name=quarkus, branch_uid=0:ffff7f000101:a423:632cadc9:c9, subordinatenodename=null, eis_name=0 >
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:714)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:422)
        at io.agroal.narayana.NarayanaTransactionIntegration.associate(NarayanaTransactionIntegration.java:93)
        at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:245)
        at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
        ....

2022-09-22 18:47:39,595 WARN  [io.agroal.pool] (main) Datasource '<default>': Closing open connection after completion
2022-09-22 18:47:40,268 INFO  [io.quarkus] (main) Keycloak 19.0.2 on JVM (powered by Quarkus 2.7.6.Final) started in 17.973s. Listening on: https://0.0.0.0:443
2022-09-22 18:47:40,269 INFO  [io.quarkus] (main) Profile prod activated.
2022-09-22 18:47:40,270 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-orm, jdbc-h2, jdbc-mariadb, jdbc-mssql, jdbc-mysql, jdbc-oracle, jdbc-postgresql, keycloak, logging-gelf, narayana-jta, reactive-routes, resteasy, resteasy-jackson, smallrye-context-propagation, smallrye-health, smallrye-metrics, vault, vertx]

Any help would be appreciated. Thanks.

Navigation Menu

Repository navigation

Database errors when upgrading from 18 to 19.0.2 #14557

Uh oh!

{{title}}

Uh oh!

Replies: 0 comments

Select a reply

Uh oh!

Database errors when upgrading from 18 to 19.0.2 #14557

Uh oh!

colbiJavier Sep 23, 2022

Replies: 0 comments

colbiJavier
Sep 23, 2022