Skip to content

Fix intermittent build failure for test_SfpStateUpdateTask_task_run_stop #461

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Apr 9, 2024

Conversation

mihirpat1
Copy link
Contributor

@mihirpat1 mihirpat1 commented Apr 8, 2024

Description

An intermittent build failure is seen for the test_SfpStateUpdateTask_task_run_stop unit-test with the below backtrace. We have observed more than one type of backtrace so far (details are mentioned in the issues mentioned below).

[2023-06-21T12:27:31.213Z] =================================== FAILURES ===================================
[2023-06-21T12:27:31.213Z] ____________ TestXcvrdScript.test_SfpStateUpdateTask_task_run_stop _____________
[2023-06-21T12:27:31.213Z]
[2023-06-21T12:27:31.213Z] self = <tests.test_xcvrd.TestXcvrdScript object at 0x7ff1f404b610>
[2023-06-21T12:27:31.213Z]
[2023-06-21T12:27:31.213Z] @patch('xcvrd.xcvrd_utilities.port_mapping.subscribe_port_config_change', MagicMock(return_value=(None, None)))
[2023-06-21T12:27:31.213Z] def test_SfpStateUpdateTask_task_run_stop(self):
[2023-06-21T12:27:31.213Z] port_mapping = PortMapping()
[2023-06-21T12:27:31.213Z] stop_event = threading.Event()
[2023-06-21T12:27:31.213Z] sfp_error_event = threading.Event()
[2023-06-21T12:27:31.213Z] task = SfpStateUpdateTask(DEFAULT_NAMESPACE, port_mapping, stop_event, sfp_error_event)
[2023-06-21T12:27:31.213Z] task.start()
[2023-06-21T12:27:31.213Z] assert wait_until(5, 1, task.is_alive)
[2023-06-21T12:27:31.213Z] task.raise_exception()
[2023-06-21T12:27:31.213Z] > task.join()
[2023-06-21T12:27:31.213Z]
[2023-06-21T12:27:31.213Z] tests/test_xcvrd.py:1041:
[2023-06-21T12:27:31.214Z] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[2023-06-21T12:27:31.214Z] xcvrd/xcvrd.py:2200: in join
[2023-06-21T12:27:31.214Z] raise self.exc
[2023-06-21T12:27:31.214Z] xcvrd/xcvrd.py:2175: in run
[2023-06-21T12:27:31.214Z] self.task_worker(self.task_stopping_event, self.sfp_error_event)
[2023-06-21T12:27:31.214Z] xcvrd/xcvrd.py:1987: in task_worker
[2023-06-21T12:27:31.214Z] self.init()
[2023-06-21T12:27:31.214Z] xcvrd/xcvrd.py:1905: in init
[2023-06-21T12:27:31.214Z] self.retry_eeprom_set = self._post_port_sfp_info_and_dom_thr_to_db_once(port_mapping_data, self.xcvr_table_helper, self.main_thread_stop_event)
[2023-06-21T12:27:31.214Z] xcvrd/xcvrd.py:1845: in _post_port_sfp_info_and_dom_thr_to_db_once
[2023-06-21T12:27:31.214Z] warmstart.initialize("xcvrd", "pmon")
[2023-06-21T12:27:31.214Z] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[2023-06-21T12:27:31.214Z]
[2023-06-21T12:27:31.214Z] app_name = 'xcvrd', docker_name = 'pmon', db_timeout = 0, isTcpConn = False
[2023-06-21T12:27:31.214Z]
[2023-06-21T12:27:31.214Z] @staticmethod
[2023-06-21T12:27:31.214Z] def initialize(app_name, docker_name, db_timeout=0, isTcpConn=False):
[2023-06-21T12:27:31.214Z] > return _swsscommon.WarmStart_initialize(app_name, docker_name, db_timeout, isTcpConn)
[2023-06-21T12:27:31.214Z] E RuntimeError: Unable to connect to redis (unix-socket): Cannot assign requested address
[2023-06-21T12:27:31.214Z]
[2023-06-21T12:27:31.214Z] /usr/lib/python3/dist-packages/swsscommon/swsscommon.py:3369: RuntimeError
[2023-06-21T12:27:31.214Z] =============================== warnings summary ===============================

Consistent way to fail the test
Add at least 1s sleep in between the below lines

task.start()
assert wait_until(5, 1, task.is_alive)

Motivation and Context

fixes #369, fixes #370, fixes #382

