Create Cypher Overwriting Existing Nodes

[mattszo]

Exported a database (using the neo4j-admin dump command) and imported into my local environment (using neo4j-admin import).

My first node id exists at 12. Creating a new node generates an id of 8, another id of 9, another of 10, another of 11, and finally running a simple CREATE(n) cypher overwrites 12. The database continues at this point to ignore existing nodes with ids and sequentially overwrites nodes in my database.

Any ideas why this may be happening?

[tom_geudens]

Greetings Matthew,
That sounds very weird ...

1. What version are we talking about ?
2. You create a dump with neo4j-admin dump and you create a new database with neo4j-admin load right ? Unless you are using a very old version neo4j-admin import does not work with a dump ...

Regards,
Tom

[mattszo]

1. Using a docker image of neo4j:3.2.2 locally, and a clustered version of 3.2.3 on a production linux server.

2. More specifically my command for load is (sorry for the confusion)
   bin/neo4j-admin load --from=/data/backup.dmp --database=graph.db

[tom_geudens]

Hello Matthew,

Is not a problem (it would have been extremely weird - and interesting - if that worked :-). Right ... how exactly are you getting that database into the Docker instance ?

1. Are you creating the graph.db outside of Docker on a persistent volume that you then pass inside on the docker run?
2. Are you somehow running the neo4j-admin command inside the Docker instance ?

I know this sounds like a game of multiple choice but I'm trying to understand what the setup is so I (or somebody following along) can make a correct analysis of what goes wrong. So thank you for bearing with me !

Regards,
Tom

[mattszo]

I do have a persistent volume, specifically this command
docker run --publish=7474:7474 --publish=7687:7687 --volume=$HOME/neo4j/data:/data --volume=$HOME/neo4j/logs:/logs -i -t neo4j /bin/bash bin/neo4j-admin load --from=/data/backup.dmp --database=graph.db --force

Afterwards, I run a docker-compose up on my neo4j image which has the same volume configured.

[tom_geudens]

Greetings Matthew,

Well, as far as I can quickly test the graph.db does indeed get created that way. Instead of running a docker-compose afterwards, can you do a

docker run --publish=7474:7474 --publish=7687:7687 --volume=$HOME/neo4j/data:/data --volume=$HOME/neo4j/logs:/logs neo4j

And check if that instance has the same behaviour (it doesn't on a more recent version, I'm creating a 3.2.2 dump in the mean time to fully test your setup) ? If it has the same behaviour it must be version related.

Thanks !

Regards,
Tom

[mattszo]

Hmm I think you're on to something...
docker run --publish=7474:7474 --publish=7687:7687 --volume=$HOME/neo4j/data:/data --volume=$HOME/neo4j/logs:/logs neo4j:3.2.2 continues to overwrite existing nodes.

docker run --publish=7474:7474 --publish=7687:7687 --volume=$HOME/neo4j/data:/data --volume=$HOME/neo4j/logs:/logs neo4j (which pulls the latest) is correctly assigning ids.

[tom_geudens]

I can't reproduce it myself with a 3.2.2 instance

Can you run this ?
docker run --publish=7474:7474 --publish=7687:7687 --volume=$HOME/neo4j/data:/data --volume=$HOME/neo4j/logs:/logs -i -t neo4j /bin/bash bin/neo4j-admin check-consistency

Is the database consistent ?

Regards,
Tom

[mattszo]

$ docker run --publish=7474:7474 --publish=7687:7687 --volume=$HOME/neo4j/data:/data --volume=$HOME/neo4j/logs:/logs -i -t neo4j /bin/bash bin/neo4j-admin check-consistency
2018-08-28 18:37:24.623+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Selected RecordFormat:StandardV3_2[v0.A.8] record format from store /var/lib/neo4j/data/databases/graph.db
2018-08-28 18:37:24.626+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Format not configured. Selected format from the store: RecordFormat:StandardV3_2[v0.A.8]
.................... 10%
.................... 20%
.................... 30%
.................... 40%
.................... 50%
.................... 60%
.................... 70%
.................... 80%
..........Checking node and relationship counts
.................... 10%
.................... 20%
.................... 30%
.................... 40%
.................... 50%
.................... 60%
.................... 70%
.................... 80%
.................... 90%
.................... 100%

[mattszo]

Could it related to indices?
CREATE (n:User {nodeId:"test1"}) return n
CREATE (n:User {nodeId:"test2"}) return n
CREATE (n:User {nodeId:"test3"}) return n
CREATE (n:User {nodeId:"test4"}) return n

