| 2021-05-06 14:41:07 |
Ghada Khalil |
description |
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 [[34;1mDEBUG [0m] [notificationclientsdk.client.base][MainThread] Created Broker client:controller-1,rabbit://admin:admin@[172.16.166.143]:5672
2021-04-30 18:37:20,017 [[1mINFO [0m] [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 [[1mINFO [0m] [notificationclientsdk.services.ptp][MainThread] initial ptpstatus is delivered successfully
2021-04-30 18:37:20,043 [[1mINFO [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] daemon control event is asserted
2021-04-30 18:37:20,044 [[1mINFO [0m] [pecan.commands.serve][MainThread] "POST /ocloudNotifications/v1/subscriptions HTTP/1.1" 201 309
2021-04-30 18:37:20,045 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] found 1 subscriptions
2021-04-30 18:37:20,046 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.broker_state_manager][MainThread] Failed to enumerate broker names for controller-1
2021-04-30 18:37:20,050 [[34;1mDEBUG [0m] [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 [[1mINFO [0m] [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 [[1mINFO [0m] [pecan.commands.serve][MainThread] "GET /ocloudNotifications/v1/subscriptions HTTP/1.1" 200 311
2021-04-30 18:37:30,281 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.client.base][MainThread] Created Broker client:controller-1,rabbit://admin:admin@[172.16.166.143]:5672
2021-04-30 18:37:31,325 [[1mINFO [0m] [pecan.commands.serve][MainThread] "GET /ocloudNotifications/v1/PTP/CurrentState HTTP/1.1" 200 145
2021-04-30 18:39:37,584 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] daemon control event is asserted
2021-04-30 18:39:37,585 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] Start to consume location event
2021-04-30 18:39:37,585 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] Add NodeInfo: controller-1
2021-04-30 18:39:37,592 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] Finished consuming location event
2021-04-30 18:39:37,593 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] signal event to refresh brokers state from subscription
2021-04-30 18:39:37,593 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] try to refresh brokers state due to changes of node info
2021-04-30 18:39:37,596 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] found 1 subscriptions
2021-04-30 18:39:37,596 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] try to sync up watcher for 1 brokers
2021-04-30 18:39:37,602 [[34;1mDEBUG [0m] [notificationclientsdk.services.broker_state_manager][MainThread] Start watching due to connected: controller-1
2021-04-30 18:39:37,602 [[34;1mDEBUG [0m] [notificationclientsdk.services.broker_connection_manager][MainThread] Start watching location announcement of notificationservice@controller-1
2021-04-30 18:39:37,634 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.broker_connection_manager][MainThread] Start watching notifications from notificationservice@controller-1
2021-04-30 18:39:37,637 [[34;1mDEBUG [0m] [notificationclientsdk.client.base][MainThread] Created Broker client:controller-1,rabbit://admin:admin@[172.16.166.143]:5672
2021-04-30 18:39:37,637 [[34;1mDEBUG [0m] [notificationclientsdk.services.broker_connection_manager][MainThread] Start watching PTP@controller-1
2021-04-30 18:39:37,647 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] try to sync up data for 1 brokers
2021-04-30 18:39:37,648 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] daemon control event is asserted
2021-04-30 18:39:37,649 [[34;1mDEBUG [0m] [notificationclientsdk.client.base][Thread-2] Started rpcserver@LocationListener-controller-1@LocationListener-140370110676384
2021-04-30 18:39:37,662 [[34;1mDEBUG [0m] [notificationclientsdk.client.base][Thread-13] Started rpcserver@PTP-Event-controller-1@PTP-EventListener-140370071332456
2021-04-30 18:39:39,881 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_handler][Thread-17] start notification delivery
2021-04-30 18:39:39,903 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_handler][Thread-17] notification is delivered successfully to 189770ba-a9e3-11eb-bec1-a27428df2af2
2021-04-30 18:39:39,903 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_handler][Thread-17] Finished notification delivery
2021-04-30 18:39:42,312 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_handler][Thread-17] start notification delivery
Test Activity
-------------
Feature Testing
Workaround
----------
Unknown |
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
--------
Minor
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 [[34;1mDEBUG [0m] [notificationclientsdk.client.base][MainThread] Created Broker client:controller-1,rabbit://admin:admin@[172.16.166.143]:5672
2021-04-30 18:37:20,017 [[1mINFO [0m] [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 [[1mINFO [0m] [notificationclientsdk.services.ptp][MainThread] initial ptpstatus is delivered successfully
2021-04-30 18:37:20,043 [[1mINFO [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] daemon control event is asserted
2021-04-30 18:37:20,044 [[1mINFO [0m] [pecan.commands.serve][MainThread] "POST /ocloudNotifications/v1/subscriptions HTTP/1.1" 201 309
2021-04-30 18:37:20,045 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] found 1 subscriptions
2021-04-30 18:37:20,046 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.broker_state_manager][MainThread] Failed to enumerate broker names for controller-1
2021-04-30 18:37:20,050 [[34;1mDEBUG [0m] [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 [[1mINFO [0m] [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 [[1mINFO [0m] [pecan.commands.serve][MainThread] "GET /ocloudNotifications/v1/subscriptions HTTP/1.1" 200 311
2021-04-30 18:37:30,281 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.client.base][MainThread] Created Broker client:controller-1,rabbit://admin:admin@[172.16.166.143]:5672
2021-04-30 18:37:31,325 [[1mINFO [0m] [pecan.commands.serve][MainThread] "GET /ocloudNotifications/v1/PTP/CurrentState HTTP/1.1" 200 145
2021-04-30 18:39:37,584 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] daemon control event is asserted
2021-04-30 18:39:37,585 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] Start to consume location event
2021-04-30 18:39:37,585 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] Add NodeInfo: controller-1
2021-04-30 18:39:37,592 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] Finished consuming location event
2021-04-30 18:39:37,593 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] signal event to refresh brokers state from subscription
2021-04-30 18:39:37,593 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] try to refresh brokers state due to changes of node info
2021-04-30 18:39:37,596 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] found 1 subscriptions
2021-04-30 18:39:37,596 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] try to sync up watcher for 1 brokers
2021-04-30 18:39:37,602 [[34;1mDEBUG [0m] [notificationclientsdk.services.broker_state_manager][MainThread] Start watching due to connected: controller-1
2021-04-30 18:39:37,602 [[34;1mDEBUG [0m] [notificationclientsdk.services.broker_connection_manager][MainThread] Start watching location announcement of notificationservice@controller-1
2021-04-30 18:39:37,634 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.broker_connection_manager][MainThread] Start watching notifications from notificationservice@controller-1
2021-04-30 18:39:37,637 [[34;1mDEBUG [0m] [notificationclientsdk.client.base][MainThread] Created Broker client:controller-1,rabbit://admin:admin@[172.16.166.143]:5672
2021-04-30 18:39:37,637 [[34;1mDEBUG [0m] [notificationclientsdk.services.broker_connection_manager][MainThread] Start watching PTP@controller-1
2021-04-30 18:39:37,647 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] try to sync up data for 1 brokers
2021-04-30 18:39:37,648 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_worker][MainThread] daemon control event is asserted
2021-04-30 18:39:37,649 [[34;1mDEBUG [0m] [notificationclientsdk.client.base][Thread-2] Started rpcserver@LocationListener-controller-1@LocationListener-140370110676384
2021-04-30 18:39:37,662 [[34;1mDEBUG [0m] [notificationclientsdk.client.base][Thread-13] Started rpcserver@PTP-Event-controller-1@PTP-EventListener-140370071332456
2021-04-30 18:39:39,881 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_handler][Thread-17] start notification delivery
2021-04-30 18:39:39,903 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_handler][Thread-17] notification is delivered successfully to 189770ba-a9e3-11eb-bec1-a27428df2af2
2021-04-30 18:39:39,903 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_handler][Thread-17] Finished notification delivery
2021-04-30 18:39:42,312 [[34;1mDEBUG [0m] [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 [[34;1mDEBUG [0m] [notificationclientsdk.services.notification_handler][Thread-17] start notification delivery
Test Activity
-------------
Feature Testing
Workaround
----------
Unknown |
|
