Spring ACL - JdbcMutableAclService updateAcl prone to deadlocks

[arun1ram]

Describe the bug When 2 or more threads (or in a distributed environment - 2 or more instances) are invoking the JdbcMutableAclService#updateAcl() method concurrently, one of the threads succeeds but others fail with DeadlockLoserDataAccessException

To Reproduce

1. Setup a simple Java project with a main class
2. Setup 2 threads that invoke the following operations concurrently. I have omitted the code for setting up threads and executing multiple runs for simplicity:

import org.springframework.security.acls.domain.BasePermission;
import org.springframework.security.acls.domain.ObjectIdentityImpl;
import org.springframework.security.acls.domain.PrincipalSid;
import org.springframework.security.acls.model.*;
import org.springframework.transaction.support.TransactionTemplate;

import java.util.List;

class Demo {
    private final MutableAclService   aclService;
    private final TransactionTemplate transactionTemplate;

    Demo(MutableAclService aclService, TransactionTemplate transactionTemplate) {
        this.aclService = aclService;
        this.transactionTemplate = transactionTemplate;
    }

    public void doOperations() {
        MutableAcl acl = getMutableAcl("REPORT", 1005, new PrincipalSid("user1"));
        List<Permission> permissions = List.of(BasePermission.READ, BasePermission.WRITE);
        for (Permission permission : permissions) {
            acl.insertAce(acl.getEntries().size(), permission, new PrincipalSid("user2"), true);
        }
        updateAcl(acl);
    }

    public MutableAcl getMutableAcl(String name, int objectId, Sid sid) {
        ObjectIdentity oi = new ObjectIdentityImpl(name, objectId);
        MutableAcl acl;
        try {
            acl = (MutableAcl) aclService.readAclById(oi);
        } catch (NotFoundException nfe) {
            acl = createAcl(oi, sid);
        }
        return acl;
    }

    MutableAcl createAcl(ObjectIdentity oi, Sid sid) {
        return transactionTemplate.execute(arg0 -> {
            return aclService.createAcl(oi);
        });
    }

    public void updateAcl(final MutableAcl acl) {
        transactionTemplate.execute(arg0 -> {
            aclService.updateAcl(acl);
            return null;
        });
    }
}

Expected behavior I expect that an ACL will be created if it does not already exist and the ACL entries (corresponding to the permissions) are added successfully.

Sample The following is the stacktrace of the error for the thread that fails. (The other thread is successful):

org.springframework.dao.DeadlockLoserDataAccessException: PreparedStatementCallback; SQL [insert into acl_entry (acl_object_identity, ace_order, sid, mask, granting, audit_success, audit_failure)values (?, ?, ?, ?, ?, ?, ?)]; Deadlock found when trying to get lock; try restarting transaction; nested exception is java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction
    at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:271) ~[spring-jdbc-5.3.22.jar:5.3.22]
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:70) ~[spring-jdbc-5.3.22.jar:5.3.22]
    at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1541) ~[spring-jdbc-5.3.22.jar:5.3.22]
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:667) ~[spring-jdbc-5.3.22.jar:5.3.22]
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:691) ~[spring-jdbc-5.3.22.jar:5.3.22]
    at org.springframework.jdbc.core.JdbcTemplate.batchUpdate(JdbcTemplate.java:1034) ~[spring-jdbc-5.3.22.jar:5.3.22]
    at org.springframework.security.acls.jdbc.JdbcMutableAclService.createEntries(JdbcMutableAclService.java:141) ~[spring-security-acl-5.7.2.jar:5.7.2]
    at org.springframework.security.acls.jdbc.JdbcMutableAclService.updateAcl(JdbcMutableAclService.java:343) ~[spring-security-acl-5.7.2.jar:5.7.2]
    at com.spartasystems.hcls.apqrservice.authorization.service.AccessControlService.lambda$updateAcl$2(AccessControlService.java:97) ~[classes/:na]
    at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) ~[spring-tx-5.3.18.jar:5.3.18]
    at com.spartasystems.hcls.apqrservice.authorization.service.AccessControlService.updateAcl(AccessControlService.java:96) ~[classes/:na]
Caused by: java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction
    at jdk.internal.reflect.GeneratedConstructorAccessor45.newInstance(Unknown Source) ~[na:na]
    at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:na]
    at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[na:na]
    at com.mysql.cj.util.Util.handleNewInstance(Util.java:192) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.util.Util.getInstance(Util.java:167) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.util.Util.getInstance(Util.java:174) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.exceptions.SQLError.createBatchUpdateException(SQLError.java:224) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.StatementImpl.handleExceptionForBatch(StatementImpl.java:1101) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchedInserts(ClientPreparedStatement.java:681) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchInternal(ClientPreparedStatement.java:409) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.StatementImpl.executeBatch(StatementImpl.java:795) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.zaxxer.hikari.pool.ProxyStatement.executeBatch(ProxyStatement.java:127) ~[HikariCP-4.0.3.jar:na]
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeBatch(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar:na]
    at org.springframework.jdbc.core.JdbcTemplate.lambda$batchUpdate$4(JdbcTemplate.java:1048) ~[spring-jdbc-5.3.22.jar:5.3.22]
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651) ~[spring-jdbc-5.3.22.jar:5.3.22]
    ... 10 common frames omitted
