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.
