search

amazon-archives / dynamodb-janusgraph-storage-backend

The Amazon DynamoDB Storage Backend for JanusGraph
Apache License 2.0
446 stars 99 forks source link

NullPointerException in TitanBlueprintsGraph$GraphTransaction #31

Closed mohataher closed 8 years ago

mohataher commented 8 years ago

I have a code structure that looks like this

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)
}

I get this error at random times (usually after around 100k commits)

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

While this seems like a Titan issue, I have run the same script against Berkeley backend and it worked multiple times with no issue. Therefore, I assume there is an issue somewhere causing this NullPointerException in your code.

My configuration file looks like this:

#general Titan configuration
gremlin.graph=com.thinkaurelius.titan.core.TitanFactory
storage.setup-wait=60000
storage.buffer-size=1024
# Metrics configuration - http://s3.thinkaurelius.com/docs/titan/1.0.0/titan-config-ref.html#_metrics
#metrics.enabled=true
#metrics.prefix=t
# Required; specify logging interval in milliseconds
#metrics.csv.interval=500
#metrics.csv.directory=metrics
# Turn off titan retries as we batch and have our own exponential backoff strategy.
storage.write-time=2 ms
storage.read-time=2 ms
storage.backend=com.amazon.titan.diskstorage.dynamodb.DynamoDBStoreManager

#Amazon DynamoDB Storage Backend for Titan configuration
storage.dynamodb.force-consistent-read=true
# should be the graph name rexster/graphs/graph/graph-name
storage.dynamodb.prefix=v100
storage.dynamodb.metrics-prefix=d
storage.dynamodb.enable-parallel-scans=false
storage.dynamodb.max-self-throttled-retries=60
storage.dynamodb.control-plane-rate=10

# DynamoDB client configuration: credentials
storage.dynamodb.client.credentials.class-name=com.amazonaws.auth.DefaultAWSCredentialsProviderChain
storage.dynamodb.client.credentials.constructor-args=

# DynamoDB client configuration: endpoint (Below, set to DynamoDB Local as invoked by mvn test -Pstart-dynamodb-local).
# You can change the endpoint to point to Production DynamoDB regions.)
storage.dynamodb.client.endpoint=https://dynamodb.us-east-1.amazonaws.com

# max http connections - not recommended to use more than 250 connections in DynamoDB Local
storage.dynamodb.client.connection-max=250
# turn off sdk retries
storage.dynamodb.client.retry-error-max=0

# DynamoDB client configuration: thread pool
storage.dynamodb.client.executor.core-pool-size=25
# Do not need more threads in thread pool than the number of http connections
storage.dynamodb.client.executor.max-pool-size=250
storage.dynamodb.client.executor.keep-alive=600000
storage.dynamodb.client.executor.max-concurrent-operations=1
# should be at least as large as the storage.buffer-size
storage.dynamodb.client.executor.max-queue-length=1024

#750 r/w CU result in provisioning the maximum equal numbers read and write Capacity Units that can
# be set on one table before it is split into two or more partitions for IOPS. If you will have more than one Rexster server
# accessing the same graph, you should set the read-rate and write-rate properties to values commensurately lower than the
# read and write capacity of the backend tables.

storage.dynamodb.stores.edgestore.capacity-read=100
storage.dynamodb.stores.edgestore.capacity-write=100
storage.dynamodb.stores.edgestore.read-rate=100
storage.dynamodb.stores.edgestore.write-rate=100
storage.dynamodb.stores.edgestore.scan-limit=10000

storage.dynamodb.stores.graphindex.capacity-read=100
storage.dynamodb.stores.graphindex.capacity-write=100
storage.dynamodb.stores.graphindex.read-rate=100
storage.dynamodb.stores.graphindex.write-rate=100
storage.dynamodb.stores.graphindex.scan-limit=10000

storage.dynamodb.stores.systemlog.capacity-read=10
storage.dynamodb.stores.systemlog.capacity-write=10
storage.dynamodb.stores.systemlog.read-rate=10
storage.dynamodb.stores.systemlog.write-rate=10
storage.dynamodb.stores.systemlog.scan-limit=10000

storage.dynamodb.stores.titan_ids.capacity-read=10
storage.dynamodb.stores.titan_ids.capacity-write=10
storage.dynamodb.stores.titan_ids.read-rate=10
storage.dynamodb.stores.titan_ids.write-rate=10
storage.dynamodb.stores.titan_ids.scan-limit=10000

