dbms.lock.acquisition.timeout not triggered by apoc

[neo-technology-build-agent]

Issue by Dcanzano Thursday Feb 27, 2020 at 15:31 GMT Originally opened as https://github.com/neo4j-contrib/neo4j-apoc-procedures/issues/1430

---

Expected Behavior (Mandatory)

that apoc.periodic.iterate exit if during it runs it waits more than dbms.lock.acquitision.timeout duration attempting to get a lock

Actual Behavior (Mandatory)

today the parameter is not recognized

How to Reproduce the Problem

using Neo4j 4.0.1 and APOC

-rw-rw-r-- 1 neo4j neo4j 18109483 Feb 27 06:53 apoc-4.0.0.4-all.jar configure conf/neo4j.conf with

dbms.lock.acquisition.timeout=5s

Start Neo4j, create a database and then run the following so as to populate the database

foreach ( x in range (1,300000) | create (n:TxnDetail {id: x , vendorId: toInteger(rand()*50)}));
foreach ( x in range (300001,600000) | create (n:TxnDetail {id: x , vendorId: toInteger(rand()*50)}));
foreach ( x in range (600001,900000) | create (n:TxnDetail {id: x , vendorId: toInteger(rand()*50)}));
foreach ( x in range (900001,1200000) | create (n:TxnDetail {id: x , vendorId: toInteger(rand()*50)}));

foreach ( x in range (1,50) | create (n:Vendor {id:x}));
create index on :Vendor(id);
create index on :TxnDetail(vendorId);

now startup 2 bin/cypher-shell sessions.

in session1 run

   @proddb1> match (n:Vendor {id:1}) set n.status='active' with n call apoc.util.sleep(10000000) return n;

which will update the :Vendor node at id:1 set a property named status to the value `active' and as such result in a lock on said node and then we will sleep for 10000000 msec thus maintaining the lock for said duration

in a 2nd cypher-shell session run

   @proddb1> match (n:Vendor {id:1}) set n.status2='active' return n;

and this correctly errors as

          The transaction has been terminated. Retry your operation in a new transaction, and you should see a successful result. Unable to acquire lock within configured timeout (dbms.lock.acquisition.timeout). Unable to acquire lock for resource: NODE with id: 1200000 within 5000 millis.

so at least we know dbms.lock.acquistion.timeout is working.

Lets repeat the steps and run session1 as previoulsy described causing a lock in :Vendor and {id:1} and in session 2 run

@proddb1> CALL apoc.periodic.iterate('MATCH (v:Vendor {id:1}) WITH v MATCH (txn:TxnDetail) WHERE txn.vendorId = v.id  RETURN txn, v', 'MERGE (txn)-[:VENDOR]->(v)', {batchSize: 100, parallel: false, iterateList: true, retries:3});

this statement does not exit after 5 seconds, or even 15 seconds (i.e. maybe taking into account the retries:3 )

and the debug.log reports

2020-02-27 14:06:49.641+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] [proddb1] Checkpoint triggered by "Scheduled checkpoint for every 15 minutes threshold" @ txId: 12017 checkpoint completed in 89ms
2020-02-27 14:06:49.642+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] [proddb1] No log version pruned. The strategy used was '7 days'. Last checkpoint was made in log version 1.
2020-02-27 14:09:50.850+0000 INFO [o.n.k.a.p.GlobalProcedures] starting batching from `MATCH (v:Vendor {id:1}) WITH v MATCH (txn:TxnDetail) WHERE txn.vendorId = v.id  RETURN txn, v` operation using iteration `MERGE (txn)-[:VENDOR]->(v)` in separate thread
2020-02-27 14:09:55.858+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 0 of 3
2020-02-27 14:10:00.962+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 1 of 3
2020-02-27 14:10:06.069+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 2 of 3
2020-02-27 14:10:16.193+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 0 of 3
2020-02-27 14:10:21.298+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 1 of 3
2020-02-27 14:10:26.405+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 2 of 3
2020-02-27 14:10:36.513+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 0 of 3
2020-02-27 14:10:41.620+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 1 of 3
2020-02-27 14:10:46.726+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 2 of 3
2020-02-27 14:10:56.834+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 0 of 3
2020-02-27 14:11:01.939+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 1 of 3
2020-02-27 14:11:07.046+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 2 of 3
2020-02-27 14:11:17.161+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 0 of 3
2020-02-27 14:11:22.266+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 1 of 3
2020-02-27 14:11:27.371+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 2 of 3
2020-02-27 14:11:37.482+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 0 of 3
2020-02-27 14:11:42.587+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 1 of 3
2020-02-27 14:11:47.694+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 2 of 3
2020-02-27 14:11:57.804+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 0 of 3
2020-02-27 14:12:02.910+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 1 of 3
2020-02-27 14:12:08.014+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 2 of 3
2020-02-27 14:12:18.129+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 0 of 3
2020-02-27 14:12:23.237+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 1 of 3
2020-02-27 14:12:28.358+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 2 of 3
2020-02-27 14:12:38.470+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 0 of 3
2020-02-27 14:12:43.576+0000 WARN [o.n.k.a.p.GlobalProcedures] Retrying operation 1 of 3

and on and on and on.

• OS: Ubuntu 18
• Neo4j: 4.0.1
• Neo4j-Apoc: apoc-4.0.0.4-all.jar