Uploaded image for project: 'Ranger'
  1. Ranger
  2. RANGER-3681

Ranger Database deadlock when createPolicy is running parallel

Attach filesAttach ScreenshotVotersWatch issueWatchersCreate sub-taskLinkCloneUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Fixed
    • 2.1.0
    • 3.0.0, 2.3.0
    • admin
    • None
    • ranger-version: 2.1.0
      mysql-verison: 5.7.34-log
      mysql-engine: InnoDB
      mysql-isolation-level: REPEATABLE-READ

    Description

      Error

      ranger-log:

      2022-03-21 20:14:29,685 [http-bio-6080-exec-13] ERROR org.apache.ranger.rest.ServiceREST (ServiceREST.java:1709) - createPolicy(RangerPolicy={id={null} guid={null} isEnabled={true} createdBy={null} updatedBy={null} createTime={null} updateTime={null} version={1} service={default-Hive} name={dcp-desensitize_a162c40cdc0140b1848b98415575be6c-1647864869626} policyType={0} policyPriority={0} description={} resourceSignature={4f15e3de95c81650ad869cb93a8c47a132bbec54bdf5de8c01f5075c19754cd7} isAuditEnabled={true} serviceType={null} resources={database={RangerPolicyResource={values={dcp } isExcludes={false} isRecursive={false} }} column={RangerPolicyResource={values={* } isExcludes={false} isRecursive={false} }} table={RangerPolicyResource={values={desensitize_a162c40cdc0140b1848b98415575be6c } isExcludes={false} isRecursive={false} }} } policyLabels={Consoler } policyConditions={} policyItems={RangerPolicyItem={accessTypes={RangerPolicyItemAccess={type={all} isAllowed={true} }} users={tangbiao2 } groups={} roles={} conditions={} delegateAdmin={false} }} denyPolicyItems={} allowExceptions={} denyExceptions={} dataMaskPolicyItems={} rowFilterPolicyItems={} options={} validitySchedules={, zoneName=null, isDenyAllElse={false} }}) failed
      javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.5.2.v20140319-9ad6abd): org.eclipse.persistence.exceptions.DatabaseException
      Internal Exception: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
      Error Code: 1213
      Call: INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (?, ?, ?, ?, ?, ?, ?)
              bind => [7 parameters bound]
      Query: ValueReadQuery(name="x_policy_ref_resource_SEQ" sql="SELECT LAST_INSERT_ID()")
              at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:868)
              at sun.reflect.GeneratedMethodAccessor98.invoke(Unknown Source)
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
              at java.lang.reflect.Method.invoke(Method.java:498)
              at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:301)
              at com.sun.proxy.$Proxy30.flush(Unknown Source)
              at org.apache.ranger.common.db.BaseDao.batchCreate(BaseDao.java:102)
              ...

      mysql-deadlock:

      ------------------------
      LATEST DETECTED DEADLOCK
      ------------------------
      2022-03-21 09:47:22 0x7ff3a4859700
      *** (1) TRANSACTION:
      TRANSACTION 7036760, ACTIVE 0 sec inserting
      mysql tables in use 1, locked 1
      LOCK WAIT 23 lock struct(s), heap size 1136, 12 row lock(s), undo log entries 2
      MySQL thread id 27293, OS thread handle 140684415063808, query id 383930 192.168.0.76 DHCloudBG update
      INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (1, '2022-03-20 12:47:22.666', 13921, 5, 'database', '2022-03-20 12:47:22.681', 1)
      *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
      RECORD LOCKS space id 531 page no 4 n bits 376 index x_policy_ref_res_UK_polId_resDefId of table `ranger`.`x_policy_ref_resource` trx id 7036760 lock_mode X insert intention waiting
      Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
       0: len 8; hex 73757072656d756d; asc supremum;;
      *** (2) TRANSACTION:
      TRANSACTION 7036759, ACTIVE 0 sec inserting
      mysql tables in use 1, locked 1
      23 lock struct(s), heap size 1136, 12 row lock(s), undo log entries 2
      MySQL thread id 27295, OS thread handle 140684413998848, query id 383932 192.168.0.76 DHCloudBG update
      INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (1, '2022-03-20 12:47:22.666', 13920, 5, 'database', '2022-03-20 12:47:22.682', 1)
      *** (2) HOLDS THE LOCK(S):
      RECORD LOCKS space id 531 page no 4 n bits 376 index x_policy_ref_res_UK_polId_resDefId of table `ranger`.`x_policy_ref_resource` trx id 7036759 lock_mode X
      Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
       0: len 8; hex 73757072656d756d; asc supremum;;
      *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
      RECORD LOCKS space id 531 page no 4 n bits 376 index x_policy_ref_res_UK_polId_resDefId of table `ranger`.`x_policy_ref_resource` trx id 7036759 lock_mode X insert intention waiting
      Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
       0: len 8; hex 73757072656d756d; asc supremum;;*** WE ROLL BACK TRANSACTION (2)

      Description

      In our production environment, we may create ranger hive policy in parallel. In this case it will occasionally report deadlock errors. I turned on the general_log in mysql, and captured the sql when the deadlock exception occurred, as shown below (some sql was simplified, and only the sql that caused the deadlock was kept):

      2022-03-21T20:16:26.776033+08:00    239903 Query    DELETE FROM x_policy_ref_resource WHERE (policy_id = 16032)
      2022-03-21T20:16:26.776463+08:00    239902 Query    DELETE FROM x_policy_ref_resource WHERE (policy_id = 16033)
      2022-03-21T20:16:26.784333+08:00    239903 Query    INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (1, '2022-03-20 23:16:26.766', 16032, 5, 'database', '2022-03-20 23:16:26.783', 1)
      2022-03-21T20:16:26.785484+08:00    239902 Query    INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (1, '2022-03-20 23:16:26.767', 16033, 5, 'database', '2022-03-20 23:16:26.784', 1)
      2022-03-21T20:16:26.787844+08:00    239903 Query    INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (1, '2022-03-20 23:16:26.766', 16032, 8, 'column', '2022-03-20 23:16:26.786', 1)
      2022-03-21T20:16:26.788728+08:00    239903 Query    INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (1, '2022-03-20 23:16:26.766', 16032, 6, 'table', '2022-03-20 23:16:26.787', 1)
      2022-03-21T20:16:26.810405+08:00    239902 Query    rollback
      2022-03-21T20:16:26.810781+08:00    239902 Query    SET autocommit=1
      2022-03-21T20:16:26.831309+08:00    239903 Query    commit

      I exported the data in the x_policy_ref_resource table using mysqldump and simulated it in the local environment and found that there is a deadlock when the sql of the two transactions is executed as following order:

      transation1 transation2
      begin begin
      DELETE FROM x_policy_ref_resource WHERE (policy_id = 16032);  
        DELETE FROM x_policy_ref_resource WHERE (policy_id = 16033);
      INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (1, '2022-03-20 23:16:26.766', 16032, 5, 'database', '2022-03-20 23:16:26.783', 1);  
        INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (1, '2022-03-20 23:16:26.767', 16033, 5, 'database', '2022-03-20 23:16:26.784', 1);
      1. When transaction1 and transaction2 execute delete sql, they will both obtain gap lock, because gap locks are compatible.
      2. Then transaction 1 executes insert sql, it will try to acquire the insert intention lock, which conflicts with the gap lock held by transaction 2, and enters the lock waiting state.
      3. Finally, transaction2 executes insert sql, and also tries to acquire the insert intention lock, which conflicts with the gap lock held by transaction1. At this point, it is caught in a cycle where transaction1 waits for transaction 2 to release the gap lock, and transaction2 waits for transaction1 to release the gap lock. Two transactions waiting for each other to release locks eventually lead to a deadlock.

       

      Attachments

        Activity

          This comment will be Viewable by All Users Viewable by All Users
          Cancel

          People

            Xuze Yang Xuze Yang
            Xuze Yang Xuze Yang
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Slack

                Issue deployment