dm4-geospatial: using postCreateTopc may leave spatial index incosistent, restart required

[Malte]

Hey there,

i was wondering IF the postCreateTopic()-Hook (which for e.g. the dm4-geospatial module) uses to maintain its own index, is still part of the same transaction which creates the topic triggering it.

My feeling is that i might have found a new issue through the following case but to be able to confirm it i have some questions. My observation was that a new index entry was created by the dm4-geospatial module but the transaction (surrounding the topic which triggered) this new spatial-index entry somehow did not succeed leaving my spatial index inaccessible with a node id of a topic wich does not exist.

• when is postCreateTopic() exactly called: Immediate after topic creation attempt or just after a successful (transaction wise) creation of the topic?
• do must postCreateTopic listener methods take care about transactions?

INFO: Created User Assignment (admin) for Geo Object "Kategorischer Neueintrag1" in Confirmation WS
10.06.2016 11:40:14 de.deepamehta.plugins.facets.FacetsPlugin updateFacet
INFO: Updating Bezirk-Facet: {"id":7278,"uri":"","value":"","childs":{}}
10.06.2016 11:40:14 de.kiezatlas.website.WebsitePlugin storeGeoCoordinateFacet
INFO: Storing geo coordinate (52.4971767,13.4209036) for addressTopic=1762555
10.06.2016 11:40:14 de.deepamehta.plugins.geospatial.GeospatialPlugin postCreateTopic
INFO: ### Adding Geo Coordinate to geospatial index (1762619)
10.06.2016 11:40:14 de.deepamehta.core.util.UniversalExceptionMapper logException
SCHWERWIEGEND: Request "POST /website/topic/save" failed. Responding with 500 (Internal Server Error). The original exception/error is:
java.lang.RuntimeException: Creating topic failed (topic (id=1762619, uri="", typeUri="dm4.geomaps.geo_coordinate", value="13.4209036 52.4971767", childTopics={dm4.workspaces.workspace=reference topic (id=870, uri="dm4.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", childTopics={}), relating association (id=1762640, uri="", typeUri="dm4.core.aggregation", value="", childTopics={}, 
        topic role (roleTypeUri="dm4.core.parent", playerId=1762619), 
        topic role (roleTypeUri="dm4.core.child", playerId=870)), dm4.geomaps.latitude=topic (id=1762629, uri="", typeUri="dm4.geomaps.latitude", value="52.4971767", childTopics={dm4.workspaces.workspace=reference topic (id=870, uri="dm4.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", childTopics={}), relating association (id=1762632, uri="", typeUri="dm4.core.aggregation", value="", childTopics={}, 
        topic role (roleTypeUri="dm4.core.parent", playerId=1762629), 
        topic role (roleTypeUri="dm4.core.child", playerId=870))}), relating association (id=1762634, uri="", typeUri="dm4.core.composition", value="", childTopics={dm4.workspaces.workspace=reference topic (id=870, uri="dm4.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", childTopics={}), relating association (id=1762636, uri="", typeUri="dm4.core.aggregation", value="", childTopics={}, 
        association role (roleTypeUri="dm4.core.parent", playerId=1762634), 
        topic role (roleTypeUri="dm4.core.child", playerId=870))}, 
        topic role (roleTypeUri="dm4.core.parent", playerId=1762619), 
        topic role (roleTypeUri="dm4.core.child", playerId=1762629)), dm4.geomaps.longitude=topic (id=1762620, uri="", typeUri="dm4.geomaps.longitude", value="13.4209036", childTopics={dm4.workspaces.workspace=reference topic (id=870, uri="dm4.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", childTopics={}), relating association (id=1762623, uri="", typeUri="dm4.core.aggregation", value="", childTopics={}, 
        topic role (roleTypeUri="dm4.core.parent", playerId=1762620), 
        topic role (roleTypeUri="dm4.core.child", playerId=870))}), relating association (id=1762625, uri="", typeUri="dm4.core.composition", value="", childTopics={dm4.workspaces.workspace=reference topic (id=870, uri="dm4.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", childTopics={}), relating association (id=1762627, uri="", typeUri="dm4.core.aggregation", value="", childTopics={}, 
        association role (roleTypeUri="dm4.core.parent", playerId=1762625), 
        topic role (roleTypeUri="dm4.core.child", playerId=870))}, 
        topic role (roleTypeUri="dm4.core.parent", playerId=1762619), 
        topic role (roleTypeUri="dm4.core.child", playerId=1762620))}), relating association (id=-1, uri="null", typeUri="null", value="null", childTopics={}, null, null))
	at de.deepamehta.core.impl.EmbeddedService.createTopic(EmbeddedService.java:740)
	at de.deepamehta.core.impl.EmbeddedService.createTopic(EmbeddedService.java:157)
	at de.deepamehta.core.impl.AttachedChildTopics.createAndAssociateChildTopic(AttachedChildTopics.java:524)
	at de.deepamehta.core.impl.AttachedChildTopics.createChildTopicOne(AttachedChildTopics.java:509)
	at de.deepamehta.core.impl.AttachedChildTopics.updateCompositionOne(AttachedChildTopics.java:413)
	at de.deepamehta.core.impl.AttachedChildTopics.updateChildTopics(AttachedChildTopics.java:314)
	at de.deepamehta.core.impl.AttachedDeepaMehtaObject.updateChildTopic(AttachedDeepaMehtaObject.java:201)
	at de.deepamehta.plugins.facets.FacetsPlugin.updateFacet(FacetsPlugin.java:141)
	at de.kiezatlas.website.WebsitePlugin.storeGeoCoordinateFacet(WebsitePlugin.java:814)
	at de.kiezatlas.website.WebsitePlugin.createGeoObjectTopic(WebsitePlugin.java:229)
	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:622)
	at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
	at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
	at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
	at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)
	at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
	at com.sun.jersey.server.impl.uri.rules.ResourceObjectRule.accept(ResourceObjectRule.java:100)
	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:1480)
	at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1411)
	at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1360)
	at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1350)
	at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
	at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538)
	at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
	at org.apache.felix.http.base.internal.handler.ServletHandler.doHandle(ServletHandler.java:339)
	at org.apache.felix.http.base.internal.handler.ServletHandler.handle(ServletHandler.java:300)
	at org.apache.felix.http.base.internal.dispatch.ServletPipeline.handle(ServletPipeline.java:93)
	at org.apache.felix.http.base.internal.dispatch.InvocationFilterChain.doFilter(InvocationFilterChain.java:50)
	at org.apache.felix.http.base.internal.dispatch.HttpFilterChain.doFilter(HttpFilterChain.java:31)
	at org.apache.felix.http.base.internal.dispatch.FilterPipeline.dispatch(FilterPipeline.java:76)
	at org.apache.felix.http.base.internal.dispatch.Dispatcher.dispatch(Dispatcher.java:49)
	at org.apache.felix.http.base.internal.DispatcherServlet.service(DispatcherServlet.java:67)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:501)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:428)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
	at org.eclipse.jetty.server.Server.handle(Server.java:370)
	at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
	at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:982)
	at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1043)
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:865)
	at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240)
	at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
	at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:667)
	at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
	at java.lang.Thread.run(Thread.java:701)
