[stable/keycloak] [Bug report] Installation fails: Database error during release lock

[axdotl]

Version of Helm and Kubernetes:

Client: v2.11.0+g2e55dbe
Server: v2.11.0+g2e55dbe

Which chart:
stable/keycloak

What happened:
When installing 4.0.0 pod keycloak-0 fails to start.

What you expected to happen:
I expected that pod came up properly.

How to reproduce it (as minimally and precisely as possible):
Setup

• Google Kubernetes Engine v1.10.7-gke.2
• Cloud SQL (MySQL 2nd Gen 5.7)
• Cloud SQL Proxy: stable/gcloud-sqlproxy-0.5.0

Used following values:

keycloak:
  username: admin

  replicas: 1

  resources:
    limits:
      cpu: "500m"
      memory: "1024Mi"
    requests:
      cpu: "300m"
      memory: "512Mi"

  ingress:
    enabled: false

  persistence:
    deployPostgres: false
    dbVendor: mysql
    # cloud-sql proxy
    dbHost: mysqlproxy.infra
    dbPort: 3306
    dbName: keycloak
    dbUser: keycloak
    dbPassword: topSecret

Anything else we need to know:

• As described in [stable/keycloak] Update to 4.5.0.Final #8192, running keycloak as deployment works.

Here is a log snippet:

11:58:31,759 INFO  [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (ServerService Thread Pool -- 50) Node name: keycloak-0, Site name: null
11:58:33,716 ERROR [stderr] (ServerService Thread Pool -- 50) Mon Oct 15 11:58:33 UTC 2018 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
11:58:34,281 ERROR [stderr] (ServerService Thread Pool -- 50) Mon Oct 15 11:58:34 UTC 2018 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
11:58:46,074 INFO  [org.hibernate.jpa.internal.util.LogHelper] (ServerService Thread Pool -- 50) HHH000204: Processing PersistenceUnitInfo [
	name: keycloak-default
	...]
11:58:46,370 INFO  [org.hibernate.Version] (ServerService Thread Pool -- 50) HHH000412: Hibernate Core {5.1.14.Final}
11:58:46,372 INFO  [org.hibernate.cfg.Environment] (ServerService Thread Pool -- 50) HHH000206: hibernate.properties not found
11:58:46,374 INFO  [org.hibernate.cfg.Environment] (ServerService Thread Pool -- 50) HHH000021: Bytecode provider name : javassist
11:58:46,667 INFO  [org.hibernate.annotations.common.Version] (ServerService Thread Pool -- 50) HCANN000001: Hibernate Commons Annotations {5.0.2.Final}
11:58:47,411 ERROR [stderr] (ServerService Thread Pool -- 50) Mon Oct 15 11:58:47 UTC 2018 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
11:58:47,428 INFO  [org.hibernate.dialect.Dialect] (ServerService Thread Pool -- 50) HHH000400: Using dialect: org.hibernate.dialect.MySQL5Dialect
11:58:47,571 INFO  [org.hibernate.envers.boot.internal.EnversServiceImpl] (ServerService Thread Pool -- 50) Envers integration enabled? : true
11:58:49,703 INFO  [org.hibernate.validator.internal.util.Version] (ServerService Thread Pool -- 50) HV000001: Hibernate Validator 5.3.6.Final
*** JBossAS process (302) received TERM signal ***
11:58:54,859 INFO  [org.jboss.as.server] (Thread-2) WFLYSRV0220: Server shutdown has been requested via an OS signal
11:58:55,358 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-1) WFLYJCA0010: Unbound data source [java:jboss/datasources/KeycloakDS]
11:58:55,364 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-3) ISPN000080: Disconnecting JGroups channel ejb
11:58:55,365 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-6) ISPN000080: Disconnecting JGroups channel ejb
11:58:55,365 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-8) ISPN000080: Disconnecting JGroups channel ejb
11:58:55,369 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-4) WFLYUT0008: Undertow HTTPS listener https suspending
11:58:55,561 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (ServerService Thread Pool -- 65) IJ000615: Destroying active connection in pool: KeycloakDS (org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@126c5da6)
11:58:55,564 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (ServerService Thread Pool -- 65) IJ000615: Destroying active connection in pool: KeycloakDS (org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@1653db33)
11:58:55,570 INFO  [org.hibernate.hql.internal.QueryTranslatorFactoryInitiator] (ServerService Thread Pool -- 50) HHH000397: Using ASTQueryTranslatorFactory
11:58:55,665 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-4) WFLYUT0007: Undertow HTTPS listener https stopped, was bound to 0.0.0.0:8443
11:58:55,865 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-6) WFLYJCA0019: Stopped Driver service with driver-name = mysql
11:59:01,178 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (ServerService Thread Pool -- 50) SQL Error: 0, SQLState: null
11:59:01,179 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (ServerService Thread Pool -- 50) javax.resource.ResourceException: IJ000470: You are trying to use a connection factory that has been shut down: java:jboss/datasources/KeycloakDS
11:59:01,257 INFO  [org.hibernate.event.internal.DefaultLoadEventListener] (ServerService Thread Pool -- 50) HHH000327: Error performing load command : org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
11:59:01,272 ERROR [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (ServerService Thread Pool -- 50) Database error during release lock: liquibase.exception.DatabaseException: liquibase.exception.DatabaseException: java.sql.SQLException: IJ031040: Connection is not associated with a managed connection: org.jboss.jca.adapters.jdbc.jdk8.WrappedConnectionJDK8@4a60fbc4
	at liquibase.database.AbstractJdbcDatabase.commit(AbstractJdbcDatabase.java:1159)
	at org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService.releaseLock(CustomLockService.java:184)
	at org.keycloak.connections.jpa.updater.liquibase.lock.LiquibaseDBLockProvider.lambda$releaseLock$1(LiquibaseDBLockProvider.java:126)
	at org.keycloak.models.utils.KeycloakModelUtils.suspendJtaTransaction(KeycloakModelUtils.java:611)
	at org.keycloak.connections.jpa.updater.liquibase.lock.LiquibaseDBLockProvider.releaseLock(LiquibaseDBLockProvider.java:123)
	at org.keycloak.services.resources.KeycloakApplication$1.run(KeycloakApplication.java:147)
	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)
	at org.jboss.resteasy.spi.ResteasyProviderFactory.createProviderInstance(ResteasyProviderFactory.java:2676)
	at org.jboss.resteasy.spi.ResteasyDeployment.createApplication(ResteasyDeployment.java:361)
	at org.jboss.resteasy.spi.ResteasyDeployment.startInternal(ResteasyDeployment.java:274)
	at org.jboss.resteasy.spi.ResteasyDeployment.start(ResteasyDeployment.java:86)
	at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.init(ServletContainerDispatcher.java:119)
	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:300)
	at io.undertow.servlet.core.ManagedServlet.createServlet(ManagedServlet.java:140)
	at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:584)
	at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:555)
	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:1514)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514)
	at io.undertow.servlet.core.DeploymentManagerImpl.start(DeploymentManagerImpl.java:597)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService.startContext(UndertowDeploymentService.java:97)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:78)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1985)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1487)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1378)
	at java.lang.Thread.run(Thread.java:748)
	at org.jboss.threads.JBossThread.run(JBossThread.java:485)
