Re: [keycloak-user] Deadlock Encountered while Trying Keycloak with Azure SQL

HI Team, I am running the community version of Keycloak (version - 2.3.0.Final). I am using Azure SQL : https://azure.microsoft.com/ en-us/services/sql-database as the database server for this keycloak instance. Keycloak instance is deployed in Azure VM in this scenario. Keycloak started successfully without any issues with Azure SQL database. I have a JMeter script which is invoking following two Keycloak's RESTFul endpoints with 10 parallel threads (can consider it as 10 different clients). 1. POST auth/admin/realms/iotpdev/users - User creation 2. PUT auth/admin/realms/iotpdev/users/<USERID>/groups/ - Adding users to a group Behaviour: During the first few invocations, above two endpoints got executed successfully without any issue. But, after sometime, keycloak was logging some database deadlock exceptions in the log file. Stacktrace for this exception is as follows, --------------------------------- 2017-12-19T07:13:34.084336783Z [0m [33m07:13:34,079 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-15) SQL Error: 1205, SQLState: 40001 2017-12-19T07:13:34.084377183Z [0m [31m07:13:34,080 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-15) Transaction (Process ID 123) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction. 2017-12-19T07:13:34.116059274Z [0m [31m07:13:34,097 ERROR [io.undertow.request] (default task-15) UT005023: Exception handling request to /auth/admin/realms/iotpdev/users: org.jboss.resteasy.spi.UnhandledException: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement 2017-12-19T07:13:34.116097074Z at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException( ExceptionHandler.java:76) 2017-12-19T07:13:34.116104774Z at org.jboss.resteasy.core.ExceptionHandler.handleException( ExceptionHandler.java:212) 2017-12-19T07:13:34.116111874Z at org.jboss.resteasy.core.SynchronousDispatcher.writeException( SynchronousDispatcher.java:168) 2017-12-19T07:13:34.116118574Z at org.jboss.resteasy.core.SynchronousDispatcher.invoke( SynchronousDispatcher.java:411) 2017-12-19T07:13:34.116124973Z at org.jboss.resteasy.core.SynchronousDispatcher.invoke( SynchronousDispatcher.java:202) 2017-12-19T07:13:34.116131373Z at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher. service(ServletContainerDispatcher.java:221) 2017-12-19T07:13:34.116137873Z at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service( HttpServletDispatcher.java:56) 2017-12-19T07:13:34.116144673Z at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service( HttpServletDispatcher.java:51) 2017-12-19T07:13:34.116151173Z at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) 2017-12-19T07:13:34.116157473Z at io.undertow.servlet.handlers.ServletHandler.handleRequest( ServletHandler.java:85) 2017-12-19T07:13:34.116163773Z at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl. doFilter(FilterHandler.java:129) 2017-12-19T07:13:34.116170273Z at org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter( KeycloakSessionServletFilter.java:90) 2017-12-19T07:13:34.116176673Z at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:60) 2017-12-19T07:13:34.116183072Z at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl. doFilter(FilterHandler.java:131) 2017-12-19T07:13:34.116189472Z at io.undertow.servlet.handlers.FilterHandler.handleRequest( FilterHandler.java:84) 2017-12-19T07:13:34.116195872Z at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler. handleRequest(ServletSecurityRoleHandler.java:62) 2017-12-19T07:13:34.116202272Z at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest( ServletDispatchingHandler.java:36) 2017-12-19T07:13:34.116210672Z at org.wildfly.extension.undertow.security.SecurityContextAssociationHand ler.handleRequest(SecurityContextAssociationHandler.java:78) 2017-12-19T07:13:34.116233672Z at io.undertow.server.handlers.PredicateHandler.handleRequest( PredicateHandler.java:43) 2017-12-19T07:13:34.116240472Z at io.undertow.servlet.handlers.security.SSLInformationAssociationHandl er.handleRequest(SSLInformationAssociationHandler.java:131) 2017-12-19T07:13:34.116246771Z at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandl er.handleRequest(ServletAuthenticationCallHandler.java:57) 2017-12-19T07:13:34.116253171Z at io.undertow.server.handlers.PredicateHandler.handleRequest( PredicateHandler.java:43) 2017-12-19T07:13:34.116259271Z at io.undertow.security.handlers.AbstractConfidentialityHandler .handleRequest(AbstractConfidentialityHandler.java:46) 2017-12-19T07:13:34.116265471Z at io.undertow.servlet.handlers.security.ServletConfidentialityConstrai ntHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64) 2017-12-19T07:13:34.116271871Z at io.undertow.security.handlers.AuthenticationMechanismsHandle r.handleRequest(AuthenticationMechanismsHandler.java:60) 2017-12-19T07:13:34.116278071Z at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHand ler.handleRequest(CachedAuthenticatedSessionHandler.java:77) 2017-12-19T07:13:34.116284371Z at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest( NotificationReceiverHandler.java:50) 2017-12-19T07:13:34.116290571Z at io.undertow.security.handlers.AbstractSecurityContextAssocia tionHandler.handleRequest(AbstractSecurityContextAssocia tionHandler.java:43) 2017-12-19T07:13:34.116296771Z at io.undertow.server.handlers.PredicateHandler.handleRequest( PredicateHandler.java:43) 2017-12-19T07:13:34.116302871Z at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler. handleRequest(JACCContextIdHandler.java:61) 2017-12-19T07:13:34.116308970Z at io.undertow.server.handlers.PredicateHandler.handleRequest( PredicateHandler.java:43) 2017-12-19T07:13:34.116315270Z at io.undertow.server.handlers.PredicateHandler.handleRequest( PredicateHandler.java:43) 2017-12-19T07:13:34.116321470Z at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest( ServletInitialHandler.java:284) 2017-12-19T07:13:34.116327670Z at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest( ServletInitialHandler.java:263) 2017-12-19T07:13:34.116333770Z at io.undertow.servlet.handlers.ServletInitialHandler.access$ 000(ServletInitialHandler.java:81) 2017-12-19T07:13:34.116339770Z at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest( ServletInitialHandler.java:174) 2017-12-19T07:13:34.116346770Z at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202) 2017-12-19T07:13:34.116352770Z at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793) 2017-12-19T07:13:34.116358770Z at java.util.concurrent.ThreadPoolExecutor.runWorker( ThreadPoolExecutor.java:1142) 2017-12-19T07:13:34.116364770Z at java.util.concurrent.ThreadPoolExecutor$Worker.run( ThreadPoolExecutor.java:617) 2017-12-19T07:13:34.116375069Z at java.lang.Thread.run(Thread.java:745) 2017-12-19T07:13:34.116384569Z Caused by: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement 2017-12-19T07:13:34.116390969Z at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert( AbstractEntityManagerImpl.java:1692) 2017-12-19T07:13:34.116397269Z at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert( AbstractEntityManagerImpl.java:1602) 2017-12-19T07:13:34.116403369Z at org.hibernate.jpa.spi.AbstractEntityManagerImpl.throwPersistenceException( AbstractEntityManagerImpl.java:1700) 2017-12-19T07:13:34.116409469Z at org.hibernate.jpa.spi.AbstractQueryImpl.executeUpdate( AbstractQueryImpl.java:70) 2017-12-19T07:13:34.116415469Z at org.keycloak.models.jpa.UserAdapter.removeAttribute(UserAdapter.java:161) 2017-12-19T07:13:34.116421469Z at org.keycloak.models.jpa.UserAdapter.setAttribute(UserAdapter.java:137) 2017-12-19T07:13:34.116427469Z at org.keycloak.services.resources.admin.UsersResource.updateUserFromRep( UsersResource.java:267) 2017-12-19T07:13:34.116433468Z at org.keycloak.services.resources.admin.UsersResource. createUser(UsersResource.java:216) 2017-12-19T07:13:34.116439568Z at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2017-12-19T07:13:34.116445468Z at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java: 62) 2017-12-19T07:13:34.116451368Z at sun.reflect.DelegatingMethodAccessorImpl.invoke( DelegatingMethodAccessorImpl.java:43) 2017-12-19T07:13:34.116457368Z at java.lang.reflect.Method.invoke(Method.java:498) 2017-12-19T07:13:34.116463168Z at org.jboss.resteasy.core.MethodInjectorImpl.invoke( MethodInjectorImpl.java:139) 2017-12-19T07:13:34.116469168Z at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget( ResourceMethodInvoker.java:295) 2017-12-19T07:13:34.116475168Z at org.jboss.resteasy.core.ResourceMethodInvoker.invoke( ResourceMethodInvoker.java:249) 2017-12-19T07:13:34.116481268Z at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject( ResourceLocatorInvoker.java:138) 2017-12-19T07:13:34.116487268Z at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke( ResourceLocatorInvoker.java:107) 2017-12-19T07:13:34.116494767Z at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject( ResourceLocatorInvoker.java:133) 2017-12-19T07:13:34.116500967Z at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke( ResourceLocatorInvoker.java:107) 2017-12-19T07:13:34.116506967Z at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject( ResourceLocatorInvoker.java:133) 2017-12-19T07:13:34.116513067Z at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke( ResourceLocatorInvoker.java:101) 2017-12-19T07:13:34.116519067Z at org.jboss.resteasy.core.SynchronousDispatcher.invoke( SynchronousDispatcher.java:395) 2017-12-19T07:13:34.116525067Z ... 37 more 2017-12-19T07:13:34.116530767Z Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement 2017-12-19T07:13:34.116541467Z at org.hibernate.exception.internal.SQLStateConversionDelegate.convert( SQLStateConversionDelegate.java:123) 2017-12-19T07:13:34.116547967Z at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert( StandardSQLExceptionConverter.java:42) 2017-12-19T07:13:34.116554067Z at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert( SqlExceptionHelper.java:109) 2017-12-19T07:13:34.116560166Z at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert( SqlExceptionHelper.java:95) 2017-12-19T07:13:34.116566166Z at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate( ResultSetReturnImpl.java:207) 2017-12-19T07:13:34.116572366Z at org.hibernate.hql.internal.ast.exec.BasicExecutor. doExecute(BasicExecutor.java:91) 2017-12-19T07:13:34.116578366Z at org.hibernate.hql.internal.ast.exec.BasicExecutor. execute(BasicExecutor.java:60) 2017-12-19T07:13:34.116584366Z at org.hibernate.hql.internal.ast.exec.DeleteExecutor. execute(DeleteExecutor.java:111) 2017-12-19T07:13:34.116590566Z at org.hibernate.hql.internal.ast.QueryTranslatorImpl.executeUpdate( QueryTranslatorImpl.java:429) 2017-12-19T07:13:34.116596666Z at org.hibernate.engine.query.spi.HQLQueryPlan.performExecuteUpdate( HQLQueryPlan.java:374) 2017-12-19T07:13:34.116602666Z at org.hibernate.internal.SessionImpl.executeUpdate(SessionImpl.java:1348) 2017-12-19T07:13:34.116608666Z at org.hibernate.internal.QueryImpl.executeUpdate(QueryImpl.java:102) 2017-12-19T07:13:34.116614666Z at org.hibernate.jpa.internal.QueryImpl.internalExecuteUpdate( QueryImpl.java:405) 2017-12-19T07:13:34.116620665Z at org.hibernate.jpa.spi.AbstractQueryImpl.executeUpdate( AbstractQueryImpl.java:61) 2017-12-19T07:13:34.116626665Z ... 55 more 2017-12-19T07:13:34.116632465Z Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 123) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction. 2017-12-19T07:13:34.124029047Z at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError( SQLServerException.java:216) 2017-12-19T07:13:34.124058646Z at com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult( SQLServerStatement.java:1515) 2017-12-19T07:13:34.124066146Z at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement. doExecutePreparedStatement(SQLServerPreparedStatement.java:404) 2017-12-19T07:13:34.124082446Z at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$ PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:350) 2017-12-19T07:13:34.124089946Z at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:5696) 2017-12-19T07:13:34.124095946Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand( SQLServerConnection.java:1715) 2017-12-19T07:13:34.124102145Z at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand( SQLServerStatement.java:180) 2017-12-19T07:13:34.124108245Z at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement( SQLServerStatement.java:155) 2017-12-19T07:13:34.124126445Z at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeUpdate( SQLServerPreparedStatement.java:314) 2017-12-19T07:13:34.124133245Z at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate( WrappedPreparedStatement.java:537) 2017-12-19T07:13:34.124139545Z at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate( ResultSetReturnImpl.java:204) 2017-12-19T07:13:34.124145745Z ... 64 more 2017-12-19T07:13:34.124151645Z ------------------------- This JMeter script will create 1000 users in 10 threads. So, above user creation and adding to group endpoints will be invoked 1000 times each with typical TPS of 1 - 2 requests per second. When we run JMeter script several times, we can create 1000 users - means, when we run JMeter in first round, it will create 300 users approximately and other 700 requests will fail due to above deadlock issue, and once we run it for the second time it will create another 200 of users and so on... (at some point, we will get all 1000 users). The dialect which I am using for this instance is : org.hibernate.dialect.SQLServer2012Dialect Is there any specific configurations to be done if we are using Azure SQL as the database ? I am attaching the complete log file herewith. Appreciate your help on this. Regards, Buddhi Iroshana De Silva _______________________________________________ keycloak-user mailing list keycloak-user(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/keycloak-user