Bring back async_cmd_check to check for parallel extension install completion and fix dry-run mode with parallel extensions

easybuild/framework/easyblock.py

@@ -68,6 +68,7 @@
 from datetime import datetime
 from string import ascii_letters
 from textwrap import indent
+from typing import List
 
 import easybuild.tools.environment as env
 import easybuild.tools.toolchain as toolchain
@@ -108,7 +109,7 @@
     MODULE_STEP, MODULE_WRITE, PACKAGE_STEP, PATCH_STEP, PERMISSIONS_STEP, POSTITER_STEP, POSTPROC_STEP, PREPARE_STEP,
     READY_STEP, SANITYCHECK_STEP, SINGLE_EXTENSION, TEST_STEP, TESTCASES_STEP, load_hooks, run_hook,
 )
-from easybuild.tools.run import RunShellCmdError, raise_run_shell_cmd_error, run_shell_cmd
+from easybuild.tools.run import RunShellCmdError, RunShellCmdResult, raise_run_shell_cmd_error, run_shell_cmd
 from easybuild.tools.jenkins import write_to_xml
 from easybuild.tools.module_generator import ModuleGeneratorLua, ModuleGeneratorTcl, module_generator, dependencies_for
 from easybuild.tools.module_naming_scheme.utilities import det_full_ec_version
