search

jexp / neo4j-clean-remote-db-addon

A server extension that allows cleaning the db with a single rest call (use with care)
55 stars 7 forks source link

TxManager fails to commit #8

Closed garrettheaver closed 12 years ago

garrettheaver commented 12 years ago

There's a strange behavior when clearing a database or rather an index that was implicitly created (has no config).

This completely throws the server into a tailspin as subsequent requests aren't able to start a transaction (only fix I have so far is a stop start)

Not sure if this is a clean-remote problem or a neo4j problem

Jul 5, 2012 2:23:51 PM org.neo4j.kernel.impl.transaction.TxManager commit SEVERE: Commit failed java.lang.RuntimeException: Index config for 'identifiers' not found at org.neo4j.kernel.impl.index.IndexStore.remove(IndexStore.java:215) at org.neo4j.index.impl.lucene.LuceneDataSource.deleteIndex(LuceneDataSource.java:591) at org.neo4j.index.impl.lucene.LuceneCommand$DeleteCommand.perform(LuceneCommand.java:287) at org.neo4j.index.impl.lucene.LuceneTransaction.doCommit(LuceneTransaction.java:259) at org.neo4j.kernel.impl.transaction.xaframework.XaTransaction.commit(XaTransaction.java:319) at org.neo4j.kernel.impl.transaction.xaframework.XaResourceManager.commit(XaResourceManager.java:476) at org.neo4j.kernel.impl.transaction.xaframework.XaResourceHelpImpl.commit(XaResourceHelpImpl.java:64) at org.neo4j.kernel.impl.transaction.TransactionImpl.doCommit(TransactionImpl.java:541) at org.neo4j.kernel.impl.transaction.TxManager.commit(TxManager.java:444) at org.neo4j.kernel.impl.transaction.TxManager.commit(TxManager.java:406) at org.neo4j.kernel.impl.transaction.TransactionImpl.commit(TransactionImpl.java:117) at org.neo4j.kernel.TopLevelTransaction.finish(TopLevelTransaction.java:115) at org.neo4j.server.extension.test.delete.Neo4jDatabaseCleaner.cleanDb(Neo4jDatabaseCleaner.java:41) at org.neo4j.server.extension.test.delete.DeleteDatabaseResource.cleanDb(DeleteDatabaseResource.java:59) at sun.reflect.GeneratedMethodAccessor9.invoke(Unknown Source)

...

SEVERE: Unable to rollback transaction. Some resources may be commited others not. Neo4j kernel should be SHUTDOWN for resource maintance and transaction recovery ---->

jexp commented 12 years ago

How was that index created? I've never seen this behavior before?

garrettheaver commented 12 years ago

I'm still looking at it here now actually, I'm using neolograph on jruby which just goes throught the rest API. There's definitely something very wrong but its nothing to do with clean-remote

SEVERE: Commit failed java.lang.NullPointerException at org.neo4j.index.impl.lucene.IndexTypeCache.getIndexType(IndexTypeCache.java:48) at org.neo4j.index.impl.lucene.LuceneDataSource.getType(LuceneDataSource.java:245) at org.neo4j.index.impl.lucene.LuceneTransaction.doCommit(LuceneTransaction.java:254) at org.neo4j.kernel.impl.transaction.xaframework.XaTransaction.commit(XaTransaction.java:319) at org.neo4j.kernel.impl.transaction.xaframework.XaResourceManager.commit(XaResourceManager.java:476) at org.neo4j.kernel.impl.transaction.xaframework.XaResourceHelpImpl.commit(XaResourceHelpImpl.java:64) at org.neo4j.kernel.impl.transaction.TransactionImpl.doCommit(TransactionImpl.java:541) at org.neo4j.kernel.impl.transaction.TxManager.commit(TxManager.java:444) at org.neo4j.kernel.impl.transaction.TxManager.commit(TxManager.java:406) at org.neo4j.kernel.impl.transaction.TransactionImpl.commit(TransactionImpl.java:117) at org.neo4j.kernel.TopLevelTransaction.finish(TopLevelTransaction.java:115) at org.neo4j.server.rest.web.DatabaseActions.addToNodeIndex(DatabaseActions.java:813) at org.neo4j.server.rest.web.RestfulGraphDatabase.addToNodeIndex(RestfulGraphDatabase.java:773) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

...

SEVERE: Unable to rollback transaction. Some resources may be commited others not. Neo4j kernel should be SHUTDOWN for resource maintance and transaction recovery ---->

