Updates are not saved correctly, depending on the graphId of objects in the database

[Andy2003]

Current Behavior

The deletion of a relationship has only 50% success rate according to the starting graphId of newly added objects.

Steps to Reproduce (for bugs)

See test case

I suspect that it has to do with the use of HashMap and HashSet, because due to different graphIds - and thus also the hashCodes - the order in which objects are processed is different.

Your Environment

• OGM Version used: current master (3.2.0-SNAPSHOT)
• Java Version used: Oracle JDK 1.8.0_162 OR Open JDK 1.8.0_151
• Neo4J Version used: 3.4.11

[Andy2003]

I added some additional logs. Here are the outputs:

Successful run:

 org.neo4j.ogm.context.EntityGraphMapper - context-init: ($0)-[:USES]->($1)
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (0)-[0:USES]->(1) to []
 org.neo4j.ogm.context.EntityGraphMapper - context-init: ($0)-[:USES]->($2)
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (0)-[2:USES]->(2) to [(0)-[0:USES]->(1)]
 org.neo4j.ogm.context.EntityGraphMapper - context-init: ($0)-[:USES]->($1)
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (0)-[1:USES]->(1) to [(0)-[0:USES]->(1), (0)-[2:USES]->(2)]
 org.neo4j.ogm.context.EntityGraphMapper - context initialised with 3 relationships
 org.neo4j.ogm.context.EntityGraphMapper - visiting: FormulaItem(m1)
 org.neo4j.ogm.context.EntityGraphMapper - FormulaItem(m1), has not changed
 org.neo4j.ogm.context.EntityGraphMapper - mapping references declared by: FormulaItem(m1) 
 org.neo4j.ogm.context.EntityGraphMapper - context-del: (0)-[:USES]->()
.neo4j.ogm.cypher.compiler.CypherContext - deregisterOutgoingRelationships before [(0)-[0:USES]->(1), (0)-[2:USES]->(2), (0)-[1:USES]->(1)]
.neo4j.ogm.cypher.compiler.CypherContext - deregisterOutgoingRelationships clearing [(0)-[0:USES]->(1), (0)-[2:USES]->(2), (0)-[1:USES]->(1)]
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (0)-[1:USES]->(1) to []
 org.neo4j.ogm.context.EntityGraphMapper - mapping reference type: USES
 org.neo4j.ogm.context.EntityGraphMapper - linking to entity (m1)-[:USES{variable: 'A'}]->(m3) in one direction
 org.neo4j.ogm.context.EntityGraphMapper - mapping relationshipEntity (m1)-[:USES{variable: 'A'}]->(m3)
 org.neo4j.ogm.context.EntityGraphMapper - RE is new or has not changed
 org.neo4j.ogm.context.EntityGraphMapper - visiting: DataItem(m3)
 org.neo4j.ogm.context.EntityGraphMapper - DataItem(m3), has not changed
 org.neo4j.ogm.context.EntityGraphMapper - mapping references declared by: DataItem(m3) 
 org.neo4j.ogm.context.EntityGraphMapper - context-del: (2)-[:USES]->()
.neo4j.ogm.cypher.compiler.CypherContext - deregisterOutgoingRelationships before [(0)-[1:USES]->(1)]
 org.neo4j.ogm.context.EntityGraphMapper - trying to map relationship between FormulaItem(m1) and DataItem(m3)
 org.neo4j.ogm.context.EntityGraphMapper - mappingContext does contain 
 org.neo4j.ogm.context.EntityGraphMapper - context-add: (0)-[2:USES]->(2)
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (0)-[2:USES]->(2) to [(0)-[1:USES]->(1)]
 org.neo4j.ogm.context.EntityGraphMapper - linking to entity (m1)-[:USES{variable: 'B'}]->(m2) in one direction
 org.neo4j.ogm.context.EntityGraphMapper - mapping relationshipEntity (m1)-[:USES{variable: 'B'}]->(m2)
 org.neo4j.ogm.context.EntityGraphMapper - RE is new or has not changed
 org.neo4j.ogm.context.EntityGraphMapper - visiting: DataItem(m2)
 org.neo4j.ogm.context.EntityGraphMapper - DataItem(m2), has not changed
 org.neo4j.ogm.context.EntityGraphMapper - mapping references declared by: DataItem(m2) 
 org.neo4j.ogm.context.EntityGraphMapper - context-del: (1)-[:USES]->()