storage.dynamodb.stores.system_properties.capacity-read=10
storage.dynamodb.stores.system_properties.capacity-write=10
storage.dynamodb.stores.system_properties.read-rate=10
storage.dynamodb.stores.system_properties.write-rate=10
storage.dynamodb.stores.system_properties.scan-limit=10000

storage.dynamodb.stores.txlog.capacity-read=10
storage.dynamodb.stores.txlog.capacity-write=10
storage.dynamodb.stores.txlog.read-rate=10
storage.dynamodb.stores.txlog.write-rate=10
storage.dynamodb.stores.txlog.scan-limit=10000

# elasticsearch config that is required to run GraphOfTheGods
index.search.backend=elasticsearch
index.search.directory=/tmp/searchindex
index.search.elasticsearch.client-only=false
index.search.elasticsearch.local-mode=true
index.search.elasticsearch.interface=NODE

What are your thoughts on this?

amcp commented 8 years ago

I think you should try explicit transaction management. Get a tx object and work with that, instead of using implicit (thread-based) transactions. The stack trace you provided does not make it clear to me that there is an issue with the DynamoDB Storage Backend for Titan. Perhaps, something is timing out. I would turn on metrics, and verify the timing of tx.commit() relative to the executor-queue-size metric. Note, tx.rollback() in the DynamoDB Storage Backend does not take any time (does nothing, the transactions are lightweight).

mohataher commented 8 years ago

Hello Alexander:

I have changed my code structure to fit with your suggestion and added a better exception handling. Here is the new structure:

                TitanTransaction tx=((TitanGraph)graph.graph()).newTransaction();
                try {
                    ....
                        }
                    }
                    tx.commit()
                }catch(Throwable ex){
                    println ExceptionUtils.getStackTrace(ex)
                    if (tx.isOpen())
                        tx.rollback()
                    Preconditions.checkState(false, "Error occurred while parsing game logs", ex)
                }

Now I caught a strange 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)

This means that some other threads are touching the same list, which could mostly mean DynamoDB driver's code? I am assuming here. What are your thoughts here?

This error mentioned in this comment is the reason for firing the NullPointerException in TitanBlueprintsGraph$GraphTransaction. So this issue now is concerned about the concurrent exception I believe.

Just to let you know, I run the same code with berkeleyj backend and it ran okay.

mohataher commented 8 years ago

Seems like this is the real cause of the problem from Dynamo DB. Have a look at this stack trace please.

Why is the connection pool shut down? 

com.thinkaurelius.titan.core.TitanException: ID block allocation on partition(10)-namespace(0) failed with an exception in 2.806 ms
    at com.thinkaurelius.titan.graphdb.database.idassigner.StandardIDPool.waitForIDBlockGetter(StandardIDPool.java:133)
    at com.thinkaurelius.titan.graphdb.database.idassigner.StandardIDPool.nextBlock(StandardIDPool.java:172)
    at com.thinkaurelius.titan.graphdb.database.idassigner.StandardIDPool.nextID(StandardIDPool.java:198)
    at com.thinkaurelius.titan.graphdb.database.idassigner.VertexIDAssigner.assignID(VertexIDAssigner.java:320)
    at com.thinkaurelius.titan.graphdb.database.idassigner.VertexIDAssigner.assignID(VertexIDAssigner.java:169)
    at com.thinkaurelius.titan.graphdb.database.idassigner.VertexIDAssigner.assignID(VertexIDAssigner.java:140)
    at com.thinkaurelius.titan.graphdb.database.StandardTitanGraph.assignID(StandardTitanGraph.java:437)
    at com.thinkaurelius.titan.graphdb.transaction.StandardTitanTx.addVertex(StandardTitanTx.java:507)
    at com.thinkaurelius.titan.graphdb.transaction.StandardTitanTx.addVertex(StandardTitanTx.java:525)
    at com.thinkaurelius.titan.graphdb.transaction.StandardTitanTx.addVertex(StandardTitanTx.java:521)
    at com.thinkaurelius.titan.graphdb.transaction.StandardTitanTx.addVertex(StandardTitanTx.java:83)
    at peapod.FramedGraph.addVertex(FramedGraph.java:85)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser.addMediaIfNotExist(RetroSheetDataParser.groovy:191)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser.findInDBByNameOrCreatePlayer(RetroSheetDataParser.groovy:172)
    at sun.reflect.GeneratedMethodAccessor60.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:382)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1016)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser$_parseRostersAndAddToGraph_closure3$_closure9.doCall(RetroSheetDataParser.groovy:569)
    at sun.reflect.GeneratedMethodAccessor59.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:549)
    at sun.reflect.GeneratedMethodAccessor64.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:543)
    at org.codehaus.groovy.vmplugin.v7.IndyInterface.selectMethod(IndyInterface.java:215)
    at com.kapsoft.isportsdb.parsers.baseball.RetroSheetDataParser.parse(RetroSheetDataParser.groovy:108)
    at com.kapsoft.isportsdb.parsers.baseball.MainRetroSheetDataParser.main(MainRetroSheetDataParser.java:25)
    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.util.concurrent.ExecutionException: com.thinkaurelius.titan.core.TitanException: Could not acquire new ID block from storage
    at java.util.concurrent.FutureTask.report(FutureTask.java:122)
    at java.util.concurrent.FutureTask.get(FutureTask.java:206)
    at com.thinkaurelius.titan.graphdb.database.idassigner.StandardIDPool.waitForIDBlockGetter(StandardIDPool.java:129)
    ... 57 more
