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

Tue Dec 19 05:35:18 EST 2017

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.SecurityContextAssociationHandler.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.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)
2017-12-19T07:13:34.116246771Z at
io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.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.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
2017-12-19T07:13:34.116271871Z at
io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
2017-12-19T07:13:34.116278071Z at
io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.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.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 2017_12_19_RD00155D53AAF1_docker.log
Type: application/octet-stream
Size: 1897683 bytes
Desc: not available
Url : http://lists.jboss.org/pipermail/keycloak-user/attachments/20171219/c321e6bb/attachment-0001.obj 