initial implementation of run function to replace run_cmd + run_cmd_qa

easybuild/tools/run.py

@@ -44,6 +44,7 @@
 import sys
 import tempfile
 import time
+from collections import namedtuple
 from datetime import datetime
 
 import easybuild.tools.asyncprocess as asyncprocess
@@ -73,6 +74,105 @@
 ]
 
 
+RunResult = namedtuple('RunResult', ('output', 'exit_code', 'stderr'))
+
+
+def run(cmd, fail_on_error=True, split_stderr=False, stdin=None,
+        hidden=False, in_dry_run=False, work_dir=None, shell=True,
+        output_file=False, stream_output=False, asynchronous=False,
+        qa_patterns=None, qa_wait_patterns=None):
+    """
+    Run specified (interactive) shell command, and capture output + exit code.
+
+    :param fail_on_error: fail on non-zero exit code (enabled by default)
+    :param split_stderr: split of stderr from stdout output
+    :param stdin: input to be sent to stdin (nothing if set to None)
+    :param hidden: do not show command in terminal output (when using --trace, or with --extended-dry-run / -x)
+    :param in_dry_run: also run command in dry run mode
+    :param work_dir: working directory to run command in (current working directory if None)
+    :param shell: execute command through a shell (enabled by default)
+    :param output_file: collect command output in temporary output file
+    :param stream_output: stream command output to stdout
+    :param asynchronous: run command asynchronously
+    :param qa_patterns: list of 2-tuples with patterns for questions + corresponding answers
+    :param qa_wait_patterns: list of 2-tuples with patterns for non-questions
+                             and number of iterations to allow these patterns to match with end out command output
+    :return: Named tuple with:
+    - output: command output, stdout+stderr combined if split_stderr is disabled, only stdout otherwise
+    - exit_code: exit code of command (integer)
+    - stderr: stderr output if split_stderr is enabled, None otherwise
+    """
+
+    # temporarily raise a NotImplementedError until all options are implemented
+    if any((not fail_on_error, split_stderr, stdin, in_dry_run, work_dir, output_file, stream_output, asynchronous)):
+        raise NotImplementedError
+
+    if qa_patterns or qa_wait_patterns:
+        raise NotImplementedError
+
+    if isinstance(cmd, str):
+        cmd_msg = cmd.strip()
+    elif isinstance(cmd, list):
+        cmd_msg = ' '.join(cmd)
+    else:
+        raise EasyBuildError(f"Unknown command type ('{type(cmd)}'): {cmd}")
+
+    silent = build_option('silent')
+
+    if work_dir is None:
+        work_dir = os.getcwd()
+
+    # output file for command output (only used if output_file is enabled)
+    cmd_out_fp = None
+
+    # early exit in 'dry run' mode, after printing the command that would be run (unless 'hidden' is enabled)
+    if build_option('extended_dry_run'):
+        if not hidden:
+            msg = f"  running command \"%{cmd_msg}s\"\n"
+            msg += f"  (in %{work_dir})"
+            dry_run_msg(msg, silent=silent)
+
+        return RunResult(output='', exit_code=0, stderr=None)
+
+    start_time = datetime.now()
+    if not hidden:
+        cmd_trace_msg(cmd_msg, start_time, work_dir, stdin, cmd_out_fp)
+
+    _log.info(f"Running command '{cmd_msg}' in {work_dir}")
+    proc = subprocess.run(cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, shell=shell)
+
+    # return output as a regular string (UTF-8 characters get stripped out)
+    output = proc.stdout.decode('ascii', 'ignore')
+
+    res = RunResult(output=output, exit_code=proc.returncode, stderr=None)
+    _log.info(f"Command '{cmd_msg}' exited with exit code {res.exit_code} and output:\n%{res.output}")
+
+    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}")
+
+    return res
+
+
+def cmd_trace_msg(cmd, start_time, work_dir, stdin, cmd_out_fp):
+    """
+    Helper function to construct and print trace message for command being run
+    """
+    lines = [
+        "running command:",
+        "\t[started at: %s]" % start_time.strftime('%Y-%m-%d %H:%M:%S'),
+        "\t[working dir: %s]" % work_dir,
+    ]
+    if stdin:
+        lines.append("\t[input: %s]" % stdin)
+    if cmd_out_fp:
+        lines.append("\t[output logged in %s]" % cmd_out_fp)
+
+    lines.append('\t' + cmd)
+
+    trace_msg('\n'.join(lines))
+
+
 def run_cmd_cache(func):
     """Function decorator to cache (and retrieve cached) results of running commands."""
     cache = {}

