Description
I have a User Storage SPI implementation which extends AbstractUserAdapterFederatedStorage for its UserModel implementation.I further want to manage authorization (Roles & Groups) in Keycloak.
Functionally this works fine so far.
The problem is when I access the users Groups or Role Mappings tabs, I encounter a locking exception from the Keycloak database - most of the time.
After some debugging I found that multiple threads are accessing the user simultaneously, ultimately calling
org.keycloak.storage.jpa.JpaUserFederatedStorageProvider.deleteAttribute(JpaUserFederatedStorageProvider.java:121)
causing conflicting updates.
Question
- Why are multiple threads active for what I would consider a simple lookup?
- How can I get rid of this problem?
Is there something I can change in my User Storage SPI implementation?
Appendix
Error Log - Includes some log messages from my UserModel implementation, showing parallel calls to setSingleAttribute() from three different threads (174, 179, 182)Error Log
13:19:06,958 INFO [stdout] (default task-4) 179 → create() de.dfb.keycloak.spi.userstorage.oauth.provider.impl.TmaDfbOAuthUserStorageProviderFactory@557e65c1
13:19:06,968 INFO [stdout] (default task-4) 179 → getUserById: f:0be6a6e8-cd28-405f-9702-185559f982ac:02CBPENPRG000000VS510N3HVS2RELR6
13:19:06,970 INFO [stdout] (default task-4) null
13:19:06,972 INFO [stdout] (default task-4) de.dfb.keycloak.spi.userstorage.oauth.model.User@64ca6a30
13:19:06,973 INFO [stdout] (default task-4) 179 → setSingleAttribute: firstName : null
13:19:06,989 INFO [stdout] (default task-4) 179 → setSingleAttribute: lastName : null
13:19:06,994 INFO [stdout] (default task-4) 179 → setSingleAttribute: email : full@monty.de
13:19:06,999 INFO [stdout] (default task-4) 179 → setSingleAttribute: EMAIL_VERIFIED : false
13:19:07,002 INFO [stdout] (default task-4) 179 → setSingleAttribute: ENABLED : true
13:19:07,005 INFO [stdout] (default task-4) 179 → setSingleAttribute: CREATED_TIMESTAMP : 1611836347005
13:19:07,010 INFO [stdout] (default task-4) Caching: f:0be6a6e8-cd28-405f-9702-185559f982ac:02CBPENPRG000000VS510N3HVS2RELR6
13:19:07,014 INFO [stdout] (default task-4) 179 → getUserById: f:0be6a6e8-cd28-405f-9702-185559f982ac:02CBPENPRG000000VS510N3HVS2RELR6
13:19:07,014 INFO [stdout] (default task-4) de.dfb.keycloak.spi.userstorage.oauth.provider.DfbOAuthUser@392c8dc
13:19:07,086 INFO [stdout] (default task-4) 179 → create() de.dfb.keycloak.spi.userstorage.oauth.provider.impl.TmaDfbOAuthUserStorageProviderFactory@557e65c1
13:19:07,087 INFO [stdout] (default task-4) 179 → getUserById: f:0be6a6e8-cd28-405f-9702-185559f982ac:02CBPENPRG000000VS510N3HVS2RELR6
13:19:07,088 INFO [stdout] (default task-1) 174 → create() de.dfb.keycloak.spi.userstorage.oauth.provider.impl.TmaDfbOAuthUserStorageProviderFactory@557e65c1
13:19:07,088 INFO [stdout] (default task-4) null
13:19:07,088 INFO [stdout] (default task-5) 182 → create() de.dfb.keycloak.spi.userstorage.oauth.provider.impl.TmaDfbOAuthUserStorageProviderFactory@557e65c1
13:19:07,088 INFO [stdout] (default task-4) de.dfb.keycloak.spi.userstorage.oauth.model.User@64ca6a30
13:19:07,089 INFO [stdout] (default task-1) 174 → getUserById: f:0be6a6e8-cd28-405f-9702-185559f982ac:02CBPENPRG000000VS510N3HVS2RELR6
13:19:07,097 INFO [stdout] (default task-4) 179 → setSingleAttribute: firstName : null
13:19:07,097 INFO [stdout] (default task-5) 182 → getUserById: f:0be6a6e8-cd28-405f-9702-185559f982ac:02CBPENPRG000000VS510N3HVS2RELR6
13:19:07,097 INFO [stdout] (default task-1) null
13:19:07,098 INFO [stdout] (default task-5) null
13:19:07,098 INFO [stdout] (default task-5) de.dfb.keycloak.spi.userstorage.oauth.model.User@64ca6a30
13:19:07,098 INFO [stdout] (default task-1) de.dfb.keycloak.spi.userstorage.oauth.model.User@64ca6a30
13:19:07,099 INFO [stdout] (default task-5) 182 → setSingleAttribute: firstName : null
13:19:07,100 INFO [stdout] (default task-1) 174 → setSingleAttribute: firstName : null
13:19:07,101 INFO [stdout] (default task-4) 179 → setSingleAttribute: lastName : null
13:19:07,103 INFO [stdout] (default task-4) 179 → setSingleAttribute: email : full@monty.de
13:19:07,105 INFO [stdout] (default task-4) 179 → setSingleAttribute: EMAIL_VERIFIED : false
13:19:07,108 INFO [stdout] (default task-4) 179 → setSingleAttribute: ENABLED : true
13:19:07,111 INFO [stdout] (default task-4) 179 → setSingleAttribute: CREATED_TIMESTAMP : 1611836347111
13:19:07,112 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-5) SQL Error: 1213, SQLState: 40001
13:19:07,112 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-1) SQL Error: 1213, SQLState: 40001
13:19:07,112 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-5) Deadlock found when trying to get lock; try restarting transaction
13:19:07,113 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-1) Deadlock found when trying to get lock; try restarting transaction
13:19:07,114 INFO [stdout] (default task-4) Caching: f:0be6a6e8-cd28-405f-9702-185559f982ac:02CBPENPRG000000VS510N3HVS2RELR6
13:19:07,114 ERROR [org.keycloak.services.error.KeycloakErrorHandler] (default task-5) Uncaught server error: javax.persistence.OptimisticLockException: org.hibernate.exception.LockAcquisitionException: could not execute statement
at org.hibernate.internal.ExceptionConverterImpl.wrapLockException(ExceptionConverterImpl.java:277)
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:98)
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181)
at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1594)
at org.keycloak.storage.jpa.JpaUserFederatedStorageProvider.deleteAttribute(JpaUserFederatedStorageProvider.java:121)
at org.keycloak.storage.jpa.JpaUserFederatedStorageProvider.setSingleAttribute(JpaUserFederatedStorageProvider.java:138)
at org.keycloak.storage.adapter.AbstractUserAdapterFederatedStorage.setSingleAttribute(AbstractUserAdapterFederatedStorage.java:344)
at de.dfb.keycloak.spi.userstorage.oauth.provider.DfbOAuthUser.setSingleAttribute(DfbOAuthUser.java:59)
at org.keycloak.models.UserModelDefaultMethods.setFirstName(UserModelDefaultMethods.java:33)
at de.dfb.keycloak.spi.userstorage.oauth.provider.DfbOAuthUser.(DfbOAuthUser.java:25)
at de.dfb.keycloak.spi.userstorage.oauth.provider.DfbOAuthUserStorageProvider.cacheBuildUser(DfbOAuthUserStorageProvider.java:45)
at de.dfb.keycloak.spi.userstorage.oauth.provider.DfbOAuthUserStorageProvider.getUserById(DfbOAuthUserStorageProvider.java:99)
at org.keycloak.storage.UserStorageManager.getUserById(UserStorageManager.java:388)
at org.keycloak.models.cache.infinispan.UserAdapter.getUserModel(UserAdapter.java:403)
at org.keycloak.models.cache.infinispan.DefaultLazyLoader.get(DefaultLazyLoader.java:42)
at org.keycloak.models.cache.infinispan.entities.CachedUser.getGroups(CachedUser.java:116)
at org.keycloak.models.cache.infinispan.UserAdapter.getGroups(UserAdapter.java:354)
at org.keycloak.models.UserModel.getGroups(UserModel.java:128)
at org.keycloak.models.UserModel.getGroups(UserModel.java:124)
at org.keycloak.models.utils.ModelToRepresentation.toGroupHierarchy(ModelToRepresentation.java:171)
at org.keycloak.services.resources.admin.UserResource.groupMembership(UserResource.java:882)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:138)
at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:543)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:432)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$0(ResourceMethodInvoker.java:393)
at org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:395)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:364)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:150)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:110)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:141)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:110)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:141)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:110)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:141)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:104)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:440)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:229)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:135)
at org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358)
at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:138)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:215)
at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:245)
at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:61)
at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at org.keycloak.provider.wildfly.WildFlyRequestFilter.lambda$doFilter$0(WildFlyRequestFilter.java:41)
at org.keycloak.services.filters.AbstractRequestFilter.filter(AbstractRequestFilter.java:43)
at org.keycloak.provider.wildfly.WildFlyRequestFilter.doFilter(WildFlyRequestFilter.java:39)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:132)
at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:269)
at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:78)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:133)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:130)
at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:249)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:78)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:99)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:370)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
at org.hibernate.dialect.MySQLDialect$3.convert(MySQLDialect.java:547)
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:178)
at org.hibernate.hql.internal.ast.exec.BasicExecutor.doExecute(BasicExecutor.java:100)
at org.hibernate.hql.internal.ast.exec.BasicExecutor.execute(BasicExecutor.java:59)
at org.hibernate.hql.internal.ast.exec.DeleteExecutor.execute(DeleteExecutor.java:109)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:453)
at org.hibernate.engine.query.spi.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:378)
at org.hibernate.internal.SessionImpl.executeUpdate(SessionImpl.java:1550)
at org.hibernate.query.internal.AbstractProducedQuery.doExecuteUpdate(AbstractProducedQuery.java:1603)
at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1585)
… 95 more
Caused by: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:123)
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97)
at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:953)
at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1092)
at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1040)
at com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1347)
at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdate(ClientPreparedStatement.java:1025)
at com.mysql.cj.jdbc.PreparedStatementWrapper.executeUpdate(PreparedStatementWrapper.java:595)
at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:537)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175)
… 103 more