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? 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(a)autonomic.ai] Sent: Friday, August 3, 2018 5:41 PM To: Nalyvayko, Peter Cc: keycloak-user(a)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@autonomic.ai<mailto:joy@ 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(a)agi.com <mailto:pnalyvayko@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@lists.jboss.org<mailto:keycloak- user-bounces(a)lists.jboss.org&gt; [keycloak-user-bounces(a)lists.jboss.org <mailto:keycloak-user-bounces@lists.jboss.org>] on behalf of Joy Kent [ joy@autonomic.ai<mailto:joy@autonomic.ai>] Sent: Friday, August 3, 2018 2:30 PM To: keycloak-user@lists.jboss.org<mailto:keycloak-user@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@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.flushBeforeTransactionCompleti on(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.flushBeforeTransactionCompleti on(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@lists.jboss.org<mailto:keycloak-user@lists.jboss.org> https://lists.jboss.org/mailman/listinfo/keycloak-user