Uploaded image for project: 'Keycloak'
  1. Keycloak
  2. KEYCLOAK-4976

AbstractUserAdapterFederatedStorage.setSingleAttribute(,) causing deadlocks on MSSQL

    XMLWordPrintable

    Details

    • Security Sensitive Issue:
      This issue is security relevant
    • Steps to Reproduce:
      Hide

      Create a user storage provider that represents each user as a subclass of AbstractUserAdapterFederatedStorage. Within the constructor of the subclass of AbstractUserAdapterFederatedStorage, after calling the super constructor and setting the value to be returned by getId(), call setSingleAttribute(name, value). Setup Keycloak to use MSSQL as its backend and to use your custom user storage provider when logging in. Setup 40 VMs or services on a separate server; these services will post valid login credentials to the Keycloak login page while attempting to access <Keycloak FQDN>\auth\realms\<realm>\account, all starting at the same time and repeating as soon as they can either get back a failed login response or get into the resource and log off successfully. Let the tests run for a while, then stop them. The Keycloak server should now either return a login page that hangs when being submitted (i.e. a deadlock condition) or return either a 404 or 500 (i.e. an out-of-memory condition).

      Show
      Create a user storage provider that represents each user as a subclass of AbstractUserAdapterFederatedStorage. Within the constructor of the subclass of AbstractUserAdapterFederatedStorage, after calling the super constructor and setting the value to be returned by getId(), call setSingleAttribute(name, value). Setup Keycloak to use MSSQL as its backend and to use your custom user storage provider when logging in. Setup 40 VMs or services on a separate server; these services will post valid login credentials to the Keycloak login page while attempting to access <Keycloak FQDN>\auth\realms\<realm>\account, all starting at the same time and repeating as soon as they can either get back a failed login response or get into the resource and log off successfully. Let the tests run for a while, then stop them. The Keycloak server should now either return a login page that hangs when being submitted (i.e. a deadlock condition) or return either a 404 or 500 (i.e. an out-of-memory condition).
    • Docs QE Status:
      NEW
    • QE Status:
      NEW

      Description

      I have developed a federated user storage authenticator for Keycloak. Upon each login we set/update at least one federated attribute on the user using AbstractUserAdapterFederatedStorage.setSingleAttribute(String name, String value). During load testing, though, Keycloak starts running into deadlock issues that look to be caused by this method. The error logged is:

      2017-05-24 05:15:01,376 WARN [org.keycloak.services] (default task-7) KC-SERVICES0013: Failed authentication: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
      at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1692)
      at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1602)
      at org.hibernate.jpa.spi.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1700)
      at org.hibernate.jpa.spi.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:70)
      at org.keycloak.storage.jpa.JpaUserFederatedStorageProvider.deleteAttribute(JpaUserFederatedStorageProvider.java:112)
      at org.keycloak.storage.jpa.JpaUserFederatedStorageProvider.setSingleAttribute(JpaUserFederatedStorageProvider.java:129)
      at org.keycloak.storage.adapter.AbstractUserAdapterFederatedStorage.setSingleAttribute(AbstractUserAdapterFederatedStorage.java:341)
      ...
      Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
      at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:123)
      at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
      at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109)
      at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:95)
      at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:207)
      at org.hibernate.hql.internal.ast.exec.BasicExecutor.doExecute(BasicExecutor.java:91)
      at org.hibernate.hql.internal.ast.exec.BasicExecutor.execute(BasicExecutor.java:60)
      at org.hibernate.hql.internal.ast.exec.DeleteExecutor.execute(DeleteExecutor.java:111)
      at org.hibernate.hql.internal.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:429)
      at org.hibernate.engine.query.spi.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:374)
      at org.hibernate.internal.SessionImpl.executeUpdate(SessionImpl.java:1348)
      at org.hibernate.internal.QueryImpl.executeUpdate(QueryImpl.java:102)
      at org.hibernate.jpa.internal.QueryImpl.internalExecuteUpdate(QueryImpl.java:405)
      at org.hibernate.jpa.spi.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:61)
      ... 65 more
      Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 111) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
      at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:217)
      at com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult(SQLServerStatement.java:1655)
      at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(SQLServerPreparedStatement.java:440)
      at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:385)
      at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7505)
      at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:2445)
      at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:191)
      at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:166)
      at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeUpdate(SQLServerPreparedStatement.java:328)
      at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:537)
      at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:204)
      ... 74 more

      Eventually, none of the deadlocks are released and the JVM crashes due to an out-of-memory error.

      The tests are being run from 40 VMs that hit the server simultaneously each executing separate login tests. Each server using it's own set of test accounts, so no two servers log in as the same user, but a server may log in multiple times as the same user through its testing cycle.

      Keycloak is hosted in Azure, and the latest version of the following driver is used to connect with Azure MSSQL:
      <driver name="sqlserver" module="com.microsoft">
      <driver-class>com.microsoft.sqlserver.jdbc.SQLServerDriver</driver-class>
      <xa-datasource-class>com.microsoft.sqlserver.jdbc.SQLServerXADataSource</xa-datasource-class>
      </driver>

      My guess is that two login processes are attempting to update a user's federated property at almost the same time and deadlock with eachother, or the lock from the first update isn't released until a little while after the user successfully logs in.

      Despite the deadlock, the greater issue is that deadlocked threads do not seem to get recycled, even after the login process has failed from the client's perspective.

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  hmlnarik Hynek Mlnařík
                  Reporter:
                  dlustig David Lustig
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  6 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: