StarlingX

  1. Bug #1927502
  2. Comment #0

Comment 0 for bug 1927502

Revision history for this message
Ghada Khalil (gkhalil) wrote :

Brief Description
-----------------
Create a subscription right after second round of lock/unlock of standby controller results in the app not receiving ptp status change event

Severity
--------
Major

Steps to Reproduce
------------------
lock/unlock standby controller
swact controller
lock/unlock standby controller again
subscribe ptp notification of active controller
change class on GM

Expected Behavior
------------------
app receives Holdover and Freerun events

Actual Behavior
---------------
app didn't receive event

Reproducibility
---------------
Reproducible

System Configuration
---------------------
standard system

Branch/Pull Time/Commit
-----------------------
stx master 2021-04-28_20-00-06

Last Pass
---------
N/A - new robustness test scenario

Timestamp/Logs
--------------
change class on GM right after "2021-04-30T18:37:31+00:00"

pod logs

2021-04-30 18:37:19,978 [DEBUG ] [notificationclientsdk.client.base][MainThread] Created Broker client:controller-1,rabbit://admin:admin@[172.16.166.143]:5672
2021-04-30 18:37:20,017 [INFO ] [notificationclientsdk.services.ptp][MainThread] initial ptpstatus:{'ResourceType': 'PTP', 'EventData': {'State': 'Locked'}, 'ResourceQualifier': {'NodeName': 'controller-1'}, 'EventTimestamp': 1619807502.971857}
2021-04-30 18:37:20,037 [INFO ] [notificationclientsdk.services.ptp][MainThread] initial ptpstatus is delivered successfully
2021-04-30 18:37:20,043 [INFO ] [sidecar.controllers.v1.subscriptions][MainThread] created subscription: {'SubscriptionId': '189770ba-a9e3-11eb-bec1-a27428df2af2', 'ResourceType': 'PTP', 'UriLocation': 'http://127.0.0.1:8080/ocloudNotifications/v1/subscriptions/189770ba-a9e3-11eb-bec1-a27428df2af2', 'EndpointUri': 'http://127.0.0.1:9090/v1/resource_status/ptp', 'ResourceQualifier': {'NodeName': 'controller-1'}}
2021-04-30 18:37:20,043 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] daemon control event is asserted
2021-04-30 18:37:20,044 [INFO ] [pecan.commands.serve][MainThread] "POST /ocloudNotifications/v1/subscriptions HTTP/1.1" 201 309
2021-04-30 18:37:20,045 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] found 1 subscriptions
2021-04-30 18:37:20,046 [DEBUG ] [notificationclientsdk.services.broker_state_manager][MainThread] subscription:{'SubscriptionId': '189770ba-a9e3-11eb-bec1-a27428df2af2', 'ResourceType': 'PTP', 'UriLocation': 'http://127.0.0.1:8080/ocloudNotifications/v1/subscriptions/189770ba-a9e3-11eb-bec1-a27428df2af2', 'EndpointUri': 'http://127.0.0.1:9090/v1/resource_status/ptp', 'ResourceQualifier': {'NodeName': 'controller-1'}}, Status:1
2021-04-30 18:37:20,049 [DEBUG ] [notificationclientsdk.services.broker_state_manager][MainThread] Failed to enumerate broker names for controller-1
2021-04-30 18:37:20,050 [DEBUG ] [notificationclientsdk.services.notification_handler][MainThread] delivery time @node: controller-1,subscription:189770ba-a9e3-11eb-bec1-a27428df2af2 is added
2021-04-30 18:37:28,330 [INFO ] [pecan.commands.serve][MainThread] "GET /ocloudNotifications/v1/subscriptions/189770ba-a9e3-11eb-bec1-a27428df2af2 HTTP/1.1" 200 309
2021-04-30 18:37:29,302 [INFO ] [pecan.commands.serve][MainThread] "GET /ocloudNotifications/v1/subscriptions HTTP/1.1" 200 311
2021-04-30 18:37:30,281 [DEBUG ] [notificationclientsdk.services.ptp][MainThread] Pulled location info@controller-1:{'NodeName': 'controller-1', 'PodIP': '172.16.166.143', 'ResourceTypes': ['PTP'], 'Timestamp': 1619806955.3530345}
2021-04-30 18:37:30,283 [DEBUG ] [notificationclientsdk.client.base][MainThread] Created Broker client:controller-1,rabbit://admin:admin@[172.16.166.143]:5672
2021-04-30 18:37:31,325 [INFO ] [pecan.commands.serve][MainThread] "GET /ocloudNotifications/v1/PTP/CurrentState HTTP/1.1" 200 145
2021-04-30 18:39:37,584 [DEBUG ] [notificationclientsdk.client.locationservice][Thread-7] LocationServiceClient NotifyLocation called {'NodeName': 'controller-1', 'PodIP': '172.16.166.143', 'ResourceTypes': ['PTP'], 'Timestamp': 1619806955.3530345}
2021-04-30 18:39:37,584 [DEBUG ] [notificationclientsdk.services.notification_worker][Thread-7] Received location info:{'NodeName': 'controller-1', 'PodIP': '172.16.166.143', 'ResourceTypes': ['PTP'], 'Timestamp': 1619806955.3530345}
2021-04-30 18:39:37,584 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] daemon control event is asserted
2021-04-30 18:39:37,585 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] Start to consume location event
2021-04-30 18:39:37,585 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] consume location info @controller-1:{'NodeName': 'controller-1', 'PodIP': '172.16.166.143', 'ResourceTypes': ['PTP'], 'Timestamp': 1619806955.3530345}
2021-04-30 18:39:37,592 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] Add NodeInfo: controller-1
2021-04-30 18:39:37,592 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] Finished consuming location event
2021-04-30 18:39:37,593 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] signal event to refresh brokers state from subscription
2021-04-30 18:39:37,593 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] try to refresh brokers state due to changes of node info
2021-04-30 18:39:37,596 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] found 1 subscriptions
2021-04-30 18:39:37,596 [DEBUG ] [notificationclientsdk.services.broker_state_manager][MainThread] subscription:{'SubscriptionId': '189770ba-a9e3-11eb-bec1-a27428df2af2', 'ResourceType': 'PTP', 'UriLocation': 'http://127.0.0.1:8080/ocloudNotifications/v1/subscriptions/189770ba-a9e3-11eb-bec1-a27428df2af2', 'EndpointUri': 'http://127.0.0.1:9090/v1/resource_status/ptp', 'ResourceQualifier': {'NodeName': 'controller-1'}}, Status:1
2021-04-30 18:39:37,602 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] try to sync up watcher for 1 brokers
2021-04-30 18:39:37,602 [DEBUG ] [notificationclientsdk.services.broker_state_manager][MainThread] Start watching due to connected: controller-1
2021-04-30 18:39:37,602 [DEBUG ] [notificationclientsdk.services.broker_connection_manager][MainThread] Start watching location announcement of notificationservice@controller-1
2021-04-30 18:39:37,634 [DEBUG ] [notificationclientsdk.services.broker_connection_manager][MainThread] Pulled location info@controller-1:{'NodeName': 'controller-1', 'PodIP': '172.16.166.143', 'ResourceTypes': ['PTP'], 'Timestamp': 1619806955.3530345}
2021-04-30 18:39:37,635 [DEBUG ] [notificationclientsdk.services.broker_connection_manager][MainThread] Start watching notifications from notificationservice@controller-1
2021-04-30 18:39:37,637 [DEBUG ] [notificationclientsdk.client.base][MainThread] Created Broker client:controller-1,rabbit://admin:admin@[172.16.166.143]:5672
2021-04-30 18:39:37,637 [DEBUG ] [notificationclientsdk.services.broker_connection_manager][MainThread] Start watching PTP@controller-1
2021-04-30 18:39:37,647 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] try to sync up data for 1 brokers
2021-04-30 18:39:37,648 [DEBUG ] [notificationclientsdk.services.notification_worker][MainThread] daemon control event is asserted
2021-04-30 18:39:37,649 [DEBUG ] [notificationclientsdk.client.base][Thread-2] Started rpcserver@LocationListener-controller-1@LocationListener-140370110676384
2021-04-30 18:39:37,662 [DEBUG ] [notificationclientsdk.client.base][Thread-13] Started rpcserver@PTP-Event-controller-1@PTP-EventListener-140370071332456
2021-04-30 18:39:39,881 [DEBUG ] [notificationclientsdk.client.notificationservice][Thread-17] NotificationServiceClient NotifyStatus called {'ResourceType': 'PTP', 'EventData': {'State': 'Freerun'}, 'ResourceQualifier': {'NodeName': 'controller-1'}, 'EventTimestamp': 1619807868.160548}
2021-04-30 18:39:39,881 [DEBUG ] [notificationclientsdk.services.notification_handler][Thread-17] start notification delivery
2021-04-30 18:39:39,903 [DEBUG ] [notificationclientsdk.services.notification_handler][Thread-17] notification is delivered successfully to 189770ba-a9e3-11eb-bec1-a27428df2af2
2021-04-30 18:39:39,903 [DEBUG ] [notificationclientsdk.services.notification_handler][Thread-17] delivery time @node: controller-1,subscription:189770ba-a9e3-11eb-bec1-a27428df2af2 is updated
2021-04-30 18:39:39,903 [DEBUG ] [notificationclientsdk.services.notification_handler][Thread-17] Finished notification delivery
2021-04-30 18:39:42,312 [DEBUG ] [notificationclientsdk.client.notificationservice][Thread-17] NotificationServiceClient NotifyStatus called {'ResourceType': 'PTP', 'EventData': {'State': 'Freerun'}, 'ResourceQualifier': {'NodeName': 'controller-1'}, 'EventTimestamp': 1619807868.160548}
2021-04-30 18:39:42,313 [DEBUG ] [notificationclientsdk.services.notification_handler][Thread-17] start notification delivery

Test Activity
-------------
Feature Testing

Workaround
----------
Unknown