Operating System: All
Platform: All

##ID Allocation: Below 2 messages come from IDManager when ID is allocated to idkey.

The newIdValues [1011] for the idKey TCP_DESTINATION_1_0Ingress33216dc65c-dab2-44e4-a649-d5b3d094003c
Updated id entry with idValues [1011], idKey TCP_DESTINATION_1_0Ingress33216dc65c-dab2-44e4-a649-d5b3d094003c, pool acl.flow.priorities.pool.123829938003760.243.PERMIT.169676308

1. 1. ID Release failed: Below 3 messages come from IDManager when ID release is failed for idkey.

Releasing ID TCP_DESTINATION_1_0Ingress33216dc65c-dab2-44e4-a649-d5b3d094003c from pool acl.flow.priorities.pool.123829938003760.243.PERMIT
releaseId failed: ReleaseIdInput [_idKey=TCP_DESTINATION_1_0Ingress33216dc65c-dab2-44e4-a649-d5b3d094003c, _poolName=acl.flow.priorities.pool.123829938003760.243.PERMIT, augmentation=[]]
org.opendaylight.genius.idmanager.IdManagerException: Id Entries does not exist
RPC Call to release Id TCP_DESTINATION_1_0Ingress33216dc65c-dab2-44e4-a649-d5b3d094003c with Key [RpcError [message=releaseId failed: ReleaseIdInput [_idKey=TCP_DESTINATION_1_0Ingress33216dc65c-dab2-44e4-a649-d5b3d094003c, _poolName=acl.flow.priorities.pool.123829938003760.243.PERMIT, augmentation=[]], severity=ERROR, errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null, cause=org.opendaylight.genius.idmanager.IdManagerException: Id Entries does not exist]] returned with Errors {}

1. 1. ID Allocation: Below 2 messages come from IDManager when ID is allocated to idkey.

The newIdValues [1000] for the idKey TCP_DESTINATION_1_0Ingress33216dc65c-dab2-44e4-a649-d5b3d094003c
Updated id entry with idValues [1000], idKey TCP_DESTINATION_1_0Ingress33216dc65c-dab2-44e4-a649-d5b3d094003c, pool acl.flow.priorities.pool.123829938003760.243.PERMIT.169676308

1. 1. ID Release Pass: Below 2 messages come from IDManager when ID release is successful for idkey.

Releasing ID TCP_DESTINATION_1_0Ingress33216dc65c-dab2-44e4-a649-d5b3d094003c from pool acl.flow.priorities.pool.123829938003760.243.PERMIT
Updated id entry with idValues null, idKey TCP_DESTINATION_1_0Ingress33216dc65c-dab2-44e4-a649-d5b3d094003c, pool acl.flow.priorities.pool.123829938003760.243.PERMIT.169676308

Same is the pattern for other keys (around 32 idKeys in karaf logs) as well.
As per above pattern, I found that first time allocated ID is not getting released and fails, thereafter allocated IDs for idKey gets released successfully.

This issue does not occur if VM or neutron port is deleted.

But, it has been observed that when ovs (br-int on which neutron port is associated) is restarted and then after VM or neutron port is deleted, then releaseId fails.

1. This issue is reproduced in dev environment locally on our laptop VMs.
2. Issue occurs only when OVS switch is restarted before deleting VM.
3. After switch restart, if VM is deleted, then ‘releaseId failed’ exception comes in the karaf logs. Root cause found for this issue is:

3.a. After OVS restart, ACL pools are created again and performed through IdManager transaction. (NOTE: it consumes time)

3.b. In parallel, control proceeds and other operations in ACL gets performed like pushing fixed rules, conntrack rules and then ACL rules.

3.c. While ACL rules are being pushed, allocateId() method is getting called which allocates ID for ACL rule and IDManager’s allocateId() method tries to fetch pool in which it will allocate ID, but till this time ACL pool (as mentioned in above step 3.a) is not yet created, hence allocateId() method fails.

3.d. Since allocateId() is failed and ID is not allocated, then later while VM deletion, releaseId() fails because it does not find ID in pool, which is very obvious.

Issue is fixed and code change review is raised:
https://git.opendaylight.org/gerrit/#/c/60012/

Seen in CSIT