garrettheaver commented 12 years ago

Just getting back to you on this, it's definitely not in your plugin. However I do think there is a race condition on the REST API that can bring the server to its knees. I've two processes running which watch for changes in a single test file then execute the tests within that file. The API is perfect on one process but it dies a horrid death when they both start interacting with it.

jexp commented 12 years ago

I assume you're running 1.7.1 ? Could you upgrade your server to 1.7.2 and see if the problem persists?

garrettheaver commented 12 years ago

Still present

INFO: Using database at /Users/garrett/Downloads/neo4j-community-1.7.2/data/graph.db ... Jul 5, 2012 7:24:32 PM org.neo4j.kernel.impl.transaction.TxManager commit SEVERE: Commit failed java.lang.RuntimeException: Index config for 'identifiers' not found at org.neo4j.kernel.impl.index.IndexStore.remove(IndexStore.java:215) at org.neo4j.index.impl.lucene.LuceneDataSource.deleteIndex(LuceneDataSource.java:611) at org.neo4j.index.impl.lucene.LuceneCommand$DeleteCommand.perform(LuceneCommand.java:287) at org.neo4j.index.impl.lucene.LuceneTransaction.doCommit(LuceneTransaction.java:262) at org.neo4j.kernel.impl.transaction.xaframework.XaTransaction.commit(XaTransaction.java:319) at org.neo4j.kernel.impl.transaction.xaframework.XaResourceManager.commit(XaResourceManager.java:476) at org.neo4j.kernel.impl.transaction.xaframework.XaResourceHelpImpl.commit(XaResourceHelpImpl.java:64) at org.neo4j.kernel.impl.transaction.TransactionImpl.doCommit(TransactionImpl.java:541) at org.neo4j.kernel.impl.transaction.TxManager.commit(TxManager.java:444) at org.neo4j.kernel.impl.transaction.TxManager.commit(TxManager.java:406) at org.neo4j.kernel.impl.transaction.TransactionImpl.commit(TransactionImpl.java:117) at org.neo4j.kernel.TopLevelTransaction.finish(TopLevelTransaction.java:115) at org.neo4j.server.rest.web.DatabaseActions.removeNodeIndex(DatabaseActions.java:435) at org.neo4j.server.rest.web.RestfulGraphDatabase.deleteNodeIndex(RestfulGraphDatabase.java:725) at sun.reflect.GeneratedMethodAccessor62.invoke(Unknown Source) ... SEVERE: Unable to rollback transaction. Some resources may be commited others not. Neo4j kernel should be SHUTDOWN for resource maintance and transaction recovery ---->

On 5 Jul 2012, at 19:09, Michael Hunger wrote:

I assume you're running 1.7.1 ? Could you upgrade your server to 1.7.2 and see if the problem persists?

Reply to this email directly or view it on GitHub: https://github.com/jexp/neo4j-clean-remote-db-addon/issues/8#issuecomment-6786195

garrettheaver commented 12 years ago

And just for good measure, 1.8M05

SEVERE: Commit failed java.lang.RuntimeException: Index config for 'identifiers' not found at org.neo4j.kernel.impl.index.IndexStore.remove(IndexStore.java:215) at org.neo4j.index.impl.lucene.LuceneDataSource.deleteIndex(LuceneDataSource.java:610) at org.neo4j.index.impl.lucene.LuceneCommand$DeleteCommand.perform(LuceneCommand.java:287) at org.neo4j.index.impl.lucene.LuceneTransaction.doCommit(LuceneTransaction.java:265) at org.neo4j.kernel.impl.transaction.xaframework.XaTransaction.commit(XaTransaction.java:319) at org.neo4j.kernel.impl.transaction.xaframework.XaResourceManager.commit(XaResourceManager.java:476) at org.neo4j.kernel.impl.transaction.xaframework.XaResourceHelpImpl.commit(XaResourceHelpImpl.java:64) at org.neo4j.kernel.impl.transaction.TransactionImpl.doCommit(TransactionImpl.java:541) at org.neo4j.kernel.impl.transaction.TxManager.commit(TxManager.java:444) at org.neo4j.kernel.impl.transaction.TxManager.commit(TxManager.java:406) at org.neo4j.kernel.impl.transaction.TransactionImpl.commit(TransactionImpl.java:117) at org.neo4j.kernel.TopLevelTransaction.finish(TopLevelTransaction.java:115) at org.neo4j.server.rest.web.DatabaseActions.removeNodeIndex(DatabaseActions.java:432) at org.neo4j.server.rest.web.RestfulGraphDatabase.deleteNodeIndex(RestfulGraphDatabase.java:729) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

