StarlingX

ptp-notification: Subscription creation right after second lock/unlock attempt results in app not receiving ptp status change event

Bug #1927502 reported by Ghada Khalil on 2021-05-06

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	StarlingX	In Progress	Low	Bin Yang

Bug 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
--------
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

See original description

Tags:

Revision history for this message

Ghada Khalil (gkhalil) wrote on 2021-05-06:

screening: stx.6.0 / medium to low - very specific test scenario associated with the optional ptp-notification containerized service.

Changed in starlingx:
assignee:	nobody → Bin Yang (biny993)
description:	updated
tags:	added: stx.6.0 stx.networking
Changed in starlingx:
importance:	Undecided → Medium
status:	New → Triaged

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2021-05-07: Fix proposed to ptp-notification-armada-app (master)

Fix proposed to branch: master
Review: https://review.opendev.org/c/starlingx/ptp-notification-armada-app/+/790206

Changed in starlingx:
status:	Triaged → In Progress

Ghada Khalil (gkhalil) on 2021-10-30

Changed in starlingx:
importance:	Medium → Low
tags:	removed: stx.6.0

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2022-11-29: Change abandoned on ptp-notification-armada-app (master)

Change abandoned by "Bin Yang <email address hidden>" on branch: master
Review: https://review.opendev.org/c/starlingx/ptp-notification-armada-app/+/790206

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.