[CONTROLLER-1830] Add path to exception logs Created: 19/May/18 Updated: 22/May/18 Resolved: 22/May/18 |
|
| Status: | Resolved |
| Project: | controller |
| Component/s: | clustering |
| Affects Version/s: | None |
| Fix Version/s: | None |
| Type: | Improvement | Priority: | Medium |
| Reporter: | Sam Hague | Assignee: | Unassigned |
| Resolution: | Done | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| 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. 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
|
| Comments |
| Comment by Tom Pantelis [ 19/May/18 ] |
|
This belongs in yangtools where the exceptions originate. |
| Comment by Robert Varga [ 19/May/18 ] |
|
ConflictingModificationAppliedException already carries the path, just as all subclasses of DataValidationFailedException. It is the job of CDS to properly log the path. |
| Comment by Robert Varga [ 19/May/18 ] |
|
no, the path will not be part of the message itself, it is properly exposed through getPath() |
| Comment by Tom Pantelis [ 19/May/18 ] |
|
The ShardDataTree does print a warning but Sam is asking for it to be included in the ConflictingModificationAppliedException - in SchemaAwareApplyOperation checkConflicting eg "Node at <path> children was modified by other transaction". It has to do with making it easier for CSIT log scraping and correlating the WARN message with the actual logged exception which occurs elsewhere. I'll let Sam elaborate more if need be. |
| Comment by Robert Varga [ 19/May/18 ] |
|
Right, the path is included in the exception itself and it is a checked exception - hence CDS nas to have an explicit catch block for it, where that path should be extracted and acted upon.... |
| Comment by Tom Pantelis [ 19/May/18 ] |
|
Our comments crossed. ShardDataTree does log a warning for the path already so I don't seen anything else for controller to do here. |
| Comment by Tom Pantelis [ 19/May/18 ] |
|
ShardDataTree rethrows as OptimisticLockFailedException. I suppose It could include the path in the message although it seems more natural to me for the "Node at children was modified by other transaction" message to include it regardless if the path is exposed via a method as that doesn't really help if only the ConflictingModificationAppliedException was logged. I'll let Sam chime in... |
| Comment by Sam Hague [ 19/May/18 ] |
|
rovarga tpantelis can you help me understand what you guys are talking about as far as where the node path is? In my limited world all I have is the exception dumped in the karaf log. For that it simply says "Node". It would be great if the path is printed in the OLFE and CMAE. As it is today, both exceptions come out and simple say Node so we have no idea what path caused the exception. |
| Comment by Sam Hague [ 19/May/18 ] |
|
Another example, OLFE and CMAE and there is no context to relate it back to path. If both of those exceptions could also log the path that would be very helpful. Or some other contextual meaning that is unique and that will help us identify the root cause. Side question - why do these exceptions always come out later in the log that when there timestamp indicates? The OLFE timestamp is "2018-05-19T19:10:05,044" but it comes out in the log after the ":05,50" timestamp. These exceptions always fall in that pattern. I realize it is probably threading, but just curious why these exceptions always come out this way and want to make sure there is not a problem here. If it is just the logger getting behind since there is so much output from the thread that is fine. 2018-05-19T19:10:05,044 | INFO | org.opendaylight.yang.gen.v1.urn.opendaylight.netvirt.fibmanager.rev150330.vrfentries.VrfEntry_AsyncDataTreeChangeListenerBase-DataTreeChangeHandler-0 | VrfEntryListener | 369 - org.opendaylight.netvirt.fibmanager-impl - 0.7.0.SNAPSHOT | ADD: Added Fib Entry rd 2200:2 prefix 10.10.10.7/32 route-paths [RoutePaths{getLabel=100419, getNexthopAddress=10.30.170.18, augmentations={}}]
2018-05-19T19:10:05,055 | INFO | ForkJoinPool-1-worker-6 | UpdateIdEntryJob | 267 - org.opendaylight.genius.idmanager-impl - 0.5.0.SNAPSHOT | Updated id entry with idValues [100418], idKey 2200:2.10.10.10.6/32, pool vpnservices.169781788
2018-05-19T19:10:05,050 | INFO | pool-43-thread-2 | VpnFootprintService | 386 - org.opendaylight.netvirt.vpnmanager-impl - 0.7.0.SNAPSHOT | publishAddNotification: Successful in notifying listeners for add dpn 26967086219975 in vpn 4ae8cd92-48ca-49b5-94e1-b2921a261111 rd 2200:2 event
2018-05-19T19:10:05,049 | INFO | CommitFutures-19 | VpnFootprintService$DpnEnterExitVpnWorker | 386 - org.opendaylight.netvirt.vpnmanager-impl - 0.7.0.SNAPSHOT | onSuccess: FootPrint established for vpn 4ae8cd92-48ca-49b5-94e1-b2921a261111 rd 2200:2 on dpn 26967086219975
2018-05-19T19:10:05,044 | ERROR | opendaylight-cluster-data-akka.actor.default-dispatcher-56 | LocalThreePhaseCommitCohort | 246 - org.opendaylight.controller.sal-distributed-datastore - 1.8.0.SNAPSHOT | Failed to prepare transaction member-1-datastore-config-fe-0-txn-149697-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 was created by other transaction.
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkWriteApplicable(SchemaAwareApplyOperation.java:182) ~[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.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
|
| Comment by Tom Pantelis [ 19/May/18 ] |
|
The CMAE contains the path as a field but it's not included in the message - call sites would have to do that. It would be useful if it did but that's in yangtools. The OLFE is constructed in the controller with the CMAE as the cause so we can at least change that to include the path in the message. |
| Comment by Tom Pantelis [ 19/May/18 ] |
|
The one from VpnFootprintService is logged at "10:05,050" - I don't know the context of that one - does it have a causal relationship with the OLFE (it doesn't seem so since the former indicates something was successful)? Also does the app code that committed the Tx log the error (that should come after "10:05,044")? That would also help to pinpoint the root cause. |
| Comment by Sam Hague [ 20/May/18 ] |
|
Yes, there is a warning a little earlier that goes with that I think goes with that exception. It is at ,040. The some other logs properly timestamped, then the OLFE with the out-of-order timestamp. 2018-05-19T19:10:05,040 | WARN | opendaylight-cluster-data-shard-dispatcher-28 | ShardDataTree | 246 - org.opendaylight.controller.sal-distributed-datastore - 1.8.0.SNAPSHOT | member-1-shard-inventory-config: Store Tx member-1-datastore-config-fe-0-txn-149697-0: Conflicting modification for path /(urn:opendaylight:inventory?revision=2013-08-19)nodes/node/node[{(urn:opendaylight:inventory?revision=2013-08-19)id=openflow:26967086219975}]/AugmentationIdentifier{childNames=[(urn:opendaylight:flow:inventory?revision=2013-08-19)description, (urn:opendaylight:flow:inventory?revision=2013-08-19)supported-actions, (urn:opendaylight:flow:inventory?revision=2013-08-19)hardware, (urn:opendaylight:flow:inventory?revision=2013-08-19)switch-features, (urn:opendaylight:flow:inventory?revision=2013-08-19)stale-meter, (urn:opendaylight:flow:inventory?revision=2013-08-19)supported-instructions, (urn:opendaylight:flow:inventory?revision=2013-08-19)meter, (urn:opendaylight:flow:inventory?revision=2013-08-19)serial-number, (urn:opendaylight:flow:inventory?revision=2013-08-19)stale-group, (urn:opendaylight:flow:inventory?revision=2013-08-19)supported-match-types, (urn:opendaylight:flow:inventory?revision=2013-08-19)port-number, (urn:opendaylight:flow:inventory?revision=2013-08-19)table, (urn:opendaylight:flow:inventory?revision=2013-08-19)group, (urn:opendaylight:flow:inventory?revision=2013-08-19)manufacturer, (urn:opendaylight:flow:inventory?revision=2013-08-19)table-features, (urn:opendaylight:flow:inventory?revision=2013-08-19)software, (urn:opendaylight:flow:inventory?revision=2013-08-19)ip-address]}/(urn:opendaylight:flow:inventory?revision=2013-08-19)table/table[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=20}]/flow/flow[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=L3.26967086219975.20.100416.10}].
|
| Comment by Tom Pantelis [ 20/May/18 ] |
|
I see - so the timestamp sequence goes from 10:05,044 -> 10:05,050 -> 10:05,044. I have seen that too - I'm sure that's due to threading and the async nature of the backend logging (pax) in karaf. |
| Comment by Tom Pantelis [ 21/May/18 ] |