.neo4j.ogm.cypher.compiler.CypherContext - deregisterOutgoingRelationships before [(0)-[1:USES]->(1), (0)-[2:USES]->(2)]
 org.neo4j.ogm.context.EntityGraphMapper - trying to map relationship between FormulaItem(m1) and DataItem(m2)
 org.neo4j.ogm.context.EntityGraphMapper - mappingContext does contain 
 org.neo4j.ogm.context.EntityGraphMapper - context-add: (0)-[1:USES]->(1)
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (0)-[1:USES]->(1) to [(0)-[1:USES]->(1), (0)-[2:USES]->(2)]
.neo4j.ogm.cypher.compiler.CypherContext - removeRegisteredRelationship (0)-[0:USES]->(1) from [(0)-[1:USES]->(1), (0)-[2:USES]->(2)]
 org.neo4j.ogm.context.EntityGraphMapper - context-del: (0)-[0:USES]->(1)
 org.neo4j.ogm.context.EntityGraphMapper - flushing end node of: ($0)-[:USES]->($1)
 org.neo4j.ogm.context.EntityGraphMapper - flushing start node of: ($0)-[:USES]->($1)
 org.neo4j.ogm.context.EntityGraphMapper - flushing end node of: ($0)-[:USES]->($2)
.neo4j.ogm.cypher.compiler.CypherContext - removeRegisteredRelationship (0)-[2:USES]->(2) from [(0)-[1:USES]->(1), (0)-[2:USES]->(2)]
.neo4j.ogm.cypher.compiler.CypherContext - removeRegisteredRelationship (0)-[1:USES]->(1) from [(0)-[1:USES]->(1)]
neo4j.ogm.drivers.bolt.driver.BoltDriver - No current transaction, starting a new one
neo4j.ogm.drivers.bolt.driver.BoltDriver - Native transaction: org.neo4j.driver.internal.ExplicitTransaction@2dd08ff1
o4j.ogm.drivers.bolt.request.BoltRequest - Request: UNWIND {rows} AS row MATCH ()-[r]-() WHERE ID(r) = row.relId SET r += row.props RETURN ID(r) as ref, ID(r) as id, {type} as type with params {rows=[{relId=1, props={variable=B}}, {relId=2, props={variable=A}}], type=rel}
o4j.ogm.drivers.bolt.request.BoltRequest - Request: UNWIND {rows} AS row MATCH ()-[r]-() WHERE ID(r) = row.relId DELETE r RETURN ID(r) as ref, ID(r) as id, {type} as type with params {rows=[{relId=0}], type=rel}
eo4j.ogm.session.request.RequestExecutor - to (maybe) update: relEntity 1:1
eo4j.ogm.session.request.RequestExecutor - to (maybe) update: relEntity 1:1
eo4j.ogm.session.request.RequestExecutor - to (maybe) update: relEntity 2:2
eo4j.ogm.session.request.RequestExecutor - to (maybe) update: relEntity 2:2
eo4j.ogm.session.request.RequestExecutor - to (maybe) update: relEntity 0:0
eo4j.ogm.session.request.RequestExecutor - to (maybe) update: relEntity 0:0
drivers.bolt.transaction.BoltTransaction - Committing native transaction: org.neo4j.driver.internal.ExplicitTransaction@2dd08ff1
   org.neo4j.ogm.transaction.Transaction - Thread 1: Commit transaction extent: 0
   org.neo4j.ogm.transaction.Transaction - Thread 1: Committed
   org.neo4j.ogm.transaction.Transaction - Thread 1: Close transaction extent: 0
   org.neo4j.ogm.transaction.Transaction - Thread 1: Closing transaction

Failed run:

There is an offset of 20 in the graphIds compared to the successful run

 org.neo4j.ogm.context.EntityGraphMapper - context-init: ($20)-[:USES]->($22)
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (20)-[22:USES]->(22) to []
 org.neo4j.ogm.context.EntityGraphMapper - context-init: ($20)-[:USES]->($21)
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (20)-[21:USES]->(21) to [(20)-[22:USES]->(22)]
 org.neo4j.ogm.context.EntityGraphMapper - context-init: ($20)-[:USES]->($21)
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (20)-[20:USES]->(21) to [(20)-[22:USES]->(22), (20)-[21:USES]->(21)]
 org.neo4j.ogm.context.EntityGraphMapper - context initialised with 3 relationships
 org.neo4j.ogm.context.EntityGraphMapper - visiting: FormulaItem(m1)
 org.neo4j.ogm.context.EntityGraphMapper - FormulaItem(m1), has not changed
 org.neo4j.ogm.context.EntityGraphMapper - mapping references declared by: FormulaItem(m1) 
 org.neo4j.ogm.context.EntityGraphMapper - context-del: (20)-[:USES]->()
.neo4j.ogm.cypher.compiler.CypherContext - deregisterOutgoingRelationships before [(20)-[22:USES]->(22), (20)-[21:USES]->(21), (20)-[20:USES]->(21)]
.neo4j.ogm.cypher.compiler.CypherContext - deregisterOutgoingRelationships clearing [(20)-[22:USES]->(22), (20)-[21:USES]->(21), (20)-[20:USES]->(21)]
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (20)-[20:USES]->(21) to []
 org.neo4j.ogm.context.EntityGraphMapper - mapping reference type: USES
 org.neo4j.ogm.context.EntityGraphMapper - linking to entity (m1)-[:USES{variable: 'A'}]->(m3) in one direction
 org.neo4j.ogm.context.EntityGraphMapper - mapping relationshipEntity (m1)-[:USES{variable: 'A'}]->(m3)
 org.neo4j.ogm.context.EntityGraphMapper - RE is new or has not changed
 org.neo4j.ogm.context.EntityGraphMapper - visiting: DataItem(m3)
 org.neo4j.ogm.context.EntityGraphMapper - DataItem(m3), has not changed
 org.neo4j.ogm.context.EntityGraphMapper - mapping references declared by: DataItem(m3) 
 org.neo4j.ogm.context.EntityGraphMapper - context-del: (22)-[:USES]->()
.neo4j.ogm.cypher.compiler.CypherContext - deregisterOutgoingRelationships before [(20)-[20:USES]->(21)]
 org.neo4j.ogm.context.EntityGraphMapper - trying to map relationship between FormulaItem(m1) and DataItem(m3)
 org.neo4j.ogm.context.EntityGraphMapper - mappingContext does contain 
 org.neo4j.ogm.context.EntityGraphMapper - context-add: (20)-[22:USES]->(22)
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (20)-[22:USES]->(22) to [(20)-[20:USES]->(21)]
 org.neo4j.ogm.context.EntityGraphMapper - linking to entity (m1)-[:USES{variable: 'B'}]->(m2) in one direction
 org.neo4j.ogm.context.EntityGraphMapper - mapping relationshipEntity (m1)-[:USES{variable: 'B'}]->(m2)
 org.neo4j.ogm.context.EntityGraphMapper - RE is new or has not changed
 org.neo4j.ogm.context.EntityGraphMapper - visiting: DataItem(m2)
 org.neo4j.ogm.context.EntityGraphMapper - DataItem(m2), has not changed
 org.neo4j.ogm.context.EntityGraphMapper - mapping references declared by: DataItem(m2) 
 org.neo4j.ogm.context.EntityGraphMapper - context-del: (21)-[:USES]->()