Seen in CSIT in latest build
https://logs.opendaylight.org/releng/jenkins092/netvirt-csit-1node-openstack-newton-nodl-v2-upstream-stateful-nitrogen/123/odl1_karaf.log.gz

2017-07-13 21:46:24,492 | ERROR | eChangeHandler-1 | IdManager | 228 - org.opendaylight.genius.idmanager-impl - 0.3.0.SNAPSHOT | releaseId failed: ReleaseIdInput [_idKey=TCP_DESTINATION_1_0Ingress1025410a80-dffd-40e2-99ed-1f50a6d20d53, _poolName=acl.flow.priorities.pool.159194546606218.243.PERMIT, augmentation=[]]
ExpectedDataObjectNotFoundException{message=Expected to find data in CONFIGURATION at KeyedInstanceIdentifier

, but there was none, severity=ERROR, errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null, cause=null]]}
at org.opendaylight.genius.datastoreutils.SingleTransactionDataBroker.syncRead(SingleTransactionDataBroker.java:112)[237:org.opendaylight.genius.mdsalutil-api:0.3.0.SNAPSHOT]
at org.opendaylight.genius.datastoreutils.SingleTransactionDataBroker.syncRead(SingleTransactionDataBroker.java:100)[237:org.opendaylight.genius.mdsalutil-api:0.3.0.SNAPSHOT]
at org.opendaylight.genius.idmanager.IdManager.releaseIdFromLocalPool(IdManager.java:634)[228:org.opendaylight.genius.idmanager-impl:0.3.0.SNAPSHOT]
at org.opendaylight.genius.idmanager.IdManager.releaseId(IdManager.java:298)[228:org.opendaylight.genius.idmanager-impl:0.3.0.SNAPSHOT]
at org.opendaylight.yangtools.yang.binding.util.RpcMethodInvokerWithInput.invokeOn(RpcMethodInvokerWithInput.java:31)[285:org.opendaylight.mdsal.yang-binding:0.11.0.SNAPSHOT]
at org.opendaylight.yangtools.yang.binding.util.AbstractMappedRpcInvoker.invokeRpc(AbstractMappedRpcInvoker.java:52)[285:org.opendaylight.mdsal.yang-binding:0.11.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.BindingDOMRpcImplementationAdapter.invoke(BindingDOMRpcImplementationAdapter.java:83)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.BindingDOMRpcImplementationAdapter.invokeRpc(BindingDOMRpcImplementationAdapter.java:70)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.dom.broker.impl.GlobalDOMRpcRoutingTableEntry.invokeRpc(GlobalDOMRpcRoutingTableEntry.java:39)[201:org.opendaylight.controller.sal-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRoutingTable.invokeRpc(DOMRpcRoutingTable.java:177)[201:org.opendaylight.controller.sal-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter.invokeRpc(DOMRpcRouter.java:102)[201:org.opendaylight.controller.sal-broker-impl:1.6.0.SNAPSHOT]
at Proxy8f3656f0_0eb6_4e36_97f4_3ff313b90630.invokeRpc(Unknown Source)[:]
at Proxy38f9105e_0afd_412f_a32c_a40ea931afa0.invokeRpc(Unknown Source)[:]
at org.opendaylight.controller.md.sal.binding.impl.RpcServiceAdapter.invoke0(RpcServiceAdapter.java:65)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.RpcServiceAdapter.access$000(RpcServiceAdapter.java:43)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.RpcServiceAdapter$RpcInvocationStrategy.invoke(RpcServiceAdapter.java:156)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.RpcServiceAdapter.invoke(RpcServiceAdapter.java:96)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at com.sun.proxy.$Proxy102.releaseId(Unknown Source)[227:org.opendaylight.genius.idmanager-api:0.3.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.utils.AclServiceUtils.releaseId(AclServiceUtils.java:783)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.utils.AclServiceUtils.releaseAndRemoveFlowPriorityFromCache(AclServiceUtils.java:839)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractIngressAclServiceImpl.getIngressSpecificAclFlowPriority(AbstractIngressAclServiceImpl.java:392)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.StatefulIngressAclServiceImpl.syncSpecificAclFlow(StatefulIngressAclServiceImpl.java:104)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractIngressAclServiceImpl.programAceRule(AbstractIngressAclServiceImpl.java:240)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractIngressAclServiceImpl.programAclRules(AbstractIngressAclServiceImpl.java:209)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractAclServiceImpl.updateCustomRules(AbstractAclServiceImpl.java:189)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractAclServiceImpl.processInterfaceUpdate(AbstractAclServiceImpl.java:171)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractAclServiceImpl.updateAcl(AbstractAclServiceImpl.java:142)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AclServiceManagerImpl.notify(AclServiceManagerImpl.java:57)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.listeners.AclInterfaceListener.update(AclInterfaceListener.java:104)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.listeners.AclInterfaceListener.update(AclInterfaceListener.java:33)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.genius.datastoreutils.AsyncDataTreeChangeListenerBase$DataTreeChangeHandler.run(AsyncDataTreeChangeListenerBase.java:153)[237:org.opendaylight.genius.mdsalutil-api:0.3.0.SNAPSHOT]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_131]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_131]
2017-07-13 21:46:24,496 | WARN | eChangeHandler-1 | AclServiceUtils | 291 - org.opendaylight.netvirt.aclservice-impl - 0.5.0.SNAPSHOT | RPC Call to release Id TCP_DESTINATION_1_0Ingress1025410a80-dffd-40e2-99ed-1f50a6d20d53 with Key [RpcError [message=releaseId failed: ReleaseIdInput [_idKey=TCP_DESTINATION_1_0Ingress1025410a80-dffd-40e2-99ed-1f50a6d20d53, _poolName=acl.flow.priorities.pool.159194546606218.243.PERMIT, augmentation=[]], severity=ERROR, errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null, cause=ExpectedDataObjectNotFoundException{message=Expected to find data in CONFIGURATION at KeyedInstanceIdentifier

, but there was none, severity=ERROR, errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null, cause=null]]}], RpcError [message=Expected to find data in CONFIGURATION at KeyedInstanceIdentifier

, but there was none, severity=ERROR, errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null, cause=null]] returned with Errors {}