Caused by: liquibase.exception.DatabaseException: java.sql.SQLException: IJ031040: Connection is not associated with a managed connection: org.jboss.jca.adapters.jdbc.jdk8.WrappedConnectionJDK8@4a60fbc4
	at liquibase.database.jvm.JdbcConnection.commit(JdbcConnection.java:126)
	at liquibase.database.AbstractJdbcDatabase.commit(AbstractJdbcDatabase.java:1157)
	... 43 more
Caused by: java.sql.SQLException: IJ031040: Connection is not associated with a managed connection: org.jboss.jca.adapters.jdbc.jdk8.WrappedConnectionJDK8@4a60fbc4
	at org.jboss.jca.adapters.jdbc.WrappedConnection.lock(WrappedConnection.java:169)
	at org.jboss.jca.adapters.jdbc.WrappedConnection.getAutoCommit(WrappedConnection.java:807)
	at liquibase.database.jvm.JdbcConnection.commit(JdbcConnection.java:122)
	... 44 more

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Any further update will cause the issue/pull request to no longer be considered stale. Thank you for your contributions.

[stale]

This issue is being automatically closed due to inactivity.

[nurgasemetey]

Any fixes?

[axdotl]

In fact, it was not an issue. It was caused by a kind of misconfiguration.
We run keycloak with limited resources:

  resources:
    limits:
      cpu: "500m"
      memory: "1024Mi"
    requests:
      cpu: "100m"
      memory: "512Mi"

But we were not aware of the default readinessProbe config: https://github.com/helm/charts/blob/master/stable/keycloak/values.yaml#L96

Due the limited resource config keycloak startup finished not in time, as a result readinessProbe failed and pod were killed.

After adjusting the probe config (see below), keylcoak started successfully.

  livenessProbe:
    initialDelaySeconds: 240
    timeoutSeconds: 5
  readinessProbe:
    initialDelaySeconds: 120
    timeoutSeconds: 5

[nurgasemetey]

Thanks for fix and explanation. It saved me. Otherwise I would use H2 database