On 5 Jul 2012, at 19:09, Michael Hunger wrote:

I assume you're running 1.7.1 ? Could you upgrade your server to 1.7.2 and see if the problem persists?

Reply to this email directly or view it on GitHub: https://github.com/jexp/neo4j-clean-remote-db-addon/issues/8#issuecomment-6786195

jexp commented 12 years ago

@garrettheaver could you look at the index tab in webadmin how that index is listed there?

garrettheaver commented 12 years ago

It happens during a number of test runs Michael and I'm still trying to isolate the exact sequence (the test runs curl -X DELETE the index at the start of each test). It's almost as if a call is made to index a node by one process as the delete is being processed by another. Not 100% whats happening yet, am cloning out the master here and will debug through that when I get a chance.

On 5 Jul 2012, at 19:59, Michael Hunger wrote:

@garrettheaver could you look at the index tab in webadmin how that index is listed there?

Reply to this email directly or view it on GitHub: https://github.com/jexp/neo4j-clean-remote-db-addon/issues/8#issuecomment-6787478

garrettheaver commented 12 years ago

Hi Michael

Below is the relevant section of log for the problem I'm seeing

I believe the last two requests (@6ab17e0a, @320aad0b) are virtually simultaneous requests to delete the index via curl -X DELETE http://.….

Just to be sure I reset the DB and introduced a random sleep before the call to delete the index and sure enough the problem disappeared, remove the sleep and it reoccurs immediately.

FINE: REQUEST /db/data/index/node/identifiers/urn/urn:def:00000002 on org.mortbay.jetty.HttpConnection@3e9d9edd FINE: REQUEST /db/data/index/node/identifiers/urn/urn:def:00000002 on org.mortbay.jetty.HttpConnection@3643b5bb FINE: RESPONSE /db/data/index/node/identifiers/urn/urn:def:00000002 200 FINE: RESPONSE /db/data/index/node/identifiers/urn/urn:def:00000002 200 FINE: REQUEST /db/data/node/3/properties on org.mortbay.jetty.HttpConnection@272b72f4 FINE: RESPONSE /db/data/node/3/properties 200 FINE: REQUEST /db/data/node/3/properties on org.mortbay.jetty.HttpConnection@16ff6348 FINE: RESPONSE /db/data/node/3/properties 200 FINE: REQUEST /db/data/index/node/identifiers on org.mortbay.jetty.HttpConnection@6ab17e0a FINE: REQUEST /db/data/index/node/identifiers on org.mortbay.jetty.HttpConnection@320aad0b FINE: RESPONSE /db/data/index/node/identifiers 204 Jul 5, 2012 8:55:31 PM org.neo4j.kernel.impl.transaction.TxManager commit SEVERE: Commit failed java.lang.RuntimeException: Index config for 'identifiers' not found at org.neo4j.kernel.impl.index.IndexStore.remove(IndexStore.java:215) at org.neo4j.index.impl.lucene.LuceneDataSource.deleteIndex(LuceneDataSource.java:591) at org.neo4j.index.impl.lucene.LuceneCommand$DeleteCommand.perform(LuceneCommand.java:287) at org.neo4j.index.impl.lucene.LuceneTransaction.doCommit(LuceneTransaction.java:259)

On 5 Jul 2012, at 19:59, Michael Hunger wrote:

@garrettheaver could you look at the index tab in webadmin how that index is listed there?

Reply to this email directly or view it on GitHub: https://github.com/jexp/neo4j-clean-remote-db-addon/issues/8#issuecomment-6787478

jexp commented 12 years ago

@garrettheaver would it be possible to share your db with us? Please send them to mattias at neotechnology.com or if it is too big, at least the messages.log and the logical-log files?

Thanks a lot.

garrettheaver commented 12 years ago

Apologies Michael, I meant to let you know I opened the following

https://github.com/neo4j/community/issues/679#issuecomment-6802696

If you can replicate would you mind adding your voice to the comments?

On 9 Jul 2012, at 14:33, Michael Hunger reply@reply.github.com wrote:

@garrettheaver would it be possible to share your db with us? Please send them to mattias at neotechnology.com or if it is too big, at least the messages.log and the logical-log files?

Thanks a lot.

Reply to this email directly or view it on GitHub: https://github.com/jexp/neo4j-clean-remote-db-addon/issues/8#issuecomment-6846459