then running a check returns the following:
docker run --publish=7474:7474 --publish=7687:7687 --volume=$HOME/neo4j/data:/data --volume=$HOME/neo4j/logs:/logs -i -t neo4j /bin/bash bin/neo4j-admin check-consistency
2018-08-28 18:39:46.308+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Selected RecordFormat:StandardV3_2[v0.A.8] record format from store /var/lib/neo4j/data/databases/graph.db
2018-08-28 18:39:46.310+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Format not configured. Selected format from the store: RecordFormat:StandardV3_2[v0.A.8]
.................... 10%
.................... 20%
...........2018-08-28 18:39:47.443+0000 ERROR [o.n.c.ConsistencyCheckService] The source node does not have a relationship chain.
Relationship[134,used=true,source=12,target=1475,type=4,sPrev=143,sNext=135,tPrev=138,tNext=20267,prop=-1,secondaryUnitId=-1,!sFirst,!tFirst]
Inconsistent with: Node[12,used=true,rel=-1,prop=666,labels=Inline(0x1000000004:[4]),light,secondaryUnitId=-1]
2018-08-28 18:39:47.446+0000 ERROR [o.n.c.ConsistencyCheckService] The target node does not have a relationship chain.
Relationship[135,used=true,source=1919,target=12,type=0,sPrev=139,sNext=20345,tPrev=134,tNext=136,prop=-1,secondaryUnitId=-1,!sFirst,!tFirst]
Inconsistent with: Node[12,used=true,rel=-1,prop=666,labels=Inline(0x1000000004:[4]),light,secondaryUnitId=-1]
2018-08-28 18:39:47.447+0000 ERROR [o.n.c.ConsistencyCheckService] The target node does not have a relationship chain.
Relationship[136,used=true,source=2211,target=12,type=2,sPrev=207,sNext=10253,tPrev=135,tNext=-1,prop=-1,secondaryUnitId=-1,!sFirst,!tFirst]
Inconsistent with: Node[12,used=true,rel=-1,prop=666,labels=Inline(0x1000000004:[4]),light,secondaryUnitId=-1]
2018-08-28 18:39:47.448+0000 ERROR [o.n.c.ConsistencyCheckService] This record should be the first in the source chain, but the source node does not reference this record.
Relationship[143,used=true,source=12,target=1916,type=1,sCount=4,sNext=134,tPrev=149,tNext=142,prop=-1,secondaryUnitId=-1, sFirst,!tFirst]
Inconsistent with: Node[12,used=true,rel=-1,prop=666,labels=Inline(0x1000000004:[4]),light,secondaryUnitId=-1]
......... 30%
.................... 40%
.................... 50%
.................... 60%
.................... 70%
.................2018-08-28 18:39:48.539+0000 ERROR [o.n.c.ConsistencyCheckService] This label scan document refers to a node that does not have the expected label.
NodeLabelRange[idRange=0-64; {Node[0]: Labels[null], Node[1]: Labels[null], Node[2]: Labels[null], Node[3]: Labels[null], Node[4]: Labels[null], Node[5]: Labels[null], Node[6]: Labels[null], Node[7]: Labels[null], Node[8]: Labels[11], Node[9]: Labels[4], Node[10]: Labels[4], Node[11]: Labels[4], Node[12]: Labels[4, 8, 9], Node[13]: Labels[8, 9], Node[14]: Labels[8, 9], Node[15]: Labels[8, 9], Node[16]: Labels[8, 9], Node[17]: Labels[1, 6, 7], Node[18]: Labels[8, 9], Node[19]: Labels[4], Node[20]: Labels[8, 9], Node[21]: Labels[8, 9], Node[22]: Labels[8, 9], Node[23]: Labels[8, 9], Node[24]: Labels[8, 9], Node[25]: Labels[null], Node[26]: Labels[null], Node[27]: Labels[null], Node[28]: Labels[null], Node[29]: Labels[null], Node[30]: Labels[null], Node[31]: Labels[null], Node[32]: Labels[null], Node[33]: Labels[null], Node[34]: Labels[null], Node[35]: Labels[null], Node[36]: Labels[null], Node[37]: Labels[null], Node[38]: Labels[null], Node[39]: Labels[null], Node[40]: Labels[null], Node[41]: Labels[null], Node[42]: Labels[null], Node[43]: Labels[null], Node[44]: Labels[null], Node[45]: Labels[null], Node[46]: Labels[null], Node[47]: Labels[null], Node[48]: Labels[null], Node[49]: Labels[null], Node[50]: Labels[null], Node[51]: Labels[null], Node[52]: Labels[null], Node[53]: Labels[null], Node[54]: Labels[null], Node[55]: Labels[null], Node[56]: Labels[null], Node[57]: Labels[null], Node[58]: Labels[null], Node[59]: Labels[null], Node[60]: Labels[null], Node[61]: Labels[null], Node[62]: Labels[null], Node[63]: Labels[null]}]
Inconsistent with: Node[12,used=true,rel=-1,prop=666,labels=Inline(0x1000000004:[4]),light,secondaryUnitId=-1] 8
2018-08-28 18:39:48.541+0000 ERROR [o.n.c.ConsistencyCheckService] This label scan document refers to a node that does not have the expected label.
NodeLabelRange[idRange=0-64; {Node[0]: Labels[null], Node[1]: Labels[null], Node[2]: Labels[null], Node[3]: Labels[null], Node[4]: Labels[null], Node[5]: Labels[null], Node[6]: Labels[null], Node[7]: Labels[null], Node[8]: Labels[11], Node[9]: Labels[4], Node[10]: Labels[4], Node[11]: Labels[4], Node[12]: Labels[4, 8, 9], Node[13]: Labels[8, 9], Node[14]: Labels[8, 9], Node[15]: Labels[8, 9], Node[16]: Labels[8, 9], Node[17]: Labels[1, 6, 7], Node[18]: Labels[8, 9], Node[19]: Labels[4], Node[20]: Labels[8, 9], Node[21]: Labels[8, 9], Node[22]: Labels[8, 9], Node[23]: Labels[8, 9], Node[24]: Labels[8, 9], Node[25]: Labels[null], Node[26]: Labels[null], Node[27]: Labels[null], Node[28]: Labels[null], Node[29]: Labels[null], Node[30]: Labels[null], Node[31]: Labels[null], Node[32]: Labels[null], Node[33]: Labels[null], Node[34]: Labels[null], Node[35]: Labels[null], Node[36]: Labels[null], Node[37]: Labels[null], Node[38]: Labels[null], Node[39]: Labels[null], Node[40]: Labels[null], Node[41]: Labels[null], Node[42]: Labels[null], Node[43]: Labels[null], Node[44]: Labels[null], Node[45]: Labels[null], Node[46]: Labels[null], Node[47]: Labels[null], Node[48]: Labels[null], Node[49]: Labels[null], Node[50]: Labels[null], Node[51]: Labels[null], Node[52]: Labels[null], Node[53]: Labels[null], Node[54]: Labels[null], Node[55]: Labels[null], Node[56]: Labels[null], Node[57]: Labels[null], Node[58]: Labels[null], Node[59]: Labels[null], Node[60]: Labels[null], Node[61]: Labels[null], Node[62]: Labels[null], Node[63]: Labels[null]}]
Inconsistent with: Node[12,used=true,rel=-1,prop=666,labels=Inline(0x1000000004:[4]),light,secondaryUnitId=-1] 9
... 80%
.2018-08-28 18:39:48.597+0000 ERROR [o.n.c.ConsistencyCheckService] This index entry refers to a node that does not have the expected label.
IndexEntry[nodeId=12]
Inconsistent with: Node[12,used=true,rel=-1,prop=666,labels=Inline(0x1000000004:[4]),light,secondaryUnitId=-1] 8
.....2018-08-28 18:39:48.612+0000 ERROR [o.n.c.ConsistencyCheckService] This index entry refers to a node that does not have the expected label.
IndexEntry[nodeId=12]
Inconsistent with: Node[12,used=true,rel=-1,prop=666,labels=Inline(0x1000000004:[4]),light,secondaryUnitId=-1] 9
....Checking node and relationship counts
.................... 10%
...2018-08-28 18:39:48.639+0000 ERROR [o.n.c.ConsistencyCheckService] The node count does not correspond with the expected count.
CountsEntry[NodeKey[(:label=8)]: 2361]
Inconsistent with: 2360
...2018-08-28 18:39:48.640+0000 ERROR [o.n.c.ConsistencyCheckService] The node count does not correspond with the expected count.
CountsEntry[NodeKey[(:label=9)]: 2361]
Inconsistent with: 2360
........2018-08-28 18:39:48.641+0000 ERROR [o.n.c.ConsistencyCheckService] The node count does not correspond with the expected count.
CountsEntry[NodeKey[()]: 4740]
Inconsistent with: 4739
...... 20%
.................... 30%
.................... 40%
....2018-08-28 18:39:48.647+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[(:label=8)-[:type=1]->()]: 305]
Inconsistent with: 304
..2018-08-28 18:39:48.648+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[(:label=8)-[:type=4]->()]: 2361]
Inconsistent with: 2360
......2018-08-28 18:39:48.649+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[(:label=8)-->()]: 9643]
Inconsistent with: 9641
...2018-08-28 18:39:48.650+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[(:label=9)-[:type=1]->()]: 305]
Inconsistent with: 304
...2018-08-28 18:39:48.650+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[(:label=9)-[:type=4]->()]: 2361]
Inconsistent with: 2360
.. 50%
....2018-08-28 18:39:48.651+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[(:label=9)-->()]: 9643]
Inconsistent with: 9641
................ 60%
.2018-08-28 18:39:48.653+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[()-[:type=0]->(:label=8)]: 2361]
Inconsistent with: 2360
...2018-08-28 18:39:48.654+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[()-[:type=0]->(:label=9)]: 2361]
Inconsistent with: 2360
...............2018-08-28 18:39:48.655+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[()-[:type=2]->(:label=8)]: 2361]
Inconsistent with: 2360
. 70%
..2018-08-28 18:39:48.656+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[()-[:type=2]->(:label=9)]: 2361]
Inconsistent with: 2360
.................. 80%
.................... 90%
...........2018-08-28 18:39:48.660+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[()-->(:label=8)]: 4722]
Inconsistent with: 4720
...2018-08-28 18:39:48.661+0000 ERROR [o.n.c.ConsistencyCheckService] The relationship count does not correspond with the expected count.
CountsEntry[RelationshipKey[()-->(:label=9)]: 4722]
Inconsistent with: 4720
...... 100%
2018-08-28 18:39:48.664+0000 WARN [o.n.c.ConsistencyCheckService] Inconsistencies found: ConsistencySummaryStatistics{
Number of errors: 23
Number of warnings: 0
Number of inconsistent RELATIONSHIP records: 4
Number of inconsistent LABEL_SCAN_DOCUMENT records: 2
Number of inconsistent INDEX records: 2
Number of inconsistent COUNTS records: 15
}
2018-08-28 18:39:48.701+0000 WARN [o.n.c.ConsistencyCheckService] See '/var/lib/neo4j/inconsistencies-2018-08-28.18.39.45.report' for a detailed consistency report.
org.neo4j.commandline.admin.CommandFailed: Inconsistencies found. See '/var/lib/neo4j/inconsistencies-2018-08-28.18.39.45.report' for details.
at org.neo4j.consistency.CheckConsistencyCommand.execute(CheckConsistencyCommand.java:203)
at org.neo4j.commandline.admin.AdminTool.execute(AdminTool.java:127)
at org.neo4j.commandline.admin.AdminTool.main(AdminTool.java:51)
command failed: Inconsistencies found. See '/var/lib/neo4j/inconsistencies-2018-08-28.18.39.45.report' for details.

