diff --git a/easybuild/framework/easyblock.py b/easybuild/framework/easyblock.py index e86d475f64..5886fe8500 100644 --- a/easybuild/framework/easyblock.py +++ b/easybuild/framework/easyblock.py @@ -87,7 +87,7 @@ from easybuild.tools.hooks import MODULE_STEP, MODULE_WRITE, PACKAGE_STEP, PATCH_STEP, PERMISSIONS_STEP, POSTITER_STEP from easybuild.tools.hooks import POSTPROC_STEP, PREPARE_STEP, READY_STEP, SANITYCHECK_STEP, SOURCE_STEP from easybuild.tools.hooks import SINGLE_EXTENSION, TEST_STEP, TESTCASES_STEP, load_hooks, run_hook -from easybuild.tools.run import check_async_cmd, run_cmd +from easybuild.tools.run import RunShellCmdError, check_async_cmd, run_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 @@ -4124,6 +4124,11 @@ def run_all_steps(self, run_test_cases): start_time = datetime.now() try: self.run_step(step_name, step_methods) + except RunShellCmdError as err: + err.print() + ec_path = os.path.basename(self.cfg.path) + error_msg = f"shell command '{err.cmd_name} ...' failed in {step_name} step for {ec_path}" + raise EasyBuildError(error_msg) finally: if not self.dry_run: step_duration = datetime.now() - start_time @@ -4225,7 +4230,7 @@ def build_and_install_one(ecdict, init_env): app.cfg['skip'] = skip # build easyconfig - errormsg = '(no error)' + error_msg = '(no error)' # timing info start_time = time.time() try: @@ -4263,9 +4268,7 @@ def build_and_install_one(ecdict, init_env): adjust_permissions(app.installdir, stat.S_IWUSR, add=False, recursive=True) except EasyBuildError as err: - first_n = 300 - errormsg = "build failed (first %d chars): %s" % (first_n, err.msg[:first_n]) - _log.warning(errormsg) + error_msg = err.msg result = False ended = 'ended' @@ -4387,11 +4390,7 @@ def ensure_writable_log_dir(log_dir): # build failed success = False summary = 'FAILED' - - build_dir = '' - if app.builddir: - build_dir = " (build directory: %s)" % (app.builddir) - succ = "unsuccessfully%s: %s" % (build_dir, errormsg) + succ = "unsuccessfully: " + error_msg # cleanup logs app.close_log() @@ -4424,7 +4423,7 @@ def ensure_writable_log_dir(log_dir): del app - return (success, application_log, errormsg) + return (success, application_log, error_msg) def copy_easyblocks_for_reprod(easyblock_instances, reprod_dir): diff --git a/easybuild/main.py b/easybuild/main.py index d6d5755e9a..0f2c69733c 100644 --- a/easybuild/main.py +++ b/easybuild/main.py @@ -70,7 +70,7 @@ from easybuild.tools.github import add_pr_labels, install_github_token, list_prs, merge_pr, new_branch_github, new_pr from easybuild.tools.github import new_pr_from_branch from easybuild.tools.github import sync_branch_with_develop, sync_pr_with_develop, update_branch, update_pr -from easybuild.tools.hooks import BUILD_AND_INSTALL_LOOP, PRE_PREF, POST_PREF, START, END, CANCEL, FAIL +from easybuild.tools.hooks import BUILD_AND_INSTALL_LOOP, PRE_PREF, POST_PREF, START, END, CANCEL, CRASH, FAIL from easybuild.tools.hooks import load_hooks, run_hook from easybuild.tools.modules import modules_tool from easybuild.tools.options import opts_dict_to_eb_opts, set_up_configuration, use_color @@ -149,11 +149,11 @@ def build_and_install_software(ecs, init_session_state, exit_on_failure=True): # keep track of success/total count if ec_res['success']: - test_msg = "Successfully built %s" % ec['spec'] + test_msg = "Successfully installed %s" % ec['spec'] else: - test_msg = "Build of %s failed" % ec['spec'] + test_msg = "Installation of %s failed" % os.path.basename(ec['spec']) if 'err' in ec_res: - test_msg += " (err: %s)" % ec_res['err'] + test_msg += ": %s" % ec_res['err'] # dump test report next to log file test_report_txt = create_test_report(test_msg, [(ec, ec_res)], init_session_state) @@ -169,8 +169,8 @@ def build_and_install_software(ecs, init_session_state, exit_on_failure=True): adjust_permissions(parent_dir, stat.S_IWUSR, add=False, recursive=False) if not ec_res['success'] and exit_on_failure: - if 'traceback' in ec_res: - raise EasyBuildError(ec_res['traceback']) + if not isinstance(ec_res['err'], EasyBuildError): + raise ec_res['err'] else: raise EasyBuildError(test_msg) @@ -747,14 +747,22 @@ def prepare_main(args=None, logfile=None, testing=None): return init_session_state, eb_go, cfg_settings -if __name__ == "__main__": - init_session_state, eb_go, cfg_settings = prepare_main() +def main_with_hooks(args=None): + init_session_state, eb_go, cfg_settings = prepare_main(args=args) hooks = load_hooks(eb_go.options.hooks) try: - main(prepared_cfg_data=(init_session_state, eb_go, cfg_settings)) + main(args=args, prepared_cfg_data=(init_session_state, eb_go, cfg_settings)) except EasyBuildError as err: run_hook(FAIL, hooks, args=[err]) - print_error(err.msg) + sys.exit(1) except KeyboardInterrupt as err: run_hook(CANCEL, hooks, args=[err]) print_error("Cancelled by user: %s" % err) + except Exception as err: + run_hook(CRASH, hooks, args=[err]) + sys.stderr.write("EasyBuild crashed! Please consider reporting a bug, this should not happen...\n\n") + raise + + +if __name__ == "__main__": + main_with_hooks() diff --git a/easybuild/tools/build_log.py b/easybuild/tools/build_log.py index 215b8d38aa..e8a479e24e 100644 --- a/easybuild/tools/build_log.py +++ b/easybuild/tools/build_log.py @@ -167,7 +167,7 @@ def nosupport(self, msg, ver): def error(self, msg, *args, **kwargs): """Print error message and raise an EasyBuildError.""" - ebmsg = "EasyBuild crashed with an error %s: " % self.caller_info() + ebmsg = "EasyBuild encountered an error %s: " % self.caller_info() fancylogger.FancyLogger.error(self, ebmsg + msg, *args, **kwargs) def devel(self, msg, *args, **kwargs): diff --git a/easybuild/tools/hooks.py b/easybuild/tools/hooks.py index 319b864398..2bb329027b 100644 --- a/easybuild/tools/hooks.py +++ b/easybuild/tools/hooks.py @@ -67,6 +67,7 @@ END = 'end' CANCEL = 'cancel' +CRASH = 'crash' FAIL = 'fail' RUN_SHELL_CMD = 'run_shell_cmd' @@ -107,6 +108,7 @@ POST_PREF + BUILD_AND_INSTALL_LOOP, END, CANCEL, + CRASH, FAIL, PRE_PREF + RUN_SHELL_CMD, POST_PREF + RUN_SHELL_CMD, diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index 85b79a7868..e43edbe7cf 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -37,6 +37,7 @@ """ import contextlib import functools +import inspect import os import re import signal @@ -75,7 +76,81 @@ ] -RunResult = namedtuple('RunResult', ('cmd', 'exit_code', 'output', 'stderr', 'work_dir')) +RunShellCmdResult = namedtuple('RunShellCmdResult', ('cmd', 'exit_code', 'output', 'stderr', 'work_dir')) + + +class RunShellCmdError(BaseException): + + def __init__(self, cmd, exit_code, work_dir, output, stderr, caller_info, *args, **kwargs): + """Constructor for RunShellCmdError.""" + self.cmd = cmd + self.cmd_name = cmd.split(' ')[0] + self.exit_code = exit_code + self.work_dir = work_dir + self.output = output + self.stderr = stderr + self.caller_info = caller_info + + msg = f"Shell command '{self.cmd_name}' failed!" + super(RunShellCmdError, self).__init__(msg, *args, **kwargs) + + def print(self): + """ + Report failed shell command for this RunShellCmdError instance + """ + + def pad_4_spaces(msg): + return ' ' * 4 + msg + + error_info = [ + '', + "ERROR: Shell command failed!", + pad_4_spaces(f"full command -> {self.cmd}"), + pad_4_spaces(f"exit code -> {self.exit_code}"), + pad_4_spaces(f"working directory -> {self.work_dir}"), + ] + + tmpdir = tempfile.mkdtemp(prefix='shell-cmd-error-') + output_fp = os.path.join(tmpdir, f"{self.cmd_name}.out") + with open(output_fp, 'w') as fp: + fp.write(self.output or '') + + if self.stderr is None: + error_info.append(pad_4_spaces(f"output (stdout + stderr) -> {output_fp}")) + else: + stderr_fp = os.path.join(tmpdir, f"{self.cmd_name}.err") + with open(stderr_fp, 'w') as fp: + fp.write(self.stderr) + error_info.extend([ + pad_4_spaces(f"output (stdout) -> {output_fp}"), + pad_4_spaces(f"error/warnings (stderr) -> {stderr_fp}"), + ]) + + caller_file_name, caller_line_nr, caller_function_name = self.caller_info + called_from_info = f"'{caller_function_name}' function in {caller_file_name} (line {caller_line_nr})" + error_info.extend([ + pad_4_spaces(f"called from -> {called_from_info}"), + '', + ]) + + sys.stderr.write('\n'.join(error_info) + '\n') + + +def raise_run_shell_cmd_error(cmd, exit_code, work_dir, output, stderr): + """ + Raise RunShellCmdError for failing shell command, after collecting additional caller info + """ + + # figure out where failing command was run + # need to go 3 levels down: + # 1) this function + # 2) run_shell_cmd function + # 3) run_cmd_cache decorator + # 4) actual caller site + frameinfo = inspect.getouterframes(inspect.currentframe())[3] + caller_info = (frameinfo.filename, frameinfo.lineno, frameinfo.function) + + raise RunShellCmdError(cmd, exit_code, work_dir, output, stderr, caller_info) def run_cmd_cache(func): @@ -178,7 +253,7 @@ def to_cmd_str(cmd): msg += f" (in {work_dir})" dry_run_msg(msg, silent=silent) - return RunResult(cmd=cmd_str, exit_code=0, output='', stderr=None, work_dir=work_dir) + return RunShellCmdResult(cmd=cmd_str, exit_code=0, output='', stderr=None, work_dir=work_dir) start_time = datetime.now() if not hidden: @@ -204,14 +279,29 @@ def to_cmd_str(cmd): _log.info("Command to run was changed by pre-%s hook: '%s' (was: '%s')", RUN_SHELL_CMD, cmd, old_cmd) _log.info(f"Running command '{cmd_str}' in {work_dir}") - proc = subprocess.run(cmd, stdout=subprocess.PIPE, stderr=stderr, check=fail_on_error, + proc = subprocess.run(cmd, stdout=subprocess.PIPE, stderr=stderr, check=False, cwd=work_dir, env=env, input=stdin, shell=shell, executable=executable) # return output as a regular string rather than a byte sequence (and non-UTF-8 characters get stripped out) output = proc.stdout.decode('utf-8', 'ignore') - stderr_output = proc.stderr.decode('utf-8', 'ignore') if split_stderr else None + stderr = proc.stderr.decode('utf-8', 'ignore') if split_stderr else None + + res = RunShellCmdResult(cmd=cmd_str, exit_code=proc.returncode, output=output, stderr=stderr, work_dir=work_dir) - res = RunResult(cmd=cmd_str, exit_code=proc.returncode, output=output, stderr=stderr_output, work_dir=work_dir) + # always log command output + cmd_name = cmd_str.split(' ')[0] + if split_stderr: + _log.info(f"Output of '{cmd_name} ...' shell command (stdout only):\n{res.output}") + _log.info(f"Warnings and errors of '{cmd_name} ...' shell command (stderr only):\n{res.stderr}") + else: + _log.info(f"Output of '{cmd_name} ...' shell command (stdout + stderr):\n{res.output}") + + if res.exit_code == 0: + _log.info(f"Shell command completed successfully (see output above): {cmd_str}") + else: + _log.warning(f"Shell command FAILED (exit code {res.exit_code}, see output above): {cmd_str}") + if fail_on_error: + raise_run_shell_cmd_error(res.cmd, res.exit_code, res.work_dir, output=res.output, stderr=res.stderr) if with_hooks: run_hook_kwargs = { @@ -222,13 +312,6 @@ def to_cmd_str(cmd): } run_hook(RUN_SHELL_CMD, hooks, post_step_hook=True, args=[cmd], kwargs=run_hook_kwargs) - if split_stderr: - log_msg = f"Command '{cmd_str}' exited with exit code {res.exit_code}, " - log_msg += f"with stdout:\n{res.output}\nstderr:\n{res.stderr}" - else: - log_msg = f"Command '{cmd_str}' exited with exit code {res.exit_code} and output:\n{res.output}" - _log.info(log_msg) - if not hidden: time_since_start = time_str_since(start_time) trace_msg(f"command completed: exit {res.exit_code}, ran in {time_since_start}") diff --git a/test/framework/build_log.py b/test/framework/build_log.py index a1792b998f..21755b62b3 100644 --- a/test/framework/build_log.py +++ b/test/framework/build_log.py @@ -139,8 +139,8 @@ def test_easybuildlog(self): r"fancyroot.test_easybuildlog \[WARNING\] :: Deprecated functionality.*onemorewarning.*", r"fancyroot.test_easybuildlog \[WARNING\] :: Deprecated functionality.*lastwarning.*", r"fancyroot.test_easybuildlog \[WARNING\] :: Deprecated functionality.*thisisnotprinted.*", - r"fancyroot.test_easybuildlog \[ERROR\] :: EasyBuild crashed with an error \(at .* in .*\): kaput", - r"fancyroot.test_easybuildlog \[ERROR\] :: EasyBuild crashed with an error \(at .* in .*\): err: msg: %s", + r"fancyroot.test_easybuildlog \[ERROR\] :: EasyBuild encountered an error \(at .* in .*\): kaput", + r"fancyroot.test_easybuildlog \[ERROR\] :: EasyBuild encountered an error \(at .* in .*\): err: msg: %s", r"fancyroot.test_easybuildlog \[ERROR\] :: .*EasyBuild encountered an exception \(at .* in .*\): oops", '', ]) @@ -168,7 +168,7 @@ def test_easybuildlog(self): r"fancyroot.test_easybuildlog \[WARNING\] :: bleh", r"fancyroot.test_easybuildlog \[INFO\] :: 4\+2 = 42", r"fancyroot.test_easybuildlog \[DEBUG\] :: this is just a test", - r"fancyroot.test_easybuildlog \[ERROR\] :: EasyBuild crashed with an error \(at .* in .*\): foo baz baz", + r"fancyroot.test_easybuildlog \[ERROR\] :: EasyBuild encountered an error \(at .* in .*\): foo baz baz", '', ]) logtxt_regex = re.compile(r'^%s' % expected_logtxt, re.M) @@ -223,7 +223,7 @@ def test_log_levels(self): info_msg = r"%s \[INFO\] :: fyi" % prefix warning_msg = r"%s \[WARNING\] :: this is a warning" % prefix deprecated_msg = r"%s \[WARNING\] :: Deprecated functionality, .*: almost kaput; see .*" % prefix - error_msg = r"%s \[ERROR\] :: EasyBuild crashed with an error \(at .* in .*\): kaput" % prefix + error_msg = r"%s \[ERROR\] :: EasyBuild encountered an error \(at .* in .*\): kaput" % prefix expected_logtxt = '\n'.join([ error_msg, diff --git a/test/framework/hooks.py b/test/framework/hooks.py index 152d2352a4..c8e5d34583 100644 --- a/test/framework/hooks.py +++ b/test/framework/hooks.py @@ -79,6 +79,9 @@ def setUp(self): '', 'def fail_hook(err):', ' print("EasyBuild FAIL: %s" % err)', + '', + 'def crash_hook(err):', + ' print("EasyBuild CRASHED, oh no! => %s" % err)', ]) write_file(self.test_hooks_pymod, test_hooks_pymod_txt) @@ -97,8 +100,9 @@ def test_load_hooks(self): hooks = load_hooks(self.test_hooks_pymod) - self.assertEqual(len(hooks), 8) + self.assertEqual(len(hooks), 9) expected = [ + 'crash_hook', 'fail_hook', 'parse_hook', 'post_configure_hook', @@ -140,6 +144,7 @@ def test_find_hook(self): pre_single_extension_hook = [hooks[k] for k in hooks if k == 'pre_single_extension_hook'][0] start_hook = [hooks[k] for k in hooks if k == 'start_hook'][0] pre_run_shell_cmd_hook = [hooks[k] for k in hooks if k == 'pre_run_shell_cmd_hook'][0] + crash_hook = [hooks[k] for k in hooks if k == 'crash_hook'][0] fail_hook = [hooks[k] for k in hooks if k == 'fail_hook'][0] pre_build_and_install_loop_hook = [hooks[k] for k in hooks if k == 'pre_build_and_install_loop_hook'][0] @@ -175,6 +180,10 @@ def test_find_hook(self): self.assertEqual(find_hook('fail', hooks, pre_step_hook=True), None) self.assertEqual(find_hook('fail', hooks, post_step_hook=True), None) + self.assertEqual(find_hook('crash', hooks), crash_hook) + self.assertEqual(find_hook('crash', hooks, pre_step_hook=True), None) + self.assertEqual(find_hook('crash', hooks, post_step_hook=True), None) + hook_name = 'build_and_install_loop' self.assertEqual(find_hook(hook_name, hooks), None) self.assertEqual(find_hook(hook_name, hooks, pre_step_hook=True), pre_build_and_install_loop_hook) @@ -209,6 +218,7 @@ def run_hooks(): run_hook('single_extension', hooks, post_step_hook=True, args=[None]) run_hook('extensions', hooks, post_step_hook=True, args=[None]) run_hook('fail', hooks, args=[EasyBuildError('oops')]) + run_hook('crash', hooks, args=[RuntimeError('boom!')]) stdout = self.get_stdout() stderr = self.get_stderr() self.mock_stdout(False) @@ -244,6 +254,8 @@ def run_hooks(): "this is run before installing an extension", "== Running fail hook...", "EasyBuild FAIL: 'oops'", + "== Running crash hook...", + "EasyBuild CRASHED, oh no! => boom!", ] expected_stdout = '\n'.join(expected_stdout_lines) diff --git a/test/framework/options.py b/test/framework/options.py index bde1e565c5..f6742131bf 100644 --- a/test/framework/options.py +++ b/test/framework/options.py @@ -737,6 +737,7 @@ def test_avail_hooks(self): " post_build_and_install_loop_hook", " end_hook", " cancel_hook", + " crash_hook", " fail_hook", " pre_run_shell_cmd_hook", " post_run_shell_cmd_hook", diff --git a/test/framework/run.py b/test/framework/run.py index 4d6974bb04..5bce2d20f1 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -49,9 +49,10 @@ import easybuild.tools.utilities from easybuild.tools.build_log import EasyBuildError, init_logging, stop_logging from easybuild.tools.config import update_build_option -from easybuild.tools.filetools import adjust_permissions, mkdir, read_file, write_file -from easybuild.tools.run import check_async_cmd, check_log_for_errors, complete_cmd, get_output_from_process -from easybuild.tools.run import RunResult, parse_log_for_error, run_shell_cmd, run_cmd, run_cmd_qa, subprocess_terminate +from easybuild.tools.filetools import adjust_permissions, change_dir, mkdir, read_file, write_file +from easybuild.tools.run import RunShellCmdResult, RunShellCmdError, check_async_cmd, check_log_for_errors +from easybuild.tools.run import complete_cmd, get_output_from_process, parse_log_for_error +from easybuild.tools.run import run_cmd, run_cmd_qa, run_shell_cmd, subprocess_terminate from easybuild.tools.config import ERROR, IGNORE, WARN @@ -248,7 +249,7 @@ def test_run_shell_cmd_log(self): os.close(fd) regex_start_cmd = re.compile("Running command 'echo hello' in /") - regex_cmd_exit = re.compile("Command 'echo hello' exited with exit code [0-9]* and output:") + regex_cmd_exit = re.compile(r"Shell command completed successfully \(see output above\): echo hello") # command output is always logged init_logging(logfile, silent=True) @@ -257,8 +258,9 @@ def test_run_shell_cmd_log(self): stop_logging(logfile) self.assertEqual(res.exit_code, 0) self.assertEqual(res.output, 'hello\n') - self.assertEqual(len(regex_start_cmd.findall(read_file(logfile))), 1) - self.assertEqual(len(regex_cmd_exit.findall(read_file(logfile))), 1) + logtxt = read_file(logfile) + self.assertEqual(len(regex_start_cmd.findall(logtxt)), 1) + self.assertEqual(len(regex_cmd_exit.findall(logtxt)), 1) write_file(logfile, '') # with debugging enabled, exit code and output of command should only get logged once @@ -310,6 +312,9 @@ def test_run_shell_cmd_fail(self): def handler(signum, _): raise RuntimeError("Signal handler called with signal %s" % signum) + # disable trace output for this test (so stdout remains empty) + update_build_option('trace', False) + orig_sigalrm_handler = signal.getsignal(signal.SIGALRM) try: @@ -317,9 +322,87 @@ def handler(signum, _): signal.signal(signal.SIGALRM, handler) signal.alarm(3) - with self.mocked_stdout_stderr(): - res = run_shell_cmd("kill -9 $$", fail_on_error=False) + # command to kill parent shell + cmd = "kill -9 $$" + + work_dir = os.path.realpath(self.test_prefix) + change_dir(work_dir) + + try: + run_shell_cmd(cmd) + self.assertFalse("This should never be reached, RunShellCmdError should occur!") + except RunShellCmdError as err: + self.assertEqual(str(err), "Shell command 'kill' failed!") + self.assertEqual(err.cmd, "kill -9 $$") + self.assertEqual(err.cmd_name, 'kill') + self.assertEqual(err.exit_code, -9) + self.assertEqual(err.work_dir, work_dir) + self.assertEqual(err.output, '') + self.assertEqual(err.stderr, None) + self.assertTrue(isinstance(err.caller_info, tuple)) + self.assertEqual(len(err.caller_info), 3) + self.assertEqual(err.caller_info[0], __file__) + self.assertTrue(isinstance(err.caller_info[1], int)) # line number of calling site + self.assertEqual(err.caller_info[2], 'test_run_shell_cmd_fail') + + with self.mocked_stdout_stderr() as (_, stderr): + err.print() + + # check error reporting output + stderr = stderr.getvalue() + patterns = [ + r"^ERROR: Shell command failed!", + r"^\s+full command\s* -> kill -9 \$\$", + r"^\s+exit code\s* -> -9", + r"^\s+working directory\s* -> " + work_dir, + r"^\s+called from\s* -> 'test_run_shell_cmd_fail' function in .*/test/.*/run.py \(line [0-9]+\)", + r"^\s+output \(stdout \+ stderr\)\s* -> .*/shell-cmd-error-.*/kill.out", + ] + for pattern in patterns: + regex = re.compile(pattern, re.M) + self.assertTrue(regex.search(stderr), "Pattern '%s' should be found in: %s" % (pattern, stderr)) + + # check error reporting output when stdout/stderr are collected separately + try: + run_shell_cmd(cmd, split_stderr=True) + self.assertFalse("This should never be reached, RunShellCmdError should occur!") + except RunShellCmdError as err: + self.assertEqual(str(err), "Shell command 'kill' failed!") + self.assertEqual(err.cmd, "kill -9 $$") + self.assertEqual(err.cmd_name, 'kill') + self.assertEqual(err.exit_code, -9) + self.assertEqual(err.work_dir, work_dir) + self.assertEqual(err.output, '') + self.assertEqual(err.stderr, '') + self.assertTrue(isinstance(err.caller_info, tuple)) + self.assertEqual(len(err.caller_info), 3) + self.assertEqual(err.caller_info[0], __file__) + self.assertTrue(isinstance(err.caller_info[1], int)) # line number of calling site + self.assertEqual(err.caller_info[2], 'test_run_shell_cmd_fail') + + with self.mocked_stdout_stderr() as (_, stderr): + err.print() + + # check error reporting output + stderr = stderr.getvalue() + patterns = [ + r"^ERROR: Shell command failed!", + r"^\s+full command\s+ -> kill -9 \$\$", + r"^\s+exit code\s+ -> -9", + r"^\s+working directory\s+ -> " + work_dir, + r"^\s+called from\s+ -> 'test_run_shell_cmd_fail' function in .*/test/.*/run.py \(line [0-9]+\)", + r"^\s+output \(stdout\)\s+ -> .*/shell-cmd-error-.*/kill.out", + r"^\s+error/warnings \(stderr\)\s+ -> .*/shell-cmd-error-.*/kill.err", + ] + for pattern in patterns: + regex = re.compile(pattern, re.M) + self.assertTrue(regex.search(stderr), "Pattern '%s' should be found in: %s" % (pattern, stderr)) + + # no error reporting when fail_on_error is disabled + with self.mocked_stdout_stderr() as (_, stderr): + res = run_shell_cmd(cmd, fail_on_error=False) self.assertEqual(res.exit_code, -9) + self.assertEqual(stderr.getvalue(), '') finally: # cleanup: disable the alarm + reset signal handler for SIGALRM @@ -825,7 +908,8 @@ def test_run_shell_cmd_cache(self): # inject value into cache to check whether executing command again really returns cached value with self.mocked_stdout_stderr(): - cached_res = RunResult(cmd=cmd, output="123456", exit_code=123, stderr=None, work_dir='/test_ulimit') + cached_res = RunShellCmdResult(cmd=cmd, output="123456", exit_code=123, stderr=None, + work_dir='/test_ulimit') run_shell_cmd.update_cache({(cmd, None): cached_res}) res = run_shell_cmd(cmd) self.assertEqual(res.cmd, cmd) @@ -843,7 +927,7 @@ def test_run_shell_cmd_cache(self): # inject different output for cat with 'foo' as stdin to check whether cached value is used with self.mocked_stdout_stderr(): - cached_res = RunResult(cmd=cmd, output="bar", exit_code=123, stderr=None, work_dir='/test_cat') + cached_res = RunShellCmdResult(cmd=cmd, output="bar", exit_code=123, stderr=None, work_dir='/test_cat') run_shell_cmd.update_cache({(cmd, 'foo'): cached_res}) res = run_shell_cmd(cmd, stdin='foo') self.assertEqual(res.cmd, cmd) diff --git a/test/framework/systemtools.py b/test/framework/systemtools.py index c86427326a..63bcfffe2e 100644 --- a/test/framework/systemtools.py +++ b/test/framework/systemtools.py @@ -40,7 +40,7 @@ import easybuild.tools.systemtools as st from easybuild.tools.build_log import EasyBuildError from easybuild.tools.filetools import adjust_permissions, read_file, symlink, which, write_file -from easybuild.tools.run import RunResult, run_shell_cmd +from easybuild.tools.run import RunShellCmdResult, run_shell_cmd from easybuild.tools.systemtools import CPU_ARCHITECTURES, AARCH32, AARCH64, POWER, X86_64 from easybuild.tools.systemtools import CPU_FAMILIES, POWER_LE, DARWIN, LINUX, UNKNOWN from easybuild.tools.systemtools import CPU_VENDORS, AMD, APM, ARM, CAVIUM, IBM, INTEL @@ -340,7 +340,7 @@ def mocked_run_shell_cmd(cmd, **kwargs): "ulimit -u": '40', } if cmd in known_cmds: - return RunResult(cmd=cmd, exit_code=0, output=known_cmds[cmd], stderr=None, work_dir=os.getcwd()) + return RunShellCmdResult(cmd=cmd, exit_code=0, output=known_cmds[cmd], stderr=None, work_dir=os.getcwd()) else: return run_shell_cmd(cmd, **kwargs) @@ -774,7 +774,8 @@ def test_gcc_version_darwin(self): """Test getting gcc version (mocked for Darwin).""" st.get_os_type = lambda: st.DARWIN out = "Apple LLVM version 7.0.0 (clang-700.1.76)" - mocked_run_res = RunResult(cmd="gcc --version", exit_code=0, output=out, stderr=None, work_dir=os.getcwd()) + cwd = os.getcwd() + mocked_run_res = RunShellCmdResult(cmd="gcc --version", exit_code=0, output=out, stderr=None, work_dir=cwd) st.run_shell_cmd = lambda *args, **kwargs: mocked_run_res self.assertEqual(get_gcc_version(), None) diff --git a/test/framework/toy_build.py b/test/framework/toy_build.py index 2c4bef191c..74a467175b 100644 --- a/test/framework/toy_build.py +++ b/test/framework/toy_build.py @@ -42,7 +42,7 @@ import textwrap from easybuild.tools import LooseVersion from importlib import reload -from test.framework.utilities import EnhancedTestCase, TestLoaderFiltered +from test.framework.utilities import EnhancedTestCase, TestLoaderFiltered, cleanup from test.framework.package import mock_fpm from unittest import TextTestRunner @@ -50,6 +50,7 @@ import easybuild.tools.module_naming_scheme # required to dynamically load test module naming scheme(s) from easybuild.framework.easyconfig.easyconfig import EasyConfig from easybuild.framework.easyconfig.parser import EasyConfigParser +from easybuild.main import main_with_hooks from easybuild.tools.build_log import EasyBuildError from easybuild.tools.config import get_module_syntax, get_repositorypath from easybuild.tools.environment import modify_env @@ -373,8 +374,8 @@ def test_toy_buggy_easyblock(self): 'verify': False, 'verbose': False, } - err_regex = r"Traceback[\S\s]*toy_buggy.py.*build_step[\S\s]*name 'run_cmd' is not defined" - self.assertErrorRegex(EasyBuildError, err_regex, self.run_test_toy_build_with_output, **kwargs) + err_regex = r"name 'run_cmd' is not defined" + self.assertErrorRegex(NameError, err_regex, self.run_test_toy_build_with_output, **kwargs) def test_toy_build_formatv2(self): """Perform a toy build (format v2).""" @@ -1434,7 +1435,7 @@ def test_toy_extension_extract_cmd(self): ]) write_file(test_ec, test_ec_txt) - error_pattern = "unzip .*/bar-0.0.tar.gz.* returned non-zero exit status" + error_pattern = r"shell command 'unzip \.\.\.' failed in extensions step for test.eb" with self.mocked_stdout_stderr(): # for now, we expect subprocess.CalledProcessError, but eventually 'run' function will # do proper error reporting @@ -2641,7 +2642,7 @@ def test_toy_build_enhanced_sanity_check(self): test_ec_txt = test_ec_txt + '\nenhance_sanity_check = False' write_file(test_ec, test_ec_txt) - error_pattern = r" Missing mandatory key 'dirs' in sanity_check_paths." + error_pattern = r"Missing mandatory key 'dirs' in sanity_check_paths." with self.mocked_stdout_stderr(): self.assertErrorRegex(EasyBuildError, error_pattern, self._test_toy_build, ec_file=test_ec, extra_args=eb_args, raise_error=True, verbose=False) @@ -4068,6 +4069,41 @@ def test_toy_build_info_msg(self): regex = re.compile(pattern, re.M) self.assertTrue(regex.search(stdout), "Pattern '%s' should be found in: %s" % (regex.pattern, stdout)) + def test_eb_crash(self): + """ + Test behaviour when EasyBuild crashes, for example due to a buggy hook + """ + hooks_file = os.path.join(self.test_prefix, 'my_hooks.py') + hooks_file_txt = textwrap.dedent(""" + def pre_configure_hook(self, *args, **kwargs): + no_such_thing + """) + write_file(hooks_file, hooks_file_txt) + + topdir = os.path.dirname(os.path.dirname(os.path.dirname(__file__))) + toy_eb = os.path.join(topdir, 'test', 'framework', 'sandbox', 'easybuild', 'easyblocks', 't', 'toy.py') + toy_ec = os.path.join(topdir, 'test', 'framework', 'easyconfigs', 'test_ecs', 't', 'toy', 'toy-0.0.eb') + + args = [ + toy_ec, + f'--hooks={hooks_file}', + '--force', + f'--installpath={self.test_prefix}', + f'--include-easyblocks={toy_eb}', + ] + + with self.mocked_stdout_stderr() as (_, stderr): + cleanup() + try: + main_with_hooks(args=args) + self.assertFalse("This should never be reached, main function should have crashed!") + except NameError as err: + self.assertEqual(str(err), "name 'no_such_thing' is not defined") + + regex = re.compile(r"EasyBuild crashed! Please consider reporting a bug, this should not happen") + stderr = stderr.getvalue() + self.assertTrue(regex.search(stderr), f"Pattern '{regex.pattern}' should be found in {stderr}") + def suite(): """ return all the tests in this file """