.neo4j.ogm.cypher.compiler.CypherContext - deregisterOutgoingRelationships before [(20)-[22:USES]->(22), (20)-[20:USES]->(21)]
 org.neo4j.ogm.context.EntityGraphMapper - trying to map relationship between FormulaItem(m1) and DataItem(m2)
 org.neo4j.ogm.context.EntityGraphMapper - mappingContext does contain 
 org.neo4j.ogm.context.EntityGraphMapper - context-add: (20)-[21:USES]->(21)
.neo4j.ogm.cypher.compiler.CypherContext - registerRelationship (20)-[21:USES]->(21) to [(20)-[22:USES]->(22), (20)-[20:USES]->(21)]
.neo4j.ogm.cypher.compiler.CypherContext - removeRegisteredRelationship (20)-[22:USES]->(22) from [(20)-[22:USES]->(22), (20)-[21:USES]->(21), (20)-[20:USES]->(21)]
.neo4j.ogm.cypher.compiler.CypherContext - removeRegisteredRelationship (20)-[21:USES]->(21) from [(20)-[21:USES]->(21), (20)-[20:USES]->(21)]
.neo4j.ogm.cypher.compiler.CypherContext - removeRegisteredRelationship (20)-[20:USES]->(21) from [(20)-[20:USES]->(21)]
neo4j.ogm.drivers.bolt.driver.BoltDriver - No current transaction, starting a new one
neo4j.ogm.drivers.bolt.driver.BoltDriver - Native transaction: org.neo4j.driver.internal.ExplicitTransaction@6dbeaef8
o4j.ogm.drivers.bolt.request.BoltRequest - Request: UNWIND {rows} AS row MATCH ()-[r]-() WHERE ID(r) = row.relId SET r += row.props RETURN ID(r) as ref, ID(r) as id, {type} as type with params {rows=[{relId=21, props={variable=B}}, {relId=22, props={variable=A}}], type=rel}
eo4j.ogm.session.request.RequestExecutor - to (maybe) update: relEntity 21:21
eo4j.ogm.session.request.RequestExecutor - to (maybe) update: relEntity 21:21
eo4j.ogm.session.request.RequestExecutor - to (maybe) update: relEntity 22:22
eo4j.ogm.session.request.RequestExecutor - to (maybe) update: relEntity 22:22
drivers.bolt.transaction.BoltTransaction - Committing native transaction: org.neo4j.driver.internal.ExplicitTransaction@6dbeaef8
   org.neo4j.ogm.transaction.Transaction - Thread 1: Commit transaction extent: 0
   org.neo4j.ogm.transaction.Transaction - Thread 1: Committed
   org.neo4j.ogm.transaction.Transaction - Thread 1: Close transaction extent: 0
   org.neo4j.ogm.transaction.Transaction - Thread 1: Closing transaction
eo4j.ogm.session.request.RequestExecutor - updating existing relationship entity id: 21
eo4j.ogm.session.request.RequestExecutor - updating existing relationship entity id: 21
eo4j.ogm.session.request.RequestExecutor - updating existing relationship entity id: 22
eo4j.ogm.session.request.RequestExecutor - updating existing relationship entity id: 22

[michael-simons]

Thanks Andy. We’ll investigate this after the holidays. Thanks a lot for the detailed reproducer. The caching of all the things especially around native and non native ids is bugging us all over the place.

Also thanks for giving 3.2 a test run. Does it happen with 3.1 as well?

[Andy2003]

Yes, the problem also exists in version 3.1.4. As you can see in the fix #576, this is not a caching problem but a problem in the order of processing.

[michael-simons]

Resolved in both 3.1.x and 3.2.

Expect the next alpha of 3.2 this week. Thanks again for reporting this issue and your contribution.