4

For my data import I suddenly get the following error:

neo4j.exceptions.DatabaseError: NOT PART OF CHAIN! RelationshipTraversalCursor[id=328769435, open state with: denseNode=false, next=328769435, mode=regular, underlying record=Relationship[328769435,used=false,source=0,target=0,type=0,sPrev=0,sNext=0,tPrev=0,tNext=0,prop=0,secondaryUnitId=-1,!sFirst,!tFirst] ]

What does this error actually mean? And how could I debug it further?

I haven't found any documentation on this.

last part of the debug.log (more not allowed by StackOverflow):

2018-07-19 14:29:57.551+0000 ERROR [o.n.b.v.r.ErrorReporter] Client 

...
org.neo4j.cypher.internal.runtime.slotted.pipes.ApplySlottedPipe$$anonfun$internalCreateResults$1.apply(ApplySlottedPipe.scala:34)
        at scala.collection.Iterator$$anon$12.nextCur(Iterator.scala:435)
        at scala.collection.Iterator$$anon$12.hasNext(Iterator.scala:441)
        at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:409)
        at scala.collection.Iterator$class.foreach(Iterator.scala:891)
        at scala.collection.AbstractIterator.foreach(Iterator.scala:1334)
        at scala.collection.generic.Growable$class.$plus$plus$eq(Growable.scala:59)
        at scala.collection.immutable.VectorBuilder.$plus$plus$eq(Vector.scala:732)
        at scala.collection.immutable.VectorBuilder.$plus$plus$eq(Vector.scala:708)
        at scala.collection.TraversableOnce$class.to(TraversableOnce.scala:310)
        at scala.collection.AbstractIterator.to(Iterator.scala:1334)
        at scala.collection.TraversableOnce$class.toIndexedSeq(TraversableOnce.scala:300)
        at scala.collection.AbstractIterator.toIndexedSeq(Iterator.scala:1334)
        at org.neo4j.cypher.internal.runtime.slotted.pipes.EagerSlottedPipe.internalCreateResults(EagerSlottedPipe.scala:40)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:76)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.runtime.interpreted.pipes.PipeWithSource.createResults(Pipe.scala:72)
        at org.neo4j.cypher.internal.compatibility.v3_4.runtime.executionplan.BaseExecutionResultBuilderFactory$BaseExecutionWorkflowBuilder.createResults(DefaultExecutionResultBuilderFactory.scala:105)
        at org.neo4j.cypher.internal.compatibility.v3_4.runtime.executionplan.BaseExecutionResultBuilderFactory$BaseExecutionWorkflowBuilder.build(DefaultExecutionResultBuilderFactory.scala:77)
        at org.neo4j.cypher.internal.compatibility.v3_4.runtime.BuildInterpretedExecutionPlan$$anonfun$getExecutionPlanFunction$1.apply(BuildInterpretedExecutionPlan.scala:97)
        at org.neo4j.cypher.internal.compatibility.v3_4.runtime.BuildInterpretedExecutionPlan$$anonfun$getExecutionPlanFunction$1.apply(BuildInterpretedExecutionPlan.scala:80)
        at org.neo4j.cypher.internal.BuildSlottedExecutionPlan$SlottedExecutionPlan.run(BuildSlottedExecutionPlan.scala:152)
        at org.neo4j.cypher.internal.compatibility.LatestRuntimeVariablePlannerCompatibility$ExecutionPlanWrapper$$anonfun$run$1.apply(LatestRuntimeVariablePlannerCompatibility.scala:128)
        at org.neo4j.cypher.internal.compatibility.LatestRuntimeVariablePlannerCompatibility$ExecutionPlanWrapper$$anonfun$run$1.apply(LatestRuntimeVariablePlannerCompatibility.scala:124)
        at org.neo4j.cypher.exceptionHandler$runSafely$.apply(exceptionHandler.scala:89)
        at org.neo4j.cypher.internal.compatibility.LatestRuntimeVariablePlannerCompatibility$ExecutionPlanWrapper.run(LatestRuntimeVariablePlannerCompatibility.scala:124)
        at org.neo4j.cypher.internal.PreparedPlanExecution.execute(PreparedPlanExecution.scala:29)
        at org.neo4j.cypher.internal.ExecutionEngine.execute(ExecutionEngine.scala:119)
        at org.neo4j.cypher.internal.javacompat.ExecutionEngine.executeQuery(ExecutionEngine.java:61)
        at org.neo4j.bolt.v1.runtime.TransactionStateMachineSPI$1.start(TransactionStateMachineSPI.java:144)
        at org.neo4j.bolt.v1.runtime.TransactionStateMachine$State.startExecution(TransactionStateMachine.java:446)
        at org.neo4j.bolt.v1.runtime.TransactionStateMachine$State$2.run(TransactionStateMachine.java:343)
        at org.neo4j.bolt.v1.runtime.TransactionStateMachine.run(TransactionStateMachine.java:81)
        at org.neo4j.bolt.v1.runtime.BoltStateMachine$State$2.run(BoltStateMachine.java:456)
        at org.neo4j.bolt.v1.runtime.BoltStateMachine.run(BoltStateMachine.java:222)
        at org.neo4j.bolt.v1.messaging.BoltMessageRouter.lambda$onRun$3(BoltMessageRouter.java:93)
        at org.neo4j.bolt.runtime.MetricsReportingBoltConnection.lambda$enqueue$0(MetricsReportingBoltConnection.java:69)
        at org.neo4j.bolt.runtime.DefaultBoltConnection.processNextBatch(DefaultBoltConnection.java:193)
        at org.neo4j.bolt.runtime.MetricsReportingBoltConnection.processNextBatch(MetricsReportingBoltConnection.java:87)
        at org.neo4j.bolt.runtime.DefaultBoltConnection.processNextBatch(DefaultBoltConnection.java:143)
        at org.neo4j.bolt.runtime.ExecutorBoltScheduler.executeBatch(ExecutorBoltScheduler.java:163)
        at org.neo4j.bolt.runtime.ExecutorBoltScheduler.lambda$null$0(ExecutorBoltScheduler.java:145)
        at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:748)