Caused by: java.lang.RuntimeException: An error occurred in the PostCreateTopicListener of plugin "DeepaMehta 4 Geospatial"
	at de.deepamehta.core.impl.EventManager.deliverEvent(EventManager.java:110)
	at de.deepamehta.core.impl.EventManager.fireEvent(EventManager.java:63)
	at de.deepamehta.core.impl.EmbeddedService.fireEvent(EmbeddedService.java:531)
	at de.deepamehta.core.impl.EmbeddedService.createTopic(EmbeddedService.java:737)
	... 60 more
Caused by: org.neo4j.graphdb.NotFoundException: Node[1762430] not found.
	at org.neo4j.kernel.impl.core.NodeManager.getNodeForProxy(NodeManager.java:441)
	at org.neo4j.kernel.InternalAbstractGraphDatabase$4.lookup(InternalAbstractGraphDatabase.java:671)
	at org.neo4j.kernel.impl.core.NodeProxy.createRelationshipTo(NodeProxy.java:207)
	at org.neo4j.gis.spatial.EditableLayerImpl.addGeomNode(EditableLayerImpl.java:108)
	at org.neo4j.gis.spatial.EditableLayerImpl.add(EditableLayerImpl.java:49)
	at de.deepamehta.plugins.geospatial.GeospatialPlugin.addToIndex(GeospatialPlugin.java:218)
	at de.deepamehta.plugins.geospatial.GeospatialPlugin.postCreateTopic(GeospatialPlugin.java:181)
	at de.deepamehta.core.impl.CoreEvent$5.deliver(CoreEvent.java:72)
	at de.deepamehta.core.impl.EventManager.deliverEvent(EventManager.java:97)
	... 63 more
10.06.2016 11:40:14 de.deepamehta.core.impl.TransactionFactory$TransactionResourceFilter$2 filter
WARNUNG: ### Rollback transaction of AbstractSubResourceMethod(WebsitePlugin#createGeoObjectTopic

Restarting the database resolves the issue. Does someone has an idea about what causes this? What do you think about my assumptions?

Thanks for your suppprt.

[jri]

DM opens the outermost transaction before entering your @Transactional resource method, and commits it after the resource method has completed. All DM event listeners perform synchronously. So, all the event listener code is executed before the outermost transaction is committed. Basically, when using @Transactional all your resource method code and all the event listeners are executed within the same transaction.

The POST_CREATE_TOPIC event is fired immediately after a topic is created in the DB. At this time its child topics (in case of a composite) are created already. The transaction is not yet committed.

The DM4 Geospatial module hooks in after a dm4.geomaps.geo_coordinate topic is created in order to add the coordinate to the geo index. As far as I know you forked the DM4 Geospatial module, so at the moment I'm not fully sure what happens at this point. I don't understand what's that node the Neo4j-spatial component wants to look up (org.neo4j.graphdb.NotFoundException: Node[1762430] not found). Where does this ID originate from?

