Re: [keycloak-dev] Deadlocks on /realms/{realm-name}/protocol/openid-connect/token

On Jul 6, 2015, at 10:58 AM, Bill Burke <bburke(a)redhat.com&gt; 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(a)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(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/keycloak-dev