search

thinkaurelius / titan

Distributed Graph Database
http://titandb.io
Apache License 2.0
5.25k stars 1.01k forks source link

NullPointerException in TitanBlueprintsGraph$GraphTransaction #1251

Closed mohataher closed 8 years ago

mohataher commented 8 years ago

I'm using Titan 1.0.0 and Amazon DynamoDB as a backend. I'm getting this severe error causing my code to continuously crash at random times. Each time I run my code that involves opening and committing loads of transaction for around 6 hours, I get this error at random times. It's caused by a NullPointerException in TitanBlueprintsGraph$GraphTransaction

30069381 [SIGHUP handler] WARN  com.thinkaurelius.titan.graphdb.database.StandardTitanGraph  - Unable to close transaction standardtitantx[0x19977dbb]
java.lang.IllegalArgumentException: The transaction has already been closed
    at com.google.common.base.Preconditions.checkArgument(Preconditions.java:122)
    at com.thinkaurelius.titan.graphdb.transaction.StandardTitanTx.commit(StandardTitanTx.java:1345)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsTransaction$1.commit(TitanBlueprintsTransaction.java:172)
    at org.apache.tinkerpop.gremlin.structure.Transaction$CLOSE_BEHAVIOR$1.accept(Transaction.java:174)
    at org.apache.tinkerpop.gremlin.structure.Transaction$CLOSE_BEHAVIOR$1.accept(Transaction.java:171)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsGraph$GraphTransaction.close(TitanBlueprintsGraph.java:288)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsTransaction$1.close(TitanBlueprintsTransaction.java:203)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsTransaction.close(TitanBlueprintsTransaction.java:235)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph.closeInternal(StandardTitanGraph.java:202)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph.access$600(StandardTitanGraph.java:78)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph$ShutdownThread.start(StandardTitanGraph.java:803)
    at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:102)
    at java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
    at java.lang.Shutdown.runHooks(Shutdown.java:123)
    at java.lang.Shutdown.sequence(Shutdown.java:167)
    at java.lang.Shutdown.exit(Shutdown.java:212)
    at java.lang.Terminator$1.handle(Terminator.java:52)
    at sun.misc.Signal$1.run(Signal.java:212)
    at java.lang.Thread.run(Thread.java:745)
30069421 [SIGHUP handler] INFO  com.amazon.titan.diskstorage.dynamodb.AbstractDynamoDBStore  - Closing table:v100_systemlog
[WARNING] 
java.lang.reflect.InvocationTargetException
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:293)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsGraph$GraphTransaction.isOpen(TitanBlueprintsGraph.java:278)
    at org.codehaus.groovy.vmplugin.v7.IndyInterface.selectMethod(IndyInterface.java:215)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser$_parseGameLogsAndAddToGraph_closure2$_closure8.doCall(RetroSheetDataParser.groovy:391)
    at sun.reflect.GeneratedMethodAccessor67.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:324)
    at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:292)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1016)
    at groovy.lang.Closure.call(Closure.java:423)
    at groovy.lang.Closure.call(Closure.java:439)
    at org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:2027)
    at org.codehaus.groovy.runtime.dgm$161.doMethodInvoke(Unknown Source)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser$_parseGameLogsAndAddToGraph_closure2.doCall(RetroSheetDataParser.groovy:316)
    at sun.reflect.GeneratedMethodAccessor75.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:324)
    at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:292)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1016)
    at groovy.lang.Closure.call(Closure.java:423)
    at groovy.lang.Closure.call(Closure.java:439)
    at org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:2027)
    at org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:2012)
    at org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:2053)
    at org.codehaus.groovy.runtime.dgm$162.doMethodInvoke(Unknown Source)
    at org.codehaus.groovy.vmplugin.v7.IndyInterface.selectMethod(IndyInterface.java:215)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser.parseGameLogsAndAddToGraph(RetroSheetDataParser.groovy:313)
    at org.codehaus.groovy.vmplugin.v7.IndyInterface.selectMethod(IndyInterface.java:215)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser.parse(RetroSheetDataParser.groovy:115)
    at com.kapsoft.isportsdb.parsers.baseball.MainRetroSheetDataParser.main(MainRetroSheetDataParser.java:25)
    ... 6 more