@@ -2221,6 +2222,8 @@ def _install_extensions_check_fake_mod_file(self, fake_mod_file_path, fake_mod_f
         after installing extension(s)
         """
         res = None
+        if self.dry_run:
+            return res  # No module file is written, so no changes. See _install_extensions_det_init_build_env
 
         self.log.debug(f"Checking whether contents of fake module file {fake_mod_file_path} have changed...")
 
@@ -2273,25 +2276,24 @@ def install_extensions_sequential(self, install=True):
 
         build_env, fake_mod_file_txt = self._install_extensions_det_init_build_env(fake_mod_file_path)
 
-        for idx, ext in enumerate(self.ext_instances):
+        for idx, ext in enumerate(self.ext_instances, start=1):
             self.log.info("Starting extension %s", ext.name)
 
             run_hook(SINGLE_EXTENSION, self.hooks, pre_step_hook=True, args=[ext])
 
             # always go back to original work dir to avoid running stuff from a dir that no longer exists
             change_dir(self.orig_workdir)
 
-            progress_info = "Installing '%s' extension (%s/%s)" % (ext.name, idx + 1, exts_cnt)
+            progress_info = f"Installing '{ext.name}' extension ({idx}/{exts_cnt})"
             self.update_exts_progress_bar(progress_info)
 
-            tup = (ext.name, ext.version or '', idx + 1, exts_cnt)
-            print_msg("installing extension %s %s (%d/%d)..." % tup, silent=self.silent, log=self.log)
+            print_msg(f"installing extension {ext.name} {ext.version or ''} ({idx}/{exts_cnt})...",
+                      silent=self.silent, log=self.log)
             start_time = datetime.now()
 
             if self.dry_run:
-                tup = (ext.name, ext.version, ext.__class__.__name__)
-                msg = "\n* installing extension %s %s using '%s' easyblock\n" % tup
-                self.dry_run_msg(msg)
+                self.dry_run_msg(f"\n* installing extension {ext.name} {ext.version} "
+                                 f"using '{ext.__class__.__name__}' easyblock\n")
 
             # actual installation of the extension
             elif install:
@@ -2332,7 +2334,11 @@ def install_extensions_parallel(self, install=True):
         :param install: actually install extensions, don't just prepare environment for installing
         """
         self.log.info("Installing extensions in parallel...")
-
+        if self.dry_run:
+            # No tasks started in dry-run so use dummy result
+            dry_run_mock_result = RunShellCmdResult(cmd='dummy', output="bar", exit_code=0, stderr=None,
+                                                    work_dir='/test_cat', out_file='/tmp/cat.out', err_file=None,
+                                                    cmd_sh='/tmp/cmd.sh', thread_id=None, task_id=None)
         thread_pool = ThreadPoolExecutor(max_workers=self.cfg.parallel)
 
         # path to fake module file, so we can check if contents change after installing extensions
@@ -2341,8 +2347,8 @@ def install_extensions_parallel(self, install=True):
         self.log.debug("Determining build environment for extensions...")
         build_env, fake_mod_file_txt = self._install_extensions_det_init_build_env(fake_mod_file_path)
 
-        running_exts = []
-        installed_ext_names = []
+        running_exts: List[Extension] = []
+        installed_ext_names: List[str] = []
 
         all_ext_names = [x['name'] for x in self.exts_all]
         self.log.debug("List of names of all extensions: %s", all_ext_names)
@@ -2352,7 +2358,7 @@ def install_extensions_parallel(self, install=True):
         installed_ext_names = [n for n in all_ext_names if n not in to_install_ext_names]
 
         exts_cnt = len(all_ext_names)
-        exts_queue = self.ext_instances[:]
+        exts_queue: List[Extension] = self.ext_instances[:]
 
         def update_exts_progress_bar_helper(running_exts, progress_size):
             """Helper function to update extensions progress bar."""
@@ -2411,15 +2417,8 @@ def update_exts_progress_bar_helper(running_exts, progress_size):
                     else:
                         pending_deps = []
 
-                if self.dry_run:
-                    tup = (ext.name, ext.version, ext.__class__.__name__)
-                    msg = "\n* installing extension %s %s using '%s' easyblock\n" % tup
-                    self.dry_run_msg(msg)
-                    running_exts.append(ext)
-
                 # if some of the required dependencies are not installed yet, requeue this extension
-                elif pending_deps:
-
+                if pending_deps:
                     # check whether all required dependency extensions are actually going to be installed;
                     # if not, we assume that they are provided by dependencies;
                     missing_deps = [x for x in required_deps if x not in all_ext_names]
@@ -2435,49 +2434,57 @@ def update_exts_progress_bar_helper(running_exts, progress_size):
                         msg = f"Pending dependencies for {ext.name} after taking into account missing dependencies: "
                         self.log.debug(msg + ', '.join(pending_deps))
 
-                    if pending_deps:
-                        msg = f"Required dependencies not installed yet for extension {ext.name} ("
-                        msg += ', '.join(pending_deps)
-                        msg += "), adding it back to queue..."
-                        self.log.info(msg)
-                        # purposely adding extension back in the queue at Nth place rather than at the end,
-                        # since we assume that the required dependencies will be installed soon...
-                        exts_queue.insert(max_iter, ext)
-
                 # list of pending dependencies may be empty now after taking into account required extensions
                 # that are not being installed above, so extension may be ready to install
-                if not pending_deps:
-                    tup = (ext.name, ext.version or '')
-                    print_msg("starting installation of extension %s %s..." % tup, silent=self.silent, log=self.log)
-
-                    if install and not self.dry_run:
-                        # restore build environment for this extension
-                        restore_env(build_env, log_changes=False)
+                if pending_deps:
+                    msg = f"Required dependencies not installed yet for extension {ext.name} ("
+                    msg += ', '.join(pending_deps)
+                    msg += "), adding it back to queue..."
+                    self.log.info(msg)
+                    # purposely adding extension back in the queue at Nth place rather than at the end,
+                    # since we assume that the required dependencies will be installed soon...
+                    exts_queue.insert(max_iter, ext)
+                else:
+                    print_msg(f"starting installation of extension {ext.name} {ext.version or ''}...",
+                              silent=self.silent, log=self.log)
+
+                    if install:
+                        if self.dry_run:
+                            self.dry_run_msg(f"\n* installing extension {ext.name} {ext.version} using "
+                                             f"'{ext.__class__.__name__}' easyblock\n")
+                            running_exts.append(ext)
+                        else:
+                            # restore build environment for this extension
+                            restore_env(build_env, log_changes=False)
 
-                        ext.install_extension_substep("pre_install_extension")
+                            ext.install_extension_substep("pre_install_extension")
 
-                        # note: current build environment is copied when install_extension_async is called
-                        ext.async_cmd_task = ext.install_extension_substep("install_extension_async", thread_pool)
-                        running_exts.append(ext)
+                            # note: current build environment is copied when install_extension_async is called
+                            ext.async_cmd_task = ext.install_extension_substep("install_extension_async", thread_pool)
+                            running_exts.append(ext)
 
-                        self.log.info(f"Started installation of extension {ext.name} in the background...")
-                        update_exts_progress_bar_helper(running_exts, 0)
+                            self.log.info(f"Started installation of extension {ext.name} in the background...")
+                            update_exts_progress_bar_helper(running_exts, 0)
 
             # check for extension installations that have completed
             installs_completed = False
             if running_exts:
                 self.log.info(f"Checking for completed extension installations ({len(running_exts)} running)...")
                 for ext in running_exts[:]:
-                    if self.dry_run or ext.async_cmd_task.done():
+                    if self.dry_run or ext.async_cmd_check():
+                        if self.dry_run:
+                            res = dry_run_mock_result
+                        else:
+                            res = ext.async_cmd_task.result()
                         installs_completed = True
-                        res = ext.async_cmd_task.result()
                         if res.exit_code == EasyBuildExit.SUCCESS:
                             print_msg(f"installation of extension {ext.name} {ext.version or ''} completed!",
                                       silent=self.silent, log=self.log)
-                            # run post-install method for extension from same working dir as installation of extension
-                            cwd = change_dir(res.work_dir)
-                            ext.install_extension_substep("post_install_extension")
-                            change_dir(cwd)
+                            if not self.dry_run:
+                                # run post-install method for extension from same working dir as installation of it
+                                cwd = change_dir(res.work_dir)
+                                ext.install_extension_substep("post_install_extension")
+                                change_dir(cwd)
                             running_exts.remove(ext)
                             installed_ext_names.append(ext.name)
                             update_exts_progress_bar_helper(running_exts, 1)

easybuild/framework/extension.py

@@ -37,13 +37,15 @@
 """
 import copy
 import os
+from concurrent.futures import Future
+from typing import Optional
 
 from easybuild.framework.easyconfig.default import get_easyconfig_parameter_default
 from easybuild.framework.easyconfig.easyconfig import resolve_template
 from easybuild.framework.easyconfig.templates import TEMPLATE_NAMES_EASYBLOCK_RUN_STEP, template_constant_dict
 from easybuild.tools.build_log import EasyBuildError, EasyBuildExit
 from easybuild.tools.filetools import change_dir
-from easybuild.tools.run import run_shell_cmd
+from easybuild.tools.run import run_shell_cmd, RunShellCmdResult
 from easybuild.tools.utilities import trace_msg
 
 
@@ -125,6 +127,7 @@ def __init__(self, mself, ext, extra_params=None):
         self.cfg = self.master.cfg.copy(validate=False)
         self.ext = copy.deepcopy(ext)
         self.dry_run = self.master.dry_run
+        self.async_cmd_task: Optional[Future[RunShellCmdResult]] = None
 
         if 'name' not in self.ext:
             raise EasyBuildError("'name' is missing in supplied class instance 'ext'.")
@@ -253,6 +256,20 @@ def install_extension_async(self, *args, **kwargs):
         """
         raise NotImplementedError
 
+    def async_cmd_check(self):
+        """
+        Check progress of installation command that was started asynchronously.
+        :return: True if command completed, False otherwise
+        """
+        if not self.async_cmd_task.done():
+            return False
+        res: RunShellCmdResult = self.async_cmd_task.result()
+        self.log.debug(f"Asynchronous command for {self.name} finished with exit code {res.exit_code}")
+        self.async_cmd_output = res.output
+        if res.stderr:
+            self.async_cmd_output += res.stderr
+        return True
+
     def postrun(self):
         """
         [DEPRECATED][6.0] Stuff to do after installing a extension.

test/framework/sandbox/easybuild/easyblocks/generic/toy_extension.py

@@ -97,6 +97,13 @@ def install_extension_async(self, thread_pool):
         return thread_pool.submit(run_shell_cmd, cmd, asynchronous=True, env=os.environ.copy(),
                                   fail_on_error=False, task_id=task_id, work_dir=os.getcwd())
 
+    def async_cmd_check(self):
+        """Show success"""
+        done = super().async_cmd_check()
+        if done:
+            print("Async toy extension build done")
+        return done
+
     def post_install_extension(self):
         """
         Wrap up installation of toy extension.

test/framework/toy_build.py

@@ -116,7 +116,8 @@ def tearDown(self):
         if os.path.exists(self.dummylogfn):
             os.remove(self.dummylogfn)
 
-    def check_toy(self, installpath, outtxt, name='toy', version='0.0', versionprefix='', versionsuffix='', error=None):
+    def check_toy(self, installpath, outtxt, name='toy', version='0.0', versionprefix='', versionsuffix='', error=None,
+                  args=None):
         """Check whether toy build succeeded."""
 
         full_version = ''.join([versionprefix, version, versionsuffix])
@@ -129,6 +130,8 @@ def check_toy(self, installpath, outtxt, name='toy', version='0.0', versionprefi
         # check for success
         success = re.compile(r"COMPLETED: Installation (ended|STOPPED) successfully \(took .* secs?\)")
         self.assertTrue(success.search(outtxt), "COMPLETED message found in '%s'%s" % (outtxt, error_msg))
+        if args and any(arg in args for arg in ('--dry-run', '--extended-dry-run')):
+            return  # No module created
 
         # if the module exists, it should be fine
         toy_module = os.path.join(installpath, 'modules', 'all', name, full_version)
@@ -199,7 +202,8 @@ def _test_toy_build(self, extra_args=None, ec_file=None, tmpdir=None, verify=Tru
                 raise myerr
 
         if verify:
-            self.check_toy(self.test_installpath, outtxt, name=name, versionsuffix=versionsuffix, error=myerr)
+            self.check_toy(self.test_installpath, outtxt, name=name, versionsuffix=versionsuffix, error=myerr,
+                           args=args)
 
         if test_readme:
             # make sure postinstallcmds were used
@@ -1997,7 +2001,7 @@ def _test_toy_exts_common(self, args=None):
         ])
         write_file(test_ec, test_ec_txt)
 
-        extra_args = ['--force', '--parallel=3']
+        extra_args = ['--rebuild', '--parallel=3']
         if args:
             extra_args.extend(args)
 
@@ -2009,7 +2013,7 @@ def _test_toy_exts_common(self, args=None):
 
         logtxt = read_file(self.logfile)
 
-        return logtxt
+        return stdout, logtxt
 
     def test_toy_exts_sequential(self):
         """
@@ -2019,7 +2023,7 @@ def test_toy_exts_sequential(self):
         # but also test with it disable explicitly
         for args in ([], ['--disable-parallel-extensions-install']):
 
-            logtxt = self._test_toy_exts_common(args=args)
+            logtxt = self._test_toy_exts_common(args=args)[1]
 
             self.assertRegex(logtxt, "INFO Installing extensions sequentially")
 
@@ -2061,7 +2065,7 @@ def test_toy_exts_sequential(self):
             # also test skipping of extensions in parallel
             args.append('--skip')
 
-            logtxt = self._test_toy_exts_common(args=args)
+            logtxt = self._test_toy_exts_common(args=args)[1]
 
             # order in which these patterns occur is not fixed, so check them one by one
             patterns = [
@@ -2079,7 +2083,7 @@ def test_toy_exts_parallel(self):
         """
         args = ['--parallel-extensions-install']
 
-        logtxt = self._test_toy_exts_common(args=args)
+        stdout, logtxt = self._test_toy_exts_common(args=args)
 
         # take into account that each of these lines may appear multiple times,
         # in case no progress was made between checks
@@ -2118,11 +2122,29 @@ def test_toy_exts_parallel(self):
             "toy/0.0-GCC-12.3.0",
         ]
         self.assertEqual(res, expected)