Indeed, I encountered situations when (Lucene) index updates are not immediately visible within the tx, but only after committing and creating another tx. This is against what is documented in the Neo4j manual. See the comments in these CoreService? tests (see dm4-test module):

retypeAssociation()
retypeAssociationRoles()
retypeTopicAndTraverse()
retypeAssociationAndTraverse()
retypeTopicAndTraverseInstantiations()

I never could clarify the commented oddities.
But I'm not sure at the moment if this is related to your problem at all.

Was there a time when this worked for you? What has changed since then?

In case you want experiment with creating/committing the transactions yourself, yon can do so by removing the @Transactional annotation. Note: in case you create an transaction within another (outer) transaction, your inner transaction is ignored by Neo4j. Only the outermost transaction matters.

[Malte]

Thank you very much for your questions, this detailed description of the environment of postCreateTopic and sharing something about the oddities you identified with neo4j/lucene.

I don't understand what's that node the Neo4j-spatial component wants to look up (org.neo4j.graphdb.NotFoundException?: Node[1762430] not found). Where does this ID originate from?

This must/should be a topic node in neo4j but i did not investigate this. In the geospatial index layer, next to the numerical coordinate values, we keep just the "topic_id" as a neo4j property to know to which topic it corresponds.

[Malte]

Yes, so in the hope to get you on board here, let me shortly elaborate on the changes i made to the dm4-geospatial module:

The DM4 Geospatial module hooks in after a dm4.geomaps.geo_coordinate topic is created in order to add the coordinate to the geo index. As far as I know you forked the DM4 Geospatial module, so at the moment I'm not fully sure what happens at this point. I don't understand what's that node the Neo4j-spatial component wants to look up (org.neo4j.graphdb.NotFoundException?: Node[1762430] not found). Where does this ID originate from?

The ID it cant fetch must be neo4j-node that the dm4-geospatial module should maintain.

Why i starting creating seperate neo4j-nodes for the dm4-geospatial module is because i did not understand what or why exactly you were doing in the addToIndex method:

private void addToIndex(Topic geoCoord) {
    layer.add((Node) geoCoord.getDatabaseVendorObject());
}

So, as i am still not familiar with neo4j - can you tell me what this does? I did not understand this because it would not add any langitude/longitude values to an the index right?, just the geo coordinate topic which hasn't got those.

Subsequently this meant in decodeGeometry we would need to fetch and load the topic coordinate values we are trying to index in first place, on every read through fetching them via the dm4-core service.

So the only change i was trying to make was freeing the decodeGeometry call in ​the GeoCoordinateEncoder.java from a dms.getTopic() call. The performance issue became more only obvious operating on a larger index (mine 8000+) as dm4-core topic lookup was done per entry, instead of being an index traversal (triggered by a call to GeoPipeline.startNearestNeighborLatLonSearch(layer, point, maxDistanceInKm); and that made no sense to me.

So what i did where three changes, ​see diff here:

1. encoding the lat/lon values properly as geometry nodes of type POINT (through looking the values up before indexing and storing them in a extra geospatial neo4j-node, "geometry-node")
2. adding the originating topic id (geo coordinate topic) to that very geometry-node as a neo4j property
3. adding the id of the geometry-node to the deepamehta neo4j-node as a new property ("dm4.geospatial.geometry_node_id";) as well to easify lookup/altering the geometry-nodes on updates to geo-coordinate topics

So the geometry node for indexing of lat/long became of type "POINT" and the first time the coordinate values where properly encoded, which you skipped entirely in the original implementation.

I was following the OSM neo4j-spatial example and adding the lat/lon coordiante values directly to the layer into a new neo4j-node while writing into a neo4j-node property the topic_id of the originating geo coordinate topic so i can fetch those (but just for the final resultset and not during traversal).

So now as you now of this "external (spatial) index layer" you might better understand that missing node id lookup i am experience. Something seems not to be in sync here.

Maybe using the lat/long neo4j-nodes by dm4 and indexing their value properties additional as nodes of type point would free us of maintaing an external index at all, if you know what i mean. So, that where my question about better understanding the getDatabaseVendorObject() line originates from.

Anyway, thanks for your help!

[Malte]

So, meanwhile verstion 0.3 of the geospatial plugin was released and that included a fix where the geometry node id (stored as a neo4j node property at the corresponding geo coordinate topic) was not indexed while being set.

This resulted in lookup failures and made updates and deletions of any geo coordinate values indexed in the spatial layer impossible.

The 0.3 release comes with a migration which fixes this issue and has fixed the cause of the issue.

[jri]

Sorry, Malte, at the moment I can't answer to all of your points.
Just one hint here (that might or might not useful for you):
since DM 4.8 you can add (neo4j node) property indexes afterwards. See #897.

Did I understand it right that with 0.3 you solved the original problem, but older spatial DB content is not compatible anymore. I would be fine with this.