Intention of the testcase
The test case tests a scenario wherein while SfpStateUpdateTask thread is busy polling for few seconds, its parent process (xcvrd in an ideal case) generates an exception to stop the SfpStateUpdateTask thread in the middle of polling.

RCA for current failure
Since test_SfpStateUpdateTask_task_run_stop does not have all the underlying functions of SfpStateUpdateTask.task_worker mocked, there is a probability of SfpStateUpdateTask thread exiting early which will thereby cause assert wait_until(5, 1, task.is_alive) to fail based on the place at which SfpStateUpdateTask thread crashes.

Fix details
Modified the implementation of XcvrTableHelper function to have a busy polling to ensure that SfpStateUpdateTask thread does not quit before the test_SfpStateUpdateTask_task_run_stop testcase raises an exception.
Also, this approach will ensure that if any new function calls are being added in SfpStateUpdateTask.task_worker, they will not needed to be mocked in SfpStateUpdateTask.task_worker since XcvrTableHelper is the first function called in SfpStateUpdateTask.task_worker.

How Has This Been Tested?

Ran the test multiple times to ensure that the testcases passes.
Also, added a 3s sleep in between the below lines and ensured that the testcases was passing consistently.

task.start()
assert wait_until(5, 1, task.is_alive)

Additional Information (Optional)

MSFT ADO - 24271303

@mihirpat1 mihirpat1 changed the title Fix intermittent built failure for test_SfpStateUpdateTask_task_run_stop Fix intermittent build failure for test_SfpStateUpdateTask_task_run_stop Apr 9, 2024
task.raise_exception()
task.join()
assert wait_until(5, 1, lambda: task.is_alive() is False)
def poll_for_5s(*args, **kwargs):
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@mihirpat1 can you make poll_for_ever()

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@prgeor I have addressed this now.