My code struture looks similar to this

                graph.graph().tx().open()
                try {
                   //add new vertices, edges and retrieve and update existing ones.
                   ...
                }catch(Throwable ex){
                    if (graph.graph().tx().isOpen())
                        graph.graph().tx().rollback()
                    Preconditions.checkState(false, "Error occurred while parsing rosters", ex)
                }finally {
                    if (graph.graph().tx().isOpen()) // crashes here.
                        graph.graph().tx().commit()
                }
spmallette commented 8 years ago

what happens if your structure is just:

try {
  //add new vertices, edges and retrieve and update existing ones.
  ...
  graph.graph().tx().commit()
} catch(Throwable ex){
    graph.graph().tx().rollback()
    Preconditions.checkState(false, "Error occurred while parsing rosters", ex)
}
mohataher commented 8 years ago

I switched my code structure to what you propose, I got this error


792893 [SIGHUP handler] WARN  com.thinkaurelius.titan.graphdb.database.StandardTitanGraph  - Unable to close transaction standardtitantx[0x342ec625]
java.lang.IllegalArgumentException: The transaction has already been closed
    at com.google.common.base.Preconditions.checkArgument(Preconditions.java:122)
    at com.thinkaurelius.titan.graphdb.transaction.StandardTitanTx.commit(StandardTitanTx.java:1345)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsTransaction$1.commit(TitanBlueprintsTransaction.java:172)
    at org.apache.tinkerpop.gremlin.structure.Transaction$CLOSE_BEHAVIOR$1.accept(Transaction.java:174)
    at org.apache.tinkerpop.gremlin.structure.Transaction$CLOSE_BEHAVIOR$1.accept(Transaction.java:171)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsGraph$GraphTransaction.close(TitanBlueprintsGraph.java:288)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsTransaction$1.close(TitanBlueprintsTransaction.java:203)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsTransaction.close(TitanBlueprintsTransaction.java:235)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph.closeInternal(StandardTitanGraph.java:202)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph.access$600(StandardTitanGraph.java:78)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph$ShutdownThread.start(StandardTitanGraph.java:803)
    at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:102)
    at java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
    at java.lang.Shutdown.runHooks(Shutdown.java:123)
    at java.lang.Shutdown.sequence(Shutdown.java:167)
    at java.lang.Shutdown.exit(Shutdown.java:212)
    at java.lang.Terminator$1.handle(Terminator.java:52)
    at sun.misc.Signal$1.run(Signal.java:212)
    at java.lang.Thread.run(Thread.java:745)
[WARNING] 
java.lang.reflect.InvocationTargetException
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:293)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsGraph$GraphTransaction.isOpen(TitanBlueprintsGraph.java:278)
    at org.apache.tinkerpop.gremlin.structure.Transaction$READ_WRITE_BEHAVIOR$1.accept(Transaction.java:209)
    at org.apache.tinkerpop.gremlin.structure.Transaction$READ_WRITE_BEHAVIOR$1.accept(Transaction.java:206)
    at org.apache.tinkerpop.gremlin.structure.util.AbstractTransaction.rollback(AbstractTransaction.java:104)
    at org.codehaus.groovy.vmplugin.v7.IndyInterface.selectMethod(IndyInterface.java:215)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser$_parseRostersAndAddToGraph_closure3$_closure9.doCall(RetroSheetDataParser.groovy:581)
    at sun.reflect.GeneratedMethodAccessor62.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:324)
    at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:292)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1016)
    at groovy.lang.Closure.call(Closure.java:423)
    at groovy.lang.Closure.call(Closure.java:439)
    at org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:2027)
    at org.codehaus.groovy.runtime.dgm$161.doMethodInvoke(Unknown Source)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser$_parseRostersAndAddToGraph_closure3.doCall(RetroSheetDataParser.groovy:541)
    at sun.reflect.GeneratedMethodAccessor67.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:324)
    at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:292)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1016)
    at groovy.lang.Closure.call(Closure.java:423)
    at groovy.lang.Closure.call(Closure.java:439)
    at org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:2027)
    at org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:2012)
    at org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:2053)
    at org.codehaus.groovy.runtime.dgm$162.doMethodInvoke(Unknown Source)
    at org.codehaus.groovy.vmplugin.v7.IndyInterface.selectMethod(IndyInterface.java:215)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser.parseRostersAndAddToGraph(RetroSheetDataParser.groovy:539)
    at org.codehaus.groovy.vmplugin.v7.IndyInterface.selectMethod(IndyInterface.java:215)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser.parse(RetroSheetDataParser.groovy:110)
    at com.kapsoft.isportsdb.parsers.baseball.MainRetroSheetDataParser.main(MainRetroSheetDataParser.java:25)
    ... 6 more