Caused by: com.thinkaurelius.titan.core.TitanException: Could not acquire new ID block from storage
    at com.thinkaurelius.titan.graphdb.database.idassigner.StandardIDPool$IDBlockGetter.call(StandardIDPool.java:285)
    at com.thinkaurelius.titan.graphdb.database.idassigner.StandardIDPool$IDBlockGetter.call(StandardIDPool.java:245)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    ... 1 more
Caused by: com.thinkaurelius.titan.diskstorage.PermanentBackendException: Query_v100_titan_ids Connection pool shut down
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBDelegate.processDynamoDBAPIException(DynamoDBDelegate.java:223)
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBDelegate.query(DynamoDBDelegate.java:473)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff$Query.call(ExponentialBackoff.java:74)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff$Query.call(ExponentialBackoff.java:65)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff.runWithBackoff(ExponentialBackoff.java:158)
    at com.amazon.titan.diskstorage.dynamodb.QueryWorker.next(QueryWorker.java:62)
    at com.amazon.titan.diskstorage.dynamodb.QueryWithLimitWorker.next(QueryWithLimitWorker.java:44)
    at com.amazon.titan.diskstorage.dynamodb.QueryWithLimitWorker.next(QueryWithLimitWorker.java:32)
    at com.amazon.titan.diskstorage.dynamodb.PaginatingTask.call(PaginatingTask.java:42)
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBStore.getKeysRangeQuery(DynamoDBStore.java:172)
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBStore.getSlice(DynamoDBStore.java:211)
    at com.thinkaurelius.titan.diskstorage.util.MetricInstrumentedStore$1.call(MetricInstrumentedStore.java:92)
    at com.thinkaurelius.titan.diskstorage.util.MetricInstrumentedStore$1.call(MetricInstrumentedStore.java:90)
    at com.thinkaurelius.titan.diskstorage.util.MetricInstrumentedStore.runWithMetrics(MetricInstrumentedStore.java:214)
    at com.thinkaurelius.titan.diskstorage.util.MetricInstrumentedStore.getSlice(MetricInstrumentedStore.java:89)
    at com.thinkaurelius.titan.diskstorage.util.MetricInstrumentedStore$1.call(MetricInstrumentedStore.java:92)
    at com.thinkaurelius.titan.diskstorage.util.MetricInstrumentedStore$1.call(MetricInstrumentedStore.java:90)
    at com.thinkaurelius.titan.diskstorage.util.MetricInstrumentedStore.runWithMetrics(MetricInstrumentedStore.java:214)
    at com.thinkaurelius.titan.diskstorage.util.MetricInstrumentedStore.getSlice(MetricInstrumentedStore.java:89)
    at com.thinkaurelius.titan.diskstorage.idmanagement.ConsistentKeyIDAuthority$1.call(ConsistentKeyIDAuthority.java:163)
    at com.thinkaurelius.titan.diskstorage.idmanagement.ConsistentKeyIDAuthority$1.call(ConsistentKeyIDAuthority.java:160)
    at com.thinkaurelius.titan.diskstorage.util.BackendOperation.execute(BackendOperation.java:133)
    at com.thinkaurelius.titan.diskstorage.idmanagement.ConsistentKeyIDAuthority.getCurrentID(ConsistentKeyIDAuthority.java:160)
    at com.thinkaurelius.titan.diskstorage.idmanagement.ConsistentKeyIDAuthority.getIDBlock(ConsistentKeyIDAuthority.java:225)
    at com.thinkaurelius.titan.graphdb.database.idassigner.StandardIDPool$IDBlockGetter.call(StandardIDPool.java:278)
    ... 5 more
