[#CONTROLLER-1460] Transaction member is not ready yet after many read and write transactions and fails

[CONTROLLER-1460] Transaction member is not ready yet after many read and write transactions and fails Created: 14/Dec/15 Updated: 20/Dec/15 Resolved: 20/Dec/15
Status:	Resolved
Project:	controller
Component/s:	clustering
Affects Version/s:	Beryllium
Fix Version/s:	None

Type:

Bug

Reporter:

Martin Mihálek

Assignee:

Tom Pantelis

Resolution:

Done

Votes:

Labels:

None

Remaining Estimate:

Not Specified

Time Spent:

Not Specified

Original Estimate:

Not Specified

Environment:

Operating System: All
Platform: All

External issue ID:

4774

Priority:

Normal

Description

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)topology-id=sxp}

]/node/node[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=127.0.0.5}

]/AugmentationIdentifier

{childNames=[(urn:opendaylight:sxp:node?revision=2014-10-02)source-ip, (urn:opendaylight:sxp:node?revision=2014-10-02)security, (urn:opendaylight:sxp:node?revision=2014-10-02)mapping-expanded, (urn:opendaylight:sxp:node?revision=2014-10-02)enabled, (urn:opendaylight:sxp:node?revision=2014-10-02)master-database, (urn:opendaylight:sxp:node?revision=2014-10-02)version, (urn:opendaylight:sxp:node?revision=2014-10-02)name, (urn:opendaylight:sxp:node?revision=2014-10-02)sxp-database, (urn:opendaylight:sxp:node?revision=2014-10-02)timers, (urn:opendaylight:sxp:node?revision=2014-10-02)tcp-port, (urn:opendaylight:sxp:node?revision=2014-10-02)connections, (urn:opendaylight:sxp:node?revision=2014-10-02)capabilities, (urn:opendaylight:sxp:node?revision=2014-10-02)description]}

/(urn:opendaylight:sxp:node?revision=2014-10-02)master-database
2015-12-14 09:32:13,173 | DEBUG | ool-50-thread-10 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-658: Found primary ActorSelectionAnchor(akka://opendaylight-cluster-data/), Path(/user/shardmanager-operational/member-1-shard-topology-operational#-973471239) for shard topology
2015-12-14 09:32:13,173 | DEBUG | ool-50-thread-10 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-658 - Creating local component for shard topology using factory org.opendaylight.controller.cluster.datastore.LocalTransactionChain@217d8371
2015-12-14 09:32:13,174 | DEBUG | ool-50-thread-10 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-658 Readying 1 components for commit
2015-12-14 09:32:13,174 | DEBUG | ool-50-thread-10 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-658 Readying transaction for shard topology
2015-12-14 09:32:13,175 | DEBUG | pool-34-thread-5 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | New READ_ONLY Tx - member-1-chn-1-txn-659
2015-12-14 09:32:13,175 | DEBUG | pool-34-thread-5 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-659 read /(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)network-topology/topology/topology[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)topology-id=sxp}

]/node/node[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=127.0.0.1}

]/AugmentationIdentifier

/(urn:opendaylight:sxp:node?revision=2014-10-02)sxp-database
2015-12-14 09:32:13,175 | DEBUG | pool-34-thread-5 | TransactionChainProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Waiting for ready futures with pending Tx member-1-chn-1-txn-658
2015-12-14 09:32:13,176 | DEBUG | pool-53-thread-1 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | New READ_ONLY Tx - member-1-chn-1-txn-660
2015-12-14 09:32:13,176 | DEBUG | pool-53-thread-1 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-660 read /(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)network-topology/topology/topology[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)topology-id=sxp}

]/node/node[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=127.0.0.1}

]/AugmentationIdentifier

