[keycloak-dev] Deadlocks on /realms/{realm-name}/protocol/openid-connect/token
Scott Rossillo
srossillo at smartling.com
Mon Jul 6 12:47:08 EDT 2015
So,
It would seem the cause is the ClearExpiredUserSessions scheduled task which is executing the named query, “removeUserSessionByExpired”:
delete from UserSessionEntity s where s.realmId = :realmId and (s.started < :maxTime or s.lastSessionRefresh < :idleTime)
This is doing a table scan, causing locks on the USER_SESSION table's primary key.
Based on the stock keycloak-server.json, it seems to be done every 15 minutes. Further complicating things is that scheduled tasks are going to run on every Keycloak server in a given environment, so if you have 3 servers, each will try to execute this cleanup at 15 minute intervals from its startup.
~ Scott
> On Jul 6, 2015, at 11:10 AM, Bill Burke <bburke at redhat.com> wrote:
>
> Ugh, then there are a ton of inserts/updates happening to the same few tables.
>
> On 7/6/2015 11:03 AM, Scott Rossillo wrote:
>>
>> Yes, using JPA user session storage.
>>
>> May have to add some code to get a better stack trace.
>>
>>
>>
>>> On Jul 6, 2015, at 10:58 AM, Bill Burke <bburke at redhat.com> wrote:
>>>
>>> Are you using JPA user session storage? Everything but session data
>>> should be read-only unless some write operation snuck in
>>>
>>> Stack trace doesn't really help :(
>>>
>>> On 7/6/2015 10:42 AM, Scott Rossillo wrote:
>>>> Hi,
>>>>
>>>> We’re seeing MySQL deadlocks on requests to /realms/{realm-name}/protocol/openid-connect/token ranging from 8 to > 40 per day causing internal server errors. The thrown exception doesn’t really give enough information on what caused the deadlock.
>>>>
>>>> This is on 1.2.0. Any thoughts? Stack below.
>>>>
>>>> 2015-07-06 08:46:01,599 [ERROR] [default task-1] (LoggingExceptionHandler.java:handleThrowable:80) UT005023: Exception handling request to /auth/realms/xyz/protocol/openid-connect/token: java.lang.RuntimeException: request path: /auth/realms/xyz/protocol/openid-connect/token
>>>> at org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:54)
>>>> at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:60) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:132) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:85) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:61) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
>>>> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:56) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:45) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:63) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:58) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:70) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.security.handlers.SecurityInitialHandler.handleRequest(SecurityInitialHandler.java:76) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>> at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
>>>> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:261) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:247) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:76) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:166) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.server.Connectors.executeRootHandler(Connectors.java:197) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>> at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:759) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_79]
>>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_79]
>>>> at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_79]
>>>> Caused by: org.keycloak.models.ModelException: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
>>>> at org.keycloak.connections.jpa.PersistenceExceptionConverter.convert(PersistenceExceptionConverter.java:44) [keycloak-connections-jpa-1.2.Final.jar:1.2.0.Final]
>>>> at org.keycloak.connections.jpa.JpaKeycloakTransaction.commit(JpaKeycloakTransaction.java:30) [keycloak-connections-jpa-1.2.Final.jar:1.2.0.Final]
>>>> at org.keycloak.services.DefaultKeycloakTransactionManager.commit(DefaultKeycloakTransactionManager.java:55) [keycloak-services-1.2.Final.jar:1.2.0.Final]
>>>> at org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:43) [keycloak-services-1.2.Final.jar:1.2.0.Final]
>>>> ... 28 more
>>>> Caused by: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
>>>> at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:82) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.keycloak.connections.jpa.JpaKeycloakTransaction.commit(JpaKeycloakTransaction.java:28) [keycloak-connections-jpa-1.2.Final.jar:1.2.0.Final]
>>>> ... 30 more
>>>> Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
>>>> at org.hibernate.dialect.MySQLDialect$1.convert(MySQLDialect.java:451) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:211) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:62) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3281) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3183) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3525) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:159) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1222) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:425) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.beforeTransactionCommit(JdbcTransaction.java:101) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:177) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:77) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
>>>> ... 31 more
>>>> Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
>>>> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_79]
>>>> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_79]
>>>> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_79]
>>>> at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_79]
>>>> at com.mysql.jdbc.Util.handleNewInstance(Util.java:389)
>>>> at com.mysql.jdbc.Util.getInstance(Util.java:372)
>>>> at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987)
>>>> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3835)
>>>> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3771)
>>>> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2435)
>>>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2582)
>>>> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2535)
>>>> at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1911)
>>>> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2145)
>>>> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2081)
>>>> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2066)
>>>> at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:493)
>>>> at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:208) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>> ... 45 more
>>>> _______________________________________________
>>>> keycloak-dev mailing list
>>>> keycloak-dev at lists.jboss.org
>>>> https://lists.jboss.org/mailman/listinfo/keycloak-dev
>>>>
>>>
>>> --
>>> Bill Burke
>>> JBoss, a division of Red Hat
>>> http://bill.burkecentral.com
>>> _______________________________________________
>>> keycloak-dev mailing list
>>> keycloak-dev at lists.jboss.org
>>> https://lists.jboss.org/mailman/listinfo/keycloak-dev
>>
>
> --
> Bill Burke
> JBoss, a division of Red Hat
> http://bill.burkecentral.com
More information about the keycloak-dev
mailing list