From 46c686fd010e1f941097297b9ae2a0ee4644461b Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 15:53:12 +0200 Subject: [PATCH 01/12] let run_shell_cmd produce error report when shell command failed --- easybuild/tools/run.py | 59 ++++++++++++++++++++++++++++++++++++++++-- test/framework/run.py | 44 ++++++++++++++++++++++++++++--- 2 files changed, 98 insertions(+), 5 deletions(-) diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index 85b79a7868..4a08220484 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 @@ -49,7 +50,8 @@ import easybuild.tools.asyncprocess as asyncprocess from easybuild.base import fancylogger -from easybuild.tools.build_log import EasyBuildError, dry_run_msg, print_msg, time_str_since +from easybuild.base.exceptions import LoggedException +from easybuild.tools.build_log import EasyBuildError, dry_run_msg, print_error, print_msg, time_str_since from easybuild.tools.config import ERROR, IGNORE, WARN, build_option from easybuild.tools.hooks import RUN_SHELL_CMD, load_hooks, run_hook from easybuild.tools.utilities import trace_msg @@ -78,6 +80,56 @@ RunResult = namedtuple('RunResult', ('cmd', 'exit_code', 'output', 'stderr', 'work_dir')) +def report_run_shell_cmd_error(cmd, exit_code, work_dir, output, stderr): + """ + Report error that occurred when running a shell command. + """ + cmd_name = cmd.split(' ')[0] + + tmpdir = tempfile.mkdtemp(prefix='shell-cmd-error-') + output_fp = os.path.join(tmpdir, f"{cmd_name}.out") + with open(output_fp, 'w') as fp: + fp.write(output or '') + stderr_fp = os.path.join(tmpdir, f"{cmd_name}.err") + with open(stderr_fp, 'w') as fp: + fp.write(stderr or '') + + # 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_file_name = frameinfo.filename + caller_line_nr = frameinfo.lineno + caller_function_name = frameinfo.function + + error_info = [ + f"| full shell command | {cmd}", + f"| exit code | {exit_code}", + f"| working directory | {work_dir}", + ] + if stderr is None: + error_info.append(f"| output (stdout + stderr) | {output_fp}") + else: + error_info.extend([ + f"| output (stdout) | {output_fp}", + f"| error/warnings (stderr) | {stderr_fp}", + ]) + + called_from_info = f"{caller_function_name} function in {caller_file_name} (line {caller_line_nr})" + error_info.append(f"| called from | {called_from_info}") + + error_msg = '\n'.join([''] + error_info + [ + '', + f"ERROR: shell command '{cmd_name}' failed!", + '', + ]) + sys.stderr.write(error_msg) + sys.exit(exit_code) + + def run_cmd_cache(func): """Function decorator to cache (and retrieve cached) results of running commands.""" cache = {} @@ -204,7 +256,7 @@ 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) @@ -213,6 +265,9 @@ def to_cmd_str(cmd): res = RunResult(cmd=cmd_str, exit_code=proc.returncode, output=output, stderr=stderr_output, work_dir=work_dir) + if res.exit_code != 0 and fail_on_error: + report_run_shell_cmd_error(res.cmd, res.exit_code, res.work_dir, output=res.output, stderr=res.stderr) + if with_hooks: run_hook_kwargs = { 'exit_code': res.exit_code, diff --git a/test/framework/run.py b/test/framework/run.py index 4d6974bb04..0ae3b23396 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -49,7 +49,7 @@ 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.filetools import adjust_permissions, change_dir, 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.config import ERROR, IGNORE, WARN @@ -317,9 +317,47 @@ 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 $$" + + workdir = os.path.realpath(self.test_prefix) + change_dir(workdir) + + with self.mocked_stdout_stderr() as (_, stderr): + self.assertErrorRegex(SystemExit, '.*', run_shell_cmd, cmd) + + # check error reporting output + stderr = stderr.getvalue() + patterns = [ + r"^\| full shell command[ ]*\| kill -9 \$\$", + r"^\| exit code[ ]*\| -9", + r"^\| working directory[ ]*\| " + workdir, + r"^\| called from[ ]*\| assertErrorRegex function in .*/easybuild/base/testing.py \(line [0-9]+\)", + r"^ERROR: shell command 'kill' failed!", + r"^\| output \(stdout \+ stderr\)[ ]*\| .*/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" % (regex.pattern, stderr)) + + # check error reporting output when stdout/stderr are collected separately + with self.mocked_stdout_stderr() as (_, stderr): + self.assertErrorRegex(SystemExit, '.*', run_shell_cmd, cmd, split_stderr=True) + stderr = stderr.getvalue() + patterns.pop(-1) + patterns.extend([ + r"^\| output \(stdout\)[ ]*\| .*/shell-cmd-error-.*/kill.out", + r"^\| error/warnings \(stderr\)[ ]*\| .*/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" % (regex.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 From 07c85f289eb9151e901707ff9164f1486a373de3 Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 16:43:44 +0200 Subject: [PATCH 02/12] rename RunResult to RunShellCmdResult --- easybuild/tools/run.py | 8 ++++---- test/framework/run.py | 10 ++++++---- test/framework/systemtools.py | 7 ++++--- 3 files changed, 14 insertions(+), 11 deletions(-) diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index 4a08220484..b48e6a8a89 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -77,7 +77,7 @@ ] -RunResult = namedtuple('RunResult', ('cmd', 'exit_code', 'output', 'stderr', 'work_dir')) +RunShellCmdResult = namedtuple('RunShellCmdResult', ('cmd', 'exit_code', 'output', 'stderr', 'work_dir')) def report_run_shell_cmd_error(cmd, exit_code, work_dir, output, stderr): @@ -230,7 +230,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: @@ -261,9 +261,9 @@ def to_cmd_str(cmd): # 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 = RunResult(cmd=cmd_str, exit_code=proc.returncode, output=output, stderr=stderr_output, work_dir=work_dir) + res = RunShellCmdResult(cmd=cmd_str, exit_code=proc.returncode, output=output, stderr=stderr, work_dir=work_dir) if res.exit_code != 0 and fail_on_error: report_run_shell_cmd_error(res.cmd, res.exit_code, res.work_dir, output=res.output, stderr=res.stderr) diff --git a/test/framework/run.py b/test/framework/run.py index 0ae3b23396..609f74ebcc 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -50,8 +50,9 @@ 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, change_dir, 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.run import RunShellCmdResult, check_async_cmd, check_log_for_errors, complete_cmd +from easybuild.tools.run import get_output_from_process, parse_log_for_error, run_shell_cmd, run_cmd, run_cmd_qa +from easybuild.tools.run import subprocess_terminate from easybuild.tools.config import ERROR, IGNORE, WARN @@ -863,7 +864,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) @@ -881,7 +883,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) From 2119ff4bc393f32388494ec5f09f168766dc09be Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 18:04:15 +0200 Subject: [PATCH 03/12] separate EasyBuild crashes (unexpected exception being raised) from EasyBuildError being raised, add crash hook, improve general error reporting --- easybuild/main.py | 19 ++++++++++++------- easybuild/tools/build_log.py | 2 +- easybuild/tools/hooks.py | 2 ++ test/framework/build_log.py | 8 ++++---- test/framework/options.py | 1 + 5 files changed, 20 insertions(+), 12 deletions(-) diff --git a/easybuild/main.py b/easybuild/main.py index d6d5755e9a..ff94cf0aec 100644 --- a/easybuild/main.py +++ b/easybuild/main.py @@ -70,13 +70,14 @@ 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 from easybuild.tools.output import COLOR_GREEN, COLOR_RED, STATUS_BAR, colorize, print_checks, rich_live_cm from easybuild.tools.output import start_progress_bar, stop_progress_bar, update_progress_bar from easybuild.tools.robot import check_conflicts, dry_run, missing_deps, resolve_dependencies, search_easyconfigs +from easybuild.tools.run import RunShellCmdError from easybuild.tools.package.utilities import check_pkg_support from easybuild.tools.parallelbuild import submit_jobs from easybuild.tools.repository.repository import init_repository @@ -149,11 +150,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 +170,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) @@ -754,7 +755,11 @@ def prepare_main(args=None, logfile=None, testing=None): main(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 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/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/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", From df3b72c53eb55e7b8b977bd8cac14ddc17cb3596 Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 18:34:18 +0200 Subject: [PATCH 04/12] separate raising of RunShellCmdError from printing info on failed shell command, log command output before log message that mentions success of failure for command --- easybuild/tools/run.py | 112 +++++++++++++++++++++++++++-------------- test/framework/run.py | 107 +++++++++++++++++++++++++++------------ 2 files changed, 148 insertions(+), 71 deletions(-) diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index b48e6a8a89..fb31e9db35 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -80,19 +80,69 @@ RunShellCmdResult = namedtuple('RunShellCmdResult', ('cmd', 'exit_code', 'output', 'stderr', 'work_dir')) -def report_run_shell_cmd_error(cmd, exit_code, work_dir, output, stderr): +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_run_shell_cmd_error(err): """ - Report error that occurred when running a shell command. + Report failed shell command using provided RunShellCmdError instance """ - cmd_name = cmd.split(' ')[0] + + def pad_4_spaces(msg): + return ' ' * 4 + msg + + cmd_name = err.cmd.split(' ')[0] + error_info = [ + '', + f"ERROR: Shell command failed!", + pad_4_spaces(f"full command -> {err.cmd}"), + pad_4_spaces(f"exit code -> {err.exit_code}"), + pad_4_spaces(f"working directory -> {err.work_dir}"), + ] tmpdir = tempfile.mkdtemp(prefix='shell-cmd-error-') output_fp = os.path.join(tmpdir, f"{cmd_name}.out") with open(output_fp, 'w') as fp: - fp.write(output or '') - stderr_fp = os.path.join(tmpdir, f"{cmd_name}.err") - with open(stderr_fp, 'w') as fp: - fp.write(stderr or '') + fp.write(err.output or '') + + if err.stderr is None: + error_info.append(pad_4_spaces(f"output (stdout + stderr) -> {output_fp}")) + else: + stderr_fp = os.path.join(tmpdir, f"{cmd_name}.err") + with open(stderr_fp, 'w') as fp: + fp.write(err.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 = err.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: @@ -104,30 +154,9 @@ def report_run_shell_cmd_error(cmd, exit_code, work_dir, output, stderr): caller_file_name = frameinfo.filename caller_line_nr = frameinfo.lineno caller_function_name = frameinfo.function + caller_info = (frameinfo.filename, frameinfo.lineno, frameinfo.function) - error_info = [ - f"| full shell command | {cmd}", - f"| exit code | {exit_code}", - f"| working directory | {work_dir}", - ] - if stderr is None: - error_info.append(f"| output (stdout + stderr) | {output_fp}") - else: - error_info.extend([ - f"| output (stdout) | {output_fp}", - f"| error/warnings (stderr) | {stderr_fp}", - ]) - - called_from_info = f"{caller_function_name} function in {caller_file_name} (line {caller_line_nr})" - error_info.append(f"| called from | {called_from_info}") - - error_msg = '\n'.join([''] + error_info + [ - '', - f"ERROR: shell command '{cmd_name}' failed!", - '', - ]) - sys.stderr.write(error_msg) - sys.exit(exit_code) + raise RunShellCmdError(cmd, exit_code, work_dir, output, stderr, caller_info) def run_cmd_cache(func): @@ -265,8 +294,20 @@ def to_cmd_str(cmd): res = RunShellCmdResult(cmd=cmd_str, exit_code=proc.returncode, output=output, stderr=stderr, work_dir=work_dir) - if res.exit_code != 0 and fail_on_error: - report_run_shell_cmd_error(res.cmd, res.exit_code, res.work_dir, output=res.output, stderr=res.stderr) + # 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 = { @@ -277,13 +318,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/run.py b/test/framework/run.py index 609f74ebcc..0e4de57cf7 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -50,9 +50,9 @@ 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, change_dir, mkdir, read_file, write_file -from easybuild.tools.run import RunShellCmdResult, check_async_cmd, check_log_for_errors, complete_cmd -from easybuild.tools.run import get_output_from_process, parse_log_for_error, run_shell_cmd, run_cmd, run_cmd_qa -from easybuild.tools.run import subprocess_terminate +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 print_run_shell_cmd_error, run_cmd, run_cmd_qa, run_shell_cmd, subprocess_terminate from easybuild.tools.config import ERROR, IGNORE, WARN @@ -311,6 +311,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: @@ -321,38 +324,78 @@ def handler(signum, _): # command to kill parent shell cmd = "kill -9 $$" - workdir = os.path.realpath(self.test_prefix) - change_dir(workdir) + work_dir = os.path.realpath(self.test_prefix) + change_dir(work_dir) - with self.mocked_stdout_stderr() as (_, stderr): - self.assertErrorRegex(SystemExit, '.*', run_shell_cmd, cmd) - - # check error reporting output - stderr = stderr.getvalue() - patterns = [ - r"^\| full shell command[ ]*\| kill -9 \$\$", - r"^\| exit code[ ]*\| -9", - r"^\| working directory[ ]*\| " + workdir, - r"^\| called from[ ]*\| assertErrorRegex function in .*/easybuild/base/testing.py \(line [0-9]+\)", - r"^ERROR: shell command 'kill' failed!", - r"^\| output \(stdout \+ stderr\)[ ]*\| .*/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" % (regex.pattern, stderr)) + 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): + print_run_shell_cmd_error(err) + + # 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 - with self.mocked_stdout_stderr() as (_, stderr): - self.assertErrorRegex(SystemExit, '.*', run_shell_cmd, cmd, split_stderr=True) - stderr = stderr.getvalue() - patterns.pop(-1) - patterns.extend([ - r"^\| output \(stdout\)[ ]*\| .*/shell-cmd-error-.*/kill.out", - r"^\| error/warnings \(stderr\)[ ]*\| .*/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" % (regex.pattern, stderr)) + 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): + print_run_shell_cmd_error(err) + + # 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): From 0b7f3514e1e12cf30285a32b2ab2a150934082f7 Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 18:35:13 +0200 Subject: [PATCH 05/12] catch RunShellCmdError in EasyBlock.run_all_steps to do more meaningful error reporting incl. step name and easyconfig filename --- easybuild/framework/easyblock.py | 21 ++++++++++----------- 1 file changed, 10 insertions(+), 11 deletions(-) diff --git a/easybuild/framework/easyblock.py b/easybuild/framework/easyblock.py index e86d475f64..79d32ff20a 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, print_run_shell_cmd_error, 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: + print_run_shell_cmd_error(err) + 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): From ce34aae3e45bd0dafeaf7c8bcf970d7683698d17 Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 19:41:04 +0200 Subject: [PATCH 06/12] make hooks tests aware of crash hook --- test/framework/hooks.py | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) 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) From 9d716d9bb7e44f3353d16cb70d1949cb9b795ee6 Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 19:41:37 +0200 Subject: [PATCH 07/12] add test that cover EasyBuild crashing --- easybuild/main.py | 10 +++++++--- test/framework/toy_build.py | 40 +++++++++++++++++++++++++++++++++++-- 2 files changed, 45 insertions(+), 5 deletions(-) diff --git a/easybuild/main.py b/easybuild/main.py index ff94cf0aec..98f76b9cd1 100644 --- a/easybuild/main.py +++ b/easybuild/main.py @@ -748,11 +748,11 @@ 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]) sys.exit(1) @@ -763,3 +763,7 @@ def prepare_main(args=None, logfile=None, testing=None): 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/test/framework/toy_build.py b/test/framework/toy_build.py index 2c4bef191c..5b83b98a62 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 @@ -57,7 +58,7 @@ from easybuild.tools.filetools import read_file, remove_dir, remove_file, which, write_file from easybuild.tools.module_generator import ModuleGeneratorTcl from easybuild.tools.modules import Lmod -from easybuild.tools.run import run_cmd +from easybuild.tools.run import RunShellCmdError, run_cmd, run_shell_cmd from easybuild.tools.utilities import nub from easybuild.tools.systemtools import get_shared_lib_ext from easybuild.tools.version import VERSION as EASYBUILD_VERSION @@ -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}', + f'--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 """ From 7d2d5379cdfbbd17e7d5fc7c69299920df23ac05 Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 19:45:00 +0200 Subject: [PATCH 08/12] fix unused imports + trivial code style issues in main.py and tools/run.py --- easybuild/main.py | 1 - easybuild/tools/run.py | 8 ++------ 2 files changed, 2 insertions(+), 7 deletions(-) diff --git a/easybuild/main.py b/easybuild/main.py index 98f76b9cd1..0f2c69733c 100644 --- a/easybuild/main.py +++ b/easybuild/main.py @@ -77,7 +77,6 @@ from easybuild.tools.output import COLOR_GREEN, COLOR_RED, STATUS_BAR, colorize, print_checks, rich_live_cm from easybuild.tools.output import start_progress_bar, stop_progress_bar, update_progress_bar from easybuild.tools.robot import check_conflicts, dry_run, missing_deps, resolve_dependencies, search_easyconfigs -from easybuild.tools.run import RunShellCmdError from easybuild.tools.package.utilities import check_pkg_support from easybuild.tools.parallelbuild import submit_jobs from easybuild.tools.repository.repository import init_repository diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index fb31e9db35..9ab09ade64 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -50,8 +50,7 @@ import easybuild.tools.asyncprocess as asyncprocess from easybuild.base import fancylogger -from easybuild.base.exceptions import LoggedException -from easybuild.tools.build_log import EasyBuildError, dry_run_msg, print_error, print_msg, time_str_since +from easybuild.tools.build_log import EasyBuildError, dry_run_msg, print_msg, time_str_since from easybuild.tools.config import ERROR, IGNORE, WARN, build_option from easybuild.tools.hooks import RUN_SHELL_CMD, load_hooks, run_hook from easybuild.tools.utilities import trace_msg @@ -151,9 +150,6 @@ def raise_run_shell_cmd_error(cmd, exit_code, work_dir, output, stderr): # 3) run_cmd_cache decorator # 4) actual caller site frameinfo = inspect.getouterframes(inspect.currentframe())[3] - caller_file_name = frameinfo.filename - caller_line_nr = frameinfo.lineno - caller_function_name = frameinfo.function caller_info = (frameinfo.filename, frameinfo.lineno, frameinfo.function) raise RunShellCmdError(cmd, exit_code, work_dir, output, stderr, caller_info) @@ -290,7 +286,7 @@ def to_cmd_str(cmd): # 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= 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) From eb768a1f54de6081bdf8a20e2cf1b56f03cf7380 Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 19:52:57 +0200 Subject: [PATCH 09/12] fix broken tests due to changes in error handling --- test/framework/run.py | 7 ++++--- test/framework/toy_build.py | 8 ++++---- 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/test/framework/run.py b/test/framework/run.py index 0e4de57cf7..529dbb7de1 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -249,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("Shell command completed successfully \(see output above\): echo hello") # command output is always logged init_logging(logfile, silent=True) @@ -258,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 diff --git a/test/framework/toy_build.py b/test/framework/toy_build.py index 5b83b98a62..d77c9ebf11 100644 --- a/test/framework/toy_build.py +++ b/test/framework/toy_build.py @@ -374,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).""" @@ -1435,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 @@ -2642,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) From 219be7ce1902b4ce4b55a821617c525f7b291f82 Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 19:57:44 +0200 Subject: [PATCH 10/12] fix faulty imports in toy_build test module --- test/framework/run.py | 2 +- test/framework/toy_build.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/test/framework/run.py b/test/framework/run.py index 529dbb7de1..3efa53debe 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -249,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("Shell command completed successfully \(see output above\): echo hello") + 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) diff --git a/test/framework/toy_build.py b/test/framework/toy_build.py index d77c9ebf11..d2291d9625 100644 --- a/test/framework/toy_build.py +++ b/test/framework/toy_build.py @@ -58,7 +58,7 @@ from easybuild.tools.filetools import read_file, remove_dir, remove_file, which, write_file from easybuild.tools.module_generator import ModuleGeneratorTcl from easybuild.tools.modules import Lmod -from easybuild.tools.run import RunShellCmdError, run_cmd, run_shell_cmd +from easybuild.tools.run import run_cmd from easybuild.tools.utilities import nub from easybuild.tools.systemtools import get_shared_lib_ext from easybuild.tools.version import VERSION as EASYBUILD_VERSION From 9ab36ed097f540195cc7241d10404d45e1130fd5 Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Sat, 7 Oct 2023 20:12:36 +0200 Subject: [PATCH 11/12] don't use f-strings without a placeholder --- easybuild/tools/run.py | 2 +- test/framework/toy_build.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index 9ab09ade64..90699e8a96 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -106,7 +106,7 @@ def pad_4_spaces(msg): cmd_name = err.cmd.split(' ')[0] error_info = [ '', - f"ERROR: Shell command failed!", + "ERROR: Shell command failed!", pad_4_spaces(f"full command -> {err.cmd}"), pad_4_spaces(f"exit code -> {err.exit_code}"), pad_4_spaces(f"working directory -> {err.work_dir}"), diff --git a/test/framework/toy_build.py b/test/framework/toy_build.py index d2291d9625..74a467175b 100644 --- a/test/framework/toy_build.py +++ b/test/framework/toy_build.py @@ -4087,7 +4087,7 @@ def pre_configure_hook(self, *args, **kwargs): args = [ toy_ec, f'--hooks={hooks_file}', - f'--force', + '--force', f'--installpath={self.test_prefix}', f'--include-easyblocks={toy_eb}', ] From ece71c2b1cfe2264fad792269aab9d16dfe1c7f6 Mon Sep 17 00:00:00 2001 From: Kenneth Hoste Date: Mon, 16 Oct 2023 09:32:30 +0200 Subject: [PATCH 12/12] collapse print_run_shell_cmd_error into RunShellCmdError as print method --- easybuild/framework/easyblock.py | 4 +- easybuild/tools/run.py | 68 ++++++++++++++++---------------- test/framework/run.py | 6 +-- 3 files changed, 38 insertions(+), 40 deletions(-) diff --git a/easybuild/framework/easyblock.py b/easybuild/framework/easyblock.py index 79d32ff20a..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 RunShellCmdError, check_async_cmd, print_run_shell_cmd_error, 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 @@ -4125,7 +4125,7 @@ def run_all_steps(self, run_test_cases): try: self.run_step(step_name, step_methods) except RunShellCmdError as err: - print_run_shell_cmd_error(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) diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index 90699e8a96..e43edbe7cf 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -94,48 +94,46 @@ def __init__(self, cmd, exit_code, work_dir, output, stderr, caller_info, *args, 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 print_run_shell_cmd_error(err): - """ - Report failed shell command using provided RunShellCmdError instance - """ + def pad_4_spaces(msg): + return ' ' * 4 + msg - 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}"), + ] - cmd_name = err.cmd.split(' ')[0] - error_info = [ - '', - "ERROR: Shell command failed!", - pad_4_spaces(f"full command -> {err.cmd}"), - pad_4_spaces(f"exit code -> {err.exit_code}"), - pad_4_spaces(f"working directory -> {err.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 '') - tmpdir = tempfile.mkdtemp(prefix='shell-cmd-error-') - output_fp = os.path.join(tmpdir, f"{cmd_name}.out") - with open(output_fp, 'w') as fp: - fp.write(err.output or '') - - if err.stderr is None: - error_info.append(pad_4_spaces(f"output (stdout + stderr) -> {output_fp}")) - else: - stderr_fp = os.path.join(tmpdir, f"{cmd_name}.err") - with open(stderr_fp, 'w') as fp: - fp.write(err.stderr) + 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"output (stdout) -> {output_fp}"), - pad_4_spaces(f"error/warnings (stderr) -> {stderr_fp}"), + pad_4_spaces(f"called from -> {called_from_info}"), + '', ]) - caller_file_name, caller_line_nr, caller_function_name = err.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') + sys.stderr.write('\n'.join(error_info) + '\n') def raise_run_shell_cmd_error(cmd, exit_code, work_dir, output, stderr): diff --git a/test/framework/run.py b/test/framework/run.py index 3efa53debe..5bce2d20f1 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -52,7 +52,7 @@ 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 print_run_shell_cmd_error, run_cmd, run_cmd_qa, run_shell_cmd, subprocess_terminate +from easybuild.tools.run import run_cmd, run_cmd_qa, run_shell_cmd, subprocess_terminate from easybuild.tools.config import ERROR, IGNORE, WARN @@ -346,7 +346,7 @@ def handler(signum, _): self.assertEqual(err.caller_info[2], 'test_run_shell_cmd_fail') with self.mocked_stdout_stderr() as (_, stderr): - print_run_shell_cmd_error(err) + err.print() # check error reporting output stderr = stderr.getvalue() @@ -381,7 +381,7 @@ def handler(signum, _): self.assertEqual(err.caller_info[2], 'test_run_shell_cmd_fail') with self.mocked_stdout_stderr() as (_, stderr): - print_run_shell_cmd_error(err) + err.print() # check error reporting output stderr = stderr.getvalue()