onNext and onError being triggered on transaction deadlocks

[brandonburkett]

Hello,

I am running into an issue with doing lots of async merge queries. Every now and then I hit a transaction deadlock (code 127). When this happens it seems that both onNext and onError are being triggered.

The main issue is I am using a callback both in onNext and onError:

session
          .run(query, params)
          .subscribe({
            onNext: (record) => callback(null, record.get('c.id')),
            onCompleted: () => session.close(),
            onError: (err) => callback(err),
          });

And node crashes with both callbacks are called.

[pontusmelke]

Thanks for reporting this, we'll have a look at it

[brandonburkett]

No problem, I have gotten around it for now by wrap bolt queries in an async.retry and logging Bolt onNext() was called AFTER onError(): (most likely deadlock)... retrying. I am 99% certain I hit this issue when I am merging to many things (to quickly) on a single node and get the dreaded deadlock. ❤️

[dan-kez]

Hey @devourment77 would you mind posting an example of using async.retry with the driver by any chance?

[lutovich]

Hi @devourment77,

Sorry for the delayed response. I'm looking into this issue now.
Unfortunately, I'm not able to reproduce it using tests with two sessions and intentional deadlock. Killed session only gets onError call and survived session gets onNext and onCompleted as expected.

Do you always get onError and then onNext when this problem manifests, or sometimes it could be other way around?
Do you have a test to reproduce or maybe could share your merge queries?

Thanks in advance!

[brandonburkett]

lutovich,

It has been a while since I was on this, but it was for sure triggering both onError and onNext callbacks when I was doing very large amounts of merging. I no longer have the test queries or code access, but reached out to the company that does to see if they could follow up. My comment on Sept 3 above is how I got around the issue by wrapping the method in async.retry (using the async lib) and tracking this state in my wrapper.

Wish I could be more help.

Thanks
Brandon

[lutovich]

@devourment77 do you remember which neo4j version and JS driver version was used?

I've tried to reproduce this problem with simple dirty test like this: https://gist.github.com/lutovich/cca743e865f61a657269adab4649401d and with multiple node processes executing script https://gist.github.com/lutovich/414ae12bbd4019d4a293db4946a7a9cd concurrently. Queries are rather simple in both cases but they produce deadlocks. Issue did not show up in both cases. Used JS driver 1.0.5 and neo4j 3.1.0.

[brandonburkett]

Lutovich,

It was neo 3.x and most recent bolt driver that was out during 08/15/2016. Looking at your tests, I know we were using merge (not match) with large batches of data in parallel. A better test would be to:

• use a ton of mock data (like 100k nodes)
• make sure some of those data points qualify for the insert and update features of merge
• use something like async.eachLimit (http://caolan.github.io/async/docs.html#eachLimit) so you can do lots of async merges at the same time
• crank the limit up so like 10 or so are running at the same time (the higher the limit, the more likely we would see the error)

Hope it helps.
Brandon

[lutovich]

@devourment77 I've took another stab at this issue and came up with this script https://gist.github.com/lutovich/669f774111f6ba24c17ec0355a8d164c. It does the following:

• populates db with 1M (:User {userId: {...}}) nodes with only even user ids
• runs 1M generated merge queries like:

  MERGE (initialNode:User {userId: XXX})
  ON CREATE SET initialNode.created = timestamp()
  ON MATCH SET initialNode.counter = coalesce(initialNode.counter, 0) + initialNode.accessTime = timestamp()
  
  MERGE (otherNode_1:User {userId: YYY})
  ON CREATE SET otherNode_1.created = timestamp()
  ON MATCH SET otherNode_1.counter = coalesce(otherNode_1.counter, 0) + 1, otherNode_1.accessTime = timestamp()
  
  MERGE (initialNode)-[rel_1:FRIEND]->(otherNode_1)
  ON CREATE SET rel_1.created = timestamp()
  ON MATCH SET rel_1.counter = coalesce(rel_1.counter, 0) + 1, rel_1.accessTime = timestamp()
  [...]
  RETURN initialNode, otherNode_1, rel_1, otherNode_2
  

  with random (5-30) amount of similar MERGE clauses for random user ids
• queries are fired via async.eachLimit with limit set to 50
• each deadlock is logged in console
• async callback is executed from onNext and onError in the same way you've described

I can only see onError being called after onNext occasionally. This fails async.eachLimit because callback is invoked more than once. So first we receive a record in onNext and then database detects a deadlock, terminates the transaction and sends DeadlockDetected to the onError. Deadlock is detected before result is fully streamed back and thus before transaction is committed.

Could you please check the code and tell me if I'm missing something?

Thanks!

[brandonburkett]

Your flow seems to describe exactly what we were seeing. It was only occasionally, but because of that, it means we had to implement tracking for that case outside of the bolt library (we used async.retry and had to put a setTimeout around our onNext callbacks to make sure onError wasn't called at the same time.

[lutovich]

@devourment77 were you seeing onNext called after onError? I thought this was the main problem.

It is just calling onError after onNext is a valid case. Imagine a query like MATCH (n) SET n.prop1 = 42 / n.prop2 RETURN n which matches many nodes. Database executes it and gets a lazy iterator back. It starts pulling items from the iterator and streaming them back to the driver and after some number of streamed records encounters a node which has n.prop2 == 0. This results in 'Division by zero' exception being streamed to the driver and onError callback being called. Without such laziness database would need to evaluate and store result of the query before streaming which could consume lots of resources.

[brandonburkett]

Honestly, I cannot tell you 100% if it was onNext or onError that was being called first, but the fact that I remember doing a setTimout inside onNext (waiting to see if onError was called) makes me thing it probably was onNext then onError.

[lutovich]

Okey, got it. I think the only thing we could do to make observer API less confusing here is to improve documentation. I'll make sure we have a card for this. Do you agree that we can close the issue at this point?

[brandonburkett]

I think improving docs or having an option / config setting like "wait for error before invoking onNext" type of thing could make it easier, especially with batch operations merges.

Thank you for all your help on this.

[lutovich]

I think "wait for error before invoking onNext" could be achieved by using promise-like API.
So your example code could look like:

session.run(query, params)
  .then(result => {
    callback(null, result.records[0].get('c.id'));
    session.close();
  })
  .catch(error => {
    callback(error);
  });

This solution basically accumulates the whole result before returning it in then.

Thanks for reporting this problem. Hope you enjoy using Neo4j and JS driver :)