Random no node exists error

[bwallis42]

I'm running some volume/load tests against 3.0.0.beta3 in a jboss 7.2.0 snapshot and I have a couple of problems. One is an apparent memory leak in queries that I am trying to isolate and will post on later. The other is a very occasional error where a node that should exist is not found.

These tests I am running were working OK against 2.8.1 a while ago and have not been modified much to run against 3.0. The error does occur randomly and there are 10s of 1000s of nodes in the repository.

From the logging shown below it looks like a query found the node and also found another one and the error occurs when the system is asked to move the first node to under the second one. I know more info is probably required but I'm posting this incase it rings a bell with someone.

{noquote}
05:49:05,264 DEBUG [au.com.infomedix.jcrloadtest.jcrserver.operations.QueryNodesOperation] (http-localhost/127.0.0.1:8080-1) Run Query = select * from [inf:document] as d where d.[infm:unitCode] = "p1007-r25"
05:49:05,296 DEBUG [au.com.infomedix.jcrloadtest.jcrserver.operations.QueryNodesOperation] (http-localhost/127.0.0.1:8080-1)         Node 786d2b37-05ec-4133-b3dc-e95914362d73 path=/inf:patient[58]/inf:section[5]/inf:items[29]
05:49:05,310 DEBUG [au.com.infomedix.jcrloadtest.jcrserver.operations.QueryNodesOperation] (http-localhost/127.0.0.1:8080-1) Run Query = select * from [inf:episode] as e where e.[inf:id] = '00002009-008' and e.[inf:ns] = 'IHN'
05:49:05,355 DEBUG [au.com.infomedix.jcrloadtest.jcrserver.operations.QueryNodesOperation] (http-localhost/127.0.0.1:8080-1)         Node be1d8d69-8104-443d-94d6-ad5d95916070 path=/inf:patient[110]/inf:section[7]/inf:items[9]
05:49:05,380 DEBUG [au.com.infomedix.jcrloadtest.jcrserver.operations.MoveNodeOperation] (http-localhost/127.0.0.1:8080-1) Move Node 786d2b37-05ec-4133-b3dc-e95914362d73 path=/inf:patient[58]/inf:section[5]/inf:items[29] to be1d8d69-8104-443d-94d6-ad5d95916070 path=/inf:patient[110]/inf:section[7]/inf:items[9]
05:49:05,424 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/JcrServer].[au.com.infomedix.jcrloadtest.jcrserver.restapi.JcrLoadTestApplication]] (http-localhost/127.0.0.1:8080-1) Servlet.service() for servlet au.com.infomedix.jcrloadtest.jcrserver.restapi.JcrLoadTestApplication threw exception: org.jboss.resteasy.spi.UnhandledException: java.lang.RuntimeException: Could not perform operation over the repository
        at org.jboss.resteasy.core.SynchronousDispatcher.handleApplicationException(SynchronousDispatcher.java:340) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.core.SynchronousDispatcher.handleException(SynchronousDispatcher.java:214) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.core.SynchronousDispatcher.handleInvokerException(SynchronousDispatcher.java:190) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:540) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [resteasy-jaxrs-2.3.3.Final.jar:]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.17.Final.jar:]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.17.Final.jar:]
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.17.Final.jar:]
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.17.Final.jar:]
        at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.17.Final.jar:]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.17.Final.jar:]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.17.Final.jar:]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:372) [jbossweb-7.0.17.Final.jar:]
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.17.Final.jar:]
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.17.Final.jar:]
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.17.Final.jar:]
        at java.lang.Thread.run(Thread.java:680) [classes.jar:1.6.0_33]
Caused by: java.lang.RuntimeException: Could not perform operation over the repository
        at au.com.infomedix.jcrloadtest.jcrserver.repo.JcrService.executeCommand(JcrService.java:92) [classes:]
        at au.com.infomedix.jcrloadtest.jcrserver.restapi.NodeCrudMethods.moveNode(NodeCrudMethods.java:98) [classes:]
        at sun.reflect.GeneratedMethodAccessor77.invoke(Unknown Source) [:1.6.0_33]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [classes.jar:1.6.0_33]
        at java.lang.reflect.Method.invoke(Method.java:597) [classes.jar:1.6.0_33]
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:167) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:211) [resteasy-jaxrs-2.3.3.Final.jar:]
        at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525) [resteasy-jaxrs-2.3.3.Final.jar:]
        ... 19 more
