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

Tue Jan 2 04:52:20 EST 2018

There are issues with SQL server, tracked in
https://issues.jboss.org/browse/KEYCLOAK-4966

On Tue, Dec 19, 2017 at 11:35 AM, Buddhi Iroshana <gbidsilva at gmail.com>
wrote:

> 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 at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/keycloak-user
>

-- 

--Hynek