[GENIUS-100] Already locked for ACL-ID-POOL2c9a93ba-3add-4c68-9b1c-8242138262ee after waiting 1000ms, try 1 Created: 20/Nov/17  Updated: 19/Apr/18  Resolved: 19/Apr/18

Status: Resolved
Project: genius
Component/s: General
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Medium
Reporter: Sam Hague Assignee: Michael Vorburger
Resolution: Cannot Reproduce Votes: 0
Labels: csit:3node
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Epic Link: Clustering Stability

 Description   

https://logs.opendaylight.org/releng/jenkins092/netvirt-csit-3node-openstack-ocata-upstream-stateful-carbon/184/odl_1/odl1_karaf.log.gz

2017-11-20 02:52:27,848 | INFO  | eChangeHandler-0 | IdManager                        | 320 - org.opendaylight.genius.idmanager-impl - 0.2.3.SNAPSHOT | Releasing ID UDP_DESTINATION_1_0Ingress1834849402-8f40-473e-9a26-207b20f8ad93 from pool acl.flow.priorities.pool.176858005830847.243.PERMIT
2017-11-20 02:52:27,853 | INFO  | nPool-1-worker-3 | EgressServicesConfigUnbindHelper | 326 - org.opendaylight.genius.interfacemanager-impl - 0.2.3.SNAPSHOT | unbinding egress service default.b8c5863f-2e4b-4c3d-b719-f4f30e66fe9e for interface: b8c5863f-2e4b-4c3d-b719-f4f30e66fe9e
2017-11-20 02:52:27,858 | INFO  | nPool-1-worker-1 | UpdateIdEntryJob                 | 320 - org.opendaylight.genius.idmanager-impl - 0.2.3.SNAPSHOT | Updated id entry with idValues null, idKey ICMP_Ingress1879e5caaa-88af-4bae-ad5f-5dc0d96a3986, pool acl.flow.priorities.pool.176858005830847.243.PERMIT.169676285
2017-11-20 02:52:27,865 | WARN  | eChangeHandler-0 | LockManager                      | 319 - org.opendaylight.genius.lockmanager-impl - 0.2.3.SNAPSHOT | Already locked for ACL-ID-POOL2c9a93ba-3add-4c68-9b1c-8242138262ee after waiting 1000ms, try 1
2017-11-20 02:52:27,874 | WARN  | lt-dispatcher-22 | ConcurrentDOMDataBroker          | 203 - org.opendaylight.controller.sal-distributed-datastore - 1.5.3.SNAPSHOT | Tx: DOM-16780 Error during phase CAN_COMMIT, starting Abort
OptimisticLockFailedException{message=Optimistic lock failed., errorList=[RpcError [message=Optimistic lock failed., 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.controller.cluster.datastore.ShardDataTree.lambda$processNextPendingTransaction$0(ShardDataTree.java:751)
	at org.opendaylight.controller.cluster.datastore.ShardDataTree.processNextPending(ShardDataTree.java:789)
	at org.opendaylight.controller.cluster.datastore.ShardDataTree.processNextPendingTransaction(ShardDataTree.java:736)
	at org.opendaylight.controller.cluster.datastore.ShardDataTree.startCanCommit(ShardDataTree.java:819)
	at org.opendaylight.controller.cluster.datastore.SimpleShardDataTreeCohort.canCommit(SimpleShardDataTreeCohort.java:90)
	at org.opendaylight.controller.cluster.datastore.CohortEntry.canCommit(CohortEntry.java:97)
	at org.opendaylight.controller.cluster.datastore.ShardCommitCoordinator.handleCanCommit(ShardCommitCoordinator.java:236)
	at org.opendaylight.controller.cluster.datastore.ShardCommitCoordinator.handleForwardedReadyTransaction(ShardCommitCoordinator.java:114)
	at org.opendaylight.controller.cluster.datastore.Shard.handleForwardedReadyTransaction(Shard.java:699)
	at org.opendaylight.controller.cluster.datastore.Shard.handleNonRaftCommand(Shard.java:314)
	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:170)
	at org.opendaylight.controller.cluster.common.actor.MeteringBehavior.apply(MeteringBehavior.java:104)
	at akka.actor.ActorCell$$anonfun$become$1.applyOrElse(ActorCell.scala:544)
	at akka.actor.Actor$class.aroundReceive(Actor.scala:502)
	at akka.persistence.UntypedPersistentActor.akka$persistence$Eventsourced$$super$aroundReceive(PersistentActor.scala:168)
	at akka.persistence.Eventsourced$$anon$1.stateReceive(Eventsourced.scala:727)
	at akka.persistence.Eventsourced$class.aroundReceive(Eventsourced.scala:183)
	at akka.persistence.UntypedPersistentActor.aroundReceive(PersistentActor.scala:168)
	at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526)
	at akka.actor.ActorCell.invoke(ActorCell.scala:495)
	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 scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
	at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
	at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
	at scala.concurrent.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.checkWriteApplicable(SchemaAwareApplyOperation.java:174)
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:128)
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:305)
	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:131)
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:305)
	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:131)
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.StructuralContainerModificationStrategy.checkApplicable(StructuralContainerModificationStrategy.java:99)
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkChildPreconditions(AbstractNodeContainerModificationStrategy.java:305)
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.checkTouchApplicable(AbstractNodeContainerModificationStrategy.java:288)
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.checkApplicable(SchemaAwareApplyOperation.java:125)
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.RootModificationApplyOperation.checkApplicable(RootModificationApplyOperation.java:72)
	at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractDataTreeTip.validate(AbstractDataTreeTip.java:35)
	at org.opendaylight.controller.cluster.datastore.ShardDataTree.lambda$processNextPendingTransaction$0(ShardDataTree.java:743)
	... 28 more
