Error while loading data in Neo4j (Python Driver)

[amitshipra]

Got this error while loading data in Neo (using MERGE). Any pointers?

ERROR:neobolt:Failed to write data to connection Address(host='::1', port=7666, flow_info=0, scope_id=0) ("10054; 'An existing connection was forcibly closed by the remote host'; None; 10054; None")
ERROR:neobolt:Failed to write data to connection Address(host='::1', port=7666, flow_info=0, scope_id=0) ("10054; 'An existing connection was forcibly closed by the remote host'; None; 10054; None")
Traceback (most recent call last):
File "C:/Projects/PyMktDeps/mkt_data_deps/official/csv_loader_graph.py", line 92, in load
instrPath=instrPath, pKey=pKey, pType=pType)
File "C:\Users\nbd3qdj\anaconda3\lib\site-packages\neo4j_init_.py", line 498, in run
self._connection.send()
File "C:\Users\nbd3qdj\anaconda3\lib\site-packages\neobolt\direct.py", line 388, in send
self._send()
File "C:\Users\nbd3qdj\anaconda3\lib\site-packages\neobolt\direct.py", line 406, in _send
self.socket.sendall(data)
ConnectionResetError: [WinError 10054] An existing connection was forcibly closed by the remote host

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "C:/Projects/PyMktDeps/mkt_data_deps/official/csv_loader_graph.py", line 172, in
load(NEO4J_CONFIG)
File "C:/Projects/PyMktDeps/mkt_data_deps/official/csv_loader_graph.py", line 93, in load
File "C:\Users\nbd3qdj\anaconda3\lib\site-packages\neo4j_init_.py", line 363, in exit
self.close()
File "C:\Users\nbd3qdj\anaconda3\lib\site-packages\neo4j_init_.py", line 401, in close
self.disconnect(sync=True)
File "C:\Users\nbd3qdj\anaconda3\lib\site-packages\neo4j_init.py", line 380, in _disconnect
self._connection.sync()
File "C:\Users\nbd3qdj\anaconda3\lib\site-packages\neobolt\direct.py", line 511, in sync
self.send()
File "C:\Users\nbd3qdj\anaconda3\lib\site-packages\neobolt\direct.py", line 388, in send
self._send()
File "C:\Users\nbd3qdj\anaconda3\lib\site-packages\neobolt\direct.py", line 406, in _send
self.socket.sendall(data)
ConnectionResetError: [WinError 10054] An existing connection was forcibly closed by the remote host
ERROR:neobolt:Failed to write data to connection Address(host='::1', port=7666, flow_info=0, scope_id=0) ("10054; 'An existing connection was forcibly closed by the remote host'; None; 10054; None")
ERROR:neobolt:Failed to write data to connection Address(host='::1', port=7666, flow_info=0, scope_id=0) ("10054; 'An existing connection was forcibly closed by the remote host'; None; 10054; None")

[kees_vegter]

Hi,

It looks like the neo4j server went down, or another reason why the connection was lost.
It would help if you show me the neo4j.log and debug.log file of the neo4j server...

regards
Kees

[amitshipra]

Here are the logs:

2019-05-16 13:46:09.292+0000 ERROR [o.n.b.v.m.BoltRequestMessageReaderV3] Failed to write response to driver Bolt connection [/0:0:0:0:0:0:0:1:52680] will be closed because the client did not consume outgoing buffers for 00:15:00.000 which is not expected.
org.neo4j.bolt.messaging.BoltIOException: Bolt connection [/0:0:0:0:0:0:0:1:52680] will be closed because the client did not consume outgoing buffers for 00:15:00.000 which is not expected.
at org.neo4j.bolt.v1.transport.ChunkedOutput.flush(ChunkedOutput.java:136)
at org.neo4j.bolt.v1.transport.ChunkedOutput.messageSucceeded(ChunkedOutput.java:105)
at org.neo4j.bolt.v1.messaging.BoltResponseMessageWriterV1.packCompleteMessageOrFail(BoltResponseMessageWriterV1.java:105)
at org.neo4j.bolt.v1.messaging.BoltResponseMessageWriterV1.write(BoltResponseMessageWriterV1.java:79)
at org.neo4j.bolt.v1.messaging.MessageProcessingHandler.onFinish(MessageProcessingHandler.java:102)
at org.neo4j.bolt.v1.runtime.BoltStateMachineV1.after(BoltStateMachineV1.java:132)
at org.neo4j.bolt.v3.BoltStateMachineV3.after(BoltStateMachineV3.java:89)
at org.neo4j.bolt.v1.runtime.BoltStateMachineV1.process(BoltStateMachineV1.java:97)
at org.neo4j.bolt.messaging.BoltRequestMessageReader.lambda$doRead$1(BoltRequestMessageReader.java:89)
at org.neo4j.bolt.runtime.DefaultBoltConnection.processNextBatch(DefaultBoltConnection.java:191)
at org.neo4j.bolt.runtime.DefaultBoltConnection.processNextBatch(DefaultBoltConnection.java:139)
at org.neo4j.bolt.runtime.ExecutorBoltScheduler.executeBatch(ExecutorBoltScheduler.java:171)
at org.neo4j.bolt.runtime.ExecutorBoltScheduler.lambda$scheduleBatchOrHandleError$2(ExecutorBoltScheduler.java:154)
at java.util.concurrent.CompletableFuture$AsyncSupply.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: org.neo4j.bolt.transport.TransportThrottleException: Bolt connection [/0:0:0:0:0:0:0:1:52680] will be closed because the client did not consume outgoing buffers for 00:15:00.000 which is not expected.
at org.neo4j.bolt.transport.TransportWriteThrottle.acquire(TransportWriteThrottle.java:101)
at org.neo4j.bolt.v1.transport.ChunkedOutput.flush(ChunkedOutput.java:132)
... 16 more
2019-05-16 13:46:09.296+0000 WARN [io.netty.channel.AbstractChannelHandlerContext] An exception 'java.lang.NullPointerException' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:

[kees_vegter]

HI,

I saw you removed the other one. Looking at this error it seems that a query is done in python which is not consumed after 15 minutes. Is there a query where you just run a query and don't consume the results i.e. not process the records which are returned? Or are you doing a query and while processing the return records in a loop you do a lot of other time-consuming stuff?

regards

[amitshipra]

Driver is Python - 1.7.2

Query is to create/load the data in graph by merging/creating. We are using session.run like:
session.run(query, bookId=bookId, instrId=instrId, instrPath=instrPath, pKey=pKey, pType=pType)

Query:
MERGE (book:Book {bookId:{bookId}})
MERGE (instr:Instrument {instrId:{instrId}, instrPath:{instrPath}})
MERGE (dep:Dependency {key:{pKey}, type:{pType}})
WITH book, instr, dep
OPTIONAL match (book)-[:CONTAINS]->(x) with book, instr,dep, collect(distinct x) as known_instr
OPTIONAL match (instr)-[:DEPENDENCIES]->(y) with book,instr,dep,known_instr,collect(distinct y) as known_dep
FOREACH (n in ( CASE WHEN NOT instr IN known_instr THEN [1] ELSE END ) | CREATE (book)-[:CONTAINS]->(instr))
FOREACH (n in ( CASE WHEN NOT dep IN known_dep THEN [1] ELSE END ) | CREATE (instr)-[:DEPENDENCIES]->(dep))

[amitshipra]

I tried to create the Nodes for Instruments/Books and Dependencies separately but its getting 'stuck' when the number of nodes created is large within one transaction.

Total Instruments [141154]

Basically, we begin_transaction, loop in the instruments and fire:

        tx.run("CREATE (:Instrument {instrId:{instrId}, instrPath:{instrPath}})", instrId=instrId,instrPath=instrPath)

it takes 19.697 seconds for loop to execute but when tx.commit() is called - the process just hangs. No log movement at on server side as well.

Last Server side logs were:

