Indexing fails

[jar398]

I'm guessing this is a failure of backward compatibility between the v1 and v2 phylesystem APIs, or obsolescence of 'default/', or something

bash-3.2$ ./push.sh -c ../../deployed-systems/development/devapi.config  index
host=devapi.opentreeoflife.org, admin=admin, pem=/Users/jar/.ssh/opentree/opentree.pem, controller=jar, command=index
Syncing
as-admin.sh                                   100% 9791     9.6KB/s   00:00    
Java 8 OK
Indexing studies from API at http://devapi.opentreeoflife.org/phylesystem/v1
Using the oti instance at: http://127.0.0.1:7478/db/data/
Using the studies from: http://devapi.opentreeoflife.org/phylesystem/v1/../
 Indexing 2900 studies from http://devapi.opentreeoflife.org/phylesystem/v1/../
Indexing http://devapi.opentreeoflife.org/phylesystem/v1/../ study pg_719 from http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_719.json
Calling "http://127.0.0.1:7478/db/data/ext/studies/graphdb/index_studies" with data="{'urls': ['http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_719.json']}"

Indexing failed for URL "http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_719.json", study http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_719.json. Message = "Attempt to get the root of an empty NexsonTree object."
Indexing http://devapi.opentreeoflife.org/phylesystem/v1/../ study pg_710 from http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_710.json
Calling "http://127.0.0.1:7478/db/data/ext/studies/graphdb/index_studies" with data="{'urls': ['http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_710.json']}"

Indexing failed for URL "http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_710.json", study http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_710.json. Message = "Attempt to get the root of an empty NexsonTree object."
Indexing http://devapi.opentreeoflife.org/phylesystem/v1/../ study pg_711 from http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_711.json

[jar398]

No, the URL is fine: curl http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_719.json {"commentHTML": "", "branch2sha": {"master": "a0aad8a8712e6ba5b111dbb011ba904a9936e68e"}, "sha": "a0aad8a8712e6ba5b111dbb011ba904a9936e68e", ...

The reference to NexsonTree suggests maybe something to do with the recent changes to jade?

[jimallman]

So far I haven't found a smoking gun, but this error message comes from NexsonTree.getRoot, which is only called from a few places.

It does seem like we're getting null or invalid trees (or wrong class, JadeTree vs NexsonTree?) in the NexsonSource (=study) object. This call to addTree (which in turn calls getRoot) is preceded by a check for null, but some direct calls aren't. A quick look at the JSON-parsing tests for trees and tree elements look right to me, so I'm not sure what's going wrong here.

EDIT: fixed caller descriptions and links above.

[jar398]

I've looked over NexsonSource and NexsonTree as well and can't see how this situation could possibly happen.

[chinchliff]

Is there an example of a complete curl call that will reproduce this error? Maybe I just missed it. I will see about fixing it but it would be helpful to have an easy way to recreate the problem outside of the deployment scripts.

[jimallman]

We don't have curl on devapi, but I was able to work out this equivalent using wget:

# ssh devapi.opentreeoflife.org 
$ wget --header 'Content-Type: application/json' \
     --post-data '{"urls": ["http://api.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_1968.json"]}' \
     -v \
     --content-on-error \
     http://127.0.0.1:7478/db/data/ext/studies/graphdb/index_studies

[jimallman]

@chinchliff: I just realized we now expose this path in the v2 APIs, so this cURL call should work from any machine:

$ curl -H "Content-Type: application/json" \
   --data '{"urls": ["http://api.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_1968.json"]}' \
  http://devapi.opentreeoflife.org/v2/studies/index_studies
{
  "indexed" : [ ],
  "errors" : {
    "http://api.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_1968.json" : "Attempt to get the root of an empty NexsonTree object."
  }
}

[chinchliff]

thanks jim, i recreated the problem on my local machine. indeed an issue with the new changes to ot-base. working on it now

[chinchliff]

Ok, please try it again with the changes in that PR. I think it is fixed (indexing seems to be working locally) but the best test suite we have for OTI is the deployment process.

[chinchliff]

Note that this depends on https://github.com/OpenTreeOfLife/ot-base/pull/15

[jar398]

Still fails, but at least we're getting 500s.

./push.sh -c ../../deployed-systems/development/devapi.config index [...] Using the studies from: http://devapi.opentreeoflife.org/phylesystem/v1/../ Indexing 2900 studies from http://devapi.opentreeoflife.org/phylesystem/v1/../ Indexing http://devapi.opentreeoflife.org/phylesystem/v1/../ study pg_719 from http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_719.json Calling "http://127.0.0.1:7478/db/data/ext/studies/graphdb/index_studies" with data="{'urls': ['http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_719.json']}"

Indexing failed for http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_719.json

500 Server Error: Internal Server Error

[jimallman]

@chinchliff: Here's an equivalent cURL call for the failed indexing above. This will return more specific information about the error (NOTE: I've corrected the garbed study URL here):

