[OPNFLWPLUG-1022] Exception during ODL startup in cluster Created: 03/Jul/18  Updated: 10/Sep/18  Resolved: 10/Sep/18

Status: Resolved
Project: OpenFlowPlugin
Component/s: openflowplugin
Affects Version/s: Oxygen, Fluorine
Fix Version/s: Oxygen-SR4, Fluorine-SR1, Neon

Type: Bug Priority: Medium
Reporter: Victor Pickard Assignee: Anil Vishnoi
Resolution: Done Votes: 0
Labels: csit:3node
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Relates
relates to NETVIRT-1315 Troubleshooting Controller CSIT In Progress

 Description   

This OLFE occurred when ODL rwas restarted in the controller clustering CSIT.

 

2018-07-03T06:46:59,062 | ERROR | Blueprint Extender: 1 | TransactionChainManager | 436 - org.opendaylight.openflowplugin.common - 0.6.3.SNAPSHOT | Exception during INITIAL(true) || doSync(false) transaction submitting.
java.util.concurrent.ExecutionException: OptimisticLockFailedException{message=Optimistic lock failed for path /(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=flow:1}

], errorList=[RpcError [message=Optimistic lock failed for path /(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=flow:1}], severity=ERROR, errorType=APPLICATION, tag=resource-denied, applicationTag=null, info=null, cause=org.opendaylight.yangtools.yang.data.api.schema.tree.ConflictingModificationAppliedException: Node was created by other transaction.]]}
at org.opendaylight.mdsal.common.api.MappingCheckedFuture.wrapInExecutionException(MappingCheckedFuture.java:66) [379:org.opendaylight.mdsal.common-api:2.4.3.SNAPSHOT]
at org.opendaylight.mdsal.common.api.MappingCheckedFuture.get(MappingCheckedFuture.java:94) [379:org.opendaylight.mdsal.common-api:2.4.3.SNAPSHOT]
at org.opendaylight.openflowplugin.common.txchain.TransactionChainManager.submitTransaction(TransactionChainManager.java:186) [436:org.opendaylight.openflowplugin.common:0.6.3.SNAPSHOT]
at org.opendaylight.openflowplugin.common.txchain.TransactionChainManager.submitTransaction(TransactionChainManager.java:159) [436:org.opendaylight.openflowplugin.common:0.6.3.SNAPSHOT]
at org.opendaylight.openflowplugin.applications.topology.manager.FlowCapableTopologyProvider.start(FlowCapableTopologyProvider.java:62) [434:org.opendaylight.openflowplugin.applications.topology-manager:0.6.3.SNAPSHOT]
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:498) ~[?:?]
at org.apache.aries.blueprint.utils.ReflectionUtils.invoke(ReflectionUtils.java:299) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.container.BeanRecipe.invoke(BeanRecipe.java:980) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.container.BeanRecipe.runBeanProcInit(BeanRecipe.java:736) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.container.BeanRecipe.internalCreate2(BeanRecipe.java:848) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.container.BeanRecipe.internalCreate(BeanRecipe.java:811) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.di.AbstractRecipe$1.call(AbstractRecipe.java:79) [86:org.apache.aries.blueprint.core:1.8.3]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at org.apache.aries.blueprint.di.AbstractRecipe.create(AbstractRecipe.java:88) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.container.BlueprintRepository.createInstances(BlueprintRepository.java:255) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.container.BlueprintRepository.createAll(BlueprintRepository.java:186) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.container.BlueprintContainerImpl.instantiateEagerComponents(BlueprintContainerImpl.java:704) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.container.BlueprintContainerImpl.doRun(BlueprintContainerImpl.java:410) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.container.BlueprintContainerImpl.run(BlueprintContainerImpl.java:275) [86:org.apache.aries.blueprint.core:1.8.3]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at org.apache.aries.blueprint.container.ExecutorServiceWrapper.run(ExecutorServiceWrapper.java:106) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.utils.threading.impl.DiscardableRunnable.run(DiscardableRunnable.java:48) [86:org.apache.aries.blueprint.core:1.8.3]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: org.opendaylight.controller.md.sal.common.api.data.OptimisticLockFailedException: Optimistic lock failed for path /(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=flow:1}]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.lambda$processNextPendingTransaction$0(ShardDataTree.java:749) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.processNextPending(ShardDataTree.java:787) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.processNextPendingTransaction(ShardDataTree.java:734) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.startCanCommit(ShardDataTree.java:888) ~[?:?]
at org.opendaylight.controller.cluster.datastore.SimpleShardDataTreeCohort.canCommit(SimpleShardDataTreeCohort.java:99) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ChainedCommitCohort.canCommit(ChainedCommitCohort.java:60) ~[?:?]
at org.opendaylight.controller.cluster.datastore.CohortEntry.canCommit(CohortEntry.java:99) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardCommitCoordinator.handleCanCommit(ShardCommitCoordinator.java:239) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardCommitCoordinator.handleForwardedReadyTransaction(ShardCommitCoordinator.java:114) ~[?:?]
at org.opendaylight.controller.cluster.datastore.Shard.handleForwardedReadyTransaction(Shard.java:763) ~[?:?]
at org.opendaylight.controller.cluster.datastore.Shard.handleNonRaftCommand(Shard.java:334) ~[?:?]
at org.opendaylight.controller.cluster.raft.RaftActor.handleCommand(RaftActor.java:270) ~[?:?]
at org.opendaylight.controller.cluster.common.actor.AbstractUntypedPersistentActor.onReceiveCommand(AbstractUntypedPersistentActor.java:44) ~[?:?]
at akka.persistence.UntypedPersistentActor.onReceive(PersistentActor.scala:275) ~[?:?]
at org.opendaylight.controller.cluster.common.actor.MeteringBehavior.apply(MeteringBehavior.java:104) ~[?:?]
at akka.actor.ActorCell$$anonfun$become$1.applyOrElse(ActorCell.scala:608) ~[?:?]
at akka.actor.Actor.aroundReceive(Actor.scala:517) ~[?:?]
at akka.actor.Actor.aroundReceive$(Actor.scala:515) ~[?:?]
at akka.persistence.UntypedPersistentActor.akka$persistence$Eventsourced$$super$aroundReceive(PersistentActor.scala:273) ~[?:?]
at akka.persistence.Eventsourced$$anon$1.stateReceive(Eventsourced.scala:691) ~[?:?]
at akka.persistence.Eventsourced.aroundReceive(Eventsourced.scala:192) ~[?:?]
at akka.persistence.Eventsourced.aroundReceive$(Eventsourced.scala:191) ~[?:?]
at akka.persistence.UntypedPersistentActor.aroundReceive(PersistentActor.scala:273) ~[?:?]
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:590) ~[?:?]
at akka.actor.ActorCell.invoke(ActorCell.scala:559) ~[?:?]
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257) ~[?:?]
at akka.dispatch.Mailbox.run(Mailbox.scala:224) ~[?:?]
at akka.dispatch.Mailbox.exec(Mailbox.scala:234) ~[?:?]
at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) ~[?:?]
at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) ~[?:?]
at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) ~[?:?]
at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) ~[?:?]
Caused by: org.opendaylight.yangtools.yang.data.api.schema.tree.ConflictingModificationAppliedException: Node was created by other transaction.
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkConflicting(SchemaAwareApplyOperation.java:80) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkWriteApplicable(SchemaAwareApplyOperation.java:182) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:134) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:302) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkMergeApplicable(AbstractNodeContainerModificationStrategy.java:313) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:137) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:302) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkMergeApplicable(AbstractNodeContainerModificationStrategy.java:313) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:137) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.StructuralContainerModificationStrategy.checkApplicable(StructuralContainerModificationStrategy.java:100) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:302) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkTouchApplicable(AbstractNodeContainerModificationStrategy.java:284) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:131) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.RootModificationApplyOperation.checkApplicable(RootModificationApplyOperation.java:71) ~[?:?]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractDataTreeTip.validate(AbstractDataTreeTip.java:38) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.lambda$processNextPendingTransaction$0(ShardDataTree.java:741) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.processNextPending(ShardDataTree.java:787) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.processNextPendingTransaction(ShardDataTree.java:734) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.startCanCommit(ShardDataTree.java:888) ~[?:?]
at org.opendaylight.controller.cluster.datastore.SimpleShardDataTreeCohort.canCommit(SimpleShardDataTreeCohort.java:99) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ChainedCommitCohort.canCommit(ChainedCommitCohort.java:60) ~[?:?]
at org.opendaylight.controller.cluster.datastore.CohortEntry.canCommit(CohortEntry.java:99) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardCommitCoordinator.handleCanCommit(ShardCommitCoordinator.java:239) ~[?:?]
at org.opendaylight.controller.cluster.datastore.ShardCommitCoordinator.handleForwardedReadyTransaction(ShardCommitCoordinator.java:114) ~[?:?]
at org.opendaylight.controller.cluster.datastore.Shard.handleForwardedReadyTransaction(Shard.java:763) ~[?:?]
at org.opendaylight.controller.cluster.datastore.Shard.handleNonRaftCommand(Shard.java:334) ~[?:?]
at org.opendaylight.controller.cluster.raft.RaftActor.handleCommand(RaftActor.java:270) ~[?:?]
at org.opendaylight.controller.cluster.common.actor.AbstractUntypedPersistentActor.onReceiveCommand(AbstractUntypedPersistentActor.java:44) ~[?:?]
at akka.persistence.UntypedPersistentActor.onReceive(PersistentActor.scala:275) ~[?:?]
at org.opendaylight.controller.cluster.common.actor.MeteringBehavior.apply(MeteringBehavior.java:104) ~[?:?]
at akka.actor.ActorCell$$anonfun$become$1.applyOrElse(ActorCell.scala:608) ~[?:?]
at akka.actor.Actor.aroundReceive(Actor.scala:517) ~[?:?]
at akka.actor.Actor.aroundReceive$(Actor.scala:515) ~[?:?]
at akka.persistence.UntypedPersistentActor.akka$persistence$Eventsourced$$super$aroundReceive(PersistentActor.scala:273) ~[?:?]
at akka.persistence.Eventsourced$$anon$1.stateReceive(Eventsourced.scala:691) ~[?:?]
at akka.persistence.Eventsourced.aroundReceive(Eventsourced.scala:192) ~[?:?]
at akka.persistence.Eventsourced.aroundReceive$(Eventsourced.scala:191) ~[?:?]
at akka.persistence.UntypedPersistentActor.aroundReceive(PersistentActor.scala:273) ~[?:?]
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:590) ~[?:?]
at akka.actor.ActorCell.invoke(ActorCell.scala:559) ~[?:?]
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257) ~[?:?]
at akka.dispatch.Mailbox.run(Mailbox.scala:224) ~[?:?]
at akka.dispatch.Mailbox.exec(Mailbox.scala:234) ~[?:?]
at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) ~[?:?]
at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) ~[?:?]
at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) ~[?:?]
at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) ~[?:?]

 Comments   