Different keyword but root cause could be same.

Seen in CSIT in latest build
https://logs.opendaylight.org/releng/jenkins092/netvirt-csit-1node-openstack-newton-nodl-v2-upstream-stateful-nitrogen/123/odl1_karaf.log.gz

2017-07-13 21:46:24,492 | ERROR | eChangeHandler-1 | IdManager | 228 - org.opendaylight.genius.idmanager-impl - 0.3.0.SNAPSHOT | releaseId failed: ReleaseIdInput [_idKey=TCP_DESTINATION_1_0Ingress1025410a80-dffd-40e2-99ed-1f50a6d20d53, _poolName=acl.flow.priorities.pool.159194546606218.243.PERMIT, augmentation=[]]
ExpectedDataObjectNotFoundException{message=Expected to find data in CONFIGURATION at KeyedInstanceIdentifier

, but there was none, severity=ERROR, errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null, cause=null]]}
at org.opendaylight.genius.datastoreutils.SingleTransactionDataBroker.syncRead(SingleTransactionDataBroker.java:112)[237:org.opendaylight.genius.mdsalutil-api:0.3.0.SNAPSHOT]
at org.opendaylight.genius.datastoreutils.SingleTransactionDataBroker.syncRead(SingleTransactionDataBroker.java:100)[237:org.opendaylight.genius.mdsalutil-api:0.3.0.SNAPSHOT]
at org.opendaylight.genius.idmanager.IdManager.releaseIdFromLocalPool(IdManager.java:634)[228:org.opendaylight.genius.idmanager-impl:0.3.0.SNAPSHOT]
at org.opendaylight.genius.idmanager.IdManager.releaseId(IdManager.java:298)[228:org.opendaylight.genius.idmanager-impl:0.3.0.SNAPSHOT]
at org.opendaylight.yangtools.yang.binding.util.RpcMethodInvokerWithInput.invokeOn(RpcMethodInvokerWithInput.java:31)[285:org.opendaylight.mdsal.yang-binding:0.11.0.SNAPSHOT]
at org.opendaylight.yangtools.yang.binding.util.AbstractMappedRpcInvoker.invokeRpc(AbstractMappedRpcInvoker.java:52)[285:org.opendaylight.mdsal.yang-binding:0.11.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.BindingDOMRpcImplementationAdapter.invoke(BindingDOMRpcImplementationAdapter.java:83)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.BindingDOMRpcImplementationAdapter.invokeRpc(BindingDOMRpcImplementationAdapter.java:70)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.dom.broker.impl.GlobalDOMRpcRoutingTableEntry.invokeRpc(GlobalDOMRpcRoutingTableEntry.java:39)[201:org.opendaylight.controller.sal-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRoutingTable.invokeRpc(DOMRpcRoutingTable.java:177)[201:org.opendaylight.controller.sal-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter.invokeRpc(DOMRpcRouter.java:102)[201:org.opendaylight.controller.sal-broker-impl:1.6.0.SNAPSHOT]
at Proxy8f3656f0_0eb6_4e36_97f4_3ff313b90630.invokeRpc(Unknown Source)[:]
at Proxy38f9105e_0afd_412f_a32c_a40ea931afa0.invokeRpc(Unknown Source)[:]
at org.opendaylight.controller.md.sal.binding.impl.RpcServiceAdapter.invoke0(RpcServiceAdapter.java:65)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.RpcServiceAdapter.access$000(RpcServiceAdapter.java:43)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.RpcServiceAdapter$RpcInvocationStrategy.invoke(RpcServiceAdapter.java:156)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.RpcServiceAdapter.invoke(RpcServiceAdapter.java:96)[198:org.opendaylight.controller.sal-binding-broker-impl:1.6.0.SNAPSHOT]
at com.sun.proxy.$Proxy102.releaseId(Unknown Source)[227:org.opendaylight.genius.idmanager-api:0.3.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.utils.AclServiceUtils.releaseId(AclServiceUtils.java:783)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.utils.AclServiceUtils.releaseAndRemoveFlowPriorityFromCache(AclServiceUtils.java:839)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractIngressAclServiceImpl.getIngressSpecificAclFlowPriority(AbstractIngressAclServiceImpl.java:392)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.StatefulIngressAclServiceImpl.syncSpecificAclFlow(StatefulIngressAclServiceImpl.java:104)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractIngressAclServiceImpl.programAceRule(AbstractIngressAclServiceImpl.java:240)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractIngressAclServiceImpl.programAclRules(AbstractIngressAclServiceImpl.java:209)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractAclServiceImpl.updateCustomRules(AbstractAclServiceImpl.java:189)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractAclServiceImpl.processInterfaceUpdate(AbstractAclServiceImpl.java:171)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AbstractAclServiceImpl.updateAcl(AbstractAclServiceImpl.java:142)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.AclServiceManagerImpl.notify(AclServiceManagerImpl.java:57)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.listeners.AclInterfaceListener.update(AclInterfaceListener.java:104)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.netvirt.aclservice.listeners.AclInterfaceListener.update(AclInterfaceListener.java:33)[291:org.opendaylight.netvirt.aclservice-impl:0.5.0.SNAPSHOT]
at org.opendaylight.genius.datastoreutils.AsyncDataTreeChangeListenerBase$DataTreeChangeHandler.run(AsyncDataTreeChangeListenerBase.java:153)[237:org.opendaylight.genius.mdsalutil-api:0.3.0.SNAPSHOT]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_131]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_131]
2017-07-13 21:46:24,496 | WARN | eChangeHandler-1 | AclServiceUtils | 291 - org.opendaylight.netvirt.aclservice-impl - 0.5.0.SNAPSHOT | RPC Call to release Id TCP_DESTINATION_1_0Ingress1025410a80-dffd-40e2-99ed-1f50a6d20d53 with Key [RpcError [message=releaseId failed: ReleaseIdInput [_idKey=TCP_DESTINATION_1_0Ingress1025410a80-dffd-40e2-99ed-1f50a6d20d53, _poolName=acl.flow.priorities.pool.159194546606218.243.PERMIT, augmentation=[]], severity=ERROR, errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null, cause=ExpectedDataObjectNotFoundException{message=Expected to find data in CONFIGURATION at KeyedInstanceIdentifier

, but there was none, severity=ERROR, errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null, cause=null]]}], RpcError [message=Expected to find data in CONFIGURATION at KeyedInstanceIdentifier

, but there was none, severity=ERROR, errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null, cause=null]] returned with Errors {}

Different keyword but root cause could be same.

https://git.opendaylight.org/gerrit/60012