Caused by: javax.jcr.PathNotFoundException: No node exists at path '/inf:patient[58]/inf:section[5]/inf:items[29]' in workspace "default"
        at org.modeshape.jcr.JcrSession.cachedNode(JcrSession.java:509)
        at org.modeshape.jcr.JcrSession.node(JcrSession.java:530)
        at org.modeshape.jcr.JcrSession.node(JcrSession.java:549)
        at org.modeshape.jcr.JcrSession.move(JcrSession.java:834)
        at au.com.infomedix.jcrloadtest.jcrserver.operations.MoveNodeOperation.performOperation(MoveNodeOperation.java:33) [classes:]
        at au.com.infomedix.jcrloadtest.jcrserver.operations.MoveNodeOperation.performOperation(MoveNodeOperation.java:1) [classes:]
        at au.com.infomedix.jcrloadtest.jcrserver.repo.AbstractJcrOperation.execute(AbstractJcrOperation.java:44) [classes:]
        at au.com.infomedix.jcrloadtest.jcrserver.repo.JcrService.executeCommand(JcrService.java:84) [classes:]
        ... 28 more
{noquote}

[rhauch]

Yeah, this is going to be a tough one to track down. Any additional information would help a lot - even some detailed examples of which nodes were found (or not found), and which nodes were moved. (Sorry, the above log is a bit hard to figure out what operations are taking place.) Does it happen only with same-name-siblings?

[bwallis42]

Seems to only happen with same name sibs.

I can get the code to breakpoint when it happens. The following lines of code show the error

{code}
                    Node node = session.getNodeByIdentifier(operationRequest.getSource());
                    String path = node.getPath();
                    session.getNode(path);
{code}

The first line executes OK and returns a node, the second line gets the path of that node but the third one then tries to get the node via it's path and fails.

This makes no sense as we already know the node exists and we just retrieved its path but the path can't be used to retrieve the node again.

So, since I cannot reproduce this in a test case, what can I try to track it down?

The actual code where this occurs is as follows

{code}
                    Node srcNode = session.getNodeByIdentifier(operationRequest.getSource());
                    String srcPath = srcNode.getCorrespondingNodePath(session.getWorkspace().getName());
                    Node targetAncestorNode = session.getNodeByIdentifier(operationRequest.getTarget());
                    String targetPath = targetAncestorNode.getCorrespondingNodePath(session.getWorkspace().getName());
                    log.debug("Move Node "+srcNode.getIdentifier()+" path="+srcNode.getPath() + " to " + targetAncestorNode.getIdentifier()+" path="+targetAncestorNode.getPath());
                    String destPath = targetPath + "/" + operationRequest.getRelativePath();
                    try {
                              session.move(srcPath, destPath);
                    }
                    catch(PathNotFoundException e)
                    {
                    log.error("Path Not Found Exception: ",e);
                    ...
                }
{code}

[rhauch]

I think this information is a great help, and it confirms my hypothesis (okay, "guess" is more like it) that this is related to same-name-sibiling nodes that are moved. Looking a node up by identifier involves reconstructing the internal "node key" that ModeShape uses as the key within Infinispan, and simply obtaining the node representation. Looking up a node by path, however, requires processing the segments in the path and using them to find child nodes by name. If the parent node is not properly getting refreshed after the move, the child reference in the parent will be out of date and would likely exhibit the behavior you saw. At least that's my theory.

If you could log a bug and put this information in it, we can try to create a test case that reliably replicates the behavior (without the complexity of a large number of nodes and randomness).

Thanks a ton for all your help on this and other issues!

[bwallis42]

Bug report created, MODE-1613.

Thanks.