Skip to content

Commit

Permalink
separate raising of RunShellCmdError from printing info on failed she…
Browse files Browse the repository at this point in the history 
…ll command, log command output before log message that mentions success of failure for command
  • Loading branch information
@boegel
boegel committed Oct 7, 2023
1 parent 2119ff4 commit df3b72c
Show file tree
Hide file tree
Showing 2 changed files with 148 additions and 71 deletions.
112 changes: 73 additions & 39 deletions easybuild/tools/run.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand All @@ -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):
Expand Down Expand Up @@ -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 = {
Expand All @@ -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}")
Expand Down
107 changes: 75 additions & 32 deletions test/framework/run.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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


Expand Down Expand Up @@ -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:
Expand All @@ -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):
Expand Down

0 comments on commit df3b72c

Please sign in to comment.