[tom_geudens]

Strange (and clutching at straws here) ... could it be permissions ?

If you check the files in the graph.db folder on the persistent volume (after stopping the instance) ... does any of the original files (the ones created with the load) have a timestamp more recent than the load ?

Regards,
Tom

[mattszo]

They appear to be updating fine.
Reimported the db, ran some creates.

[tom_geudens]

Ok. I've been running every possible test I can think of this morning and can not reproduce it. I have one question left based on the commands you've shown and then I'm going to ask if you could share that dump with me so I can test with that.

The question is this ... in quite a few of the above commands (take for example the last one with the check-consistency) I notice that the image you use is neo4j, not (as I would expect) neo4j:3.2.2. As you said yourself, that would normally pull in the latest (3.4.6) which is not going to work correctly with a 3.2.3. dump (although it does seem to start). Could that be the issue ?

If not ... would you be willing to share that dump with me ?

Regards,
Tom

[andrew_bowman]

I think we're handling this issue on the Customer Success side.

Was able to recreate the issue with the provided dumped db, looks to be a problem with the .id files, the ids are likely not pointing at actual deleted records but good ones, explaining the overwriting.

By doing a restore, then deleting all .id files the problem goes away, we can create data without introducing inconsistencies. I'm scratching my head as to how this state was induced however.