2019-05-16 14:37:33.729+0000 WARN [o.n.b.r.BoltConnectionReadLimiter] Channel [/0:0:0:0:0:0:0:1:54413]: consumed messages on the worker queue below 100, auto-read is being enabled.
2019-05-16 14:37:34.097+0000 WARN [o.n.b.r.BoltConnectionReadLimiter] Channel [/0:0:0:0:0:0:0:1:54413]: client produced 301 messages on the worker queue, auto-read is being disabled.

[amitshipra]

Hi @kees.vegter

As expected, the program crashed with same stack trace as pasted above. Here are the server side logs. I have added the previous two log lines pasted below. you can check the timestamps.

2019-05-16 14:37:33.611+0000 WARN [o.n.b.r.BoltConnectionReadLimiter] Channel [/0:0:0:0:0:0:0:1:54413]: client produced 301 messages on the worker queue, auto-read is being disabled.
2019-05-16 14:37:33.729+0000 WARN [o.n.b.r.BoltConnectionReadLimiter] Channel [/0:0:0:0:0:0:0:1:54413]: consumed messages on the worker queue below 100, auto-read is being enabled.
2019-05-16 14:37:34.097+0000 WARN [o.n.b.r.BoltConnectionReadLimiter] Channel [/0:0:0:0:0:0:0:1:54413]: client produced 301 messages on the worker queue, auto-read is being disabled.
2019-05-16 14:46:17.873+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Checkpoint triggered by scheduler for time threshold @ txId: 287419 checkpoint started...
2019-05-16 14:46:17.898+0000 INFO [o.n.k.i.s.c.CountsTracker] Rotated counts store at transaction 287419 to [C:\neo4j-py\data\databases\graph.db\neostore.counts.db.b], from [C:\neo4j-py\data\databases\graph.db\neostore.counts.db.a].
2019-05-16 14:46:17.908+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Checkpoint triggered by scheduler for time threshold @ txId: 287419 checkpoint completed in 34ms
2019-05-16 14:46:17.909+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] No log version pruned, last checkpoint was made in version 1
2019-05-16 14:52:34.524+0000 ERROR [o.n.b.r.DefaultBoltConnection] Unexpected error detected in bolt session 'bolt-362'. Bolt connection [/0:0:0:0:0:0:0:1:54413] will be closed because the client did not consume outgoing buffers for 00:15:00.000 which is not expected.
org.neo4j.bolt.messaging.BoltIOException: Bolt connection [/0:0:0:0:0:0:0:1:54413] will be closed because the client did not consume outgoing buffers for 00:15:00.000 which is not expected.
at org.neo4j.bolt.v1.transport.ChunkedOutput.flush(ChunkedOutput.java:136)
at org.neo4j.bolt.runtime.DefaultBoltConnection.processNextBatch(DefaultBoltConnection.java:204)
at org.neo4j.bolt.runtime.DefaultBoltConnection.processNextBatch(DefaultBoltConnection.java:139)
at org.neo4j.bolt.runtime.ExecutorBoltScheduler.executeBatch(ExecutorBoltScheduler.java:171)
at org.neo4j.bolt.runtime.ExecutorBoltScheduler.lambda$scheduleBatchOrHandleError$2(ExecutorBoltScheduler.java:154)
at java.util.concurrent.CompletableFuture$AsyncSupply.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: org.neo4j.bolt.transport.TransportThrottleException: Bolt connection [/0:0:0:0:0:0:0:1:54413] will be closed because the client did not consume outgoing buffers for 00:15:00.000 which is not expected.
at org.neo4j.bolt.transport.TransportWriteThrottle.acquire(TransportWriteThrottle.java:101)
at org.neo4j.bolt.v1.transport.ChunkedOutput.flush(ChunkedOutput.java:132)
... 8 more
2019-05-16 14:52:34.525+0000 WARN [io.netty.channel.AbstractChannelHandlerContext] An exception 'java.lang.NullPointerException' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:

[amitshipra]

@kees.vegter Additional info that may help.

The browser showed that node with label: "Instrument" created but no data for that. Probably the tx.commit() failure didn't send the data but information about Node:Instrument was sent to server.

Is there any limit on Python driver on number of operations that could be tx.run() before calling commit()?