Comment by Victor Pickard [ 03/Jul/18 ]

ODL log that has the exception. Note: this is a sandbox job, I have issued the copy-logs to save for debugging:

copy-logs: controller-csit-3node-clustering-vpickard-all-oxygen/13

 

Karaf log

https://logs.opendaylight.org/sandbox/vex-yul-odl-jenkins-2/controller-csit-3node-clustering-vpickard-all-oxygen/13/odl3_karaf.log.gz

 

Job Link

https://jenkins.opendaylight.org/sandbox/job/controller-csit-3node-clustering-vpickard-all-oxygen/13/

Comment by Michael Vorburger [ 03/Jul/18 ]

vpickard just to clarify for you, as this has been brought up during the Kernel Projects call today: This technically isn't a "clustering is broken" issue, in the sense of "clustering infrastructure is broken", but one of those "application need to do something for clustering". You will find similar issue containing ConflictingModificationAppliedException in JIRA. I've deal with some of them in genius and netvirt in the past. NETVIRT-1324 is an example (OptimisticLockFailedException not ConflictingModificationAppliedException, but same general idea); perhaps that and its pointer to RetryingManagedNewTransactionRunner & RetryingManagedNewTransactionRunnerImpl could be of interest to whoever will dig into this one (although this seems to be for a TransactionChain, which that utility doesn't handle, yet; but it could be made to, I guess). So this one is something which somehow familiar with OFP code should be able to do something about, hopefully. 

Comment by Victor Pickard [ 10/Jul/18 ]

Michael,

Thanks for the input!

Here is the archived link to the job logs, etc.

 

https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/builder-copy-sandbox-logs/163/controller-csit-3node-clustering-vpickard-all-oxygen/13/

Comment by Victor Pickard [ 20/Jul/18 ]

Saw this in another job:

 

https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/builder-copy-sandbox-logs/250/controller-csit-3node-clustering-vpickard-all-oxygen/6/ 

 

Exception was on odl1, here are those logs:

https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/builder-copy-sandbox-logs/250/controller-csit-3node-clustering-vpickard-all-oxygen/6/odl1_karaf.log.gz

 

 

2018-07-17T03:13:02,365 | ERROR | Blueprint Extender: 2 | TransactionChainManager | 436 - org.opendaylight.openflowplugin.common - 0.6.3.SNAPSHOT | Exception during INITIAL(true) || doSync(false) transaction submitting. java.util.concurrent.ExecutionException: OptimisticLockFailedException{message=Optimistic lock failed for path /(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=flow:1}

], errorList=[RpcError [message=Optimistic lock failed for path /(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=flow:1}], severity=ERROR, errorType=APPLICATION, tag=resource-denied, applicationTag=null, info=null, cause=org.opendaylight.yangtools.yang.data.api.schema.tree.ConflictingModificationAppliedException: Node was created by other transaction.]]} at org.opendaylight.mdsal.common.api.MappingCheckedFuture.wrapInExecutionException(MappingCheckedFuture.java:66) [379:org.opendaylight.mdsal.common-api:2.4.3.SNAPSHOT] at org.opendaylight.mdsal.common.api.MappingCheckedFuture.get(MappingCheckedFuture.java:94) [379:org.opendaylight.mdsal.common-api:2.4.3.SNAPSHOT] at org.opendaylight.openflowplugin.common.txchain.TransactionChainManager.submitTransaction(TransactionChainManager.java:186)

Comment by Jamo Luhrsen [ 26/Jul/18 ]

Avishnoi any chance you can take a stab at this or give some ideas for someone knowledgeable in OFP to maybe provide a fix?

Comment by Anil Vishnoi [ 26/Jul/18 ]

jluhrsen Earliest i will be able to look at it is by Friday, so will update tickets with my finding. 

Comment by Jamo Luhrsen [ 14/Aug/18 ]

Avishnoi poke

Comment by Victor Pickard [ 30/Aug/18 ]

Avishnoi any chance to take a look at this one?

Thanks

Comment by Anil Vishnoi [ 30/Aug/18 ]

vpickard Fix is already pushed, but i need to push a patch to fix the CSIT test case that is failing because of this new change. I will push the patch by Monday (09/03).

Comment by Anil Vishnoi [ 30/Aug/18 ]

Pushed the CSIT patch as well : https://git.opendaylight.org/gerrit/#/c/75593/

Generated at Wed Feb 07 20:33:59 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.