test/framework/run.py

@@ -47,9 +47,9 @@
 import easybuild.tools.asyncprocess as asyncprocess
 import easybuild.tools.utilities
 from easybuild.tools.build_log import EasyBuildError, init_logging, stop_logging
-from easybuild.tools.filetools import adjust_permissions, read_file, write_file
+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 parse_log_for_error, run_cmd, run_cmd_qa, subprocess_terminate
+from easybuild.tools.run import parse_log_for_error, run, run_cmd, run_cmd_qa, subprocess_terminate
 from easybuild.tools.config import ERROR, IGNORE, WARN
 
 
@@ -159,6 +159,31 @@ def test_run_cmd(self):
             self.assertTrue(out.startswith('foo ') and out.endswith(' bar'))
             self.assertEqual(type(out), str)
 
+    def test_run_basic(self):
+        """Basic test for run function."""
+
+        with self.mocked_stdout_stderr():
+            res = run("echo hello")
+        self.assertEqual(res.output, "hello\n")
+        # no reason echo hello could fail
+        self.assertEqual(res.exit_code, 0)
+        self.assertEqual(type(res.output), str)
+
+        # test running command that emits non-UTF-8 characters
+        # this is constructed to reproduce errors like:
+        # UnicodeDecodeError: 'utf-8' codec can't decode byte 0xe2
+        # UnicodeEncodeError: 'ascii' codec can't encode character u'\u2018'
+        for text in [b"foo \xe2 bar", b"foo \u2018 bar"]:
+            test_file = os.path.join(self.test_prefix, 'foo.txt')
+            write_file(test_file, text)
+            cmd = "cat %s" % test_file
+
+            with self.mocked_stdout_stderr():
+                res = run(cmd)
+            self.assertEqual(res.exit_code, 0)
+            self.assertTrue(res.output.startswith('foo ') and res.output.endswith(' bar'))
+            self.assertEqual(type(res.output), str)
+
     def test_run_cmd_log(self):
         """Test logging of executed commands."""
         fd, logfile = tempfile.mkstemp(suffix='.log', prefix='eb-test-')
@@ -200,14 +225,47 @@ def test_run_cmd_log(self):
 
         # Test that we can set the directory for the logfile
         log_path = os.path.join(self.test_prefix, 'chicken')
-        os.mkdir(log_path)
+        mkdir(log_path)
         logfile = None
         init_logging(logfile, silent=True, tmp_logdir=log_path)
         logfiles = os.listdir(log_path)
         self.assertEqual(len(logfiles), 1)
         self.assertTrue(logfiles[0].startswith("easybuild"))
         self.assertTrue(logfiles[0].endswith("log"))
 
+    def test_run_log(self):
+        """Test logging of executed commands with run function."""
+
+        fd, logfile = tempfile.mkstemp(suffix='.log', prefix='eb-test-')
+        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:")
+
+        # command output is always logged
+        init_logging(logfile, silent=True)
+        with self.mocked_stdout_stderr():
+            res = run("echo hello")
+        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)
+        write_file(logfile, '')
+
+        # with debugging enabled, exit code and output of command should only get logged once
+        setLogLevelDebug()
+
+        init_logging(logfile, silent=True)
+        with self.mocked_stdout_stderr():
+            res = run("echo hello")
+        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)
+        write_file(logfile, '')
+
     def test_run_cmd_negative_exit_code(self):
         """Test run_cmd function with command that has negative exit code."""
         # define signal handler to call in case run_cmd takes too long