[keycloak-user] ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This connection has been closed.
Nalyvayko, Peter
pnalyvayko at agi.com
Fri Aug 3 22:13:30 EDT 2018
> Interesting. Looking over the history, I did see a huge memory jump around the time when the exception occurred. Is there a memory leak somewhere?
Lately I've been looking into performance and JVM memory consumption in effort to identify a culprit of system slowdown due to memory starvation. Preliminary results seem to indicate that simple grants such as owner password and client credential grants, can be safely marked off the list of possible causes. More complex use cases, such as identity brokering are another story, as they involve external systems downstream that could cause the entire system to misbehave, but I do not have an empirical evidence yet
________________________________________
From: Joy Kent [joy at autonomic.ai]
Sent: Friday, August 3, 2018 5:41 PM
To: Nalyvayko, Peter
Cc: keycloak-user at lists.jboss.org
Subject: Re: [keycloak-user] ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This connection has been closed.
Interesting. Looking over the history, I did see a huge memory jump around the time when the exception occurred. Is there a memory leak somewhere?
On Fri, Aug 3, 2018 at 1:58 PM, Joy Kent <joy at autonomic.ai<mailto:joy at autonomic.ai>> wrote:
Hi Peter,
Thanks for your suggestions. I haven't checked the memory usage around that time. I will check that and report back.
Thanks,
Joy
On Fri, Aug 3, 2018 at 12:56 PM, Nalyvayko, Peter <pnalyvayko at agi.com<mailto:pnalyvayko at agi.com>> wrote:
tl;dr :)
You may want to check if JVM is running out of memory, we've seen it happen before and the effects were similar.
My 0.02 cents
Regards,
Peter
________________________________________
From: keycloak-user-bounces at lists.jboss.org<mailto:keycloak-user-bounces at lists.jboss.org> [keycloak-user-bounces at lists.jboss.org<mailto:keycloak-user-bounces at lists.jboss.org>] on behalf of Joy Kent [joy at autonomic.ai<mailto:joy at autonomic.ai>]
Sent: Friday, August 3, 2018 2:30 PM
To: keycloak-user at lists.jboss.org<mailto:keycloak-user at lists.jboss.org>
Subject: [keycloak-user] ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This connection has been closed.
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.re<http://com.arjuna.ats.internal.jta.re>sources.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.tr<http://com.arjuna.ats.internal.jta.tr>ansaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1289)
at
com.arjuna.ats.internal.jta.tr<http://com.arjuna.ats.internal.jta.tr>ansaction.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.tr<http://com.arjuna.ats.internal.jta.tr>ansaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1289)
at
com.arjuna.ats.internal.jta.tr<http://com.arjuna.ats.internal.jta.tr>ansaction.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.Ba<http://org.jboss.jca.adapters.jdbc.Ba>seWrapperManagedConnection.doPrepareStatement(BaseWrapperManagedConnection.java:757)
at
org.jboss.jca.adapters.jdbc.Ba<http://org.jboss.jca.adapters.jdbc.Ba>seWrapperManagedConnection.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
_______________________________________________
keycloak-user mailing list
keycloak-user at lists.jboss.org<mailto:keycloak-user at lists.jboss.org>
https://lists.jboss.org/mailman/listinfo/keycloak-user
More information about the keycloak-user
mailing list