This also happens now for files which I successfully imported before.

This must have to do something with my cypher query because it works when I reduce it to the absolute minimum, but it would be helpful to understand the error.

EDIT - TRYING TO DEBUG

Now I am quite stuck with this error.

With this super minimal Cypher query from my script everything works fine:

WITH $custom_dict as pubmed_list
UNWIND pubmed_list as article
    MERGE (p:Publication {pmid: COALESCE (article.pmid, 'NO-PMID')})
    ON CREATE SET p.title = article.article_title, p.journal_title = article.journal_title, p.db = 'pubmed'

However, when I add this:

    MERGE (dc:Date { year: COALESCE (article.year_revised, 'NO-YEAR-COMPLETION') })
    MERGE (p)-[:COMPLETED]->(dc)

    MERGE (dr:Date { year: COALESCE (article.year_completed, 'NO-YEAR-REVISION')})
    MERGE (p)-[:REVISED]->(dr)

The dict I am passing for UNWINDing looks also perfectly fine: enter image description here

EDIT 2 - CONSISTENCY CHECK

After running a consistency check:

$ "$NEO4J_HOME"/bin/neo4j-admin check-consistency --database=graph.db

It starts like this:

2018-07-20 08:41:15.337+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Selected RecordFormat:StandardV3_4[v0.A.9] record format from store /Users/rich/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-4ca696a4-add3-4f69-a97b-1b89ce8e854b/installation-3.4.0/data/databases/graph.db
2018-07-20 08:41:15.340+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Format not configured. Selected format from the store: RecordFormat:StandardV3_4[v0.A.9]

Then I get a few thousands of these:

2018-07-20 08:42:49.837+0000 ERROR [o.n.c.ConsistencyCheckService] The referenced relationship group record is not in use.
    Node[145800979,used=true,group=8661147,prop=275750014,labels=Inline(0x1000000000:[0]),light,secondaryUnitId=-1]
    Inconsistent with: RelationshipGroup[8661147,type=0,out=0,in=0,loop=0,prev=-1,next=0,used=false,owner=0,secondaryUnitId=-1]

Then it continues with:

...  10%
....................  20%
................2018-07-20 08:49:01.023+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.

Now it runs forever with the error described before, like this:

Inconsistent with: Node[6577082,used=true,rel=329016678,prop=11682171,labels=Inline(0x1000000000:[0]),light,secondaryUnitId=-1]
2018-07-20 09:07:05.171+0000 ERROR [o.n.c.ConsistencyCheckService] This record should be the first in the target chain, but the target node does not reference this record.
    Relationship[314188818,used=true,source=140353187,target=78456590,type=4,sPrev=314188819,sNext=314188812,tCount=32,tNext=301551374,prop=-1,secondaryUnitId=-1,!sFirst, tFirst]

and this:

2018-07-20 09:08:14.715+0000 ERROR [o.n.c.ConsistencyCheckService] The next record in the target chain does not have this record as its previous record.
    Relationship[192261,used=true,source=28336,target=5180,type=4,sPrev=192264,sNext=192260,tPrev=191008,tNext=184760,prop=-1,secondaryUnitId=-1,!sFirst,!tFirst]
    Inconsistent with: Relationship[184760,used=true,source=24761,target=5180,type=4,sPrev=184750,sNext=184761,tPrev=184738,tNext=192261,prop=-1,secondaryUnitId=-1,!sFirst,!tFirst]

What does it mean for my database and how could I fix it?

Abbas Gadhia
  • 14,532
  • 10
  • 61
  • 73
Rich Steinmetz
  • 1,020
  • 13
  • 28
  • Can you try running a [consistency check](https://neo4j.com/docs/operations-manual/current/tools/consistency-checker/) on your database? Maybe something got corrupted. – InverseFalcon Jul 19 '18 at 20:12
  • @InverseFalcon I updated my answer with the consistency check. It shows errors for an hour now. Does it even make sense to let the consistency check run through? It seems like there are millions of corrupted records or whatever it is. – Rich Steinmetz Jul 20 '18 at 09:21

2 Answers2

4

Looks like the database got corrupted. This usually happens either due to running out of disk space while Neo4j is running (which should now be mitigated with the latest release), or due to copying the db (filecopy, as opposed to the hot backup functionality with neo4j-admin backup) or otherwise modifying the files while Neo4j is running.

You should take a backup of the database (disable the consistency check, you won't need that again) and use the store copy utils to rebuild the db from the backup, then restore the instance (or cluster) from the rebuilt data store.

The rebuild store skips all corrupted records, so you may want to sanity check the data after the operation is complete.

InverseFalcon
  • 29,576
  • 4
  • 38
  • 51
  • thank you, I will try this one, as soon as I get the Developer/Education Edition, which is needed to perform `neo4j-admin backup`. Is it possible that a corruption comes up due to a changing/corrupted cypher statement or from manipulating the database while importing stuff(e.g. running algorithms/performing MERGE statements while the import runs)? – Rich Steinmetz Jul 20 '18 at 19:22
  • 1
    I would say no to both of those. Bad cypher will either not run at all, or will make changes to your data that may be unexpected, but it won't corrupt the data. Likewise on concurrent changes while importing, that shouldn't induce corruption. – InverseFalcon Jul 20 '18 at 19:55
  • Ah ok, and by 'disk' in your answer you mean RAM and/or hard drive? I easily could have run out of RAM but not gard drive. – Rich Steinmetz Jul 21 '18 at 07:24
0

I could reproduce this error in one of my tests by simply invoking a traversal from 2 threads on a single transaction. As such, from the neo4j documentation about transactions, such an access pattern is not encouraged.

https://neo4j.com/docs/java-reference/4.1/javadocs/org/neo4j/graphdb/Transaction.html

Note that transactions should be used by a single thread only. It is generally not safe to use a transaction from multiple threads. Doing so will lead to undefined behavior.

Alternatively, if your traversal is stuck in an infinite loop or maybe waiting on a lock (inspect your thread dump), then this could also be an indication of running traversals on a single transaction with multiple threads or using Nodes/Relationships from other uncommitted transactions in another transaction.

Abbas Gadhia
  • 14,532
  • 10
  • 61
  • 73