It's interesting that it:

  1. Failed straight on my line graph.tx().rollback() which means there could be a bug in Titan code that might occur under loads of loading/creating and updating vertices and edges. Or could also be caused as a result of using DynamoDB
  2. This new structure failed very quickly in comparison to my structure.

Any solution?

spmallette commented 8 years ago

your stacktrace sill shows a call to isOpen(). are you still calling that method? if so, can you please remove it and see what happens?

mohataher commented 8 years ago

My code failed at graph.tx().rollback() line. Looking at the trace, it seems like isOpen() method is called from Transaction$READ_WRITE_BEHAVIOR at line 209. This line was originally called through Consumer<Transaction>#accept() method which was called from graph.tx().rollaback() line.

Here is a snippet of the error 

Caused by: java.lang.NullPointerException
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsGraph$GraphTransaction.isOpen(TitanBlueprintsGraph.java:278)
    at org.apache.tinkerpop.gremlin.structure.Transaction$READ_WRITE_BEHAVIOR$1.accept(Transaction.java:209)
    at org.apache.tinkerpop.gremlin.structure.Transaction$READ_WRITE_BEHAVIOR$1.accept(Transaction.java:206)
    at org.apache.tinkerpop.gremlin.structure.util.AbstractTransaction.rollback(AbstractTransaction.java:104)
    at org.codehaus.groovy.vmplugin.v7.IndyInterface.selectMethod(IndyInterface.java:215)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser$_parseRostersAndAddToGraph_closure3$_closure9.doCall(RetroSheetDataParser.groovy:581)
mohataher commented 8 years ago

Hello Stephen:

I switched to Berkeley and ran the same script. It passed with no issues.

Now looking at this issue, I feel it should be more vendor specific rather than Titan. However, I think it would have been great if Titan code exposed the real reason of the error (which I assume it's vendor specific).

I'm going to post an issue on dynamodb-titan-storage-backend. This issue is up to you to either leave it open or close it.

spmallette commented 8 years ago

I was wondering if it was a dynamo issue....ok - thanks for the update.

mohataher commented 8 years ago

Hello Stephen:

Sorry to get this back to life. I have changed my code to managed transactions. I caught this error

ERROR com.thinkaurelius.titan.graphdb.database.StandardTitanGraph  - Could not commit transaction [2678] due to exception
java.util.ConcurrentModificationException
    at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:901)
    at java.util.ArrayList$Itr.next(ArrayList.java:851)
    at com.google.common.collect.Iterators$7.computeNext(Iterators.java:651)
    at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)
    at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph.prepareCommit(StandardTitanGraph.java:521)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph.commit(StandardTitanGraph.java:683)
    at com.thinkaurelius.titan.graphdb.transaction.StandardTitanTx.commit(StandardTitanTx.java:1352)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsTransaction$1.commit(TitanBlueprintsTransaction.java:172)
    at org.apache.tinkerpop.gremlin.structure.Transaction$CLOSE_BEHAVIOR$1.accept(Transaction.java:174)
    at org.apache.tinkerpop.gremlin.structure.Transaction$CLOSE_BEHAVIOR$1.accept(Transaction.java:171)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsGraph$GraphTransaction.close(TitanBlueprintsGraph.java:288)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsTransaction$1.close(TitanBlueprintsTransaction.java:203)
    at com.thinkaurelius.titan.graphdb.tinkerpop.TitanBlueprintsTransaction.close(TitanBlueprintsTransaction.java:235)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph.closeInternal(StandardTitanGraph.java:202)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph.access$600(StandardTitanGraph.java:78)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph$ShutdownThread.start(StandardTitanGraph.java:803)
    at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:102)
    at java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
    at java.lang.Shutdown.runHooks(Shutdown.java:123)
    at java.lang.Shutdown.sequence(Shutdown.java:167)
    at java.lang.Shutdown.exit(Shutdown.java:212)
    at java.lang.Terminator$1.handle(Terminator.java:52)
    at sun.misc.Signal$1.run(Signal.java:212)
    at java.lang.Thread.run(Thread.java:745)

The same code passed when I used berekelyj as a persistence backend. I have also opened up an issue at dynamodb-titan-storage-backend, please access it through this link.

What are your thoughts about this?

spmallette commented 8 years ago

I don't know anything about dynamodb's implementation so I can't comment intelligently on that.