Caused by: java.lang.IllegalStateException: Connection pool shut down
    at org.apache.http.util.Asserts.check(Asserts.java:34)
    at org.apache.http.pool.AbstractConnPool.lease(AbstractConnPool.java:184)
    at org.apache.http.pool.AbstractConnPool.lease(AbstractConnPool.java:217)
    at org.apache.http.impl.conn.PoolingClientConnectionManager.requestConnection(PoolingClientConnectionManager.java:184)
    at sun.reflect.GeneratedMethodAccessor21.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at com.amazonaws.http.conn.ClientConnectionManagerFactory$Handler.invoke(ClientConnectionManagerFactory.java:72)
    at com.amazonaws.http.conn.$Proxy40.requestConnection(Unknown Source)
    at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
    at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:882)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)
    at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:843)
    at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:597)
    at com.amazonaws.http.AmazonHttpClient.doExecute(AmazonHttpClient.java:363)
    at com.amazonaws.http.AmazonHttpClient.executeWithTimer(AmazonHttpClient.java:329)
    at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:308)
    at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.invoke(AmazonDynamoDBClient.java:1820)
    at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.query(AmazonDynamoDBClient.java:1457)
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBDelegate.query(DynamoDBDelegate.java:471)
    ... 28 more
mohataher commented 8 years ago

Again, with another run, I'm getting another exception

2367351 [delegate-14] INFO  com.amazonaws.http.AmazonHttpClient  - Unable to execute HTTP request: Socket closed
java.net.SocketException: Socket closed
    at java.net.SocketInputStream.read(SocketInputStream.java:203)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
    at sun.security.ssl.InputRecord.read(InputRecord.java:503)
    at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
    at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
    at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
    at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:160)
    at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:84)
    at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:273)
    at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:140)
    at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)
    at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:261)
    at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:283)
    at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:251)
    at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:197)
    at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:272)
    at com.amazonaws.http.protocol.SdkHttpRequestExecutor.doReceiveResponse(SdkHttpRequestExecutor.java:82)
    at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:124)
    at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:685)
    at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:487)
    at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:882)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)
    at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:843)
    at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:597)
    at com.amazonaws.http.AmazonHttpClient.doExecute(AmazonHttpClient.java:363)
    at com.amazonaws.http.AmazonHttpClient.executeWithTimer(AmazonHttpClient.java:329)
    at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:308)
    at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.invoke(AmazonDynamoDBClient.java:1820)
    at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.updateItem(AmazonDynamoDBClient.java:1634)
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBDelegate.updateItem(DynamoDBDelegate.java:513)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff$UpdateItem.call(ExponentialBackoff.java:91)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff$UpdateItem.call(ExponentialBackoff.java:84)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff.runWithBackoff(ExponentialBackoff.java:158)
    at com.amazon.titan.diskstorage.dynamodb.mutation.UpdateItemWorker.call(UpdateItemWorker.java:40)
    at com.amazon.titan.diskstorage.dynamodb.mutation.UpdateItemWorker.call(UpdateItemWorker.java:27)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
2367381 [TitanID(23)(0)[0]] WARN  com.thinkaurelius.titan.diskstorage.idmanagement.ConsistentKeyIDAuthority  - Storage exception while deleting old block application - retrying in PT0.2S
com.thinkaurelius.titan.diskstorage.PermanentBackendException: DeleteItem_v100_titan_ids Connection pool shut down
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBDelegate.processDynamoDBAPIException(DynamoDBDelegate.java:223)
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBDelegate.deleteItem(DynamoDBDelegate.java:553)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff$DeleteItem.call(ExponentialBackoff.java:108)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff$DeleteItem.call(ExponentialBackoff.java:101)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff.runWithBackoff(ExponentialBackoff.java:158)
    at com.amazon.titan.diskstorage.dynamodb.mutation.DeleteItemWorker.call(DeleteItemWorker.java:39)
    at com.amazon.titan.diskstorage.dynamodb.mutation.DeleteItemWorker.call(DeleteItemWorker.java:27)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: Connection pool shut down
    at org.apache.http.util.Asserts.check(Asserts.java:34)
    at org.apache.http.pool.AbstractConnPool.lease(AbstractConnPool.java:184)
    at org.apache.http.pool.AbstractConnPool.lease(AbstractConnPool.java:217)
    at org.apache.http.impl.conn.PoolingClientConnectionManager.requestConnection(PoolingClientConnectionManager.java:184)
    at sun.reflect.GeneratedMethodAccessor21.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at com.amazonaws.http.conn.ClientConnectionManagerFactory$Handler.invoke(ClientConnectionManagerFactory.java:72)
    at com.amazonaws.http.conn.$Proxy40.requestConnection(Unknown Source)
    at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
    at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:882)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)
    at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:843)
    at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:597)
    at com.amazonaws.http.AmazonHttpClient.doExecute(AmazonHttpClient.java:363)
    at com.amazonaws.http.AmazonHttpClient.executeWithTimer(AmazonHttpClient.java:329)
    at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:308)
    at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.invoke(AmazonDynamoDBClient.java:1820)
    at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.deleteItem(AmazonDynamoDBClient.java:927)
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBDelegate.deleteItem(DynamoDBDelegate.java:551)
    ... 11 more