@prgeor prgeor merged commit b5f838d into sonic-net:master Apr 9, 2024
5 checks passed
mihirpat1 added a commit to mihirpat1/sonic-platform-daemons that referenced this pull request Apr 9, 2024
…ask_run_stop (sonic-net#461)

* Fix intermittent built failure for test_SfpStateUpdateTask_task_run_stop

Signed-off-by: Mihir Patel <[email protected]>

* Modified polling to forever

---------

Signed-off-by: Mihir Patel <[email protected]>
mihirpat1 added a commit to mihirpat1/sonic-platform-daemons that referenced this pull request Apr 9, 2024
…ask_run_stop (sonic-net#461)

* Fix intermittent built failure for test_SfpStateUpdateTask_task_run_stop

Signed-off-by: Mihir Patel <[email protected]>

* Modified polling to forever

---------

Signed-off-by: Mihir Patel <[email protected]>
@mihirpat1
Copy link
Contributor Author

@StormLiangMS @yxieca Can you please help in merging this to 202305 and 202311?
I have raised the corresponding cherry-pick PRs.
MSFT ADO - 24271303

yxieca pushed a commit that referenced this pull request Apr 10, 2024
…ask_run_stop (#461) (#464)

* Fix intermittent built failure for test_SfpStateUpdateTask_task_run_stop

Signed-off-by: Mihir Patel <[email protected]>
StormLiangMS pushed a commit that referenced this pull request Apr 11, 2024
…ask_run_stop (#461) (#463)

Cherry-pick for #461
MSFT ADO - 24271303

Description
An intermittent build failure is seen for the test_SfpStateUpdateTask_task_run_stop unit-test with the below backtrace. We have observed more than one type of backtrace so far (details are mentioned in the issues mentioned below).

[2023-06-21T12:27:31.213Z] =================================== FAILURES ===================================
[2023-06-21T12:27:31.213Z] ____________ TestXcvrdScript.test_SfpStateUpdateTask_task_run_stop _____________
[2023-06-21T12:27:31.213Z]
[2023-06-21T12:27:31.213Z] self = <tests.test_xcvrd.TestXcvrdScript object at 0x7ff1f404b610>
[2023-06-21T12:27:31.213Z]
[2023-06-21T12:27:31.213Z] @patch('xcvrd.xcvrd_utilities.port_mapping.subscribe_port_config_change', MagicMock(return_value=(None, None)))
[2023-06-21T12:27:31.213Z] def test_SfpStateUpdateTask_task_run_stop(self):
[2023-06-21T12:27:31.213Z] port_mapping = PortMapping()
[2023-06-21T12:27:31.213Z] stop_event = threading.Event()
[2023-06-21T12:27:31.213Z] sfp_error_event = threading.Event()
[2023-06-21T12:27:31.213Z] task = SfpStateUpdateTask(DEFAULT_NAMESPACE, port_mapping, stop_event, sfp_error_event)
[2023-06-21T12:27:31.213Z] task.start()
[2023-06-21T12:27:31.213Z] assert wait_until(5, 1, task.is_alive)
[2023-06-21T12:27:31.213Z] task.raise_exception()
[2023-06-21T12:27:31.213Z] > task.join()
[2023-06-21T12:27:31.213Z]
[2023-06-21T12:27:31.213Z] tests/test_xcvrd.py:1041:
[2023-06-21T12:27:31.214Z] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[2023-06-21T12:27:31.214Z] xcvrd/xcvrd.py:2200: in join
[2023-06-21T12:27:31.214Z] raise self.exc
[2023-06-21T12:27:31.214Z] xcvrd/xcvrd.py:2175: in run
[2023-06-21T12:27:31.214Z] self.task_worker(self.task_stopping_event, self.sfp_error_event)
[2023-06-21T12:27:31.214Z] xcvrd/xcvrd.py:1987: in task_worker
[2023-06-21T12:27:31.214Z] self.init()
[2023-06-21T12:27:31.214Z] xcvrd/xcvrd.py:1905: in init
[2023-06-21T12:27:31.214Z] self.retry_eeprom_set = self._post_port_sfp_info_and_dom_thr_to_db_once(port_mapping_data, self.xcvr_table_helper, self.main_thread_stop_event)
[2023-06-21T12:27:31.214Z] xcvrd/xcvrd.py:1845: in _post_port_sfp_info_and_dom_thr_to_db_once
[2023-06-21T12:27:31.214Z] warmstart.initialize("xcvrd", "pmon")
[2023-06-21T12:27:31.214Z] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[2023-06-21T12:27:31.214Z]
[2023-06-21T12:27:31.214Z] app_name = 'xcvrd', docker_name = 'pmon', db_timeout = 0, isTcpConn = False
[2023-06-21T12:27:31.214Z]
[2023-06-21T12:27:31.214Z] @staticmethod
[2023-06-21T12:27:31.214Z] def initialize(app_name, docker_name, db_timeout=0, isTcpConn=False):
[2023-06-21T12:27:31.214Z] > return _swsscommon.WarmStart_initialize(app_name, docker_name, db_timeout, isTcpConn)
[2023-06-21T12:27:31.214Z] E RuntimeError: Unable to connect to redis (unix-socket): Cannot assign requested address
[2023-06-21T12:27:31.214Z]
[2023-06-21T12:27:31.214Z] /usr/lib/python3/dist-packages/swsscommon/swsscommon.py:3369: RuntimeError
[2023-06-21T12:27:31.214Z] =============================== warnings summary ===============================
Consistent way to fail the test
Add at least 1s sleep in between the below lines
sonic-platform-daemons/sonic-xcvrd/tests/test_xcvrd.py

Lines 1966 to 1967 in d0fd1e1

 task.start() 
 assert wait_until(5, 1, task.is_alive) 
Motivation and Context
fixes #369, fixes #370, fixes #382

Intention of the testcase
The test case tests a scenario wherein while SfpStateUpdateTask thread is busy polling for few seconds, its parent process (xcvrd in an ideal case) generates an exception to stop the SfpStateUpdateTask thread in the middle of polling.

RCA for current failure
Since test_SfpStateUpdateTask_task_run_stop does not have all the underlying functions of SfpStateUpdateTask.task_worker mocked, there is a probability of SfpStateUpdateTask thread exiting early which will thereby cause assert wait_until(5, 1, task.is_alive) to fail based on the place at which SfpStateUpdateTask thread crashes.

Fix details
Modified the implementation of XcvrTableHelper function to have a busy polling to ensure that SfpStateUpdateTask thread does not quit before the test_SfpStateUpdateTask_task_run_stop testcase raises an exception.
Also, this approach will ensure that if any new function calls are being added in SfpStateUpdateTask.task_worker, they will not needed to be mocked in SfpStateUpdateTask.task_worker since XcvrTableHelper is the first function called in SfpStateUpdateTask.task_worker.

How Has This Been Tested?
Ran the test multiple times to ensure that the testcases passes.
Also, added a 3s sleep in between the below lines and ensured that the testcases was passing consistently.
sonic-platform-daemons/sonic-xcvrd/tests/test_xcvrd.py

Lines 1966 to 1967 in d0fd1e1

 task.start() 
 assert wait_until(5, 1, task.is_alive)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment