> 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] <javascript:>> 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] <javascript:>. >> 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.