+        self.assertIn("Async toy extension build done", stdout)  # async_cmd_check of custom easyblock called
+
+        dry_run_args = args + [
+            '--extended-dry-run',
+            # Start clean, otherwise the existing dir is detected as a ghost directory
+            f'--installpath={tempfile.mkdtemp()}'
+        ]
+        logtxt = self._test_toy_exts_common(args=dry_run_args)[1]
+        # Compare those to the patterns in real mod above
+        patterns = [
+            "INFO Installing extensions in parallel",
+            # In dry-run mode extension installations complete immediately, so bar is finished already
+            r"INFO 2 out of 4 extensions installed \(2 queued, 0 running: \)$",
+            # Same for toy
+            r"INFO 3 out of 4 extensions installed \(1 queued, 0 running: \)$",
+            r"INFO 4 out of 4 extensions installed \(0 queued, 0 running: \)$",
+        ]
+        self.assert_multi_regex(patterns, logtxt)
 
         # also test skipping of extensions in parallel
         args.append('--skip')
 
-        logtxt = self._test_toy_exts_common(args=args)
+        logtxt = self._test_toy_exts_common(args=args)[1]
 
         # order in which these patterns occur is not fixed, so check them one by one
         patterns = [
@@ -2145,7 +2167,7 @@ def test_toy_exts_parallel(self):
 
         args[-1] = '--include-easyblocks=%s' % toy_ext_eb
 
-        logtxt = self._test_toy_exts_common(args=args)
+        logtxt = self._test_toy_exts_common(args=args)[1]
 
         # take into account that each of these lines may appear multiple times,
         # in case no progress was made between checks