Caused by: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:123) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:555) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:339) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1061) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1009) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1320) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchedInserts(ClientPreparedStatement.java:679) ~[mysql-connector-java-8.0.29.jar:8.0.29]
    ... 16 common frames omitted

Following the is MySQL show engine innodb status command output:

=====================================
2023-10-10 16:56:44 281472176816000 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 37 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 74 srv_active, 0 srv_shutdown, 92801 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 480
OS WAIT ARRAY INFO: signal count 430
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2023-10-10 16:52:04 281472762113920
*** (1) TRANSACTION:
TRANSACTION 101796, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 1
MySQL thread id 2846, OS thread handle 281472199008128, query id 32686 172.18.0.1 apqrapp update
insert into acl_entry (acl_object_identity, ace_order, sid, mask, granting, audit_success, audit_failure)values (1912, 0, 80, 1, 1, 0, 0),(1912, 1, 80, 2, 1, 0, 0)

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 579 page no 5 n bits 168 index UNIQUE_UK_4 of table `deadlock`.`acl_entry` trx id 101796 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;;

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 579 page no 5 n bits 168 index UNIQUE_UK_4 of table `deadlock`.`acl_entry` trx id 101796 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 101795, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 1
MySQL thread id 2845, OS thread handle 281469735874432, query id 32685 172.18.0.1 apqrapp update
insert into acl_entry (acl_object_identity, ace_order, sid, mask, granting, audit_success, audit_failure)values (1911, 0, 80, 1, 1, 0, 0),(1911, 1, 80, 2, 1, 0, 0)

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 579 page no 5 n bits 168 index UNIQUE_UK_4 of table `deadlock`.`acl_entry` trx id 101795 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 579 page no 5 n bits 168 index UNIQUE_UK_4 of table `deadlock`.`acl_entry` trx id 101795 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)
------------
TRANSACTIONS
------------
Trx id counter 101809
Purge done for trx's n:o < 101809 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 562948293082272, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 562948293079040, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 562948293079848, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 562948293078232, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 562948293081464, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 562948293080656, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 562948293077424, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 562948293076616, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests ((null))
I/O thread 1 state: waiting for completed aio requests (insert buffer thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:
Pending flushes (fsync) log: 0; buffer pool: 0
1546 OS file reads, 6142 OS file writes, 4970 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 3 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 6 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number          553611090
Log buffer assigned up to    553611090
Log buffer completed up to   553611090
Log written up to            553611090
Log flushed up to            553611090
Added dirty pages up to      553611090
Pages flushed up to          553611090
Last checkpoint at           553611090
Log minimum file id is       168
Log maximum file id is       169
2632 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 1381086
Buffer pool size   8192
Free buffers       6618
Database pages     1555
Old database pages 590
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 1386, created 169, written 2392
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 1555, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=1, Main thread ID=281472753721216 , state=sleeping
Number of rows inserted 852, updated 14, deleted 463, read 8329
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 16, updated 403, deleted 12, read 19170
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

A link to a GitHub repository with a minimal, reproducible sample.

[sjohnr]

@arun1ram, thanks for the report.

You mention:

When 2 or more threads (or in a distributed environment - 2 or more instances) are invoking the JdbcMutableAclService#updateAcl() method concurrently, one of the threads succeeds but others fail with DeadlockLoserDataAccessException

and:

I expect that an ACL will be created if it does not already exist and the ACL entries (corresponding to the permissions) are added successfully.

but these statements seem to contradict each other (since your first statement indicates the operation is still successful)? Further you haven't provided enough information or a detailed enough sample to reproduce the behavior. Additionally, the behavior you're describing could be database vendor specific.

In order to proceed, it would be very helpful for you to provide more information (database vendor, additional error details) and a complete minimal sample that allows reproducing the issue with an available open source database and minimal setup. Are you able to provide this? Also, do you have a specific recommendation for how to resolve the issue?

[spring-projects-issues]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

[arun1ram]

@sjohnr Thanks for your response. The statements are not contradictory because they are referring to what happens to the 2 threads (or instances in a distributed environment). The first thread succeeds and the second one fails. My expectation is that both threads will succeed. I am using MySQL as the backend database. This contains all the ACL related tables. I do have a reproducer that illustrates this problem. I need a few days to remove proprietary code from it. I can then share it with you.

[arun1ram]

@sjohnr Please note that I have now added error details to the issue.

[sjohnr]

@arun1ram I have reviewed your database logs and do not see enough information to determine anything new, and you have not provided a minimal sample. As I mentioned, your description of the problem states that you expect the ACL to be created, and it appears that does happen. The deadlock that occurs in your code is related to your concurrent attempt to do so on two threads, and is not in the framework's control.

The MutableAclService exposes two operations that you are using, createAcl and updateAcl. My suggestion would be to wrap the update/create operation in a transaction to see if that resolves the issue. If that doesn't work, you can also add exception handling to your code and log and/or ignore the deadlock exception thrown by the MySQL driver.

I don't see anything that the JdbcMutableAclService implementation can do to prevent your error, other than swallowing exceptions which I don't believe the framework should do. I'm going to close this issue for now. If you have additional thoughts as to what you believe the framework is doing incorrectly (aside from propagating exceptions, which I believe is correct) let me know. If you have suggestions for how the docs could be updated to better reflect correct usage of the JdbcMutableAclService (such as transaction and error handling), that would be great too.