diff --git a/easybuild/framework/easyblock.py b/easybuild/framework/easyblock.py index b9a6d062ac..20b7f834cb 100644 --- a/easybuild/framework/easyblock.py +++ b/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,7 +2276,7 @@ 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]) @@ -2281,17 +2284,16 @@ def install_extensions_sequential(self, install=True): # 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) diff --git a/easybuild/framework/extension.py b/easybuild/framework/extension.py index 77fb73d303..a682985245 100644 --- a/easybuild/framework/extension.py +++ b/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. diff --git a/test/framework/sandbox/easybuild/easyblocks/generic/toy_extension.py b/test/framework/sandbox/easybuild/easyblocks/generic/toy_extension.py index d8e01676ed..216756f184 100644 --- a/test/framework/sandbox/easybuild/easyblocks/generic/toy_extension.py +++ b/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. diff --git a/test/framework/toy_build.py b/test/framework/toy_build.py index d7dc7624f6..8819aa87d2 100644 --- a/test/framework/toy_build.py +++ b/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