[GENIUS-244] CDTCN is getting triggered twice Created: 27/Nov/18  Updated: 28/Nov/18  Resolved: 28/Nov/18

Status: Verified
Project: genius
Component/s: None
Affects Version/s: Fluorine-SR1, Neon
Fix Version/s: Fluorine-SR2, Neon

Type: Bug Priority: High
Reporter: Faseela K Assignee: Faseela K
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File debug-notif.txt    

 Description   

I am hitting one weird issue in genius, where I see a particular CDTCN being triggered twice. Was having a DEBUG log in the add(), remove() methods of the class below, which is getting printed twice in the CSIT log for the same key add/delete.

https://github.com/opendaylight/genius/blob/master/interfacemanager/interfacemanager-impl/src/main/java/org/opendaylight/genius/interfacemanager/listeners/InterfaceConfigListener.java#L99

This is a heavily used DS in genius, and this can lead to serious performance issues.

The behavior is same in Fluorine as well as Neon. [Did not check oxygen though]

The corresponding yang model at :

https://github.com/opendaylight/genius/blob/master/interfacemanager/interfacemanager-api/src/main/yang/odl-interface.yang#L241

I am able to reproduce the issue locally with a simply PUT/DELETE request.

Step 1 : opendaylight-user@root>feature:install odl-genius-rest

Step 2 : Do a PUT at http://localhost:8181/restconf/config/ietf-interfaces:interfaces/interface/l2vlan-trunk 

{
"interface": [

{ "enabled": true, "name": "l2vlan-trunk", "odl-interface:l2vlan-mode": "transparent", "odl-interface:parent-interface": "tap8ed70586-6c", "type": "iana-if-type:l2vlan" }

]
}

opendaylight-user@root>log:tail
10:59:34.962 DEBUG [opendaylight-cluster-data-notification-dispatcher-119] Received Interface Add Event: KeyedInstanceIdentifier

{targetType=interface org.o pendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.interfaces.rev140508.interfaces.Interface, path=[org.opendaylight.yang.gen.v1.urn.ietf.params.xml. ns.yang.ietf.interfaces.rev140508.Interfaces, org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.interfaces.rev140508.interfaces.Interface[key=I nterfaceKey\\\\{_name=l2vlan-trunk}

]]}, Interface

{getName=l2vlan-trunk, getType=interface org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.iana._if.typ e.rev170119.L2vlan, isEnabled=true, augmentations=

{interface org.opendaylight.yang.gen.v1.urn.opendaylight.genius.interfacemanager.rev160406.IfL2vlan=IfL2v lan

{getL2vlanMode=Transparent}

, interface org.opendaylight.yang.gen.v1.urn.opendaylight.genius.interfacemanager.rev160406.ParentRefs=ParentRefs{getParentIn terface=tap8ed70586-6c}}}
10:59:34.969 DEBUG [opendaylight-cluster-data-notification-dispatcher-139] Received Interface Add Event: KeyedInstanceIdentifier{targetType=interface org.o pendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.interfaces.rev140508.interfaces.Interface, path=[org.opendaylight.yang.gen.v1.urn.ietf.params.xml. ns.yang.ietf.interfaces.rev140508.Interfaces, org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.interfaces.rev140508.interfaces.Interface[key=I nterfaceKey{_name=l2vlan-trunk}

]]}, Interface{getName=l2vlan-trunk, getType=interface org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.iana._if.typ
e.rev170119.L2vlan, isEnabled=true, augmentations=

{interface org.opendaylight.yang.gen.v1.urn.opendaylight.genius.interfacemanager.rev160406.IfL2vlan=IfL2v lan
{getL2vlanMode=Transparent}

, interface org.opendaylight.yang.gen.v1.urn.opendaylight.genius.interfacemanager.rev160406.ParentRefs=ParentRefs

{getParentIn terface=tap8ed70586-6c}

}}
10:59:34.973 INFO [jobcoordinator-main-task-0] Creating child interface l2vlan-trunk of type Transparent bound on parent-interface tap8ed70586-6c
10:59:34.975 INFO [jobcoordinator-main-task-0] adding vlan configuration for interface l2vlan-trunk
10:59:34.983 DEBUG [jobcoordinator-main-task-0] creating lport tag to interface map for l2vlan-trunk ifIndex 5
10:59:34.998 DEBUG [jobcoordinator-main-task-0] could not retrieve interface state corresponding to l2vlan-trunk, processing will be resumed when interface
-state is available
10:59:35.010 INFO [ResourceBatchingManager-0] Total taken ##time = 12ms for resourceList of size 1 for resourceType INTERFACEMGR-DEFAULT-OPERATIONAL

 Comments   
Comment by Karthika Panneer [ 27/Nov/18 ]

CSIT Logs :

https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/builder-copy-sandbox-logs/528/

 

Comment by Robert Varga [ 27/Nov/18 ]

I don't think this is an MD-SAL issue, as the logs show CDS is delivering the same notification to four different subscribers:

 

2018-11-27T12:33:17,109 Sending 1 change notification(s) [
    DefaultDataTreeCandidate{
        rootPath=/(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)interfaces/interface/interface[{(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name=l2vlan-trunk}],
        rootNode=RecursiveWriteCandidateNode{
            data = ImmutableMapEntryNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)interface[{(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name=l2vlan-trunk}],
            value=[ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)enabled, value=true},
                ImmutableAugmentationNode{nodeIdentifier=AugmentationIdentifier{childNames=[(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)datapath-node-identifier, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)node-identifier, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)parent-interface]}, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)parent-interface, value=tap8ed70586-6c}]},
                ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)type, value=(urn:ietf:params:xml:ns:yang:iana-if-type?revision=2014-05-08)l2vlan},
                ImmutableAugmentationNode{nodeIdentifier=AugmentationIdentifier{childNames=[(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)vlan-id, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)l2vlan-mode]}, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)l2vlan-mode, value=transparent}]},
                ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name, value=l2vlan-trunk}]}
        }}]
    to listener org.opendaylight.controller.sal.core.compat.LegacyDOMDataBrokerAdapter$2$$Lambda$1234/2066369190@2f00b46b

 