/(urn:opendaylight:sxp:node?revision=2014-10-02)master-database
2015-12-14 09:32:13,176 | DEBUG | pool-53-thread-1 | TransactionChainProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Waiting for ready futures with pending Tx member-1-chn-1-txn-658
2015-12-14 09:32:13,180 | DEBUG | pool-42-thread-8 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | New READ_ONLY Tx - member-1-chn-1-txn-661
2015-12-14 09:32:13,180 | DEBUG | pool-42-thread-8 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-661 read /(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)network-topology/topology/topology[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)topology-id=sxp}

]/node/node[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=127.0.0.3}

]/AugmentationIdentifier

/(urn:opendaylight:sxp:node?revision=2014-10-02)master-database
2015-12-14 09:32:13,181 | DEBUG | pool-42-thread-8 | TransactionChainProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Waiting for ready futures with pending Tx member-1-chn-1-txn-658
2015-12-14 09:32:13,182 | DEBUG | lt-dispatcher-35 | TransactionChainProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Previous Tx member-1-chn-1-txn-658 readied - proceeding to FindPrimaryShard
2015-12-14 09:32:13,183 | DEBUG | lt-dispatcher-35 | TransactionChainProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Previous Tx member-1-chn-1-txn-658 readied - proceeding to FindPrimaryShard
2015-12-14 09:32:13,183 | DEBUG | lt-dispatcher-35 | TransactionChainProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Previous Tx member-1-chn-1-txn-658 readied - proceeding to FindPrimaryShard
2015-12-14 09:32:13,183 | DEBUG | pool-46-thread-5 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | New WRITE_ONLY Tx - member-1-chn-1-txn-662
2015-12-14 09:32:13,183 | DEBUG | lt-dispatcher-35 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-661: Found primary ActorSelectionAnchor(akka://opendaylight-cluster-data/), Path(/user/shardmanager-operational/member-1-shard-topology-operational#-973471239) for shard topology
2015-12-14 09:32:13,183 | DEBUG | lt-dispatcher-35 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-661 - Creating local component for shard topology using factory org.opendaylight.controller.cluster.datastore.LocalTransactionChain@217d8371
2015-12-14 09:32:13,183 | DEBUG | pool-46-thread-5 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-662 write /(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)network-topology/topology/topology[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)topology-id=sxp}

]/node/node[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=127.0.0.4}

]/AugmentationIdentifier

/(urn:opendaylight:sxp:node?revision=2014-10-02)master-database
2015-12-14 09:32:13,183 | DEBUG | pool-46-thread-5 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-662: Found primary ActorSelectionAnchor(akka://opendaylight-cluster-data/), Path(/user/shardmanager-operational/member-1-shard-topology-operational#-973471239) for shard topology
2015-12-14 09:32:13,183 | DEBUG | pool-46-thread-5 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-662 - Creating local component for shard topology using factory org.opendaylight.controller.cluster.datastore.LocalTransactionChain@217d8371
2015-12-14 09:32:13,183 | DEBUG | lt-dispatcher-35 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-660: Found primary ActorSelectionAnchor(akka://opendaylight-cluster-data/), Path(/user/shardmanager-operational/member-1-shard-topology-operational#-973471239) for shard topology
2015-12-14 09:32:13,183 | DEBUG | lt-dispatcher-35 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-660 - Creating local component for shard topology using factory org.opendaylight.controller.cluster.datastore.LocalTransactionChain@217d8371
2015-12-14 09:32:13,183 | DEBUG | pool-46-thread-5 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-662 Readying 1 components for commit
2015-12-14 09:32:13,183 | DEBUG | pool-46-thread-5 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-662 Readying transaction for shard topology
2015-12-14 09:32:13,185 | DEBUG | pool-38-thread-4 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | New READ_ONLY Tx - member-1-chn-1-txn-663
2015-12-14 09:32:13,185 | DEBUG | pool-38-thread-4 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-663 read /(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)network-topology/topology/topology[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)topology-id=sxp}

]/node/node[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=127.0.0.2}

]/AugmentationIdentifier

