ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This connection has been closed.
1:30 p.m.
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_ap...,
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.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
2:56 p.m.
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(a)lists.jboss.org [keycloak-user-bounces(a)lists.jboss.org] on
behalf of Joy Kent [joy(a)autonomic.ai]
Sent: Friday, August 3, 2018 2:30 PM
To: keycloak-user(a)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_ap...,
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.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
_______________________________________________
keycloak-user mailing list
keycloak-user(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/keycloak-user
3:58 p.m.
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>
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(a)lists.jboss.org [keycloak-user-bounces@lists.
jboss.org] on behalf of Joy Kent [joy(a)autonomic.ai]
Sent: Friday, August 3, 2018 2:30 PM
To: keycloak-user(a)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.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.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.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
_______________________________________________
keycloak-user mailing list
keycloak-user(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/keycloak-user
4:41 p.m.
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(a)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>
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(a)lists.jboss.org [
> keycloak-user-bounces(a)lists.jboss.org] on behalf of Joy Kent [
> joy(a)autonomic.ai]
> Sent: Friday, August 3, 2018 2:30 PM
> To: keycloak-user(a)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</b
> ackground-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</b
> ackground-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(Abst
> ractEntityManagerImpl.java:1692)
> at
> org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(Abst
> ractEntityManagerImpl.java:1602)
> at
> org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(Abst
> ractEntityManagerImpl.java:1608)
> at
> org.hibernate.jpa.internal.EntityManagerImpl$CallbackExcepti
> onMapperImpl.mapManagedFlushFailure(EntityManagerImpl.java:235)
> at
> org.hibernate.internal.SessionImpl.flushBeforeTransactionCom
> pletion(SessionImpl.java:3163)
> at
> org.hibernate.internal.SessionImpl.beforeTransactionCompleti
> on(SessionImpl.java:2352)
> at
> org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.befor
> eTransactionCompletion(JdbcCoordinatorImpl.java:491)
> at
> org.hibernate.resource.transaction.backend.jta.internal.JtaT
> ransactionCoordinatorImpl.beforeCompletion(JtaTransactionCoo
> rdinatorImpl.java:316)
> at
> org.hibernate.resource.transaction.backend.jta.internal.
> synchronization.SynchronizationCallbackCoordinatorNonTrackin
> gImpl.beforeCompletion(SynchronizationCallbackCoordinatorNon
> TrackingImpl.java:47)
> at
> org.hibernate.resource.transaction.backend.jta.internal.
> synchronization.RegisteredSynchronization.beforeCompletion(R
> egisteredSynchronization.java:37)
> at
> org.wildfly.transaction.client.AbstractTransaction.performCo
> nsumer(AbstractTransaction.java:209)
> at
> org.wildfly.transaction.client.AbstractTransaction.performCo
> nsumer(AbstractTransaction.java:220)
> at
> org.wildfly.transaction.client.AbstractTransaction$Associati
> ngSynchronization.beforeCompletion(AbstractTransaction.java:265)
> at
> com.arjuna.ats.internal.jta.resources.arjunacore.Synchroniza
> tionImple.beforeCompletion(SynchronizationImple.java:76)
> at
> com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.before
> Completion(TwoPhaseCoordinator.java:368)
> at
> com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(Tw
> oPhaseCoordinator.java:91)
> at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:
> 162)
> at
> com.arjuna.ats.internal.jta.transaction.arjunacore.Transacti
> onImple.commitAndDisassociate(TransactionImple.java:1289)
> at
> com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTrans
> action.commit(BaseTransaction.java:126)
> at
> com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.
> commit(BaseTransactionManagerDelegate.java:89)
> at
> org.wildfly.transaction.client.LocalTransaction.commitAndDis
> sociate(LocalTransaction.java:73)
> at
> org.wildfly.transaction.client.ContextTransactionManager.com
> mit(ContextTransactionManager.java:71)
> at
> org.keycloak.transaction.JtaTransactionWrapper.commit(JtaTra
> nsactionWrapper.java:92)
> at
> org.keycloak.services.DefaultKeycloakTransactionManager.
> commit(DefaultKeycloakTransactionManager.java:136)
> at
> org.keycloak.services.filters.KeycloakTransactionCommitter.f
> ilter(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.Transacti
> onImple.commitAndDisassociate(TransactionImple.java:1289)
> at
> com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTrans
> action.commit(BaseTransaction.java:126)
> at
> com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.
> commit(BaseTransactionManagerDelegate.java:89)
> at
> org.wildfly.transaction.client.LocalTransaction.commitAndDis
> sociate(LocalTransaction.java:73)
> at
> org.wildfly.transaction.client.ContextTransactionManager.com
> mit(ContextTransactionManager.java:71)
> at
> org.keycloak.transaction.JtaTransactionWrapper.commit(JtaTra
> nsactionWrapper.java:92)
> at
> org.keycloak.services.DefaultKeycloakTransactionManager.
> commit(DefaultKeycloakTransactionManager.java:136)
> at
> org.keycloak.services.filters.KeycloakTransactionCommitter.f
> ilter(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.StandardSQLExceptionConvert
> er.convert(StandardSQLExceptionConverter.java:42)
> at
> org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(Sql
> ExceptionHelper.java:111)
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$Sta
> tementPreparationTemplate.prepareStatement(StatementPreparer
> Impl.java:182)
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl.pre
> pareStatement(StatementPreparerImpl.java:78)
> at
> org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.b
> uildBatchStatement(AbstractBatchImpl.java:136)
> at
> org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.g
> etBatchStatement(AbstractBatchImpl.java:125)
> at
> org.hibernate.persister.entity.AbstractEntityPersister.inser
> t(AbstractEntityPersister.java:2980)
> at
> org.hibernate.persister.entity.AbstractEntityPersister.inser
> t(AbstractEntityPersister.java:3499)
> at
> org.hibernate.action.internal.EntityInsertAction.execute(Ent
> ityInsertAction.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.p
> erformExecutions(AbstractFlushingEventListener.java:337)
> at
> org.hibernate.event.internal.DefaultFlushEventListener.onFlu
> sh(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.flushBeforeTransactionCom
> pletion(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.doP
> repareStatement(BaseWrapperManagedConnection.java:757)
> at
> org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.pre
> pareStatement(BaseWrapperManagedConnection.java:743)
> at
> org.jboss.jca.adapters.jdbc.WrappedConnection.prepareStateme
> nt(WrappedConnection.java:454)
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$1.d
> oPrepare(StatementPreparerImpl.java:87)
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$Sta
> tementPreparationTemplate.prepareStatement(StatementPreparer
> Impl.java:172)
> ... 85 more
> _______________________________________________
> keycloak-user mailing list
> keycloak-user(a)lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/keycloak-user
>
9:13 p.m.
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@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@lists.jboss.org>
[keycloak-user-bounces@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_ap...,
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.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@lists.jboss.org<mailto:keycloak-user@lists.jboss.org>
https://lists.jboss.org/mailman/listinfo/keycloak-user
8:08 a.m.
Thanks Peter. I would like to hear more if you have more findings. I will
do more testing locally as well, and report back if I find anything.
On Fri, Aug 3, 2018 at 7:13 PM, Nalyvayko, Peter <pnalyvayko(a)agi.com> wrote:
> 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> [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
6:01 p.m.
Hi Peter,
While debugging more on this issue, we noticed that there are other
exceptions like this in the logs:
[keycloak-test-6df85dc969-nr6pt] 20:13:20,661 WARN [com.arjuna.ats.arjuna]
(Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX
0:ffff646009a0:375a4efd:5b6b81d4:123b0 in state RUN
[keycloak-test-6df85dc969-nr6pt] 20:13:20,662 WARN [com.arjuna.ats.arjuna]
(Transaction Reaper Worker 1) ARJUNA012095: Abort of action id
0:ffff646009a0:375a4efd:5b6b81d4:123b0 invoked while multiple threads
active within it.
[keycloak-test-6df85dc969-nr6pt] 20:13:20,663 WARN [com.arjuna.ats.arjuna]
(Transaction Reaper Worker 1) ARJUNA012381: Action id
0:ffff646009a0:375a4efd:5b6b81d4:123b0 completed with multiple threads -
thread default task-34 was in progress with
java.net.SocketInputStream.socketRead0(Native Method)
[keycloak-test-6df85dc969-nr6pt]
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
[keycloak-test-6df85dc969-nr6pt]
java.net.SocketInputStream.read(SocketInputStream.java:171)
[keycloak-test-6df85dc969-nr6pt]
java.net.SocketInputStream.read(SocketInputStream.java:141)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:140)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:109)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:67)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.PGStream.receiveChar(PGStream.java:288)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1963)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:169)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:117)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[keycloak-test-6df85dc969-nr6pt]
java.lang.reflect.Method.invoke(Method.java:498)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.ds.PGPooledConnection$StatementHandler.invoke(PGPooledConnection.java:424)
[keycloak-test-6df85dc969-nr6pt]
com.sun.proxy.$Proxy115.executeQuery(Unknown Source)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:504)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:70)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.getResultSet(Loader.java:2122)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1905)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1881)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.doQuery(Loader.java:925)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:342)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.doList(Loader.java:2622)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.doList(Loader.java:2605)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2434)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.list(Loader.java:2429)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:501)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:371)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.internal.SessionImpl.list(SessionImpl.java:1339)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.internal.QueryImpl.list(QueryImpl.java:87)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:606)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:483)
[keycloak-test-6df85dc969-nr6pt]
com.autonomic.keycloak.federation.AuUserStorageProvider.getUsers(AuUserStorageProvider.java:196)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[keycloak-test-6df85dc969-nr6pt]
java.lang.reflect.Method.invoke(Method.java:498)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.jpa.interceptor.SFSBInvocationInterceptor.processInvocation(SFSBInvocationInterceptor.java:57)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor.processInvocation(StatefulSessionSynchronizationInterceptor.java:135)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor.processInvocation(StatefulComponentInstanceInterceptor.java:59)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:255)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:334)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:240)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:609)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81)
[keycloak-test-6df85dc969-nr6pt]
com.autonomic.keycloak.federation.AuUserStorageProvider$$$view1.getUsers(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.storage.UserStorageManager.lambda$getUsers$0(UserStorageManager.java:517)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.storage.UserStorageManager$$Lambda$1180/1899642151.query(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.storage.UserStorageManager.query(UserStorageManager.java:503)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.storage.UserStorageManager.getUsers(UserStorageManager.java:513)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.models.cache.infinispan.UserCacheSession.getUsers(UserCacheSession.java:632)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.services.resources.admin.UsersResource.getUsers(UsersResource.java:209)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[keycloak-test-6df85dc969-nr6pt]
java.lang.reflect.Method.invoke(Method.java:498)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:138)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:107)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:133)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:107)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:133)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:101)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:406)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:213)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:228)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
[keycloak-test-6df85dc969-nr6pt]
javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:90)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction$$Lambda$1015/1489808400.call(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.Connectors.executeRootHandler(Connectors.java:326)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:812)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[keycloak-test-6df85dc969-nr6pt] java.lang.Thread.run(Thread.java:748)
[keycloak-test-6df85dc969-nr6pt]
[keycloak-test-6df85dc969-nr6pt] 20:13:20,664 WARN [com.arjuna.ats.arjuna]
(Transaction Reaper Worker 1) ARJUNA012108: CheckedAction::check - atomic
action 0:ffff646009a0:375a4efd:5b6b81d4:123b0 aborting with 1 threads
active!
[keycloak-test-6df85dc969-nr6pt] 20:13:21,162 WARN [com.arjuna.ats.arjuna]
(Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX
0:ffff646009a0:375a4efd:5b6b81d4:123b0 in state CANCEL
[keycloak-test-6df85dc969-nr6pt] 20:13:21,163 WARN [com.arjuna.ats.arjuna]
(Transaction Reaper) ARJUNA012378: ReaperElement appears to be wedged:
sun.misc.Unsafe.park(Native Method)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.lock(BaseWrapperManagedConnection.java:374)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.end(XAManagedConnection.java:290)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.end(XAResourceWrapperImpl.java:118)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.doEnd(TransactionImple.java:1089)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.endAssociation(TransactionImple.java:1060)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.endAssociation(XAResourceRecord.java:1287)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:313)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3023)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3002)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1674)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:381)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)
[keycloak-test-6df85dc969-nr6pt]
[keycloak-test-6df85dc969-nr6pt] 20:13:21,663 WARN [com.arjuna.ats.arjuna]
(Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX
0:ffff646009a0:375a4efd:5b6b81d4:123b0 in state CANCEL_INTERRUPTED
[keycloak-test-6df85dc969-nr6pt] 20:13:21,663 WARN [com.arjuna.ats.arjuna]
(Transaction Reaper) ARJUNA012120: TransactionReaper::check worker
Thread[Transaction Reaper Worker 1,5,main] not responding to interrupt when
cancelling TX 0:ffff646009a0:375a4efd:5b6b81d4:123b0 -- worker marked as
zombie and TX scheduled for mark-as-rollback
Have you seen this before? What might be causing this exception?
Thanks,
Joy
On Sat, Aug 4, 2018 at 6:08 AM, Joy Kent <joy(a)autonomic.ai> wrote:
Thanks Peter. I would like to hear more if you have more findings. I
will
do more testing locally as well, and report back if I find anything.
On Fri, Aug 3, 2018 at 7:13 PM, Nalyvayko, Peter <pnalyvayko(a)agi.com>
wrote:
> > 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@a
> utonomic.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> [keycloak-user-bounces(a)lists.jboss.org<mailto:
> keycloak-user-bounces(a)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</b
> ackground-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</b
> ackground-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(Abst
> ractEntityManagerImpl.java:1692)
> at
> org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(Abst
> ractEntityManagerImpl.java:1602)
> at
> org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(Abst
> ractEntityManagerImpl.java:1608)
> at
> org.hibernate.jpa.internal.EntityManagerImpl$CallbackExcepti
> onMapperImpl.mapManagedFlushFailure(EntityManagerImpl.java:235)
> at
> org.hibernate.internal.SessionImpl.flushBeforeTransactionCom
> pletion(SessionImpl.java:3163)
> at
> org.hibernate.internal.SessionImpl.beforeTransactionCompleti
> on(SessionImpl.java:2352)
> at
> org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.befor
> eTransactionCompletion(JdbcCoordinatorImpl.java:491)
> at
> org.hibernate.resource.transaction.backend.jta.internal.JtaT
> ransactionCoordinatorImpl.beforeCompletion(JtaTransactionCoo
> rdinatorImpl.java:316)
> at
> org.hibernate.resource.transaction.backend.jta.internal.
> synchronization.SynchronizationCallbackCoordinatorNonTrackin
> gImpl.beforeCompletion(SynchronizationCallbackCoordinatorNon
> TrackingImpl.java:47)
> at
> org.hibernate.resource.transaction.backend.jta.internal.
> synchronization.RegisteredSynchronization.beforeCompletion(R
> egisteredSynchronization.java:37)
> at
> org.wildfly.transaction.client.AbstractTransaction.performCo
> nsumer(AbstractTransaction.java:209)
> at
> org.wildfly.transaction.client.AbstractTransaction.performCo
> nsumer(AbstractTransaction.java:220)
> at
> org.wildfly.transaction.client.AbstractTransaction$Associati
> ngSynchronization.beforeCompletion(AbstractTransaction.java:265)
> at
> com.arjuna.ats.internal.jta.re<http://com.arjuna.ats.internal.jta.re>
> sources.arjunacore.SynchronizationImple.beforeCompl
> etion(SynchronizationImple.java:76)
> at
> com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.before
> Completion(TwoPhaseCoordinator.java:368)
> at
> com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(Tw
> oPhaseCoordinator.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.commitAndDisa
> ssociate(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.commitAndDis
> sociate(LocalTransaction.java:73)
> at
> org.wildfly.transaction.client.ContextTransactionManager.com
> mit(ContextTransactionManager.java:71)
> at
> org.keycloak.transaction.JtaTransactionWrapper.commit(JtaTra
> nsactionWrapper.java:92)
> at
> org.keycloak.services.DefaultKeycloakTransactionManager.
> commit(DefaultKeycloakTransactionManager.java:136)
> at
> org.keycloak.services.filters.KeycloakTransactionCommitter.f
> ilter(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.commitAndDisa
> ssociate(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.commitAndDis
> sociate(LocalTransaction.java:73)
> at
> org.wildfly.transaction.client.ContextTransactionManager.com
> mit(ContextTransactionManager.java:71)
> at
> org.keycloak.transaction.JtaTransactionWrapper.commit(JtaTra
> nsactionWrapper.java:92)
> at
> org.keycloak.services.DefaultKeycloakTransactionManager.
> commit(DefaultKeycloakTransactionManager.java:136)
> at
> org.keycloak.services.filters.KeycloakTransactionCommitter.f
> ilter(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.StandardSQLExceptionConvert
> er.convert(StandardSQLExceptionConverter.java:42)
> at
> org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(Sql
> ExceptionHelper.java:111)
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$Sta
> tementPreparationTemplate.prepareStatement(StatementPreparer
> Impl.java:182)
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl.pre
> pareStatement(StatementPreparerImpl.java:78)
> at
> org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.b
> uildBatchStatement(AbstractBatchImpl.java:136)
> at
> org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.g
> etBatchStatement(AbstractBatchImpl.java:125)
> at
> org.hibernate.persister.entity.AbstractEntityPersister.inser
> t(AbstractEntityPersister.java:2980)
> at
> org.hibernate.persister.entity.AbstractEntityPersister.inser
> t(AbstractEntityPersister.java:3499)
> at
> org.hibernate.action.internal.EntityInsertAction.execute(Ent
> ityInsertAction.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.p
> erformExecutions(AbstractFlushingEventListener.java:337)
> at
> org.hibernate.event.internal.DefaultFlushEventListener.onFlu
> sh(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.flushBeforeTransactionCom
> pletion(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(BaseW
> rapperManagedConnection.java:757)
> at
> org.jboss.jca.adapters.jdbc.Ba<http://org.jboss.jca.adapters.jdbc.Ba
> >seWrapperManagedConnection.prepareStatement(BaseWra
> pperManagedConnection.java:743)
> at
> org.jboss.jca.adapters.jdbc.WrappedConnection.prepareStateme
> nt(WrappedConnection.java:454)
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$1.d
> oPrepare(StatementPreparerImpl.java:87)
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$Sta
> tementPreparationTemplate.prepareStatement(StatementPreparer
> Impl.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
>
>
>
7:18 a.m.
Hi Joy,
Yes, we have seen similar errors, although we are yet to determine whether these errors
are the cause or just a symptom
________________________________________
From: Joy Kent [joy(a)autonomic.ai]
Sent: Thursday, August 9, 2018 7:01 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.
Hi Peter,
While debugging more on this issue, we noticed that there are other exceptions like this
in the logs:
[keycloak-test-6df85dc969-nr6pt] 20:13:20,661 WARN [com.arjuna.ats.arjuna] (Transaction
Reaper) ARJUNA012117: TransactionReaper::check timeout for TX
0:ffff646009a0:375a4efd:5b6b81d4:123b0 in state RUN
[keycloak-test-6df85dc969-nr6pt] 20:13:20,662 WARN [com.arjuna.ats.arjuna] (Transaction
Reaper Worker 1) ARJUNA012095: Abort of action id 0:ffff646009a0:375a4efd:5b6b81d4:123b0
invoked while multiple threads active within it.
[keycloak-test-6df85dc969-nr6pt] 20:13:20,663 WARN [com.arjuna.ats.arjuna] (Transaction
Reaper Worker 1) ARJUNA012381: Action id 0:ffff646009a0:375a4efd:5b6b81d4:123b0 completed
with multiple threads - thread default task-34 was in progress with
java.net.SocketInputStream.socketRead0(Native Method)
[keycloak-test-6df85dc969-nr6pt]
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
[keycloak-test-6df85dc969-nr6pt]
java.net.SocketInputStream.read(SocketInputStream.java:171)
[keycloak-test-6df85dc969-nr6pt]
java.net.SocketInputStream.read(SocketInputStream.java:141)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:140)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:109)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:67)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.PGStream.receiveChar(PGStream.java:288)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1963)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:169)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:117)
[keycloak-test-6df85dc969-nr6pt] sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[keycloak-test-6df85dc969-nr6pt] java.lang.reflect.Method.invoke(Method.java:498)
[keycloak-test-6df85dc969-nr6pt]
org.postgresql.ds.PGPooledConnection$StatementHandler.invoke(PGPooledConnection.java:424)
[keycloak-test-6df85dc969-nr6pt] com.sun.proxy.$Proxy115.executeQuery(Unknown Source)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:504)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:70)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.getResultSet(Loader.java:2122)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1905)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1881)
[keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.doQuery(Loader.java:925)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:342)
[keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.doList(Loader.java:2622)
[keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.doList(Loader.java:2605)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2434)
[keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.list(Loader.java:2429)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:501)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:371)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.internal.SessionImpl.list(SessionImpl.java:1339)
[keycloak-test-6df85dc969-nr6pt] org.hibernate.internal.QueryImpl.list(QueryImpl.java:87)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:606)
[keycloak-test-6df85dc969-nr6pt]
org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:483)
[keycloak-test-6df85dc969-nr6pt]
com.autonomic.keycloak.federation.AuUserStorageProvider.getUsers(AuUserStorageProvider.java:196)
[keycloak-test-6df85dc969-nr6pt] sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[keycloak-test-6df85dc969-nr6pt] java.lang.reflect.Method.invoke(Method.java:498)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.jpa.interceptor.SFSBInvocationInterceptor.processInvocation(SFSBInvocationInterceptor.java:57)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor.processInvocation(StatefulSessionSynchronizationInterceptor.java:135)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor.processInvocation(StatefulComponentInstanceInterceptor.java:59)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:255)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:334)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:240)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:609)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81)
[keycloak-test-6df85dc969-nr6pt]
com.autonomic.keycloak.federation.AuUserStorageProvider$$$view1.getUsers(Unknown Source)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.storage.UserStorageManager.lambda$getUsers$0(UserStorageManager.java:517)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.storage.UserStorageManager$$Lambda$1180/1899642151.query(Unknown Source)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.storage.UserStorageManager.query(UserStorageManager.java:503)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.storage.UserStorageManager.getUsers(UserStorageManager.java:513)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.models.cache.infinispan.UserCacheSession.getUsers(UserCacheSession.java:632)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.services.resources.admin.UsersResource.getUsers(UsersResource.java:209)
[keycloak-test-6df85dc969-nr6pt] sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[keycloak-test-6df85dc969-nr6pt]
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[keycloak-test-6df85dc969-nr6pt] java.lang.reflect.Method.invoke(Method.java:498)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:138)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:107)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:133)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:107)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:133)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:101)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:406)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:213)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:228)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
[keycloak-test-6df85dc969-nr6pt]
javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
[keycloak-test-6df85dc969-nr6pt]
org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:90)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction$$Lambda$1015/1489808400.call(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
[keycloak-test-6df85dc969-nr6pt]
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown
Source)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.Connectors.executeRootHandler(Connectors.java:326)
[keycloak-test-6df85dc969-nr6pt]
io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:812)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[keycloak-test-6df85dc969-nr6pt] java.lang.Thread.run(Thread.java:748)
[keycloak-test-6df85dc969-nr6pt]
[keycloak-test-6df85dc969-nr6pt] 20:13:20,664 WARN [com.arjuna.ats.arjuna] (Transaction
Reaper Worker 1) ARJUNA012108: CheckedAction::check - atomic action
0:ffff646009a0:375a4efd:5b6b81d4:123b0 aborting with 1 threads active!
[keycloak-test-6df85dc969-nr6pt] 20:13:21,162 WARN [com.arjuna.ats.arjuna] (Transaction
Reaper) ARJUNA012117: TransactionReaper::check timeout for TX
0:ffff646009a0:375a4efd:5b6b81d4:123b0 in state CANCEL
[keycloak-test-6df85dc969-nr6pt] 20:13:21,163 WARN [com.arjuna.ats.arjuna] (Transaction
Reaper) ARJUNA012378: ReaperElement appears to be wedged: sun.misc.Unsafe.park(Native
Method)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
[keycloak-test-6df85dc969-nr6pt]
java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.lock(BaseWrapperManagedConnection.java:374)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.end(XAManagedConnection.java:290)
[keycloak-test-6df85dc969-nr6pt]
org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.end(XAResourceWrapperImpl.java:118)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.doEnd(TransactionImple.java:1089)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.endAssociation(TransactionImple.java:1060)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.endAssociation(XAResourceRecord.java:1287)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:313)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3023)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3002)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1674)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:381)
[keycloak-test-6df85dc969-nr6pt]
com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)
[keycloak-test-6df85dc969-nr6pt]
[keycloak-test-6df85dc969-nr6pt] 20:13:21,663 WARN [com.arjuna.ats.arjuna] (Transaction
Reaper) ARJUNA012117: TransactionReaper::check timeout for TX
0:ffff646009a0:375a4efd:5b6b81d4:123b0 in state CANCEL_INTERRUPTED
[keycloak-test-6df85dc969-nr6pt] 20:13:21,663 WARN [com.arjuna.ats.arjuna] (Transaction
Reaper) ARJUNA012120: TransactionReaper::check worker Thread[Transaction Reaper Worker
1,5,main] not responding to interrupt when cancelling TX
0:ffff646009a0:375a4efd:5b6b81d4:123b0 -- worker marked as zombie and TX scheduled for
mark-as-rollback
Have you seen this before? What might be causing this exception?
Thanks,
Joy
On Sat, Aug 4, 2018 at 6:08 AM, Joy Kent
<joy@autonomic.ai<mailto:joy@autonomic.ai>> wrote:
Thanks Peter. I would like to hear more if you have more findings. I will do more testing
locally as well, and report back if I find anything.
On Fri, Aug 3, 2018 at 7:13 PM, Nalyvayko, Peter
<pnalyvayko@agi.com<mailto:pnalyvayko@agi.com>> wrote:
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@autonomic.ai<mailto:joy@autonomic.ai>]
Sent: Friday, August 3, 2018 5:41 PM
To: Nalyvayko, Peter
Cc: keycloak-user@lists.jboss.org<mailto:keycloak-user@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><mailto: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@agi.com<mailto:pnalyvayko@agi.com><mailto:pnalyvayko@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@lists.jboss.org><mailto:keycloak-user-bounces@lists.jboss.org<mailto:keycloak-user-bounces@lists.jboss.org>>
[keycloak-user-bounces@lists.jboss.org<mailto:keycloak-user-bounces@lists.jboss.org><mailto:keycloak-user-bounces@lists.jboss.org<mailto:keycloak-user-bounces@lists.jboss.org>>]
on behalf of Joy Kent
[joy@autonomic.ai<mailto:joy@autonomic.ai><mailto: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><mailto: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_ap...,
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.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><http://com.arjuna.ats.internal.jta.re>sources.arjunacore.Sy<http://sources.arjunacore.Sy>nchronizationImple.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><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><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><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><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><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><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><mailto:keycloak-user@lists.jboss.org<mailto:keycloak-user@lists.jboss.org>>
https://lists.jboss.org/mailman/listinfo/keycloak-user
2798
days inactive
2806
days old
7 comments
2 participants
participants (2)
-
Joy Kent -
Nalyvayko, Peter