curl -vv -H "Content-Type: application/json" \
      --data '{"urls": ["http://devapi.opentreeoflife.org/phylesystem/v1/../default/v1/study/pg_719"]}' \
     http://devapi.opentreeoflife.org/v2/studies/index_studies

Here's the current response:

* Hostname was NOT found in DNS cache
*   Trying 128.30.16.133...
* Connected to devapi.opentreeoflife.org (128.30.16.133) port 80 (#0)
> POST /v2/studies/index_studies HTTP/1.1
> User-Agent: curl/7.37.1
> Host: devapi.opentreeoflife.org
> Accept: */*
> Content-Type: application/json
> Content-Length: 78
>
* upload completely sent off: 78 out of 78 bytes
< HTTP/1.1 500 Internal Server Error
< Date: Mon, 11 May 2015 18:51:25 GMT
* Server Jetty(6.1.25) is not blacklisted
< Server: Jetty(6.1.25)
< Content-Length: 764
< Content-Type: application/json; charset=UTF-8
< Access-Control-Allow-Origin: *
< Connection: close
<
{
  "message" : "org/opentree/oti/DatabaseManager",
  "exception" : "NoClassDefFoundError",
  "fullname" : "java.lang.NoClassDefFoundError",
  "stacktrace" : [ "org.opentree.oti.plugins.studies.index_studies(studies.java:188)", "java.lang.reflect.Method.invoke(Method.java:497)", "org.neo4j.server.plugins.PluginMethod.invoke(PluginMethod.java:57)", "org.neo4j.server.plugins.PluginManager.invoke(PluginManager.java:168)", "org.neo4j.server.rest.web.ExtensionService.invokeGraphDatabaseExtension(ExtensionService.java:300)", "org.neo4j.server.rest.web.ExtensionService.invokeGraphDatabaseExtension(ExtensionService.java:122)", "java.lang.reflect.Method.invoke(Method.java:497)", "org.neo4j.server.rest.security.SecurityFilter.doFilter(SecurityFilter.java:112)" ]
* Closing connection 0
}

[jar398]

I checked the build logs for ot-base and oti, and everything looks OK ('build success' etc.). The class is present: jar tf ~/neo4j-oti/plugins/oti-neo4j-plugins-0.0.1-SNAPSHOT.jar | grep DatabaseManager org/opentree/oti/DatabaseManager.class (venv)opentree@ashby:~/repo/oti$

The plugin seems to be the one I just created (from the new-synth-update branch): ls -l ~/neo4j-oti/plugins/oti-neo4j-plugins-0.0.1-SNAPSHOT.jar -rw-r--r-- 1 opentree opentree 44437 May 11 18:34 /home/opentree/neo4j-oti/plugins/oti-neo4j-plugins-0.0.1-SNAPSHOT.jar (venv)opentree@ashby:~/repo/oti$

(venv)opentree@ashby:~/repo/oti$ git status On branch new-synth-update ...

And this seems to be the version that's running: Mon May 11 18:34:18 UTC 2015 jar ot10 Started oti Mon May 11 18:34:18 UTC 2015 jar ot10 Finished installing oti plugin

Maybe a neo4j flakeout. Poking around...

On Mon, May 11, 2015 at 2:53 PM, Jim Allman notifications@github.com wrote:

@chinchliff https://github.com/chinchliff: Here's an equivalent cURL call for the failed indexing above. This will return more specific information about the error:

curl -vv -H "Content-Type: application/json" \ --data '{"urls": ["http://devapi.opentreeoflife.org/phylesystem/v1/../ study pg_719"]}' \ http://devapi.opentreeoflife.org/v2/studies/index_studies

Here's the current response:

• Hostname was NOT found in DNS cache* Trying 128.30.16.133...* Connected to devapi.opentreeoflife.org (128.30.16.133) port 80 (#0)> POST /v2/studies/indexstudies HTTP/1.1> User-Agent: curl/7.37.1> Host: devapi.opentreeoflife.org> Accept: /> Content-Type: application/json> Content-Length: 78>* upload completely sent off: 78 out of 78 bytes< HTTP/1.1 500 Internal Server Error< Date: Mon, 11 May 2015 18:51:25 GMT* Server Jetty(6.1.25) is not blacklisted< Server: Jetty(6.1.25)< Content-Length: 764< Content-Type: application/json; charset=UTF-8< Access-Control-Allow-Origin: < Connection: close< { "message" : "org/opentree/oti/DatabaseManager", "exception" : "NoClassDefFoundError", "fullname" : "java.lang.NoClassDefFoundError", "stacktrace" : [ "org.opentree.oti.plugins.studies.indexstudies(studies.java:188)", "java.lang.reflect.Method.invoke(Method.java:497)", "org.neo4j.server.plugins.PluginMethod.invoke(PluginMethod.java:57)", "org.neo4j.server.plugins.PluginManager.invoke(PluginManager.java:168)", "org.neo4j.server.rest.web.ExtensionService.invokeGraphDatabaseExtension(ExtensionService.java:300)", "org.neo4j.server.rest.web.ExtensionServ ice.invo keGraphDatabaseExtension(ExtensionService.java:122)", "java.lang.reflect.Method.invoke(Method.java:497)", "org.neo4j.server.rest.security.SecurityFilter.doFilter(SecurityFilter.java:112)" ] Closing connection 0 }

— Reply to this email directly or view it on GitHub https://github.com/OpenTreeOfLife/oti/issues/38#issuecomment-101016191.

[jar398]

I rebuilt OTI and now it's working. I'm going to do a full reindexing of devapi, which I expect to work, after which I will declare success and merge the PR.

[jimallman]

FWIW, my curl call (above) now returns a 200 response, but with error information inside. NOTE that the error described is now java.lang.NullPointerException.

* Hostname was NOT found in DNS cache
*   Trying 128.30.16.133...
* Connected to devapi.opentreeoflife.org (128.30.16.133) port 80 (#0)
> POST /v2/studies/index_studies HTTP/1.1
> User-Agent: curl/7.37.1
> Host: devapi.opentreeoflife.org
> Accept: */*
> Content-Type: application/json
> Content-Length: 78
>
* upload completely sent off: 78 out of 78 bytes
< HTTP/1.1 200 OK
< Date: Mon, 11 May 2015 19:30:58 GMT
* Server Jetty(6.1.25) is not blacklisted
< Server: Jetty(6.1.25)
< Content-Length: 4377
< Content-Type: application/json; charset=UTF-8
< Access-Control-Allow-Origin: *
<
{
  "indexed" : [ ],
  "stack_traces" : {
    "http://devapi.opentreeoflife.org/phylesystem/v1/../ study pg_719" : "[org.opentree.nexson.io.NexsonElement.getMetadataElementsList(NexsonElement.java:168), org.opentree.nexson.io.NexsonElement.processMetadata(NexsonElement.java:138), org.opentree.nexson.io.NexsonSource.parseNexson(NexsonSource.java:164), org.opentree.nexson.io.NexsonSource.<init>(NexsonSource.java:52), org.opentree.oti.plugins.studies.readRemoteNexson(studies.java:270), org.opentree.oti.plugins.studies.index_studies(studies.java:191), sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source), sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43), java.lang.reflect.Method.invoke(Method.java:497), org.neo4j.server.plugins.PluginMethod.invoke(PluginMethod.java:57), org.neo4j.server.plugins.PluginManager.invoke(PluginManager.java:168), org.neo4j.server.rest.web.ExtensionService.invokeGraphDatabaseExtension(ExtensionService.java:300), org.neo4j.server.rest.web.ExtensionService.invokeGraphDatabaseExtension(ExtensionService.java:122), sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source), sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43), java.lang.reflect.Method.invoke(Method.java:497), com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60), com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205), com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75), com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288), com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147), com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108), com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147), com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84), com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1469), com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1400), com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1349), com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1339), com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416), com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537), com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:699), javax.servlet.http.HttpServlet.service(HttpServlet.java:820), org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511), org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166), org.neo4j.server.rest.security.SecurityFilter.doFilter(SecurityFilter.java:112), org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157), org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388), org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182), org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765), org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114), org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152), org.mortbay.jetty.Server.handle(Server.java:322), org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542), org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:943), org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756), org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218), org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404), org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:410), org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)]"
  },
  "error_types" : {
    "http://devapi.opentreeoflife.org/phylesystem/v1/../ study pg_719" : "java.lang.NullPointerException"
  },
  "errors" : {
    "http://devapi.opentreeoflife.org/phylesystem/v1/../ study pg_719" : "null"
  }
* Connection #0 to host devapi.opentreeoflife.org left intact
}

[jar398]

Server errors should never lead to a 200. neo4j is good about turning plugin exceptions into 500s. The documentation says "If the extension throws an exception response code 500 and a detailed error message is returned." but I haven't checked to see whether the 500 response body contains a stack trace. The stack trace doesn't have to be rendered as JSON, does it?

[jimallman]

I'm a fan of the JSON response, which seems like part of the API to me. The easiest fix is to send the exact same response type and body, just with a 500 status code. This is what we've done with the methods called by our GitHub webhooks.

[jar398]

The difficulty is that neo4j managed plugins don't give you that level of control. I suspect the 500 body would be composed by neo4j, with no way for the application to control what it looks like.

If we used an unmanaged plugin, it's definitely doable.

[jar398]

Seems to be fixed at last; at least indexing devapi worked and the UI now shows supporting studies there. commit b3c961b, PR #39