/(urn:opendaylight:sxp:node?revision=2014-10-02)master-database
2015-12-14 09:32:13,185 | DEBUG | pool-38-thread-4 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-663: Found primary ActorSelectionAnchor(akka://opendaylight-cluster-data/), Path(/user/shardmanager-operational/member-1-shard-topology-operational#-973471239) for shard topology
2015-12-14 09:32:13,185 | DEBUG | pool-38-thread-4 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-663 - Creating local component for shard topology using factory org.opendaylight.controller.cluster.datastore.LocalTransactionChain@217d8371
2015-12-14 09:32:13,189 | INFO | pool-46-thread-5 | BindingDispatcher | 219 - org.opendaylight.sxp.core - 1.2.0.SNAPSHOT | Export on dispatch Ipv4Address [_value=127.0.0.4] 1
2015-12-14 09:32:13,189 | INFO | ool-50-thread-10 | BindingDispatcher | 219 - org.opendaylight.sxp.core - 1.2.0.SNAPSHOT | Export on dispatch Ipv4Address [_value=127.0.0.5] 1
2015-12-14 09:32:13,196 | INFO | entLoopGroup-7-3 | Strategy | 219 - org.opendaylight.sxp.core - 1.2.0.SNAPSHOT | [127.0.0.1][127.0.0.1:64999/127.0.0.3:47734][O|Bv4/Bv4 127.0.0.3] Handle UPDATE 0 0 0 77 0 0 0 3 | 16 16 8 127 0 0 3 127 0 0 1 16 17 2 0 10 16 11 5 32 10 10 10 10 16 16 8 127 0 0 3 127 0 0 1 16 17 2 0 10 16 11 3 16 10 10 16 16 8 127 0 0 3 127 0 0 1 16 17 2 0 10 16 11 4 24 10 10 10
2015-12-14 09:32:13,211 | DEBUG | lt-dispatcher-35 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-659: Found primary ActorSelectionAnchor(akka://opendaylight-cluster-data/), Path(/user/shardmanager-operational/member-1-shard-topology-operational#-973471239) for shard topology
2015-12-14 09:32:13,211 | DEBUG | lt-dispatcher-35 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-659 - Creating local component for shard topology using factory org.opendaylight.controller.cluster.datastore.LocalTransactionChain@217d8371
2015-12-14 09:32:13,214 | DEBUG | pool-38-thread-4 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | New WRITE_ONLY Tx - member-1-chn-1-txn-664
2015-12-14 09:32:13,215 | DEBUG | pool-38-thread-4 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-664 write /(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)network-topology/topology/topology[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)topology-id=sxp}

]/node/node[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=127.0.0.2}

]/AugmentationIdentifier

