[NETCONF-625] Race condition causes multiple notification subscriptions (diagnosed) Created: 10/Jun/19  Updated: 12/Feb/20

Status: In Progress
Project: netconf
Component/s: netconf, restconf-nb
Affects Version/s: None
Fix Version/s: None

Type: Story Priority: High
Reporter: Allan Clarke Assignee: Sowmiya Chidambaram
Resolution: Unresolved Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   

I'm filing this on behalf of a developer on my team (Lukas), so I may not disambiguate all of these details...

We hit a race condition in subscribing to notifications in Carbon. I have not had time to figure out if the problem exists in later versions of ODL. The errant behavior is that a subscriber can end up with multiple subscriptions to the same thing, such that a single notification causes multiple callbacks.

The problem occurs when subscribing more than once successively in a short enough time window. 

POST:
http://controller-ip:8181/restconf/operations/sal-remote:create-notification-stream

{   "input":    

{    "notifications": [       "([http://verizon.com/yang/notification?revision=2018-11-15)event-notification]",       "([http://verizon.com/yang/notification?revision=2018-11-15)node-status-notification]"     ],     "notification-output-type": "JSON"   }

}

GET:
http://controller-ip:8181/restconf/streams/stream/create-notification-stream/bnc-notification:node-status-notification,bnc-notification:event-notification

The Carbon version of the code is here

POST:
https://github.com/opendaylight/netconf/blob/stable/carbon/restconf/sal-rest-connector/src/main/java/org/opendaylight/restconf/restful/services/impl/RestconfInvokeOperationsServiceImpl.java
GET:
https://github.com/opendaylight/netconf/blob/stable/carbon/restconf/sal-rest-connector/src/main/java/org/opendaylight/restconf/restful/services/impl/RestconfStreamsSubscriptionServiceImpl.java

The master branch version of the code is here...

POST:
https://github.com/opendaylight/netconf/blob/master/restconf/restconf-nb-rfc8040/src/main/java/org/opendaylight/restconf/nb/rfc8040/rests/services/impl/RestconfInvokeOperationsServiceImpl.java
GET:
https://github.com/opendaylight/netconf/blob/master/restconf/restconf-nb-rfc8040/src/main/java/org/opendaylight/restconf/nb/rfc8040/rests/services/impl/RestconfStreamsSubscriptionServiceImpl.java

Looking at the code, the culprit is likely in 

./restconf/sal-rest-connector/src/main/java/org/opendaylight/restconf/restful/utils/SubscribeToStreamUtil.java:notifYangStream
./restconf/sal-rest-connector/src/main/java/org/opendaylight/restconf/restful/utils/SubscribeToStreamUtil.java:registerToListenNotification
org.opendaylight.controller.md.sal.dom.broker.impl.DOMNotificationRouter.registerNotificationListener

probably do synchronized inside of this:

    private static void registerToListenNotification(final NotificationListenerAdapter listener,
            final NotificationServiceHandler notificationServiceHandler) {
        if (listener.isListening()) { --->>>condition through which pass both threads in same time
            return;                       --->>>synchronized to listener is probably ideal because it is same for both calls
        }

        final SchemaPath path = listener.getSchemaPath();
        final ListenerRegistration<DOMNotificationListener> registration =
                notificationServiceHandler.get().registerNotificationListener(listener, path);

        listener.setRegistration(registration);

    }

The master branch shows similar logic so will suffer the same behavior.

The problem likely exists in NETCONF, where there is duplicate code...

./restconf/restconf-nb-bierman02/src/main/java/org/opendaylight/netconf/sal/restconf/impl/BrokerFacade.java

There is a method with the same name and body registerToListenNotification

 Comments   
Comment by Sowmiya Chidambaram [ 03/Jan/20 ]

Hi allanclarke, 

I gave a try to reproduce this issue. Below are the steps followed, 

POST – http://localhost:8181/restconf/operations/sal-remote:create-notification-streamPOST – http://localhost:8181/restconf/operations/sal-remote:create-notification-stream
{  "input": {    "notifications": [      "(http://netconfcentral.org/ns/toaster?revision=2009-11-20)toasterRestocked",   "(http://netconfcentral.org/ns/toaster?revision=2009-11-20)toasterOutOfBread"    ],    "notification-output-type": "JSON"  }}

Response :
{  "output": {    "notification-stream-identifier": "create-notification-stream/toaster:toasterRestocked,toaster:toasterOutOfBread"  }}

 

Executed the above mentioned request around 5-7 times within a second. Then, executed the following request to get websocket link,

GET – http://localhost:8181/restconf/streams/stream/create-notification-stream/toaster:toasterRestocked,toaster:toasterOutOfBread
Response :

{"location":"ws://localhost:8185/create-notification-stream/toaster:toasterRestocked,toaster:toasterOutOfBread"}

Finally opened the websocket client with above ws url and started listening to notifications.
Created both (toasterRestocked and toasterOutOfBread ) types of notifications with toaster app.

First type of notification,

POST – http://localhost:8181/restconf/operations/toaster:restock-toaster
{  "input" :  {    "toaster:amountOfBreadToStock": "1"  }}
Response code : 204 

Received single notification in websocket.

 {"ietf-restconf:notification":{"toaster:toasterRestocked":{"amountOfBread":1}},"event-time":"2020-01-03T19:12:19.006858+05:30"}

Second type of notification,

POST – http://localhost:8181/restconf/operations/toaster:make-toast
{  "toaster:input": {    "toaster:toasterDoneness": "5",    "toaster:toasterToastType": "wheat-bread"  }}
Response code : 204
Received single notification in websocket. 
{"ietf-restconf:notification":{"toaster:toasterOutOfBread":{}},"event-time":"2020-01-03T19:12:30.503999+05:30"}

Here in both cases, only one notification  has been received per request. As per the ticket, more than one should be received. 

Tested this in carbon-sr4 as well as with latest netconf master code base. Is the steps followed here are correct or something has been missed out? 

Also, in which release of carbon you are facing this issue? 

Comment by Sowmiya Chidambaram [ 12/Jan/20 ]

Gentle reminder. Please do respond.

Comment by Allan Clarke [ 10/Feb/20 ]

I can get Lukas to respond. I forgot that he was the originator. I apologize for any delay/confusion.

Comment by Lukas Baca [ 10/Feb/20 ]

hello,

im remember for subscribe to odl is needed both calls(POST+GET). When you call only POST several time in short time internally in odl is subscribe not created. Im look on this more than 8 months back.

Probably best for reproduce will be call POST+GET several time in same time

Comment by Sowmiya Chidambaram [ 12/Feb/20 ]

Thanks allanclarke and LukasB 3 for your response. Since it's a rarely occurring one, will again try to reproduce. 

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