2017-11-20 02:52:27,875 | ERROR | eChangeHandler-0 | LockManager                      | 319 - org.opendaylight.genius.lockmanager-impl - 0.2.3.SNAPSHOT | Unable to acquire lock for ACL-ID-POOL2c9a93ba-3add-4c68-9b1c-8242138262ee, try 2
2017-11-20 02:52:27,876 | INFO  | nPool-1-worker-1 | UpdateIdEntryJob                 | 320 - org.opendaylight.genius.idmanager-impl - 0.2.3.SNAPSHOT | Updated id entry with idValues null, idKey UDP_DESTINATION_1_0Ingress1834849402-8f40-473e-9a26-207b20f8ad93, pool acl.flow.priorities.pool.176858005830847.243.PERMIT.169676285


 Comments   
Comment by Michael Vorburger [ 11/Jan/18 ]

FYI in https://git.opendaylight.org/gerrit/#/c/66362/1/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/databroker/ConcurrentDOMDataBroker.java the WARN log in ConcurrentDOMDataBroker was reduced to a DEBUG level, so we won't see the anymore. But this WARN & ERROR from genius LockManager is what we need to understand here:

WARN  | LockManager | Already locked for ACL-ID-POOL2c9a93ba-3add-4c68-9b1c-8242138262ee after waiting 1000ms, try 1
ERROR | LockManager | Unable to acquire lock for ACL-ID-POOL2c9a93ba-3add-4c68-9b1c-8242138262ee, try 2

Now this looks VERY similiar to GENIUS-62 - I actually think I fixed that in https://git.opendaylight.org/gerrit/#/c/63121/ ?

There were also other recent changes in LockManager, see https://git.opendaylight.org/gerrit/#/c/61526/ and https://git.opendaylight.org/gerrit/#/c/65233/ which was just for unlock... so if this still happens I can try that - but I suspect that it probably already does not happen anymore (thanks to GENIUS-62) - shague can you help confirm if this is solved, or still present in latest master? And if it is, can you provide how the log looks now - there should now be a cause included, which will help better understand what's going on.

Comment by Sam Hague [ 13/Jan/18 ]

Latest master runs don't look to have the problem. Question is, the original bug is written against carbon so do we want to fix this on carbon and nitrogen also?

Comment by Michael Vorburger [ 13/Jan/18 ]

> do we want to fix this on carbon and nitrogen also?

personally I do not, nope.

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