/(urn:opendaylight:sxp:node?revision=2014-10-02)master-database
2015-12-14 09:32:13,215 | DEBUG | pool-38-thread-4 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-664: Found primary ActorSelectionAnchor(akka://opendaylight-cluster-data/), Path(/user/shardmanager-operational/member-1-shard-topology-operational#-973471239) for shard topology
2015-12-14 09:32:13,215 | DEBUG | pool-38-thread-4 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-664 - Creating local component for shard topology using factory org.opendaylight.controller.cluster.datastore.LocalTransactionChain@217d8371
2015-12-14 09:32:13,215 | DEBUG | pool-38-thread-4 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-664 Readying 1 components for commit
2015-12-14 09:32:13,215 | DEBUG | pool-38-thread-4 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-664 Readying transaction for shard topology
2015-12-14 09:32:13,217 | DEBUG | pool-38-thread-4 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | New READ_ONLY Tx - member-1-chn-1-txn-665
2015-12-14 09:32:13,201 | ERROR | ult-dispatcher-4 | Dispatcher | 128 - com.typesafe.akka.slf4j - 2.3.14 | Previous transaction member-1-chn-1-txn-662 is not ready yet
java.lang.IllegalStateException: Previous transaction member-1-chn-1-txn-662 is not ready yet
at com.google.common.base.Preconditions.checkState(Preconditions.java:197)[39:com.google.guava:18.0.0]
at org.opendaylight.controller.sal.core.spi.data.AbstractSnapshotBackedTransactionChain$Allocated.getSnapshot(AbstractSnapshotBackedTransactionChain.java:71)[114:org.opendaylight.controller.sal-core-spi:1.3.0.SNAPSHOT]
at org.opendaylight.controller.sal.core.spi.data.AbstractSnapshotBackedTransactionChain.getSnapshot(AbstractSnapshotBackedTransactionChain.java:113)[114:org.opendaylight.controller.sal-core-spi:1.3.0.SNAPSHOT]
at org.opendaylight.controller.sal.core.spi.data.AbstractSnapshotBackedTransactionChain.newReadOnlyTransaction(AbstractSnapshotBackedTransactionChain.java:127)[114:org.opendaylight.controller.sal-core-spi:1.3.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.LocalTransactionChain.newReadOnlyTransaction(LocalTransactionChain.java:66)[142:org.opendaylight.controller.sal-distributed-datastore:1.3.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.AbstractTransactionContextFactory.createLocalTransactionContext(AbstractTransactionContextFactory.java:183)[142:org.opendaylight.controller.sal-distributed-datastore:1.3.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.AbstractTransactionContextFactory.maybeCreateLocalTransactionContext(AbstractTransactionContextFactory.java:58)[142:org.opendaylight.controller.sal-distributed-datastore:1.3.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.AbstractTransactionContextFactory.onFindPrimaryShardSuccess(AbstractTransactionContextFactory.java:73)[142:org.opendaylight.controller.sal-distributed-datastore:1.3.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.AbstractTransactionContextFactory.access$000(AbstractTransactionContextFactory.java:35)[142:org.opendaylight.controller.sal-distributed-datastore:1.3.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.AbstractTransactionContextFactory$1.onComplete(AbstractTransactionContextFactory.java:108)[142:org.opendaylight.controller.sal-distributed-datastore:1.3.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.AbstractTransactionContextFactory$1.onComplete(AbstractTransactionContextFactory.java:104)[142:org.opendaylight.controller.sal-distributed-datastore:1.3.0.SNAPSHOT]
at akka.dispatch.OnComplete.internal(Future.scala:248)[127:com.typesafe.akka.actor:2.3.14]
at akka.dispatch.OnComplete.internal(Future.scala:245)[127:com.typesafe.akka.actor:2.3.14]
at akka.dispatch.japi$CallbackBridge.apply(Future.scala:175)[127:com.typesafe.akka.actor:2.3.14]
at akka.dispatch.japi$CallbackBridge.apply(Future.scala:172)[127:com.typesafe.akka.actor:2.3.14]
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32)[124:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)[127:com.typesafe.akka.actor:2.3.14]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply$mcV$sp(BatchingExecutor.scala:91)[127:com.typesafe.akka.actor:2.3.14]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91)[127:com.typesafe.akka.actor:2.3.14]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91)[127:com.typesafe.akka.actor:2.3.14]
at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:72)[124:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:90)[127:com.typesafe.akka.actor:2.3.14]
at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40)[127:com.typesafe.akka.actor:2.3.14]
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:397)[127:com.typesafe.akka.actor:2.3.14]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)[124:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)[124:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)[124:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)[124:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
2015-12-14 09:32:13,223 | DEBUG | pool-38-thread-4 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-665 read /(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)network-topology/topology/topology[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)topology-id=sxp}

]/node/node[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=127.0.0.2}

]/AugmentationIdentifier

/(urn:opendaylight:sxp:node?revision=2014-10-02)master-database
2015-12-14 09:32:13,223 | DEBUG | pool-38-thread-4 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-665: Found primary ActorSelectionAnchor(akka://opendaylight-cluster-data/), Path(/user/shardmanager-operational/member-1-shard-topology-operational#-973471239) for shard topology
2015-12-14 09:32:13,223 | DEBUG | pool-38-thread-4 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-665 - Creating local component for shard topology using factory org.opendaylight.controller.cluster.datastore.LocalTransactionChain@217d8371
2015-12-14 09:32:13,224 | DEBUG | pool-42-thread-8 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | New READ_ONLY Tx - member-1-chn-1-txn-666
2015-12-14 09:32:13,224 | DEBUG | pool-42-thread-8 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-666 read /(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)network-topology/topology/topology[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)topology-id=sxp}

]/node/node[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=127.0.0.3}

]/AugmentationIdentifier

