More backoff for retries and add retries for return code 4

src/core/src/package_managers/ZypperPackageManager.py

@@ -56,6 +56,7 @@ def __init__(self, env_layer, execution_config, composite_logger, telemetry_writ
         self.zypper_exitcode_ok = 0
         self.zypper_exitcode_zypper_updated = 103
         self.zypper_exitcode_zypp_locked = 7
+        self.zypper_exitcode_zypp_lib_exit_err = 4
 
         # Support to check for processes requiring restart
         self.zypper_ps = "sudo zypper ps -s"
@@ -64,7 +65,8 @@ def __init__(self, env_layer, execution_config, composite_logger, telemetry_writ
         self.set_package_manager_setting(Constants.PKG_MGR_SETTING_IDENTITY, Constants.ZYPPER)
         self.zypper_get_process_tree_cmd = 'ps --forest -o pid,cmd -g $(ps -o sid= -p {})'
         self.package_manager_max_retries = 5
-        self.error_codes_to_retry = [self.zypper_exitcode_zypp_locked]
+        self.error_codes_to_retry = [self.zypper_exitcode_zypp_locked, self.zypper_exitcode_zypp_lib_exit_err]
+        self.zypp_lock_timeout_backup = None
 
         # auto OS updates
         self.current_auto_os_update_service = None
@@ -96,54 +98,71 @@ def invoke_package_manager(self, command):
         """Get missing updates using the command input"""
         self.composite_logger.log_debug('\nInvoking package manager using: ' + command)
 
-        for i in range(0, self.package_manager_max_retries):
-            zypp_lock_timeout_backup = None
-            code = None
-            try:
-                zypp_lock_timeout_backup = self.env_layer.get_env_var('ZYPP_LOCK_TIMEOUT')
-                self.composite_logger.log_debug("Original value of ZYPP_LOCK_TIMEOUT env var: {0}".format(str(zypp_lock_timeout_backup)))
-                self.env_layer.set_env_var('ZYPP_LOCK_TIMEOUT', 5)
+        for i in range(1, self.package_manager_max_retries + 1):
+            self.set_lock_timeout_and_backup_original()
+            code, out = self.env_layer.run_command_output(command, False, False)
+            self.restore_original_lock_timeout()
 
-                code, out = self.env_layer.run_command_output(command, False, False)
-                if code not in [self.zypper_exitcode_ok, self.zypper_exitcode_zypper_updated]:  # more known return codes should be added as appropriate
-                    self.composite_logger.log('[ERROR] Package manager was invoked using: ' + command)
-                    self.composite_logger.log_warning(" - Return code from package manager: " + str(code))
-                    self.composite_logger.log_warning(" - Output from package manager: \n|\t" + "\n|\t".join(out.splitlines()))
+            if code not in [self.zypper_exitcode_ok, self.zypper_exitcode_zypper_updated]:  # more known return codes should be added as appropriate
+                self.log_errors_on_invoke(command, out, code)
+                error_msg = 'Unexpected return code (' + str(code) + ') from package manager on command: ' + command
+                self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.PACKAGE_MANAGER_FAILURE)
 
-                    process_tree = self.get_process_tree_from_pid_in_output(out)
-                    if process_tree is not None:
-                        self.composite_logger.log_warning(" - Process tree for the pid in output: \n{}".format(str(process_tree)))
-
-                    self.telemetry_writer.write_execution_error(command, code, out)
-                    error_msg = 'Unexpected return code (' + str(code) + ') from package manager on command: ' + command
-
-                    self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.PACKAGE_MANAGER_FAILURE)
-                    raise Exception(error_msg, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS))
-                else:  # verbose diagnostic log
-                    self.composite_logger.log_debug("\n\n==[SUCCESS]===============================================================")
-                    self.composite_logger.log_debug(" - Return code from package manager: " + str(code))
-                    self.composite_logger.log_debug(" - Output from package manager: \n|\t" + "\n|\t".join(out.splitlines()))
-                    self.composite_logger.log_debug("==========================================================================\n\n")
-
-                if code == self.zypper_exitcode_zypper_updated:
-                    self.composite_logger.log_debug(" - Package manager update detected. Patch installation run will be repeated.")
-                    self.set_package_manager_setting(Constants.PACKAGE_MGR_SETTING_REPEAT_PATCH_OPERATION, True)
-                return out
-            except Exception as error:
-                error_msg = repr(error)
+                # Not a retriable error code, so raise an exception
                 if code not in self.error_codes_to_retry:
-                    raise
+                    raise Exception(error_msg, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS))
 
-                if i < self.package_manager_max_retries - 1:
+                # Retriable error code, so check number of retries and wait then retry if applicable; otherwise, raise error after max retries
+                if i < self.package_manager_max_retries:
                     self.composite_logger.log_warning("Exception on package manager invoke. [Exception={0}] [RetryCount={1}]".format(error_msg, str(i)))
-                    time.sleep(i + 1)
+                    time.sleep(pow(2, i + 2))
+                    continue
                 else:
-                    self.composite_logger.log_warning("Unable to invoke package manager (retries exhausted) [{0}] [RetryCount={1}]".format(repr(error), str(i)))
+                    error_msg = "Unable to invoke package manager (retries exhausted) [{0}] [RetryCount={1}]".format(error_msg, str(i))
                     self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.PACKAGE_MANAGER_FAILURE)
                     raise Exception(error_msg, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS))
-            finally:
-                # Restore original env var, if it existed
-                self.env_layer.set_env_var('ZYPP_LOCK_TIMEOUT', zypp_lock_timeout_backup)
+            else:  # verbose diagnostic log
+                self.log_success_on_invoke(code, out)
+
+            if code == self.zypper_exitcode_zypper_updated:
+                self.composite_logger.log_debug(" - Package manager update detected. Patch installation run will be repeated.")
+                self.set_package_manager_setting(Constants.PACKAGE_MGR_SETTING_REPEAT_PATCH_OPERATION, True)
+            return out
+
+    def log_errors_on_invoke(self, command, out, code):
+        """Logs verbose error messages if there is an error on invoke_package_manager"""
+        self.composite_logger.log('[ERROR] Package manager was invoked using: ' + command)
+        self.composite_logger.log_warning(" - Return code from package manager: " + str(code))
+        self.composite_logger.log_warning(" - Output from package manager: \n|\t" + "\n|\t".join(out.splitlines()))
+        self.log_process_tree_if_exists(out)
+        self.telemetry_writer.write_execution_error(command, code, out)
+
+    def log_success_on_invoke(self, code, out):
+        """Logs verbose success messages on invoke_package_manager"""
+        self.composite_logger.log_debug("\n\n==[SUCCESS]===============================================================")
+        self.composite_logger.log_debug(" - Return code from package manager: " + str(code))
+        self.composite_logger.log_debug(" - Output from package manager: \n|\t" + "\n|\t".join(out.splitlines()))
+        self.composite_logger.log_debug("==========================================================================\n\n")
+
+    def log_process_tree_if_exists(self, out):
+        """Logs the process tree based on locking PID in output, if there is a process tree to be found"""
+        process_tree = self.get_process_tree_from_pid_in_output(out)
+        if process_tree is not None:
+            self.composite_logger.log_warning(" - Process tree for the pid in output: \n{}".format(str(process_tree)))
+
+    def set_lock_timeout_and_backup_original(self):
+        """Saves the env var ZYPP_LOCK_TIMEOUT and sets it to 5"""
+        self.zypp_lock_timeout_backup = self.env_layer.get_env_var('ZYPP_LOCK_TIMEOUT')
+        self.composite_logger.log_debug("Original value of ZYPP_LOCK_TIMEOUT env var: {0}".format(str(self.zypp_lock_timeout_backup)))
+        self.env_layer.set_env_var('ZYPP_LOCK_TIMEOUT', 5)
+
+    def restore_original_lock_timeout(self):
+        """Restores the original value of the env var ZYPP_LOCK_TIMEOUT, if any was saved"""
+        if self.zypp_lock_timeout_backup is None:
+            self.composite_logger.log_debug("Attempted to restore original lock timeout when none was saved")
+
+        self.env_layer.set_env_var('ZYPP_LOCK_TIMEOUT', self.zypp_lock_timeout_backup)
+        self.zypp_lock_timeout_backup = None
 
     def get_process_tree_from_pid_in_output(self, message):
         """ Fetches pid from the error message by searching for the text 'pid' and returns the process tree with all details.

src/core/tests/Test_ZypperPackageManager.py

@@ -393,6 +393,95 @@ def test_update_image_default_patch_mode(self):
         self.assertTrue(yast2_online_update_configuration_os_patch_configuration_settings_file_path_read is not None)
         self.assertTrue('AOU_ENABLE_CRONJOB="false"' in yast2_online_update_configuration_os_patch_configuration_settings_file_path_read)
 
+    def is_string_in_status_file(self, str_to_find):
+        with open(self.runtime.execution_config.status_file_path, 'r') as file_handle:
+            file_contents = json.loads(file_handle.read())
+            return str_to_find in str(file_contents)
+
+    def test_package_manager_with_retries(self):
+        package_manager = self.container.get('package_manager')
+        # Setting operation to assessment to add all errors under assessment substatus
+        self.runtime.status_handler.set_current_operation(Constants.ASSESSMENT)
+
+        # Wrap count in a mutable container to modify in mocked method to keep track of retries
+        counter = [0]
+        backup_mocked_method = package_manager.env_layer.run_command_output
+
+        def mock_run_command_output(cmd, no_output=False, chk_err=False):
+            # Only check for refresh cmd - otherwise, it may pick up other commands like ps tree
+            if cmd == 'sudo zypper refresh':
+                counter[0] += 1
+                if counter[0] == package_manager.package_manager_max_retries - 1:
+                    # Right before it runs out of retries, allow it to succeed
+                    self.runtime.set_legacy_test_type('HappyPath')
+            return backup_mocked_method(cmd, no_output, chk_err)
+
+        package_manager.env_layer.run_command_output = mock_run_command_output
+
+        # Case 1: SadPath to HappyPath (retry a few times and then success)
+
+        # SadPath uses return code 7
+        self.runtime.set_legacy_test_type('SadPath')
+
+        # Invoke with retries should NOT raise an exception here
+        try:
+            package_manager.invoke_package_manager('sudo zypper refresh')
+        except Exception as error:
+            self.fail(repr(error))
+
+        # Should reach max retries - 1 and then succeed, per the code above
+        self.assertEqual(counter[0], package_manager.package_manager_max_retries - 1)
+        self.assertFalse(self.is_string_in_status_file('Unexpected return code (4) from package manager on command: sudo zypper refresh'))
+
+        # Case 2: UnalignedPath to HappyPath (retry a few times and then success)
+        counter = [0]
+
+        # UnalignedPath uses return code 4
+        self.runtime.set_legacy_test_type('UnalignedPath')
+
+        # Invoke with retries should raise an exception here
+        try:
+            package_manager.invoke_package_manager('sudo zypper refresh')
+        except Exception as error:
+            self.fail(repr(error))
+
+        # Should reach max retries - 1 and then succeed, per the code above
+        self.assertEqual(counter[0], package_manager.package_manager_max_retries - 1)
+        self.assertTrue(self.is_string_in_status_file('Unexpected return code (7) from package manager on command: sudo zypper refresh'))
+
+        # Case 3: NonexistentErrorCodePath to HappyPath (should not retry since error code is not supported)
+        counter = [0]
+
+        # UnalignedPath uses return code 7
+        self.runtime.set_legacy_test_type('NonexistentErrorCodePath')
+
+        # Invoke with retries should raise an exception here
+        try:
+            package_manager.invoke_package_manager('sudo zypper refresh')
+            self.fail('Package manager should fail without retrying')
+        except Exception as error:
+            self.assertEqual(counter[0], 1)  # invoke should only be called once
+            self.assertTrue(self.is_string_in_status_file('Unexpected return code (999999) from package manager on command: sudo zypper refresh'))
+            self.assertTrue('Unexpected return code (999999) from package manager on command: sudo zypper refresh' in repr(error))
+
+        # Case 4: SadPath (retry and ultimately fail)
+        # Set counter to max retries already so it does not hit the condition to enable HappyPath
+        counter = [package_manager.package_manager_max_retries]
+
+        # SadPath uses return code 7
+        self.runtime.set_legacy_test_type('SadPath')
+
+        # Invoke with retries should raise an exception here
+        try:
+            package_manager.invoke_package_manager('sudo zypper refresh')
+        except Exception as error:
+            # Should reach max retries * 2 and fail (since it started at max retries)
+            self.assertEqual(counter[0], package_manager.package_manager_max_retries * 2)
+            self.assertTrue(self.is_string_in_status_file('Unexpected return code (7) from package manager on command: sudo zypper refresh'))
+            self.assertTrue('Unexpected return code (7) from package manager on command: sudo zypper refresh' in repr(error))
+
+        package_manager.env_layer.run_command_output = backup_mocked_method
+
 
 if __name__ == '__main__':
     unittest.main()

src/core/tests/library/LegacyEnvLayerExtensions.py

@@ -226,6 +226,11 @@ def run_command_output(self, cmd, no_output=False, chk_err=True):
                                  "7984  |               \_ /usr/bin/python3 /usr/bin/azuremetadata --api latest --subscriptionId --billingTag --attestedData --signature\n" + \
                                  "7986  \_ python3 package_test.py\n" + \
                                  "8298      \_ sudo LANG=en_US.UTF8 zypper --non-interactive update --dry-run grub2-i386-pc\n"
+                    elif cmd.find('sudo zypper refresh') > -1:
+                        code = 0
+                        output = "Retrieving repository 'SLE-Module-Basesystem15-SP3-Pool' metadata ................................................................[done]\n" + \
+                                 "Building repository 'SLE-Module-Basesystem15-SP3-Pool' cache .....................................................................[done]\n" + \
+                                 "All repositories have been refreshed."
                 elif self.legacy_package_manager_name is Constants.YUM:
                     if cmd.find("--security check-update") > -1:
                         code = 100
@@ -512,6 +517,9 @@ def run_command_output(self, cmd, no_output=False, chk_err=True):
                     if cmd.find('ps --forest -o pid,cmd -g $(ps -o sid= -p') > -1:
                         output = 'test'
                         code = 1
+                    elif cmd.find('sudo zypper refresh') > -1:
+                        code = 7
+                        output = 'System management is locked by the application with pid 7914 (/usr/bin/zypper).'
                 elif cmd.find("systemctl") > -1:
                     code = 1
                     output = ''
@@ -546,6 +554,14 @@ def run_command_output(self, cmd, no_output=False, chk_err=True):
                     if cmd.find('ps --forest -o pid,cmd -g $(ps -o sid= -p') > -1:
                         output = ''
                         code = 0
+                    elif cmd.find('sudo zypper refresh') > -1:
+                        code = 4
+                        output = 'System management is locked by the application with pid 7914 (/usr/bin/zypper).'
+            elif self.legacy_test_type == 'NonexistentErrorCodePath':
+                if self.legacy_package_manager_name is Constants.ZYPPER:
+                    if cmd.find('sudo zypper refresh') > -1:
+                        code = 999999
+                        output = 'Unexpected return code (100) from package manager on command: LANG=en_US.UTF8 sudo apt-get -s dist-upgrade'
             elif self.legacy_test_type == 'ExceptionPath':
                 code = -1
                 output = ''