Next round of scale testing had issue: https://gist.github.com/smalleni/c96b97db950f925aa879dac91ad3b635
This one MAY be easy to fix, I'm not sure sure - worth a try to see if with a retry = 3 instead of the default 1 in that enqueueJob() we see in this class this may go away? Here are Gerrits for all branches to try this out:
I see the below exception, has retryCount=3 so I guess the code is in. Does the exception mean it did not fix the problem?
2017-11-29 23:51:58,501 | WARN | ult-dispatcher-6 | ConcurrentDOMDataBroker | 203 - org.opendaylight.controller.sal-distributed-datastore - 1.5.3.SNAPSHOT | Tx: DOM-318 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.]]}
Caused by: org.opendaylight.yangtools.yang.data.api.schema.tree.ConflictingModificationAppliedException: Node was created by other transaction.
2017-11-29 23:51:58,503 | WARN | CommitFutures-2 | DataStoreJobCoordinator | 293 - org.opendaylight.genius.mdsalutil-api - 0.2.3.SNAPSHOT | Job: JobEntry{key='VPNNODE-30811640961648', mainWorker=org.opendaylight.netvirt.vpnmanager.VpnNodeListener$$Lambda$368/1576234995@54571922, rollbackWorker=null, retryCount=3, futures=[org.opendaylight.controller.cluster.databroker.ConcurrentDOMDataBroker$AsyncNotifyingSettableFuture@5a90edd8]} failed
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.]]}
Caused by: org.opendaylight.yangtools.yang.data.api.schema.tree.ConflictingModificationAppliedException: Node was created by other transaction.*no* further _formatting_ is done here
shague I wonder if the change really does not fix the problem, or if this is "just" a kind of confusing logging issue.. do you have any way of verifiying if the "functionality" actually worked? Can you link to a full log where this was seen, preferably from master (with JobCoordinatorImpl instead of DataStoreJobCoordinator).
For the 2nd log, I'm expecting a closer inspection of a full log should show that after the WARN with retryCount=3, it retried and that then worked (hopefully); to confirm that, you would have to see if there also a retryCount=2 and retryCount=1 (shortly after, for the exact same Job), or not. If there isn't, then this means the fix did work - it just confusing that it's still gives us a WARN on the first attempt which failed but then the retry worked. That could be fixed by proposed https://git.opendaylight.org/gerrit/66355, if others agree to this.
For the 1st log, that's a WARN from controller. I'm not sure I agree that controller should emit that WARN.. it's one of those "where shld you log, in the callee or in the caller" kind of discussions; I've just raised this on thread "How about reducing WARN to DEBUG for ConflictingModificationAppliedException in ConcurrentDOMDataBroker?" on controller-dev, see https://lists.opendaylight.org/pipermail/controller-dev/2017-December/014099.html.
Here is the log from the master patch (https://git.opendaylight.org/gerrit/#/c/65944/) gate job: https://logs.opendaylight.org/releng/jenkins092/netvirt-csit-3node-openstack-ocata-gate-stateful-oxygen/8/odl_1/odl1_karaf.log.gz
In that run there all you see is the retryCount=3 and no decrement. There is a preceding OLFE before the rertryCount exception. Does that imply it only tried once as you mention and worked? If so, then yes, that is very confusing to see the WARN with OLFE - I would never think that it worked in that case.
Agreed on the first log. These are things very difficult to control in the downstream apps since the errors pop up regardless of what the app thinks.
Does that imply it only tried once as you mention and worked?
That is my understanding, yes.
Agreed on the first log. These are things very difficult to control in the downstream apps since the errors pop up regardless of what the app thinks.
==> CONTROLLER-1802
Michael,
in this job: https://logs.opendaylight.org/releng/jenkins092/netvirt-csit-1node-openstack-ocata-gate-stateful-oxygen/535/odl_1/odl1_exception.log.gz we only got a retryCount=0 - does that mean the patch did what it was supposed to and only log the final exception after the last retry? The bug is still there, but the number of logs was reduced?
Also can you clarify that your patches here - they don't fix this bug, they just reduce the number of logs? Do I have that right?
2017-12-12 04:41:41,597 | WARN | ult-dispatcher-3 | ConcurrentDOMDataBroker | 217 - org.opendaylight.controller.sal-distributed-datastore - 1.7.0.SNAPSHOT | Tx: DOM-163473 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 replaced by other transaction.]]}
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)[417:org.scala-lang.scala-library:2.11.11.v20170413-090219-8a413ba7cc]
Caused by: org.opendaylight.yangtools.yang.data.api.schema.tree.ConflictingModificationAppliedException: Node was replaced by other transaction.
2017-12-12 04:41:41,601 | WARN | CommitFutures-15 | JobCoordinatorImpl | 261 - org.opendaylight.infrautils.jobcoordinator-impl - 1.3.0.SNAPSHOT | Job: JobEntry{key='c7da4167-372c-46c4-b718-9331ac4faff0', mainWorker=ItmTepRemoveWorker { Delete Dpn List : [DPNTEPsInfo [_dPNID=181234940435320, _key=DPNTEPsInfoKey [_dPNID=181234940435320], _tunnelEndPoints=[TunnelEndPoints [_gwIpAddress=IpAddress [_ipv4Address=Ipv4Address [_value=0.0.0.0]], _interfaceName=181234940435320:tunnel_port:0, _ipAddress=IpAddress [_ipv4Address=Ipv4Address [_value=10.29.15.6]], _key=TunnelEndPointsKey [_portname=tunnel_port, _vLANID=0, _ipAddress=IpAddress [_ipv4Address=Ipv4Address [_value=10.29.15.6]], _tunnelType=class org.opendaylight.yang.gen.v1.urn.opendaylight.genius.interfacemanager.rev160406.TunnelTypeVxlan], _optionTunnelTos=0, _portname=tunnel_port, _subnetMask=IpPrefix [_ipv4Prefix=Ipv4Prefix [_value=0.0.0.0/0]], _tunnelType=class org.opendaylight.yang.gen.v1.urn.opendaylight.genius.interfacemanager.rev160406.TunnelTypeVxlan, _tzMembership=[TzMembership [_key=TzMembershipKey [_zoneName=c7da4167-372c-46c4-b718-9331ac4faff0], _zoneName=c7da4167-372c-46c4-b718-9331ac4faff0, augmentation=[]]], _vLANID=0, _optionOfTunnel=false, augmentation=[]]], augmentation=[]], DPNTEPsInfo [_dPNID=88475369668342, _key=DPNTEPsInfoKey [_dPNID=88475369668342], _tunnelEndPoints=[TunnelEndPoints [_gwIpAddress=IpAddress [_ipv4Address=Ipv4Address [_value=0.0.0.0]], _interfaceName=88475369668342:tunnel_port:0, _ipAddress=IpAddress [_ipv4Address=Ipv4Address [_value=10.29.13.254]], _key=TunnelEndPointsKey [_portname=tunnel_port, _vLANID=0, _ipAddress=IpAddress [_ipv4Address=Ipv4Address [_value=10.29.13.254]], _tunnelType=class org.opendaylight.yang.gen.v1.urn.opendaylight.genius.interfacemanager.rev160406.TunnelTypeVxlan], _optionTunnelTos=0, _portname=tunnel_port, _subnetMask=IpPrefix [_ipv4Prefix=Ipv4Prefix [_value=0.0.0.0/0]], _tunnelType=class org.opendaylight.yang.gen.v1.urn.opendaylight.genius.interfacemanager.rev160406.TunnelTypeVxlan, _tzMembership=[TzMembership [_key=TzMembershipKey [_zoneName=c7da4167-372c-46c4-b718-9331ac4faff0], _zoneName=c7da4167-372c-46c4-b718-9331ac4faff0, augmentation=[]]], _vLANID=0, _optionOfTunnel=false, augmentation=[]]], augmentation=[]], DPNTEPsInfo [_dPNID=84424921983078, _key=DPNTEPsInfoKey [_dPNID=84424921983078], _tunnelEndPoints=[TunnelEndPoints [_gwIpAddress=IpAddress [_ipv4Address=Ipv4Address [_value=0.0.0.0]], _interfaceName=84424921983078:tunnel_port:0, _ipAddress=IpAddress [_ipv4Address=Ipv4Address [_value=10.29.14.8]], _key=TunnelEndPointsKey [_portname=tunnel_port, _vLANID=0, _ipAddress=IpAddress [_ipv4Address=Ipv4Address [_value=10.29.14.8]], _tunnelType=class org.opendaylight.yang.gen.v1.urn.opendaylight.genius.interfacemanager.rev160406.TunnelTypeVxlan], _optionTunnelTos=0, _portname=tunnel_port, _subnetMask=IpPrefix [_ipv4Prefix=Ipv4Prefix [_value=0.0.0.0/0]], _tunnelType=class org.opendaylight.yang.gen.v1.urn.opendaylight.genius.interfacemanager.rev160406.TunnelTypeVxlan, _tzMembership=[TzMembership [_key=TzMembershipKey [_zoneName=c7da4167-372c-46c4-b718-9331ac4faff0], _zoneName=c7da4167-372c-46c4-b718-9331ac4faff0, augmentation=[]]], _vLANID=0, _optionOfTunnel=false, augmentation=[]]], augmentation=[]]] }, rollbackWorker=null, retryCount=0, futures=[org.opendaylight.controller.cluster.databroker.ConcurrentDOMDataBroker$AsyncNotifyingSettableFuture@62cfb748, com.google.common.util.concurrent.ImmediateFuture$ImmediateSuccessfulCheckedFuture@66f03fc9]} failed
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 replaced by other transaction.]]}
we only got a retryCount=0 - does that mean the patch did what it was supposed to and only log the final exception after the last retry? The bug is still there, but the number of logs was reduced?
Now wait a second, your new log above from JobCoordinatorImpl is re. ItmTepRemoveWorker.. whereas originally this issue was re. VpnNodeListener... so what is the "scope" of this bug? 
The change above only fixed VpnNodeListener, by adding a ,3 parameter for retries, which we proved helped.
Now you either have to do the same in ItmTepRemoveWorker, and everywhere else, or we change the default retries in JobCoordinator from 0 to 3 for EVERYTHING... I'm not sure that everyone will agree that is a good idea, but I can propose it, for discussion, in c/66618 ...
Also can you clarify that your patches here - they don't fix this bug, they just reduce the number of logs? Do I have that right?
Well, no careful, you mix up 2 things here: Those 3 retries added e.g. to VpnNodeListener, or maybe by changing the default in JobCoordinator, DO fix this bug. But then the CONTROLLER-1802 improves logging to reduce where it does not make sense to log (because there are retries), that's what c/66362 does for controller (merged on Dec 13th but still appears as WARN from ConcurrentDOMDataBroker because your log above is from a Dec 12th run!) and c/66355 forJobCoordinator (finally just merged, but likely buggy; follow up in c/66634).
Ok so the fact we don't see any errors in the VpnNodeListener patch means somewhere in the 1-3 retries it passed - and failures would only be logged at debug, which is not on by default, so we don't know how many tries it took, but it did pass.
Then we need to see if we want to do the same for the new error. And in this one, it says retries =0 since that is the default - and not that is got through all retries and ended at 0.
That (above) is correct. FTR c/66618 which changed the default retries in JobCoordinator from 0 to 3 globally for everything was discussed, accepted and merged on Jan 9th.
Perhaps we could finally close this bug (with Fix Version: Oxygen), and open new ones for other places?
shague SridharG can this one finally be closed now, or is there anything else I can do here?