/(urn:opendaylight:sxp:node?revision=2014-10-02)master-database
2015-12-14 09:32:13,224 | DEBUG | pool-42-thread-8 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-666: Found primary ActorSelectionAnchor(akka://opendaylight-cluster-data/), Path(/user/shardmanager-operational/member-1-shard-topology-operational#-973471239) for shard topology
2015-12-14 09:32:13,224 | DEBUG | pool-42-thread-8 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-666 - Creating local component for shard topology using factory org.opendaylight.controller.cluster.datastore.LocalTransactionChain@217d8371
2015-12-14 09:32:13,232 | DEBUG | pool-42-thread-8 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | New WRITE_ONLY Tx - member-1-chn-1-txn-667
2015-12-14 09:32:13,232 | DEBUG | pool-42-thread-8 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-667 write /(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)network-topology/topology/topology[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)topology-id=sxp}

]/node/node[

{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=127.0.0.3}

]/AugmentationIdentifier

/(urn:opendaylight:sxp:node?revision=2014-10-02)master-database
2015-12-14 09:32:13,232 | DEBUG | pool-42-thread-8 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-667: Found primary ActorSelectionAnchor(akka://opendaylight-cluster-data/), Path(/user/shardmanager-operational/member-1-shard-topology-operational#-973471239) for shard topology
2015-12-14 09:32:13,232 | DEBUG | pool-42-thread-8 | bstractTransactionContextFactory | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-667 - Creating local component for shard topology using factory org.opendaylight.controller.cluster.datastore.LocalTransactionChain@217d8371
2015-12-14 09:32:13,233 | DEBUG | pool-42-thread-8 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-667 Readying 1 components for commit
2015-12-14 09:32:13,233 | DEBUG | pool-42-thread-8 | TransactionProxy | 142 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Tx member-1-chn-1-txn-667 Readying transaction for shard topology

Comments

Comment by Tom Pantelis [ 15/Dec/15 ]

I was able to reproduce this in a unit test with the following sequence:

1) Create write tx1 on chain
2) do write and submit
3) Create read-only tx2 on chain and do read
4) Create write tx3 on chain, do write but do not submit

The front-end TransactionChainProxy has code to wait for the previous write tx ready future on the chain to complete. This is done for read-only as well. This part works. It's the LocalTransactionChain that is the problem. If the sequence/timing is right, tx3 may create its local tx on the LocalTransactionChain before tx2. If so, tx2 fails b/c tx3 isn't ready yet. I forced this to happen with an artificial sleep.

So for the local transaction path, there is a disconnect between the front-end TransactionChainProxy and the LocalTransactionChain. Essentially we have 2 independent chains bridged by asynchronous futures which can cause the ordering to potentially be lost between the two. Thus they may not see the same sequence of tx creates.

I prototyped a solution where TransactionChainProxy::findPrimaryShard composes a Future to also wait for prior read-only transactions to be created. A little ugly but it works.

Comment by Tom Pantelis [ 15/Dec/15 ]

https://git.opendaylight.org/gerrit/#/c/31317/ adds the transaction ID to the logging to aid in debugging.

Comment by Tom Pantelis [ 15/Dec/15 ]

Fix: https://git.opendaylight.org/gerrit/#/c/31318/

Comment by Martin Mihálek [ 16/Dec/15 ]

Tested and issue looks to be fixed

Generated at Wed Feb 07 21:53:02 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.

[CONTROLLER-1460] Transaction member is not ready yet after many read and write transactions and fails Created: 14/Dec/15 Updated: 20/Dec/15 Resolved: 20/Dec/15