Merge pull request #4284 from boegel/run

initial implementation of `run` function to replace `run_cmd` + `run_cmd_qa`

Author: ocaisa

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,117 @@
 ]
 
 
+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, 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)
+
+    if stdin:
+        # 'input' value fed to subprocess.run must be a byte sequence
+        stdin = stdin.encode()
+
+    _log.info(f"Running command '{cmd_msg}' in {work_dir}")
+    proc = subprocess.run(cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, input=stdin, shell=shell)
+
+    # 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')
+
+    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
+
+    :param cmd: command being run
+    :param start_time: datetime object indicating when command was started
+    :param work_dir: path of working directory in which command is run
+    :param stdin: stdin input value for command
+    :param cmd_out_fp: path to output log file for command
+    """
+    start_time = start_time.strftime('%Y-%m-%d %H:%M:%S')
+
+    lines = [
+        "running command:",
+        f"\t[started at: {start_time}]",
+        f"\t[working dir: {work_dir}]",
+    ]
+    if stdin:
+        lines.append(f"\t[input: {stdin}]")
+    if cmd_out_fp:
+        lines.append(f"\t[output logged in {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,32 @@ 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'
+        # (such errors are ignored by the 'run' implementation)
+        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 +226,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
@@ -281,8 +340,6 @@ def test_run_cmd_log_output(self):
 
     def test_run_cmd_trace(self):
         """Test run_cmd under --trace"""
-        # replace log.experimental with log.warning to allow experimental code
-        easybuild.tools.utilities._log.experimental = easybuild.tools.utilities._log.warning
 
         init_config(build_options={'trace': True})
 
@@ -302,6 +359,7 @@ def test_run_cmd_trace(self):
         stderr = self.get_stderr()
         self.mock_stdout(False)
         self.mock_stderr(False)
+        self.assertEqual(out, 'hello\n')
         self.assertEqual(ec, 0)
         self.assertEqual(stderr, '')
         regex = re.compile('\n'.join(pattern))
@@ -315,6 +373,7 @@ def test_run_cmd_trace(self):
         stderr = self.get_stderr()
         self.mock_stdout(False)
         self.mock_stderr(False)
+        self.assertEqual(out, 'hello')
         self.assertEqual(ec, 0)
         self.assertEqual(stderr, '')
         pattern.insert(3, r"\t\[input: hello\]")
@@ -330,6 +389,63 @@ def test_run_cmd_trace(self):
         stderr = self.get_stderr()
         self.mock_stdout(False)
         self.mock_stderr(False)
+        self.assertEqual(out, 'hello\n')
+        self.assertEqual(ec, 0)
+        self.assertEqual(stdout, '')
+        self.assertEqual(stderr, '')
+
+    def test_run_trace_stdin(self):
+        """Test run under --trace + passing stdin input."""
+
+        init_config(build_options={'trace': True})
+
+        pattern = [
+            r"^  >> running command:",
+            r"\t\[started at: [0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9] [0-9][0-9]:[0-9][0-9]:[0-9][0-9]\]",
+            r"\t\[working dir: .*\]",
+            r"\techo hello",
+            r"  >> command completed: exit 0, ran in .*",
+        ]
+
+        self.mock_stdout(True)
+        self.mock_stderr(True)
+        res = run("echo hello")
+        stdout = self.get_stdout()
+        stderr = self.get_stderr()
+        self.mock_stdout(False)
+        self.mock_stderr(False)
+        self.assertEqual(res.output, 'hello\n')
+        self.assertEqual(res.exit_code, 0)
+        self.assertEqual(stderr, '')
+        regex = re.compile('\n'.join(pattern))
+        self.assertTrue(regex.search(stdout), "Pattern '%s' found in: %s" % (regex.pattern, stdout))
+
+        # also test with command that is fed input via stdin
+        self.mock_stdout(True)
+        self.mock_stderr(True)
+        res = run('cat', stdin='hello')
+        stdout = self.get_stdout()
+        stderr = self.get_stderr()
+        self.mock_stdout(False)
+        self.mock_stderr(False)
+        self.assertEqual(res.output, 'hello')
+        self.assertEqual(res.exit_code, 0)
+        self.assertEqual(stderr, '')
+        pattern.insert(3, r"\t\[input: hello\]")
+        pattern[-2] = "\tcat"
+        regex = re.compile('\n'.join(pattern))
+        self.assertTrue(regex.search(stdout), "Pattern '%s' found in: %s" % (regex.pattern, stdout))
+
+        # trace output can be disabled on a per-command basis by enabling 'hidden'
+        self.mock_stdout(True)
+        self.mock_stderr(True)
+        res = run("echo hello", hidden=True)
+        stdout = self.get_stdout()
+        stderr = self.get_stderr()
+        self.mock_stdout(False)
+        self.mock_stderr(False)
+        self.assertEqual(res.output, 'hello\n')
+        self.assertEqual(res.exit_code, 0)
         self.assertEqual(stdout, '')
         self.assertEqual(stderr, '')