[action] [PR:707] [BMC] Wait for Redfish readiness after BMC firmware update

sonic_platform_base/bmc_base.py

@@ -158,6 +158,18 @@ def _logout(self):
             return self.rf_client.logout()
         return RedfishClient.ERR_CODE_OK
 
+    def wait_until_redfish_ready(self, timeout=RedfishClient.READY_POLL_TIMEOUT,
+                                 interval=RedfishClient.READY_POLL_INTERVAL):
+        """
+        Wait until the BMC's Redfish service accepts a login again (e.g. after a
+        restart); thin pass-through to RedfishClient. Returns a RedfishClient
+        return code (ERR_CODE_OK when ready).
+
+        NOT decorated with @with_session_management -- its _login() would fail
+        while the BMC is rebooting and defeat the wait.
+        """
+        return self.rf_client.wait_until_redfish_ready(timeout, interval)
+
     def open_session(self):
         """
         Open a session with the BMC via the NOS BMC account credentials.

sonic_platform_base/bmc_fw_update.py

@@ -8,6 +8,10 @@
 import sys
 import time
 
+# request_bmc_reset() returns before the BMC drops; wait for it to go down first
+# so we don't read the still-up pre-reset BMC as ready.
+BMC_RESET_SETTLE_TIME = 20  # seconds
+
 def main():
     try:
         import sonic_platform
@@ -41,21 +45,14 @@ def main():
                 logger.log_error(f'Failed to restart BMC. Error {ret}: {error_msg}')
                 sys.exit(1)
 
-            # Wait for BMC to restart itself
-            time.sleep(20)
-            # Wait for BMC to become operational
-            max_retries = 5
-            bmc_is_up = False
-            for retry in range(max_retries):
-                bmc_is_up = bmc.get_status()
-                if bmc_is_up:
-                    break
-                if retry < max_retries - 1:
-                    logger.log_notice("Waiting for BMC to restart...")
-                    time.sleep(20)
+            # Let the BMC drop before polling (see BMC_RESET_SETTLE_TIME).
+            time.sleep(BMC_RESET_SETTLE_TIME)
 
-            if not bmc_is_up:
-                logger.log_error("BMC did not become operational after restart")
+            # Redfish accepting a login implies L3 is back too -- no ping loop needed.
+            code = bmc.wait_until_redfish_ready()
+            if code != 0:
+                logger.log_error(f"BMC Redfish service did not become ready after "
+                                 f"restart (last error code: {code})")
                 sys.exit(1)
 
             logger.log_notice("BMC firmware update completed successfully")

sonic_platform_base/redfish_client.py

@@ -54,6 +54,10 @@ class RedfishClient:
     ERR_CODE_GENERIC_ERROR = -12
     ERR_CODE_IDENTICAL_VERSION = -13
 
+    # Readiness-poll defaults for wait_until_redfish_ready() (after a BMC restart).
+    READY_POLL_TIMEOUT = 300     # seconds, hard upper bound on the readiness wait
+    READY_POLL_INTERVAL = 10     # seconds between readiness probes
+
     CURL_ERR_OK = 0
     CURL_ERR_OPERATION_TIMEDOUT = 28
     CURL_ERR_COULDNT_RESOLVE_HOST = 6
@@ -1014,28 +1018,33 @@ def has_login(self):
     '''
     Login Redfish server and get bearer token
 
+    Args:
+        log_errors: When False, log failures at notice not error (readiness poll).
+
     Returns:
         An integer, return code
     '''
-    def login(self):
+    def login(self, *, log_errors=True):
         if self.has_login():
             return RedfishClient.ERR_CODE_OK
 
+        log_fn = logger.log_error if log_errors else logger.log_notice
+
         try:
             password = self.__password_callback()
         except Exception as e:
-            logger.log_error(f'{str(e)}')
+            log_fn(f'{str(e)}')
             return RedfishClient.ERR_CODE_PASSWORD_UNAVAILABLE
 
         cmd = self.__build_login_cmd(password)
         ret, _, response, error = self.exec_curl_cmd(cmd)
 
         if (ret != 0):
-            logger.log_error(f'Login failure: code {ret}, {error}')
+            log_fn(f'Login failure: code {ret}, {error}')
             return ret
 
         if response is None or len(response) == 0:
-            logger.log_error('Got empty Redfish login response')
+            log_fn('Got empty Redfish login response')
             return RedfishClient.ERR_CODE_UNEXPECTED_RESPONSE
 
         try:
@@ -1046,29 +1055,29 @@ def login(self):
                     json_response = json.loads(body)
                     if 'error' in json_response:
                         error_msg = json_response['error']['message']
-                        logger.log_error(f'Login failure: {error_msg}')
+                        log_fn(f'Login failure: {error_msg}')
                         self.log_multi_line_str(response)
                         return RedfishClient.ERR_CODE_GENERIC_ERROR
                 except Exception as e:
-                    logger.log_error(f'Login failure: Exception during parsing body: {str(e)}')
+                    log_fn(f'Login failure: Exception during parsing body: {str(e)}')
                     self.log_multi_line_str(response)
 
             # Extract both token and session ID from headers
             token = headers.get('x-auth-token')
             if not token:
-                logger.log_error('Login failure: no "X-Auth-Token" header found')
+                log_fn('Login failure: no "X-Auth-Token" header found')
                 self.log_multi_line_str(response)
                 return RedfishClient.ERR_CODE_UNEXPECTED_RESPONSE
 
             location = headers.get('location')
             if not location:
-                logger.log_error('Login failure: no "Location" header found')
+                log_fn('Login failure: no "Location" header found')
                 self.log_multi_line_str(response)
                 return RedfishClient.ERR_CODE_UNEXPECTED_RESPONSE
 
             session_id = location.split('/')[-1]
             if not session_id:
-                logger.log_error('Login failure: could not extract session ID from Location header')
+                log_fn('Login failure: could not extract session ID from Location header')
                 self.log_multi_line_str(response)
                 return RedfishClient.ERR_CODE_UNEXPECTED_RESPONSE
 
@@ -1078,7 +1087,7 @@ def login(self):
             return RedfishClient.ERR_CODE_OK
 
         except Exception as e:
-            logger.log_error(f'Login failure: exception {str(e)}')
+            log_fn(f'Login failure: exception {str(e)}')
             self.log_multi_line_str(response)
             return RedfishClient.ERR_CODE_UNEXPECTED_RESPONSE
 
@@ -1141,6 +1150,46 @@ def logout(self, session_id=None):
             logger.log_error('Logout failed: Empty response')
             return RedfishClient.ERR_CODE_UNEXPECTED_RESPONSE
 
+    '''
+    Poll a quiet login() until the Redfish service accepts it or the timeout
+    elapses. Used after a BMC restart; a successful login is a stronger "ready"
+    signal than ping / L3.
+
+    Args:
+        timeout: Hard upper bound in seconds on the total wait.
+        interval: Seconds to sleep between probes.
+
+    Returns:
+        ERR_CODE_OK (0) when ready, else the last non-OK code seen (timeout or a
+        non-transient failure).
+    '''
+    def wait_until_redfish_ready(self, timeout=READY_POLL_TIMEOUT,
+                                 interval=READY_POLL_INTERVAL):
+        # Drop any cached session first, or login() short-circuits to OK on the
+        # cached token and falsely reports "ready". invalidate_session() is
+        # local-only, so (unlike a logout DELETE) it can't log an ERROR.
+        self.invalidate_session()
+
+        deadline = time.time() + timeout
+        last_code = None
+        while True:
+            last_code = self.login(log_errors=False)
+            if last_code == RedfishClient.ERR_CODE_OK:
+                self.logout()
+                logger.log_notice('BMC Redfish service is ready')
+                return RedfishClient.ERR_CODE_OK
+
+            # Fail fast only on a local permanent error. AUTH_FAILURE (401) is
+            # transient here: on boot the web server precedes the auth backend.
+            if last_code == RedfishClient.ERR_CODE_PASSWORD_UNAVAILABLE:
+                return last_code
+
+            remaining = deadline - time.time()
+            if remaining <= 0:
+                return last_code
+            logger.log_notice('Waiting for BMC Redfish service to become ready...')
+            time.sleep(min(interval, remaining))
+
     '''
     Get firmware inventory
 

tests/bmc_base_test.py

@@ -166,6 +166,31 @@ def test_logout_not_logged_in(self, mock_logout, mock_has_login):
         assert ret == RedfishClient.ERR_CODE_OK
         mock_logout.assert_not_called()
 
+    @mock.patch.object(RedfishClient, 'wait_until_redfish_ready')
+    def test_wait_until_redfish_ready_delegates(self, mock_wait):
+        """BMCBase.wait_until_redfish_ready passes args/return through to RedfishClient."""
+        # Non-zero so the return assertion actually tests pass-through (0 would pass
+        # even if the delegator ignored the result and returned OK).
+        mock_wait.return_value = RedfishClient.ERR_CODE_TIMEOUT
+
+        bmc = BMCBase('169.254.0.1')
+        ret = bmc.wait_until_redfish_ready(timeout=123, interval=7)
+
+        assert ret == RedfishClient.ERR_CODE_TIMEOUT
+        mock_wait.assert_called_once_with(123, 7)
+
+    @mock.patch.object(RedfishClient, 'wait_until_redfish_ready')
+    def test_wait_until_redfish_ready_default_args(self, mock_wait):
+        """BMCBase.wait_until_redfish_ready defaults come from RedfishClient constants."""
+        mock_wait.return_value = RedfishClient.ERR_CODE_SERVER_UNREACHABLE
+
+        bmc = BMCBase('169.254.0.1')
+        ret = bmc.wait_until_redfish_ready()
+
+        assert ret == RedfishClient.ERR_CODE_SERVER_UNREACHABLE
+        mock_wait.assert_called_once_with(RedfishClient.READY_POLL_TIMEOUT,
+                                          RedfishClient.READY_POLL_INTERVAL)
+
     def test_is_bmc_eeprom_content_valid_empty(self):
         """Test _is_bmc_eeprom_content_valid with empty data"""
         bmc = BMCBase('169.254.0.1')

tests/bmc_fw_update_test.py

@@ -41,7 +41,7 @@ def test_main_success_bmc_firmware_updated(self, mock_logger_class, mock_exit, m
         mock_bmc.update_firmware.return_value = (0, ('Success', ['BMC_FW_0', 'OTHER_FW']))
         mock_bmc.get_firmware_id.return_value = 'BMC_FW_0'
         mock_bmc.request_bmc_reset.return_value = (0, 'BMC reset successful')
-        mock_bmc.get_status.return_value = True
+        mock_bmc.wait_until_redfish_ready.return_value = 0
 
         test_args = ['bmc_fw_update.py', '/path/to/firmware.bin']
         with mock.patch.dict(sys.modules, {'sonic_platform': mock_sonic_platform}):
@@ -53,7 +53,8 @@ def test_main_success_bmc_firmware_updated(self, mock_logger_class, mock_exit, m
         mock_bmc.update_firmware.assert_called_once_with('/path/to/firmware.bin')
         mock_bmc.get_firmware_id.assert_called_once()
         mock_bmc.request_bmc_reset.assert_called_once()
-        mock_bmc.get_status.assert_called_once()
+        mock_bmc.wait_until_redfish_ready.assert_called_once()
+        mock_bmc.get_status.assert_not_called()
         mock_sleep.assert_called_once_with(20)
         mock_exit.assert_not_called()
 
@@ -143,9 +144,10 @@ def test_main_update_firmware_failure(self, mock_logger_class, mock_exit):
         mock_logger.log_error.assert_called_once_with('Failed to update BMC firmware. Error 1: Update failed')
         mock_exit.assert_called_once_with(1)
 
+    @mock.patch('sonic_platform_base.bmc_fw_update.time.sleep')
     @mock.patch('sys.exit')
     @mock.patch('sonic_py_common.logger.Logger')
-    def test_main_bmc_reset_failure(self, mock_logger_class, mock_exit):
+    def test_main_bmc_reset_failure(self, mock_logger_class, mock_exit, mock_sleep):
         """Test main when BMC reset fails"""
         mock_logger = mock.MagicMock()
         mock_bmc = mock.MagicMock()
@@ -159,6 +161,9 @@ def test_main_bmc_reset_failure(self, mock_logger_class, mock_exit):
         mock_bmc.update_firmware.return_value = (0, ('Success', ['BMC_FW_0']))
         mock_bmc.get_firmware_id.return_value = 'BMC_FW_0'
         mock_bmc.request_bmc_reset.return_value = (1, 'Reset failed')
+        # sys.exit is mocked to a no-op, so main() falls through past the reset
+        # failure; keep the readiness probe benign so it adds no extra error/exit.
+        mock_bmc.wait_until_redfish_ready.return_value = 0
 
         test_args = ['bmc_fw_update.py', '/path/to/firmware.bin']
         with mock.patch.dict(sys.modules, {'sonic_platform': mock_sonic_platform}):
@@ -171,8 +176,8 @@ def test_main_bmc_reset_failure(self, mock_logger_class, mock_exit):
     @mock.patch('sonic_platform_base.bmc_fw_update.time.sleep')
     @mock.patch('sys.exit')
     @mock.patch('sonic_py_common.logger.Logger')
-    def test_main_bmc_waiting_after_restart(self, mock_logger_class, mock_exit, mock_sleep):
-        """Test waiting loop when BMC is not yet operational after restart"""
+    def test_main_redfish_not_ready_after_restart(self, mock_logger_class, mock_exit, mock_sleep):
+        """Test failure when the Redfish service does not become ready after restart"""
         mock_logger = mock.MagicMock()
         mock_bmc = mock.MagicMock()
         mock_chassis = mock.MagicMock()
@@ -185,44 +190,18 @@ def test_main_bmc_waiting_after_restart(self, mock_logger_class, mock_exit, mock
         mock_bmc.update_firmware.return_value = (0, ('Success', ['BMC_FW_0']))
         mock_bmc.get_firmware_id.return_value = 'BMC_FW_0'
         mock_bmc.request_bmc_reset.return_value = (0, 'BMC reset successful')
-        mock_bmc.get_status.side_effect = [False, True]
+        # -6 == ERR_CODE_TIMEOUT: readiness never reached before the deadline.
+        mock_bmc.wait_until_redfish_ready.return_value = -6
 
         test_args = ['bmc_fw_update.py', '/path/to/firmware.bin']
         with mock.patch.dict(sys.modules, {'sonic_platform': mock_sonic_platform}):
             with mock.patch.object(sys, 'argv', test_args):
                 bmc_fw_update.main()
 
-        mock_logger.log_notice.assert_any_call("Waiting for BMC to restart...")
-        assert mock_bmc.get_status.call_count == 2
-        assert mock_sleep.call_count == 2
-        mock_sleep.assert_has_calls([mock.call(20), mock.call(20)])
-        mock_exit.assert_not_called()
-
-    @mock.patch('sonic_platform_base.bmc_fw_update.time.sleep')
-    @mock.patch('sys.exit')
-    @mock.patch('sonic_py_common.logger.Logger')
-    def test_main_bmc_not_operational_after_restart(self, mock_logger_class, mock_exit, mock_sleep):
-        """Test failure when BMC does not become operational after restart"""
-        mock_logger = mock.MagicMock()
-        mock_bmc = mock.MagicMock()
-        mock_chassis = mock.MagicMock()
-        mock_platform = mock.MagicMock()
-        mock_chassis.get_bmc.return_value = mock_bmc
-        mock_platform.get_chassis.return_value = mock_chassis
-        mock_sonic_platform = mock.MagicMock()
-        mock_sonic_platform.platform.Platform.return_value = mock_platform
-        mock_logger_class.return_value = mock_logger
-        mock_bmc.update_firmware.return_value = (0, ('Success', ['BMC_FW_0']))
-        mock_bmc.get_firmware_id.return_value = 'BMC_FW_0'
-        mock_bmc.request_bmc_reset.return_value = (0, 'BMC reset successful')
-        mock_bmc.get_status.return_value = False
-
-        test_args = ['bmc_fw_update.py', '/path/to/firmware.bin']
-        with mock.patch.dict(sys.modules, {'sonic_platform': mock_sonic_platform}):
-            with mock.patch.object(sys, 'argv', test_args):
-                bmc_fw_update.main()
-
-        mock_logger.log_error.assert_any_call("BMC did not become operational after restart")
-        assert mock_bmc.get_status.call_count == 5
-        assert mock_sleep.call_count == 5
+        # Only the settle sleep runs; the ping wait loop is gone.
+        mock_bmc.get_status.assert_not_called()
+        mock_bmc.wait_until_redfish_ready.assert_called_once()
+        mock_sleep.assert_called_once_with(20)
+        mock_logger.log_error.assert_any_call(
+            "BMC Redfish service did not become ready after restart (last error code: -6)")
         mock_exit.assert_called_once_with(1)