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 a long while we will get timeout error from Neo4j. Any idea why this kind of timeout happens? 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]. -- 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 neo4j+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/d/optout.