Three findings:
1) Tried to use bolt instead of http. The same error still happened.
2) Using bolt resulted in slower Neo4j insertion by three times than http
in our busy insertion Neo4j-py2neo Python 3 case, i.e. the time period for
exactly the same input data took three times longer than using http. So, we
went back to http.
3) See similar error message from neo4j.log, the part above neo4j.server is
different from the one I posted, but the part from neo4j.server is the same:
2017-09-07 00:24:50.554+0000 ERROR Failed to generate JSON output.
org.eclipse.jetty.io.EofException
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:192)
at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:408)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:302)
at
org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:129)
at
org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:684)
at
org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:246)
at
org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:208)
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:480)
at
org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:768)
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:801)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:142)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:135)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:350)
at
com.sun.jersey.spi.container.servlet.WebComponent$Writer.write(WebComponent.java:300)
at
com.sun.jersey.spi.container.ContainerResponse$CommittingOutputStream.write(ContainerResponse.java:135)
at
org.neo4j.server.rest.web.TransactionalService$InterruptingOutputStream.write(TransactionalService.java:283)
at
org.codehaus.jackson.impl.Utf8Generator._flushBuffer(Utf8Generator.java:1754)
at
org.codehaus.jackson.impl.Utf8Generator._writeFieldName(Utf8Generator.java:420)
at
org.codehaus.jackson.impl.Utf8Generator.writeFieldName(Utf8Generator.java:282)
at
org.codehaus.jackson.JsonGenerator.writeNumberField(JsonGenerator.java:956)
at
org.neo4j.server.rest.transactional.ExecutionResultSerializer.writeStats(ExecutionResultSerializer.java:209)
at
org.neo4j.server.rest.transactional.ExecutionResultSerializer.statementResult(ExecutionResultSerializer.java:115)
at
org.neo4j.server.rest.transactional.TransactionHandle.executeStatements(TransactionHandle.java:316)
at
org.neo4j.server.rest.transactional.TransactionHandle.commit(TransactionHandle.java:150)
at
org.neo4j.server.rest.web.TransactionalService.lambda$executeStatementsAndCommit$28(TransactionalService.java:202)
at
org.neo4j.server.rest.web.TransactionalService$$Lambda$164/1266049947.write(Unknown
Source)
at
com.sun.jersey.core.impl.provider.entity.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:71)
at
com.sun.jersey.core.impl.provider.entity.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:57)
at
com.sun.jersey.spi.container.ContainerResponse.write(ContainerResponse.java:302)
at
com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1510)
at
com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419)
at
com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409)
at
com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409)
at
com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:558)
at
com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
at
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669)
at
org.neo4j.server.rest.web.CollectUserAgentFilter.doFilter(CollectUserAgentFilter.java:69)
at
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)
at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:221)
at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
at
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at
org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
at org.eclipse.jetty.server.Server.handle(Server.java:497)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
at
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
at
org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
at
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
at
org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcherImpl.writev0(Native Method)
at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51)
at sun.nio.ch.IOUtil.write(IOUtil.java:148)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504)
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:172)
... 55 more
2017-09-07 00:24:50.838+0000 ERROR Unable to reply to request, because the
client has closed the connection (Broken pipe).
2017-09-07 00:24:50.839+0000 ERROR Unable to reply to request, because the
client has closed the connection (Broken pipe).
Any idea?
Thanks,
Ray
On Tuesday, September 5, 2017 at 7:23:52 PM UTC-7, [email protected] wrote:
>
> > Would you mind raising an issue at github.com/neo4j/neo4j ?
> Just raised an issue at github.com/neo4j/neo4j .
> > Can you try to use bolt instead of http?
> Trying bolt in our environment now. Will report back if timeout happens
> with bolt or does not happen after a couple of days.
>
> Thanks Michael.
>
> Ray
>
> On Saturday, September 2, 2017 at 9:22:39 PM UTC-7, Michael Hunger wrote:
>>
>> Would you mind raising an issue at github.com/neo4j/neo4j ?
>> Seems like a server side http issue.
>>
>> Can you try to use bolt instead of http?
>>
>> Michael
>>
>>
>> On Sat, Sep 2, 2017 at 2:08 AM, <[email protected]> wrote:
>>
>>> Hi,
>>>
>>> Our Python 3 program using version 3.1.2 py2neo on Neo4j Community
>>> Edition version 3.0.3. with transaction size about 4000, i.e. we do a
>>> transaction commit after we put 4,000 Cypher statements to a transaction.
>>>
>>> We open the py2neo Graph as this
>>>
>>> from py2neo import Graph
>>>
>>> g = Graph(bolt = False, user = .., password = ..)
>>>
>>>
>>> Once in a long while we will get timeout error from Neo4j. Any idea why
>>> this kind of timeout happens? Are there any way to prevent this timeout
>>> errors from happening?
>>>
>>>
>>> (If I increase transaction size to 8000 or 9000, timeout occurs more
>>> often, at transaction size 4000 timeout happens only occasionally. But it
>>> we use transaction size less than 4000, the insertion throughput is
>>> affected, and we are not sure if timeout will not happen with transaction
>>> size 3000.)
>>>
>>>
>>> Stack trace of py2neo, exception log from neo4j.log and debug.log of
>>> when the timeout happened are included below.
>>>
>>>
>>> Note that our Python log time zone is 7 hours behind UTC.
>>>
>>>
>>> Python 3 log including py2neo stack trace:
>>>
>>> Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,886 - read_qosmos - INFO -
>>> /opt/trendmicro/ddna/engine/flow_processor.py, line 603: stack_list =
>>> traceback.extract_stack(limit=10) + \
>>>
>>> Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,886 - read_qosmos - INFO -
>>> /opt/trendmicro/ddna/engine/flow_processor.py, line 4048: tx_b.commit()
>>>
>>> Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,886 - read_qosmos - INFO -
>>> /opt/trendmicro/ddna/engine/venv-flow-processor/lib/python3.4/site-packages/py2neo/database/__init__.py,
>>>
>>> line 1059: self._post(commit=True)
>>>
>>> Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,886 - read_qosmos - INFO -
>>> /opt/trendmicro/ddna/engine/venv-flow-processor/lib/python3.4/site-packages/py2neo/database/__init__.py,
>>>
>>> line 1220: rs = resource.post({"statements": self.statements})
>>>
>>> Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,886 - read_qosmos - INFO -
>>> /opt/trendmicro/ddna/engine/venv-flow-processor/lib/python3.4/site-packages/py2neo/database/http.py,
>>>
>>> line 203: response = self.__base.post(body, headers, **kwargs)
>>>
>>> Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,887 - read_qosmos - INFO -
>>> /opt/trendmicro/ddna/engine/venv-flow-processor/lib/python3.4/site-packages/py2neo/packages/httpstream/http.py,
>>>
>>> line 984: return rq.submit(**kwargs)
>>>
>>> Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,887 - read_qosmos - INFO -
>>> /opt/trendmicro/ddna/engine/venv-flow-processor/lib/python3.4/site-packages/py2neo/packages/httpstream/http.py,
>>>
>>> line 362: raise SocketError(code, description, host_port=uri.host_port)
>>>
>>> Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,887 - read_qosmos -
>>> WARNING - mp 0, ctx 1 Got an exception from commit(): timed out
>>>
>>> Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,887 - read_qosmos - INFO -
>>> Type of Exception is <class 'py2neo.packages.httpstream.http.SocketError'>
>>>
>>>
>>>
>>> from neo4j.log
>>>
>>> 2017-09-01 18:38:38.733+0000 WARN badMessage:
>>> java.lang.IllegalStateException: too much data after closed for
>>> HttpChannelOverHttp@4b2cc33{r=5,c=false,a=IDLE,uri=-}
>>>
>>> 2017-09-01 19:01:35.111+0000 ERROR Failed to generate JSON output.
>>> java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
>>>
>>> java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout
>>> expired: 30000/30000 ms
>>>
>>> at
>>> org.eclipse.jetty.util.SharedBlockingCallback$Blocker.block(SharedBlockingCallback.java:234)
>>>
>>> at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:136)
>>>
>>> at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:350)
>>>
>>> at
>>> com.sun.jersey.spi.container.servlet.WebComponent$Writer.write(WebComponent.java:300)
>>>
>>> at
>>> com.sun.jersey.spi.container.ContainerResponse$CommittingOutputStream.write(ContainerResponse.java:135)
>>>
>>> at
>>> org.neo4j.server.rest.web.TransactionalService$InterruptingOutputStream.write(TransactionalService.java:283)
>>>
>>> at
>>> org.codehaus.jackson.impl.Utf8Generator._flushBuffer(Utf8Generator.java:1754)
>>>
>>> at
>>> org.codehaus.jackson.impl.Utf8Generator._writeFieldName(Utf8Generator.java:432)
>>>
>>> at
>>> org.codehaus.jackson.impl.Utf8Generator.writeFieldName(Utf8Generator.java:282)
>>>
>>> at
>>> org.codehaus.jackson.JsonGenerator.writeNumberField(JsonGenerator.java:956)
>>>
>>> at
>>> org.neo4j.server.rest.transactional.ExecutionResultSerializer.writeStats(ExecutionResultSerializer.java:209)
>>>
>>> at
>>> org.neo4j.server.rest.transactional.ExecutionResultSerializer.statementResult(ExecutionResultSerializer.java:115)
>>>
>>> at
>>> org.neo4j.server.rest.transactional.TransactionHandle.executeStatements(TransactionHandle.java:316)
>>>
>>> at
>>> org.neo4j.server.rest.transactional.TransactionHandle.commit(TransactionHandle.java:150)
>>>
>>> at
>>> org.neo4j.server.rest.web.TransactionalService.lambda$executeStatementsAndCommit$28(TransactionalService.java:202)
>>>
>>> at
>>> org.neo4j.server.rest.web.TransactionalService$$Lambda$169/499200393.write(Unknown
>>>
>>> Source)
>>>
>>> at
>>> com.sun.jersey.core.impl.provider.entity.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:71)
>>>
>>> at
>>> com.sun.jersey.core.impl.provider.entity.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:57)
>>>
>>> at
>>> com.sun.jersey.spi.container.ContainerResponse.write(ContainerResponse.java:302)
>>>
>>> at
>>> com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1510)
>>>
>>> at
>>> com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419)
>>>
>>> at
>>> com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409)
>>>
>>> at
>>> com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409)
>>>
>>> at
>>> com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:558)
>>>
>>> at
>>> com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733)
>>>
>>> at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
>>>
>>> at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
>>>
>>> at
>>> org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669)
>>>
>>> at
>>> org.neo4j.server.rest.web.CollectUserAgentFilter.doFilter(CollectUserAgentFilter.java:69)
>>>
>>> at
>>> org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
>>>
>>> at
>>> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)
>>>
>>> at
>>> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:221)
>>>
>>> at
>>> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
>>>
>>> at
>>> org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
>>>
>>> at
>>> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
>>>
>>> at
>>> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
>>>
>>> at
>>> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
>>>
>>> at
>>> org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)
>>>
>>> at
>>> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
>>>
>>> at org.eclipse.jetty.server.Server.handle(Server.java:497)
>>>
>>> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
>>>
>>> at
>>> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
>>>
>>> at org.eclipse.jetty.io
>>> .AbstractConnection$2.run(AbstractConnection.java:540)
>>>
>>> at
>>> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
>>>
>>> at
>>> org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
>>>
>>> at java.lang.Thread.run(Thread.java:745)
>>>
>>> Caused by: java.util.concurrent.TimeoutException: Idle timeout expired:
>>> 30000/30000 ms
>>>
>>> at org.eclipse.jetty.io
>>> .IdleTimeout.checkIdleTimeout(IdleTimeout.java:161)
>>>
>>> at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)
>>>
>>> at
>>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
>>>
>>> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
>>>
>>> at
>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
>>>
>>> at
>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
>>>
>>> at
>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>>>
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>>>
>>> ... 1 more
>>>
>>>
>>>
>>> from debug.log
>>>
>>>
>>> 2017-09-01 18:58:33.634+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] Log
>>> Rotation [8720]: Starting log pruning.
>>>
>>> 2017-09-01 18:58:33.635+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] Log
>>> Rotation [8720]: Log pruning complete.
>>>
>>> 2017-09-01 19:03:33.641+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl]
>>> Check Pointing triggered by scheduler for time threshold [100911780]:
>>> Starting
>>> check pointing...2017-09-01 19:03:33.641+0000 INFO
>>> [o.n.k.i.t.l.c.CheckPointerImpl]
>>> Check Pointing triggered by scheduler for time threshold [100911780]:
>>> Starting
>>> store flush...2017-09-01 19:03:33.778+0000 INFO
>>> [o.n.k.i.s.c.CountsTracker]
>>> About to rotate counts store at transaction 100911780 to
>>> [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.a], from
>>> [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.b].2017-09-01
>>> 19:03:33.780+0000 INFO [o.n.k.i.s.c.CountsTracker] Successfully
>>> rotated counts store at transaction 100911780 to
>>> [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.a], from
>>> [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.b].2017-09-01
>>> 19:03:37.653+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing
>>> triggered by scheduler for time threshold [100911780]: Store flush
>>> completed2017-09-01 19:03:37.653+0000 INFO
>>> [o.n.k.i.t.l.c.CheckPointerImpl]
>>> Check Pointing triggered by scheduler for time threshold [100911780]:
>>> Starting
>>> appending check point entry into the tx log...2017-09-01 19:03:37.654+0000
>>> INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by
>>> scheduler for time threshold [100911780]: Appending check point entry
>>> into the tx log completed2017-09-01 19:03:37.654+0000 INFO
>>> [o.n.k.i.t.l.c.CheckPointerImpl]
>>> Check Pointing triggered by scheduler for time threshold [100911780]:
>>> Check
>>> pointing completed2017-09-01 19:03:37.654+0000 INFO
>>> [o.n.k.i.t.l.p.LogPruningImpl]
>>> Log Rotation [8720]: Starting log pruning.2017-09-01 19:03:37.655+0000
>>> INFO [o.n.k.i.t.l.p.LogPruningImpl] Log Rotation [8720]: Log pruning
>>> complete.
>>>
>>> 2017-09-01 19:08:37.662+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl]
>>> Check Pointing triggered by scheduler for time threshold [100911792]:
>>> Starting
>>> check pointing...2017-09-01 19:08:37.662+0000 INFO
>>> [o.n.k.i.t.l.c.CheckPointerImpl]
>>> Check Pointing triggered by scheduler for time threshold [100911792]:
>>> Starting
>>> store flush...
>>>
>>> 2017-09-01 19:08:37.747+0000 INFO [o.n.k.i.s.c.CountsTracker] About to
>>> rotate counts store at transaction 100911792 to
>>> [/data/ddna/neo4j/data/databases/graph.d
>>>
>>> b/neostore.counts.db.b], from
>>> [/data/ddna/neo4j/data/databases/graph.db/neostore
>>>
>>> .counts.db.a].
>>>
>>> 2017-09-01 19:08:37.749+0000 INFO [o.n.k.i.s.c.CountsTracker]
>>> Successfully rotated counts store at transaction 100911792 to
>>> [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.b], from
>>> [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.a].
>>>
>>>
>>> Thanks!
>>>
>>> Ray
>>>
>>> --
>>> You received this message because you are subscribed to the Google
>>> Groups "Neo4j" group.
>>> To unsubscribe from this group and stop receiving emails from it, send
>>> an email to [email protected].
>>> For more options, visit https://groups.google.com/d/optout.
>>>
>>
>>
--
You received this message because you are subscribed to the Google Groups
"Neo4j" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
For more options, visit https://groups.google.com/d/optout.