2367584 [TitanID(23)(0)[0]] WARN  com.thinkaurelius.titan.diskstorage.idmanagement.ConsistentKeyIDAuthority  - Storage exception while deleting old block application - retrying in PT0.2S
com.thinkaurelius.titan.diskstorage.PermanentBackendException: DeleteItem_v100_titan_ids Connection pool shut down
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBDelegate.processDynamoDBAPIException(DynamoDBDelegate.java:223)
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBDelegate.deleteItem(DynamoDBDelegate.java:553)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff$DeleteItem.call(ExponentialBackoff.java:108)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff$DeleteItem.call(ExponentialBackoff.java:101)
    at com.amazon.titan.diskstorage.dynamodb.ExponentialBackoff.runWithBackoff(ExponentialBackoff.java:158)
    at com.amazon.titan.diskstorage.dynamodb.mutation.DeleteItemWorker.call(DeleteItemWorker.java:39)
    at com.amazon.titan.diskstorage.dynamodb.mutation.DeleteItemWorker.call(DeleteItemWorker.java:27)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: Connection pool shut down
    at org.apache.http.util.Asserts.check(Asserts.java:34)
    at org.apache.http.pool.AbstractConnPool.lease(AbstractConnPool.java:184)
    at org.apache.http.pool.AbstractConnPool.lease(AbstractConnPool.java:217)
    at org.apache.http.impl.conn.PoolingClientConnectionManager.requestConnection(PoolingClientConnectionManager.java:184)
    at sun.reflect.GeneratedMethodAccessor21.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at com.amazonaws.http.conn.ClientConnectionManagerFactory$Handler.invoke(ClientConnectionManagerFactory.java:72)
    at com.amazonaws.http.conn.$Proxy40.requestConnection(Unknown Source)
    at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
    at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:882)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)
    at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:843)
    at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:597)
    at com.amazonaws.http.AmazonHttpClient.doExecute(AmazonHttpClient.java:363)
    at com.amazonaws.http.AmazonHttpClient.executeWithTimer(AmazonHttpClient.java:329)
    at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:308)
    at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.invoke(AmazonDynamoDBClient.java:1820)
    at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.deleteItem(AmazonDynamoDBClient.java:927)
    at com.amazon.titan.diskstorage.dynamodb.DynamoDBDelegate.deleteItem(DynamoDBDelegate.java:551)
    ... 11 more

I'm not performing any delete operations in my transaction. Do you have any idea why this is happening?

amcp commented 8 years ago

Your connection pool could be crashing for various reasons. Let me explain why you see queries and deletes even though your application is not doing any. When you create new entities like vertices in Titan, Titan assigns vertex ids to these new entities. In order for Titan to avoid handing out the same vertex id twice to different vertices, Titan writes to, deletes from and queries the titan_ids table. Leases of Titan ID ranges are handed out to the various titan instances by writing to this table. As for the concurrent modification exception, Titan transactions are thread bound and not intended to be used in multiple threads at once. If you want a thread aware tx object, call graph.tx().createThreadedTx() and share it among threads. It may be the case that you do not have enough read/write thruput provisioned for the titan_ids table. The other way to decrease the frequency and volume of reads and writes to titan_ids is to increase the id block size, with ids.block-size http://s3.thinkaurelius.com/docs/titan/1.0.0/titan-config-ref.html#_ids Making this value larger will reduce the load on titan_ids table.

The writes to DynamoDB happen asynchronously in a thread pool in DynamoDBDelegate. Closing the graph prematurely has as a side effect to kill the thread pool in the Delegate doing the writes. Instead, you should wait for Titan to tell you that the write is finished. One way to do that is to add a transaction listener with graph.tx().addTransactionListener(new Consumer { ... }) to shut down the graph after the the tx() is committed.