[CONTROLLER-1830] Add path to exception logs - OpenDaylight JIRA

XML

Word

Printable

Details

Type: Improvement
Status: Resolved
Priority: Medium
Resolution: Done
Affects Version/s: None
Fix Version/s: None
Component/s: clustering
Labels:
None

Description

This request is to add context to exceptions that are logged so that troubleshooting is easier.

Example below, notice the exception OptimisticLockFailedException followed with Caused By: "ConflictingModificationAppliedException: Node children was modified by other transaction". It would be very helpful if the Node also contained the path so we know what node had the issue. The example below we were lucky that the application code logged a WARN also, but there are other places where that does not happen. This requires manually looking at the log to find the context which is error prone.

We are adding tooling to look for new exceptions in the tests and this will help with that tooling to identify the bugs for known issues and to create new bugs.

https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/netvirt-csit-1node-openstack-queens-upstream-stateful-fluorine/470/odl_1/odl1_karaf.log.gz

2018-05-19T06:16:04,756 | WARN  | opendaylight-cluster-data-shard-dispatcher-251 | ShardDataTree                    | 246 - org.opendaylight.controller.sal-distributed-datastore - 1.8.0.SNAPSHOT | member-1-shard-default-operational: Store Tx member-1-datastore-operational-fe-0-txn-48385-0: Conflicting modification for path /(urn:opendaylight:netvirt:l3vpn?revision=2013-09-11)vpn-instance-op-data/vpn-instance-op-data-entry/vpn-instance-op-data-entry[{(urn:opendaylight:netvirt:l3vpn?revision=2013-09-11)vrf-id=051870b4-8979-4acc-a270-c154c758c6e4}]/vpn-to-dpn-list/vpn-to-dpn-list[{(urn:opendaylight:netvirt:l3vpn?revision=2013-09-11)dpnId=185202793875339}].
2018-05-19T06:16:04,762 | INFO  | ForkJoinPool-1-worker-6 | UpdateIdEntryJob                 | 267 - org.opendaylight.genius.idmanager-impl - 0.5.0.SNAPSHOT | Updated id entry with idValues [], idKey 051870b4-8979-4acc-a270-c154c758c6e4.10.0.0.2/32, pool vpnservices.169781785
2018-05-19T06:16:04,757 | ERROR | opendaylight-cluster-data-akka.actor.default-dispatcher-262 | LocalThreePhaseCommitCohort      | 246 - org.opendaylight.controller.sal-distributed-datastore - 1.8.0.SNAPSHOT | Failed to prepare transaction member-1-datastore-operational-fe-0-txn-48385-0 on backend
org.opendaylight.mdsal.common.api.OptimisticLockFailedException: Optimistic lock failed.
	at org.opendaylight.controller.cluster.datastore.ShardDataTree.lambda$processNextPendingTransaction$0(ShardDataTree.java:740) ~[246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.datastore.ShardDataTree.processNextPending(ShardDataTree.java:778) [246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.datastore.ShardDataTree.processNextPendingTransaction(ShardDataTree.java:725) [246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.datastore.ShardDataTree.startCanCommit(ShardDataTree.java:808) [246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.datastore.SimpleShardDataTreeCohort.canCommit(SimpleShardDataTreeCohort.java:84) [246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.datastore.CohortEntry.canCommit(CohortEntry.java:97) [246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.datastore.ShardCommitCoordinator.handleCanCommit(ShardCommitCoordinator.java:236) [246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.datastore.ShardCommitCoordinator.handleReadyLocalTransaction(ShardCommitCoordinator.java:200) [246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.datastore.Shard.handleReadyLocalTransaction(Shard.java:731) [246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.datastore.Shard.handleNonRaftCommand(Shard.java:333) [246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.raft.RaftActor.handleCommand(RaftActor.java:270) [230:org.opendaylight.controller.sal-akka-raft:1.8.0.SNAPSHOT]
	at org.opendaylight.controller.cluster.common.actor.AbstractUntypedPersistentActor.onReceiveCommand(AbstractUntypedPersistentActor.java:44) [238:org.opendaylight.controller.sal-clustering-commons:1.8.0.SNAPSHOT]
	at akka.persistence.UntypedPersistentActor.onReceive(PersistentActor.scala:275) [43:com.typesafe.akka.persistence:2.5.11]
	at org.opendaylight.controller.cluster.common.actor.MeteringBehavior.apply(MeteringBehavior.java:104) [238:org.opendaylight.controller.sal-clustering-commons:1.8.0.SNAPSHOT]
	at akka.actor.ActorCell$$anonfun$become$1.applyOrElse(ActorCell.scala:608) [40:com.typesafe.akka.actor:2.5.11]
	at akka.actor.Actor.aroundReceive(Actor.scala:517) [40:com.typesafe.akka.actor:2.5.11]
	at akka.actor.Actor.aroundReceive$(Actor.scala:515) [40:com.typesafe.akka.actor:2.5.11]
	at akka.persistence.UntypedPersistentActor.akka$persistence$Eventsourced$$super$aroundReceive(PersistentActor.scala:273) [43:com.typesafe.akka.persistence:2.5.11]
	at akka.persistence.Eventsourced$$anon$1.stateReceive(Eventsourced.scala:691) [43:com.typesafe.akka.persistence:2.5.11]
	at akka.persistence.Eventsourced.aroundReceive(Eventsourced.scala:192) [43:com.typesafe.akka.persistence:2.5.11]
	at akka.persistence.Eventsourced.aroundReceive$(Eventsourced.scala:191) [43:com.typesafe.akka.persistence:2.5.11]
	at akka.persistence.UntypedPersistentActor.aroundReceive(PersistentActor.scala:273) [43:com.typesafe.akka.persistence:2.5.11]
	at akka.actor.ActorCell.receiveMessage(ActorCell.scala:590) [40:com.typesafe.akka.actor:2.5.11]
	at akka.actor.ActorCell.invoke(ActorCell.scala:559) [40:com.typesafe.akka.actor:2.5.11]
	at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257) [40:com.typesafe.akka.actor:2.5.11]
	at akka.dispatch.Mailbox.run(Mailbox.scala:224) [40:com.typesafe.akka.actor:2.5.11]
	at akka.dispatch.Mailbox.exec(Mailbox.scala:234) [40:com.typesafe.akka.actor:2.5.11]
	at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) [40:com.typesafe.akka.actor:2.5.11]
	at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) [40:com.typesafe.akka.actor:2.5.11]
	at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) [40:com.typesafe.akka.actor:2.5.11]
	at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [40:com.typesafe.akka.actor:2.5.11]
Caused by: org.opendaylight.yangtools.yang.data.api.schema.tree.ConflictingModificationAppliedException: Node children was modified by other transaction
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkConflicting(SchemaAwareApplyOperation.java:81) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkNotConflicting(SchemaAwareApplyOperation.java:114) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkWriteApplicable(SchemaAwareApplyOperation.java:178) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:135) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:307) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkMergeApplicable(AbstractNodeContainerModificationStrategy.java:315) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:138) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:307) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkMergeApplicable(AbstractNodeContainerModificationStrategy.java:315) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:138) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:307) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkMergeApplicable(AbstractNodeContainerModificationStrategy.java:315) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:138) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:307) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkMergeApplicable(AbstractNodeContainerModificationStrategy.java:315) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:138) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.StructuralContainerModificationStrategy.checkApplicable(StructuralContainerModificationStrategy.java:101) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:307) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkTouchApplicable(AbstractNodeContainerModificationStrategy.java:290) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:132) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.RootModificationApplyOperation.checkApplicable(RootModificationApplyOperation.java:72) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractDataTreeTip.validate(AbstractDataTreeTip.java:35) ~[446:org.opendaylight.yangtools.yang-data-impl:2.0.3]
	at org.opendaylight.controller.cluster.datastore.ShardDataTree.lambda$processNextPendingTransaction$0(ShardDataTree.java:732) ~[246:org.opendaylight.controller.sal-distributed-datastore:1.8.0.SNAPSHOT]
	... 30 more

Attachments

Gerrit Reviews

- Issue Only
- Show All Reviews
- Show Open Reviews
- Show All Issues
- Show Open Issues

No reviews matched the request. Check your Options in the drop-down menu of this sections header.

Activity

People

Assignee:: Unassigned

Reporter:: Sam Hague

Votes:: 0 Vote for this issue

Watchers:: 6 Start watching this issue

Dates

Created:: 19/May/18 4:27 PM

Updated:: 22/May/18 12:17 PM

Resolved:: 22/May/18 12:17 PM