separate raising of RunShellCmdError from printing info on failed shell command, log command output before log message that mentions success of failure for command

Author: boegel

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}")

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):