[keycloak-user] ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This connection has been closed.
Joy Kent
joy at autonomic.ai
Fri Aug 3 14:30:24 EDT 2018
We have a keycloak 3.4.3.Final cluster with two PostgreSQL databases, one
for keycloak, and the other for user federation storage. Both keycloak and
user federation PostgreSQL databases are running with AWS RDS instances.
Recently, we noticed that keycloak continuously threw exceptions when the
user federation PostgreSQL database did a MultiAZ region failover, and
became not usable. The exception snippet will be attached below. I have
searched around, but didn't find the answer.
This is our keycloak Database configuration:
<datasource jndi-name="java:jboss/datasources/KeycloakDS"
pool-name="KeycloakDS" enabled="true" use-java-context="true"
use-ccm="true">
<connection-url>jdbc:postgresql://${env.POSTGRES_PORT_5432_TCP_ADDR}:${env.POSTGRES_PORT_5432_TCP_PORT:5432}/${env.POSTGRES_DATABASE:keycloak}</connection-url>
<driver>postgresql</driver>
<pool>
<flush-strategy>IdleConnections</flush-strategy>
</pool>
<security>
<user-name>${env.POSTGRES_USER:keycloak}</user-name>
<password>${env.POSTGRES_PASSWORD:password}</password>
</security>
<validation>
<check-valid-connection-sql>SELECT
1</check-valid-connection-sql>
<background-validation>true</background-validation>
<background-validation-millis>60000</background-validation-millis>
</validation>
</datasource>
The user federation Database configuration looks like this:
<xa-datasource jndi-name="java:jboss/datasources/IamDS"
pool-name="IamDS" enabled="true" use-java-context="true" use-ccm="false">
<xa-datasource-property name="ServerName">
${env.IAM_DB_HOST}
</xa-datasource-property>
<xa-datasource-property name="PortNumber">
${env.IAM_DB_TCP_PORT:5432}
</xa-datasource-property>
<xa-datasource-property name="DatabaseName">
${env.IAM_DB_DATABASE:iam}
</xa-datasource-property>
<driver>postgresql</driver>
<xa-pool>
<min-pool-size>${env.IAM_XA_POOL_MIN_SIZE:5}</min-pool-size>
<max-pool-size>${env.IAM_XA_POOL_MAX_SIZE:100}</max-pool-size>
<prefill>false</prefill>
</xa-pool>
<security>
<user-name>${env.IAM_POSTGRES_USER:user}</user-name>
<password>${env.IAM_POSTGRES_PASSWORD:password}</password>
</security>
<validation>
<check-valid-connection-sql>SELECT
1</check-valid-connection-sql>
<background-validation>true</background-validation>
<background-validation-millis>60000</background-validation-millis>
</validation>
</xa-datasource>
The driver is:
<drivers>
<driver name="postgresql" module="org.postgresql.jdbc">
<xa-datasource-class>org.postgresql.xa.PGXADataSource</xa-datasource-class>
</driver>
</drivers>
I found a page
https://access.redhat.com/documentation/en-us/red_hat_jboss_enterprise_application_platform/7.0/html/configuration_guide/datasource_management,
which seems to indicate that exception-sorter is important:
To configure database connection validation, you specify the validation
> timing method (when the validation occurs), the validation mechanism (how
> the validation is performed), and the exception sorter (how exceptions are
> handled).
Is the exception-sorter the missing configuration? I have tried this
change, which seems to "fix" the problem. But by looking at the code, I
can't tell how this can solve the problem.
Does anyone know where might be wrong? Thanks a lot for your help!
=====================
The exception snippet is as follows:
ESC[0mESC[0m04:44:55,502 INFO [org.keycloak.events] (default task-21)
type=CLIENT_LOGIN, realmId=xxxxxxxxxxx, clientId=xxxxxxxxxx,
userId=xxxxxxxxxxxx, ipAddress=100.96.4.0, token_id
=xxxxxxxxxxxx, grant_type=client_credentials, refresh_token_type=Refresh,
refresh_token_id=xxxxxxxxxx, client_auth_method=client-secret,
username=xxxxxxxxxxx
ESC[0mESC[33m04:44:55,503 WARN
[org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) SQL
Error: 0, SQLState: 08003
ESC[0mESC[31m04:44:55,503 ERROR
[org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This
connection has been closed.
ESC[0mESC[33m04:44:55,503 WARN [com.arjuna.ats.arjuna] (default task-21)
ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for
SynchronizationImple< 0:ffff646043f0:2ee9e692:5b425ae8:2c012df,
org.wildfly.transaction.client.AbstractTran
saction$AssociatingSynchronization at 76b2b731 >:
javax.persistence.PersistenceException:
org.hibernate.exception.JDBCConnectionException: could not prepare statement
at
org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1692)
at
org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1602)
at
org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1608)
at
org.hibernate.jpa.internal.EntityManagerImpl$CallbackExceptionMapperImpl.mapManagedFlushFailure(EntityManagerImpl.java:235)
at
org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3163)
at
org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2352)
at
org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:491)
at
org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl.beforeCompletion(JtaTransactionCoordinatorImpl.java:316)
at
org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:47)
at
org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:37)
at
org.wildfly.transaction.client.AbstractTransaction.performConsumer(AbstractTransaction.java:209)
at
org.wildfly.transaction.client.AbstractTransaction.performConsumer(AbstractTransaction.java:220)
at
org.wildfly.transaction.client.AbstractTransaction$AssociatingSynchronization.beforeCompletion(AbstractTransaction.java:265)
at
com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
at
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:368)
at
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:91)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1289)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
at
com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89)
at
org.wildfly.transaction.client.LocalTransaction.commitAndDissociate(LocalTransaction.java:73)
at
org.wildfly.transaction.client.ContextTransactionManager.commit(ContextTransactionManager.java:71)
at
org.keycloak.transaction.JtaTransactionWrapper.commit(JtaTransactionWrapper.java:92)
at
org.keycloak.services.DefaultKeycloakTransactionManager.commit(DefaultKeycloakTransactionManager.java:136)
at
org.keycloak.services.filters.KeycloakTransactionCommitter.filter(KeycloakTransactionCommitter.java:43)
at
org.jboss.resteasy.core.ServerResponseWriter.executeFilters(ServerResponseWriter.java:165)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1289)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
at
com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89)
at
org.wildfly.transaction.client.LocalTransaction.commitAndDissociate(LocalTransaction.java:73)
at
org.wildfly.transaction.client.ContextTransactionManager.commit(ContextTransactionManager.java:71)
at
org.keycloak.transaction.JtaTransactionWrapper.commit(JtaTransactionWrapper.java:92)
at
org.keycloak.services.DefaultKeycloakTransactionManager.commit(DefaultKeycloakTransactionManager.java:136)
at
org.keycloak.services.filters.KeycloakTransactionCommitter.filter(KeycloakTransactionCommitter.java:43)
at
org.jboss.resteasy.core.ServerResponseWriter.executeFilters(ServerResponseWriter.java:165)
.....
Caused by: org.hibernate.exception.JDBCConnectionException: could not
prepare statement
at
org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:115)
at
org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
at
org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:182)
at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareStatement(StatementPreparerImpl.java:78)
at
org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.buildBatchStatement(AbstractBatchImpl.java:136)
at
org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.getBatchStatement(AbstractBatchImpl.java:125)
at
org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2980)
at
org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3499)
at
org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:89)
at
org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:589)
at
org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463)
at
org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337)
at
org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1295)
at
org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:468)
at
org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3159)
... 72 more
Caused by: org.postgresql.util.PSQLException: This connection has been
closed.
at
org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
at
org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
at
org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.doPrepareStatement(BaseWrapperManagedConnection.java:757)
at
org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.prepareStatement(BaseWrapperManagedConnection.java:743)
at
org.jboss.jca.adapters.jdbc.WrappedConnection.prepareStatement(WrappedConnection.java:454)
at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$1.doPrepare(StatementPreparerImpl.java:87)
at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172)
... 85 more
More information about the keycloak-user
mailing list