7:26 p.m.
Dear all.
I try to setup KC 4.2.1 (also tried with 4.0.0) on Ubuntu 18.04 with Mysq
5.7l/MariaDB 10.x. It works totally fine on my Vagrant box (I use Ansible),
but on the "real" server the Liquibase init scripts time out. Please note
that the DB is installed physically on the same machine as Keycloak,
connection is done trough localhost.
The error is some kind of transaction timeout exception, please see below
the log. It is interesting to note that a) the script runs for more than 5
minutes before it fails, and b) most tables have been created in the DB,
but after this error the state is unrecoverable.
Do you have any pointers/hints on why I run into these timeout issues? I am
totally at loss, having tried so many combinations (KC version x DB type x
DB version), which all run fine on Vagrant but fail on the server.
Thanks in advance & greetings
Henning
------
2018-09-20 19:00:53,220 INFO
[org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory]
(ServerService Thread Pool -- 49) Node name: sso, Site name: null
2018-09-20 19:00:55,982 INFO
[org.keycloak.connections.jpa.updater.liquibase.LiquibaseJpaUpdaterProvider]
(ServerService Thread Pool -- 49) Initializing database schema. Using
changelog META-INF/jpa-changelog-master.xml
2018-09-20 19:05:53,240 WARN [com.arjuna.ats.arjuna] (Transaction Reaper)
ARJUNA012117: TransactionReaper::check timeout for TX
0:ffff91eff4af:-1fd3cdfc:5ba3d243:e in state RUN
2018-09-20 19:05:53,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:ffff91eff4af:-1fd3cdfc:5ba3d243:e
2018-09-20 19:05:53,938 WARN [com.arjuna.ats.arjuna] (Transaction Reaper)
ARJUNA012117: TransactionReaper::check timeout for TX
0:ffff91eff4af:-1fd3cdfc:5ba3d243:11 in state RUN
2018-09-20 19:05:53,940 WARN [com.arjuna.ats.arjuna] (Transaction Reaper
Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker
Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX
0:ffff91eff4af:-1fd3cdfc:5ba3d243:11
2018-09-20 19:06:13,864 INFO [org.hibernate.jpa.internal.util.LogHelper]
(ServerService Thread Pool -- 49) HHH000204: Processing PersistenceUnitInfo
[
name: keycloak-default
...]
2018-09-20 19:06:13,913 INFO [org.hibernate.Version] (ServerService Thread
Pool -- 49) HHH000412: Hibernate Core {5.1.10.Final}
2018-09-20 19:06:13,914 INFO [org.hibernate.cfg.Environment]
(ServerService Thread Pool -- 49) HHH000206: hibernate.properties not found
2018-09-20 19:06:13,916 INFO [org.hibernate.cfg.Environment]
(ServerService Thread Pool -- 49) HHH000021: Bytecode provider name :
javassist
2018-09-20 19:06:13,943 INFO [org.hibernate.annotations.common.Version]
(ServerService Thread Pool -- 49) HCANN000001: Hibernate Commons
Annotations {5.0.1.Final}
2018-09-20 19:06:14,076 INFO [org.hibernate.dialect.Dialect]
(ServerService Thread Pool -- 49) HHH000400: Using dialect:
org.hibernate.dialect.MySQL5Dialect
2018-09-20 19:06:14,107 INFO
[org.hibernate.envers.boot.internal.EnversServiceImpl] (ServerService
Thread Pool -- 49) Envers integration enabled? : true
2018-09-20 19:06:14,534 INFO
[org.hibernate.validator.internal.util.Version] (ServerService Thread Pool
-- 49) HV000001: Hibernate Validator 5.3.5.Final
2018-09-20 19:06:15,154 INFO
[org.hibernate.hql.internal.QueryTranslatorFactoryInitiator] (ServerService
Thread Pool -- 49) HHH000397: Using ASTQueryTranslatorFactory
2018-09-20 19:06:15,842 WARN
[org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (ServerService Thread
Pool -- 49) SQL Error: 0, SQLState: null
2018-09-20 19:06:15,842 ERROR
[org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (ServerService Thread
Pool -- 49) javax.resource.ResourceException: IJ000460: Error checking for
a transaction
2018-09-20 19:06:15,843 INFO
[org.hibernate.event.internal.DefaultLoadEventListener] (ServerService
Thread Pool -- 49) HHH000327: Error performing load command :
org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC
Connection
2018-09-20 19:06:15,844 WARN [com.arjuna.ats.arjuna] (ServerService Thread
Pool -- 49) ARJUNA012077: Abort called on already aborted atomic action
0:ffff91eff4af:-1fd3cdfc:5ba3d243:11
2018-09-20 19:06:15,850 WARN [com.arjuna.ats.arjuna] (ServerService Thread
Pool -- 49) ARJUNA012077: Abort called on already aborted atomic action
0:ffff91eff4af:-1fd3cdfc:5ba3d243:e
2018-09-20 19:06:15,853 INFO [org.jboss.as.server] (Thread-2) WFLYSRV0220:
Server shutdown has been requested via an OS signal
2018-09-20 19:06:15,857 ERROR [org.jboss.msc.service.fail] (ServerService
Thread Pool -- 49) MSC000001: Failed to start service
jboss.undertow.deployment.default-server.default-host./auth:
org.jboss.msc.service.StartException in service
jboss.undertow.deployment.default-server.default-host./auth:
java.lang.RuntimeException: RESTEASY003325: Failed to construct public
org.keycloak.services.resources.KeycloakApplication(javax.servlet.ServletContext,org.jboss.resteasy.core.Dispatcher)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:84)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
Caused by: java.lang.RuntimeException: RESTEASY003325: Failed to construct
public
org.keycloak.services.resources.KeycloakApplication(javax.servlet.ServletContext,org.jboss.resteasy.core.Dispatcher)
at
org.jboss.resteasy.core.ConstructorInjectorImpl.construct(ConstructorInjectorImpl.java:162)
at
org.jboss.resteasy.spi.ResteasyProviderFactory.createProviderInstance(ResteasyProviderFactory.java:2298)
at
org.jboss.resteasy.spi.ResteasyDeployment.createApplication(ResteasyDeployment.java:340)
at
org.jboss.resteasy.spi.ResteasyDeployment.start(ResteasyDeployment.java:253)
at
org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.init(ServletContainerDispatcher.java:120)
at
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.init(HttpServletDispatcher.java:36)
at
io.undertow.servlet.core.LifecyleInterceptorInvocation.proceed(LifecyleInterceptorInvocation.java:117)
at
org.wildfly.extension.undertow.security.RunAsLifecycleInterceptor.init(RunAsLifecycleInterceptor.java:78)
at
io.undertow.servlet.core.LifecyleInterceptorInvocation.proceed(LifecyleInterceptorInvocation.java:103)
at
io.undertow.servlet.core.ManagedServlet$DefaultInstanceStrategy.start(ManagedServlet.java:250)
at
io.undertow.servlet.core.ManagedServlet.createServlet(ManagedServlet.java:133)
at
io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:565)
at
io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:536)
at
io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:42)
at
io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at
org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
at
io.undertow.servlet.core.DeploymentManagerImpl.start(DeploymentManagerImpl.java:578)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentService.startContext(UndertowDeploymentService.java:100)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:81)
... 6 more
Caused by: org.keycloak.models.ModelException:
javax.persistence.PersistenceException:
org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC
Connection
at
org.keycloak.connections.jpa.PersistenceExceptionConverter.convert(PersistenceExceptionConverter.java:61)
at
org.keycloak.connections.jpa.PersistenceExceptionConverter.invoke(PersistenceExceptionConverter.java:51)
at com.sun.proxy.$Proxy68.find(Unknown Source)
at
org.keycloak.models.jpa.MigrationModelAdapter.getStoredVersion(MigrationModelAdapter.java:38)
at
org.keycloak.migration.MigrationModelManager.migrate(MigrationModelManager.java:84)
at
org.keycloak.services.resources.KeycloakApplication.migrateModel(KeycloakApplication.java:245)
at
org.keycloak.services.resources.KeycloakApplication.migrateAndBootstrap(KeycloakApplication.java:186)
at
org.keycloak.services.resources.KeycloakApplication$1.run(KeycloakApplication.java:145)
at
org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:227)
at
org.keycloak.services.resources.KeycloakApplication.<init>(KeycloakApplication.java:136)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
Method)
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at
org.jboss.resteasy.core.ConstructorInjectorImpl.construct(ConstructorInjectorImpl.java:150)
... 28 more
Caused by: javax.persistence.PersistenceException:
org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC
Connection
at
org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1692)
at
org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1619)
at
org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1106)
at
org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1033)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.keycloak.connections.jpa.PersistenceExceptionConverter.invoke(PersistenceExceptionConverter.java:49)
... 41 more
Caused by: org.hibernate.exception.GenericJDBCException: Unable to acquire
JDBC Connection
at
org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
at
org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
at
org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97)
at
org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:87)
at
org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:109)
at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:47)
at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146)
at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172)
at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148)
at
org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.prepareQueryStatement(AbstractLoadPlanBasedLoader.java:241)
at
org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:185)
at
org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:121)
at
org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:86)
at
org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:167)
at
org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4069)
at
org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:508)
at
org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:478)
at
org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:219)
at
org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:278)
at
org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:121)
at
org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:89)
at
org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1142)
at
org.hibernate.internal.SessionImpl.access$2600(SessionImpl.java:167)
at
org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.doLoad(SessionImpl.java:2762)
at
org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2741)
at org.hibernate.internal.SessionImpl.get(SessionImpl.java:978)
at
org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1075)
... 47 more
Caused by: java.sql.SQLException: javax.resource.ResourceException:
IJ000460: Error checking for a transaction
at
org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:146)
at
org.jboss.as.connector.subsystems.datasources.WildFlyDataSource.getConnection(WildFlyDataSource.java:64)
at
org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
at
org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:386)
at
org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:84)
... 70 more
Caused by: javax.resource.ResourceException: IJ000460: Error checking for a
transaction
at
org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:425)
at
org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:789)
at
org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:138)
... 74 more
Caused by: javax.resource.ResourceException: IJ000459: Transaction is not
active: tx=Local transaction (delegate=TransactionImple < ac, BasicAction:
0:ffff91eff4af:-1fd3cdfc:5ba3d243:11 status: ActionStatus.ABORTED >,
owner=Local transaction context for provider JBoss JTA transaction provider)
at
org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:409)
... 76 more
2018-09-20 19:06:15,872 INFO [org.wildfly.extension.undertow] (MSC service
thread 1-7) WFLYUT0008: Undertow HTTPS listener https suspending
2018-09-20 19:06:15,872 INFO
[org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-3)
WFLYJCA0010: Unbound data source [java:jboss/datasources/KeycloakDS]
2018-09-20 19:06:15,877 INFO
[org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-2)
WFLYJCA0010: Unbound data source [java:jboss/datasources/ExampleDS]
2018-09-20 19:06:15,878 INFO [org.jboss.as.connector.deployers.jdbc] (MSC
service thread 1-6) WFLYJCA0019: Stopped Driver service with driver-name =
h2
2018-09-20 19:06:15,881 INFO [org.jboss.as.connector.deployers.jdbc] (MSC
service thread 1-2) WFLYJCA0019: Stopped Driver service with driver-name =
mariadb
2018-09-20 19:06:15,881 INFO [org.wildfly.extension.undertow] (MSC service
thread 1-7) WFLYUT0007: Undertow HTTPS listener https stopped, was bound to
0.0.0.0:8443
2018-09-20 19:06:15,885 INFO [org.wildfly.extension.undertow] (MSC service
thread 1-7) WFLYUT0008: Undertow HTTP listener default suspendi
--