2018-11-27T12:33:17,109 Sending 1 change notification(s) [
    DefaultDataTreeCandidate{
        rootPath=/(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)interfaces/interface/interface[{(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name=l2vlan-trunk}],
        rootNode=RecursiveWriteCandidateNode{
            data = ImmutableMapEntryNode{
                nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)interface[{(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name=l2vlan-trunk}],
                value=[ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)enabled, value=true},
                    ImmutableAugmentationNode{nodeIdentifier=AugmentationIdentifier{childNames=[(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)datapath-node-identifier, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)node-identifier, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)parent-interface]}, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)parent-interface, value=tap8ed70586-6c}]},
                    ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)type, value=(urn:ietf:params:xml:ns:yang:iana-if-type?revision=2014-05-08)l2vlan},
                    ImmutableAugmentationNode{nodeIdentifier=AugmentationIdentifier{childNames=[(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)vlan-id, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)l2vlan-mode]}, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)l2vlan-mode, value=transparent}]},
                    ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name, value=l2vlan-trunk}]}}}]

    to listener org.opendaylight.controller.sal.core.compat.LegacyDOMDataBrokerAdapter$2$$Lambda$1153/947871773@284ec343

2018-11-27T12:33:17,109 Sending 1 change notification(s) [
    DefaultDataTreeCandidate{
        rootPath=/(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)interfaces/interface/interface[{(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name=l2vlan-trunk}],
        rootNode=RecursiveWriteCandidateNode{
            data = ImmutableMapEntryNode{
                nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)interface[{(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name=l2vlan-trunk}],
                value=[ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)enabled, value=true},
                    ImmutableAugmentationNode{nodeIdentifier=AugmentationIdentifier{childNames=[(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)datapath-node-identifier, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)node-identifier, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)parent-interface]}, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)parent-interface, value=tap8ed70586-6c}]},
                    ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)type, value=(urn:ietf:params:xml:ns:yang:iana-if-type?revision=2014-05-08)l2vlan},
                    ImmutableAugmentationNode{nodeIdentifier=AugmentationIdentifier{childNames=[(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)vlan-id, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)l2vlan-mode]}, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)l2vlan-mode, value=transparent}]},
                    ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name, value=l2vlan-trunk}]}}}]
    to listener org.opendaylight.controller.sal.core.compat.LegacyDOMDataBrokerAdapter$2$$Lambda$1153/947871773@74cdf8a

 

2018-11-27T12:33:17,109 ending 1 change notification(s) [
    DefaultDataTreeCandidate{
        rootPath=/(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)interfaces/interface/interface[{(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name=l2vlan-trunk}],
        rootNode=RecursiveWriteCandidateNode{
            data = ImmutableMapEntryNode{
                nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)interface[{(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name=l2vlan-trunk}],
                value=[ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)enabled, value=true},
                    ImmutableAugmentationNode{nodeIdentifier=AugmentationIdentifier{childNames=[(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)datapath-node-identifier, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)node-identifier, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)parent-interface]}, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)parent-interface, value=tap8ed70586-6c}]},
                    ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)type, value=(urn:ietf:params:xml:ns:yang:iana-if-type?revision=2014-05-08)l2vlan},
                    ImmutableAugmentationNode{nodeIdentifier=AugmentationIdentifier{childNames=[(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)vlan-id, (urn:opendaylight:genius:interfacemanager?revision=2016-04-06)l2vlan-mode]}, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:genius:interfacemanager?revision=2016-04-06)l2vlan-mode, value=transparent}]},
                    ImmutableLeafNode{nodeIdentifier=(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name, value=l2vlan-trunk}]
            }
        }}]
    to listener org.opendaylight.controller.sal.core.compat.LegacyDOMDataBrokerAdapter$2$$Lambda$1234/2066369190@547b1d6e
Comment by Robert Varga [ 27/Nov/18 ]

k.faseela Are you sure you are not subscribed to the tree twice?

Comment by Faseela K [ 27/Nov/18 ]

rovarga : If that is the case, in what circumstance the add notification log ends up twice in the same listener? that too from two different dispatcher threads?

Comment by Robert Varga [ 27/Nov/18 ]

At any rate, this is not an MD-SAL bug, it's somewhere between genius, serviceutils and controller.

Comment by Robert Varga [ 27/Nov/18 ]

Also, controller should not anonymize listeners, https://git.opendaylight.org/gerrit/78208 prevents that.

Comment by Robert Varga [ 27/Nov/18 ]

Each registration is treated independently, so even if you register the same listener object twice, it will be treated as two separate listeners, that is why you are getting a registration handle for each registration. Since each registration is independent, they are dispatched concurrently (if system load allows).

Comment by Faseela K [ 27/Nov/18 ]

rovarga : I will just debug this and get back to you.. whether the listener is registered twice.

Comment by Faseela K [ 27/Nov/18 ]

rovarga : Thanks for the inputs. Never looked into this aspect, as i never thought two times registration will be treated independently,  and the bug was right there. Should I just move this Jira to genius?

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

 

 

 

Comment by Robert Varga [ 27/Nov/18 ]

Thanks for confirming, I already moved it. Can you tag the patches with JIRA:, so they get linked here, please?

Generated at Wed Feb 07 20:00:16 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.