Neo4j Unmanaged Extension and GuardTimeoutException
I really need some advice regarding a problem I'm having with the unmanaged Neo4j extension I'm building in Java. I have created a very simple sample code that highlights my problem. The basic premise is that I would like to set
org.neo4j.server.webserver.limit.executiontime
for neo4j server to a reasonable amount of time for user requests (say 2 minutes) that come in through Cypher, other endpoints, etc. But I also have a few batch jobs that I need to do through this unmanaged extension and so I tried to split them into multiple transactions in 2 minutes. The problem I see is that although each of my transactions is less than 2 minutes long, once my process is running for 2 minutes, I get a GuardTimeoutException.
Here's an example. In this example, notice that I have limited the time to 2000 milliseconds, so I don't need all day to debug. (gets terribly close though!)
End point
/**
* Sample endpoint.
@GET
@Path("test")
@Produces(MediaType.APPLICATION_JSON)
public Response test(@Context GraphDatabaseService service) {
TestFile.test(service);
return Response.ok().build();
}
Logics
public static void test(final GraphDatabaseService service) {
for (int i = 0; i < 100000; i++) {
try (Transaction tx = service.beginTx();) {
final Node n = service.createNode();
n.addLabel(testLabel);
tx.success();
tx.close();
}
System.out.println("Added node");
}
}
I can see that each transaction only takes a fraction of a second since I am loading about 200 nodes before timeout. However, exactly 2 seconds after reaching the endpoint, I get this:
org.neo4j.kernel.guard.GuardTimeoutException: timeout occured (overtime=1)
at org.neo4j.kernel.guard.Guard$Timeout.check(Guard.java:132)
at org.neo4j.kernel.guard.Guard.check(Guard.java:43)
at org.neo4j.kernel.InternalAbstractGraphDatabase$5.createNode(InternalAbstractGraphDatabase.java:794)
at org.neo4j.kernel.impl.api.state.OldTxStateBridgeImpl.nodeCreate(OldTxStateBridgeImpl.java:120)
at org.neo4j.kernel.impl.api.state.TxStateImpl.nodeDoCreate(TxStateImpl.java:366)
at org.neo4j.kernel.impl.api.StateHandlingStatementOperations.nodeCreate(StateHandlingStatementOperations.java:99)
at org.neo4j.kernel.impl.api.ConstraintEnforcingEntityOperations.nodeCreate(ConstraintEnforcingEntityOperations.java:390)
at org.neo4j.kernel.impl.api.LockingStatementOperations.nodeCreate(LockingStatementOperations.java:207)
at org.neo4j.kernel.impl.api.OperationsFacade.nodeCreate(OperationsFacade.java:506)
at org.neo4j.kernel.InternalAbstractGraphDatabase.createNode(InternalAbstractGraphDatabase.java:1120)
at **TestFile.test(TestFile.java:15)
at **test(Jobs.java:48)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205)
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at org.neo4j.server.rest.transactional.TransactionalRequestDispatcher.dispatch(TransactionalRequestDispatcher.java:139)
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1469)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1400)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1349)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1339)
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:699)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:698)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1506)
at org.neo4j.server.guard.GuardingRequestFilter.doFilter(GuardingRequestFilter.java:68)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1477)
at org.neo4j.server.guard.GuardingRequestFilter.doFilter(GuardingRequestFilter.java:68)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1477)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:503)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:211)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1096)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:432)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:175)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1030)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:136)
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:445)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:268)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:229)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.run(AbstractConnection.java:358)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:601)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:532)
at java.lang.Thread.run(Thread.java:744)
As you can see, I tried tx.success (), tx.close (), whatever I can think of to make all transactions die when they are completed. Any advice is greatly appreciated!
update -------------
Michael. I followed the steps you suggested. I have a new java class that extends SPIPluginLifecycle and also added a new config file to / src / main / resources / META -INF / services. I see that this file ends up in a jar that goes under / plugins in META-INF / services. However, I don't see this initialization class being called at all. Heres the class and logs I see when I run.
public class GraphInitializer implements SPIPluginLifecycle {
private WebServer webServer;
@Override
public Collection<Injectable<?>> start(final GraphDatabaseService graphDatabaseService, final Configuration config) {
throw new IllegalAccessError();
}
@Override
public void stop() {
}
@Override
public Collection<Injectable<?>> start(final NeoServer neoServer) {
System.out.println("K starting!");
webServer = getWebServer(neoServer);
final Database database = neoServer.getDatabase();
final GraphDatabaseAPI graphDatabaseAPI = database.getGraph();
final Guard guard = graphDatabaseAPI.getDependencyResolver().resolveDependency(Guard.class);
final Filter filter = new GuardingRequestFilter(guard, 3000);
webServer.addFilter(filter, "/*" );
return null;
}
private WebServer getWebServer(final NeoServer neoServer) {
if (neoServer instanceof AbstractNeoServer) {
return ((AbstractNeoServer) neoServer).getWebServer();
}
throw new IllegalArgumentException("expected AbstractNeoServer");
}
Logs:
2014-10-06 16:14:23.009+0000 INFO [API] Mounted discovery module at [/]
2014-10-06 16:14:23.014+0000 INFO [API] Mounted REST API at [/db/data/]
2014-10-06 16:14:23.017+0000 INFO [API] Mounted management API at [/db/manage/]
2014-10-06 16:14:23.017+0000 INFO [API] Mounted third-party JAX-RS package [***] at [/kristen]
2014-10-06 16:14:23.017+0000 INFO [API] Mounted webadmin at [/webadmin]
2014-10-06 16:14:23.017+0000 INFO [API] Mounted Neo4j Browser at [/browser]
2014-10-06 16:14:23.070+0000 INFO [API] Mounting static content at [/webadmin] from [webadmin-html]
2014-10-06 16:14:23.124+0000 INFO [API] Mounting static content at [/browser] from [browser]
12:14:23.126 [main] WARN o.e.j.server.handler.ContextHandler - o.e.j.s.ServletContextHandler@1cb1c025{/,null,null} contextPath ends with /
12:14:23.127 [main] WARN o.e.j.server.handler.ContextHandler - Empty contextPath
12:14:23.131 [main] INFO org.eclipse.jetty.server.Server - jetty-9.0.5.v20130815
12:14:23.155 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.s.h.MovedContextHandler@5de15910{/,null,AVAILABLE}
12:14:23.245 [main] INFO o.e.j.w.StandardDescriptorProcessor - NO JSP Support for /webadmin, did not find org.apache.jasper.servlet.JspServlet
12:14:23.255 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.w.WebAppContext@4b45c74e{/webadmin,jar:file:/usr/local/Cellar/neo4j/2.1.3/libexec/system/lib/neo4j-server-2.1.3-static-web.jar!/webadmin-html,AVAILABLE}
12:14:23.668 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@2917eb65{/kristen,null,AVAILABLE}
12:14:23.817 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@54589209{/db/manage,null,AVAILABLE}
12:14:24.003 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@68a1f8e7{/db/data,null,AVAILABLE}
12:14:24.021 [main] INFO o.e.j.w.StandardDescriptorProcessor - NO JSP Support for /browser, did not find org.apache.jasper.servlet.JspServlet
12:14:24.022 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.w.WebAppContext@438e0daa{/browser,jar:file:/usr/local/Cellar/neo4j/2.1.3/libexec/system/lib/neo4j-browser-2.1.3.jar!/browser,AVAILABLE}
12:14:24.103 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@1cb1c025{/,null,AVAILABLE}
12:14:24.115 [main] INFO o.e.jetty.server.ServerConnector - Started ServerConnector@75b61dd7{HTTP/1.1}{localhost:7474}
12:14:24.503 [main] INFO o.e.jetty.server.ServerConnector - Started ServerConnector@6464d61f{SSL-HTTP/1.1}{localhost:7473}
2014-10-06 16:14:24.503+0000 INFO [API] Server started on: http://localhost:7474/
2014-10-06 16:14:24.504+0000 INFO [API] Remote interface ready and available at [http://localhost:7474/]
I was expecting a newline entry or whatever - also my changes to add a timeout don't really work, so I'm pretty sure these changes didn't have an impact. Is there something extra that I should add to neo4j-server.properties, neo4j.properties, etc.? I have already successfully added the line that installs the unmanaged extension.
Thank you!
source to share
A small transaction makes it slower as each one has to be flushed to disk. It usually makes sense to add up to 50k Nodes in one tx, which will take less than a second.
For your guard filter, this is just a servlet filter, so you can also just check the Neo4j source code where it is installed and in the init of your extension install it yourself, but exclude the endpoints you want to execute.
B: org.neo4j.server.AbstractNeoServer
line 488
Filter filter = new GuardingRequestFilter( guard,
getConfiguration().getInt( Configurator.WEBSERVER_LIMIT_EXECUTION_TIME_PROPERTY_KEY ) );
webServer.addFilter( filter, "/*" );
You can use an extension initializer to add your custom filter as shown here:
you need to add a file like this that contains the name of your initializer:
source to share
Solution Written by Michael Hung, worked great with several of my training points along the way.
- I had to update the org.neo4j.server.thirdparty_jaxrs_classes property in neo4j-server.properties in a more root directory since I didn't put my initializer in the same directory as my java api files.
- The start () method should have returned an empty collection.
- I was able to use several different filters to specify time limits for different endpoints.
Final code below:
@Override
public Collection<Injectable<?>> start(final NeoServer neoServer) {
webServer = getWebServer(neoServer);
final Database database = neoServer.getDatabase();
final GraphDatabaseAPI graphDatabaseAPI = database.getGraph();
final Guard guard = graphDatabaseAPI.getDependencyResolver().resolveDependency(Guard.class);
final Filter filter = new GuardingRequestFilter(guard, 600);
webServer.addFilter(filter, "/*" );
final Filter filter2 = new GuardingRequestFilter(guard, 3000);
webServer.addFilter(filter2, "*/batch" );
return Collections.emptyList();
}
source to share