diff --git a/easybuild/tools/run.py b/easybuild/tools/run.py index 2592e198f1..3253a372b1 100644 --- a/easybuild/tools/run.py +++ b/easybuild/tools/run.py @@ -36,6 +36,7 @@ * Ward Poelmans (Ghent University) """ import contextlib +import fcntl import functools import inspect import os @@ -201,11 +202,66 @@ def fileprefix_from_cmd(cmd, allowed_chars=False): return ''.join([c for c in cmd if c in allowed_chars]) +def _answer_question(stdout, proc, qa_patterns, qa_wait_patterns): + """ + Private helper function to try and answer questions raised in interactive shell commands. + """ + match_found = False + + for question, answers in qa_patterns: + # allow extra whitespace at the end + question += r'[\s\n]*$' + regex = re.compile(question.encode()) + res = regex.search(stdout) + if res: + _log.debug(f"Found match for question pattern '{question}' at end of stdout: {stdout[:1000]}") + # if answer is specified as a list, we take the first item as current answer, + # and add it to the back of the list (so we cycle through answers) + if isinstance(answers, list): + answer = answers.pop(0) + answers.append(answer) + elif isinstance(answers, str): + answer = answers + else: + raise EasyBuildError(f"Unknown type of answers encountered for question ({question}): {answers}") + + # answer may need to be completed via pattern extracted from question + _log.debug(f"Raw answer for question pattern '{question}': {answer}") + answer = answer % {k: v.decode() for (k, v) in res.groupdict().items()} + answer += '\n' + _log.info(f"Found match for question pattern '{question}', replying with: {answer}") + + try: + os.write(proc.stdin.fileno(), answer.encode()) + except OSError as err: + raise EasyBuildError("Failed to answer question raised by interactive command: %s", err) + + match_found = True + break + else: + _log.info("No match found for question patterns, considering question wait patterns") + # if no match was found among question patterns, + # take into account patterns for non-questions (qa_wait_patterns) + for pattern in qa_wait_patterns: + # allow extra whitespace at the end + pattern += r'[\s\n]*$' + regex = re.compile(pattern.encode()) + if regex.search(stdout): + _log.info(f"Found match for wait pattern '{pattern}'") + _log.debug(f"Found match for wait pattern '{pattern}' at end of stdout: {stdout[:1000]}") + match_found = True + break + else: + _log.info("No match found for question wait patterns") + + return match_found + + @run_shell_cmd_cache def run_shell_cmd(cmd, fail_on_error=True, split_stderr=False, stdin=None, env=None, hidden=False, in_dry_run=False, verbose_dry_run=False, work_dir=None, use_bash=True, output_file=True, stream_output=None, asynchronous=False, task_id=None, with_hooks=True, - qa_patterns=None, qa_wait_patterns=None): + qa_patterns=None, qa_wait_patterns=None, qa_timeout=100): """ Run specified (interactive) shell command, and capture output + exit code. @@ -224,8 +280,9 @@ def run_shell_cmd(cmd, fail_on_error=True, split_stderr=False, stdin=None, env=N :param task_id: task ID for specified shell command (included in return value) :param with_hooks: trigger pre/post run_shell_cmd hooks (if defined) :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 + :param qa_wait_patterns: list of strings with patterns for non-questions + :param qa_timeout: amount of seconds to wait until more output is produced when there is no matching question + :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) @@ -244,9 +301,13 @@ def to_cmd_str(cmd): return cmd_str - # temporarily raise a NotImplementedError until all options are implemented - if qa_patterns or qa_wait_patterns: - raise NotImplementedError + # make sure that qa_patterns is a list of 2-tuples (not a dict, or something else) + if qa_patterns: + if not isinstance(qa_patterns, list) or any(not isinstance(x, tuple) or len(x) != 2 for x in qa_patterns): + raise EasyBuildError("qa_patterns passed to run_shell_cmd should be a list of 2-tuples!") + + if qa_wait_patterns is None: + qa_wait_patterns = [] if work_dir is None: work_dir = os.getcwd() @@ -279,11 +340,14 @@ def to_cmd_str(cmd): else: cmd_out_fp, cmd_err_fp = None, None + interactive = bool(qa_patterns) + interactive_msg = 'interactive ' if interactive else '' + # early exit in 'dry run' mode, after printing the command that would be run (unless 'hidden' is enabled) if not in_dry_run and build_option('extended_dry_run'): if not hidden or verbose_dry_run: silent = build_option('silent') - msg = f" running shell command \"{cmd_str}\"\n" + msg = f" running {interactive_msg}shell command \"{cmd_str}\"\n" msg += f" (in {work_dir})" dry_run_msg(msg, silent=silent) @@ -292,7 +356,7 @@ def to_cmd_str(cmd): start_time = datetime.now() if not hidden: - _cmd_trace_msg(cmd_str, start_time, work_dir, stdin, cmd_out_fp, cmd_err_fp, thread_id) + _cmd_trace_msg(cmd_str, start_time, work_dir, stdin, cmd_out_fp, cmd_err_fp, thread_id, interactive=interactive) if stream_output: print_msg(f"(streaming) output for command '{cmd_str}':") @@ -309,7 +373,11 @@ def to_cmd_str(cmd): if with_hooks: hooks = load_hooks(build_option('hooks')) - hook_res = run_hook(RUN_SHELL_CMD, hooks, pre_step_hook=True, args=[cmd], kwargs={'work_dir': work_dir}) + kwargs = { + 'interactive': interactive, + 'work_dir': work_dir, + } + hook_res = run_hook(RUN_SHELL_CMD, hooks, pre_step_hook=True, args=[cmd], kwargs=kwargs) if hook_res: cmd, old_cmd = hook_res, cmd cmd_str = to_cmd_str(cmd) @@ -317,7 +385,7 @@ def to_cmd_str(cmd): stderr = subprocess.PIPE if split_stderr else subprocess.STDOUT - log_msg = f"Running shell command '{cmd_str}' in {work_dir}" + log_msg = f"Running {interactive_msg}shell command '{cmd_str}' in {work_dir}" if thread_id: log_msg += f" (via thread with ID {thread_id})" _log.info(log_msg) @@ -329,23 +397,62 @@ def to_cmd_str(cmd): if stdin: stdin = stdin.encode() - if stream_output: + if stream_output or qa_patterns: + + if qa_patterns: + # make stdout, stderr, stdin non-blocking files + channels = [proc.stdout, proc.stdin] + if split_stderr: + channels += proc.stderr + for channel in channels: + fd = channel.fileno() + flags = fcntl.fcntl(fd, fcntl.F_GETFL) + fcntl.fcntl(fd, fcntl.F_SETFL, flags | os.O_NONBLOCK) + if stdin: proc.stdin.write(stdin) exit_code = None stdout, stderr = b'', b'' + check_interval_secs = 0.1 + time_no_match = 0 + # collect output piece-wise, while checking for questions to answer (if qa_patterns is provided) while exit_code is None: - exit_code = proc.poll() # use small read size (128 bytes) when streaming output, to make it stream more fluently # -1 means reading until EOF read_size = 128 if exit_code is None else -1 - stdout += proc.stdout.read(read_size) + more_stdout = proc.stdout.read1(read_size) or b'' + stdout += more_stdout + + # note: we assume that there won't be any questions in stderr output if split_stderr: - stderr += proc.stderr.read(read_size) + stderr += proc.stderr.read1(read_size) or b'' + + if qa_patterns: + if _answer_question(stdout, proc, qa_patterns, qa_wait_patterns): + time_no_match = 0 + else: + _log.debug(f"No match found in question/wait patterns at end of stdout: {stdout[:1000]}") + # this will only run if the for loop above was *not* stopped by the break statement + time_no_match += check_interval_secs + if time_no_match > qa_timeout: + error_msg = "No matching questions found for current command output, " + error_msg += f"giving up after {qa_timeout} seconds!" + raise EasyBuildError(error_msg) + else: + _log.debug(f"{time_no_match:0.1f} seconds without match in output of interactive shell command") + + time.sleep(check_interval_secs) + + exit_code = proc.poll() + + # collect last bit of output once processed has exited + stdout += proc.stdout.read() + if split_stderr: + stderr += proc.stderr.read() else: (stdout, stderr) = proc.communicate(input=stdin) @@ -385,6 +492,7 @@ def to_cmd_str(cmd): if with_hooks: run_hook_kwargs = { 'exit_code': res.exit_code, + 'interactive': interactive, 'output': res.output, 'stderr': res.stderr, 'work_dir': res.work_dir, @@ -398,7 +506,7 @@ def to_cmd_str(cmd): return res -def _cmd_trace_msg(cmd, start_time, work_dir, stdin, cmd_out_fp, cmd_err_fp, thread_id): +def _cmd_trace_msg(cmd, start_time, work_dir, stdin, cmd_out_fp, cmd_err_fp, thread_id, interactive=False): """ Helper function to construct and print trace message for command being run @@ -409,13 +517,15 @@ def _cmd_trace_msg(cmd, start_time, work_dir, stdin, cmd_out_fp, cmd_err_fp, thr :param cmd_out_fp: path to output file for command :param cmd_err_fp: path to errors/warnings output file for command :param thread_id: thread ID (None when not running shell command asynchronously) + :param interactive: boolean indicating whether it is an interactive command, or not """ start_time = start_time.strftime('%Y-%m-%d %H:%M:%S') + interactive = 'interactive ' if interactive else '' if thread_id: - run_cmd_msg = f"running shell command (asynchronously, thread ID: {thread_id}):" + run_cmd_msg = f"running {interactive}shell command (asynchronously, thread ID: {thread_id}):" else: - run_cmd_msg = "running shell command:" + run_cmd_msg = f"running {interactive}shell command:" lines = [ run_cmd_msg, diff --git a/test/framework/run.py b/test/framework/run.py index 2f16e3978a..6e64764805 100644 --- a/test/framework/run.py +++ b/test/framework/run.py @@ -771,6 +771,106 @@ def test_run_cmd_qa(self): self.assertTrue(out.startswith("question\nanswer\nfoo ")) self.assertTrue(out.endswith('bar')) + # test handling of output that is not actually a question + cmd = ';'.join([ + "echo not-a-question-but-a-statement", + "sleep 3", + "echo question", + "read x", + "echo $x", + ]) + qa = {'question': 'answer'} + + # fails because non-question is encountered + error_pattern = "Max nohits 1 reached: end of output not-a-question-but-a-statement" + self.assertErrorRegex(EasyBuildError, error_pattern, run_cmd_qa, cmd, qa, maxhits=1, trace=False) + + (out, ec) = run_cmd_qa(cmd, qa, no_qa=["not-a-question-but-a-statement"], maxhits=1, trace=False) + self.assertEqual(out, "not-a-question-but-a-statement\nquestion\nanswer\n") + self.assertEqual(ec, 0) + + def test_run_shell_cmd_qa(self): + """Basic test for Q&A support in run_shell_cmd function.""" + + cmd = '; '.join([ + "echo question1", + "read x", + "echo $x", + "echo question2", + "read y", + "echo $y", + ]) + qa = [ + ('question1', 'answer1'), + ('question2', 'answer2'), + ] + with self.mocked_stdout_stderr(): + res = run_shell_cmd(cmd, qa_patterns=qa) + self.assertEqual(res.output, "question1\nanswer1\nquestion2\nanswer2\n") + # no reason echo hello could fail + self.assertEqual(res.exit_code, 0) + + # test running command that emits non-UTF8 characters + # this is constructed to reproduce errors like: + # UnicodeDecodeError: 'utf-8' codec can't decode byte 0xe2 + test_file = os.path.join(self.test_prefix, 'foo.txt') + write_file(test_file, b"foo \xe2 bar") + cmd += "; cat %s" % test_file + + with self.mocked_stdout_stderr(): + res = run_shell_cmd(cmd, qa_patterns=qa) + self.assertEqual(res.exit_code, 0) + self.assertTrue(res.output.startswith("question1\nanswer1\nquestion2\nanswer2\nfoo ")) + self.assertTrue(res.output.endswith('bar')) + + # check type check on qa_patterns + error_pattern = "qa_patterns passed to run_shell_cmd should be a list of 2-tuples!" + with self.mocked_stdout_stderr(): + self.assertErrorRegex(EasyBuildError, error_pattern, run_shell_cmd, cmd, qa_patterns={'foo': 'bar'}) + self.assertErrorRegex(EasyBuildError, error_pattern, run_shell_cmd, cmd, qa_patterns=('foo', 'bar')) + self.assertErrorRegex(EasyBuildError, error_pattern, run_shell_cmd, cmd, qa_patterns=(('foo', 'bar'),)) + self.assertErrorRegex(EasyBuildError, error_pattern, run_shell_cmd, cmd, qa_patterns='foo:bar') + self.assertErrorRegex(EasyBuildError, error_pattern, run_shell_cmd, cmd, qa_patterns=['foo:bar']) + + # validate use of qa_timeout to give up if there's no matching question for too long + cmd = "sleep 3; echo 'question'; read a; echo $a" + error_pattern = "No matching questions found for current command output, giving up after 1 seconds!" + with self.mocked_stdout_stderr(): + self.assertErrorRegex(EasyBuildError, error_pattern, run_shell_cmd, cmd, qa_patterns=qa, qa_timeout=1) + + # check using answer that is completed via pattern extracted from question + cmd = ';'.join([ + "echo 'and the magic number is: 42'", + "read magic_number", + "echo $magic_number", + ]) + qa = [("and the magic number is: (?P[0-9]+)", "%(nr)s")] + with self.mocked_stdout_stderr(): + res = run_shell_cmd(cmd, qa_patterns=qa) + self.assertEqual(res.exit_code, 0) + self.assertEqual(res.output, "and the magic number is: 42\n42\n") + + # test handling of output that is not actually a question + cmd = ';'.join([ + "echo not-a-question-but-a-statement", + "sleep 3", + "echo question", + "read x", + "echo $x", + ]) + qa = [('question', 'answer')] + + # fails because non-question is encountered + error_pattern = "No matching questions found for current command output, giving up after 1 seconds!" + self.assertErrorRegex(EasyBuildError, error_pattern, run_shell_cmd, cmd, qa_patterns=qa, qa_timeout=1, + hidden=True) + + qa_wait_patterns = ["not-a-question-but-a-statement"] + with self.mocked_stdout_stderr(): + res = run_shell_cmd(cmd, qa_patterns=qa, qa_wait_patterns=qa_wait_patterns, qa_timeout=1) + self.assertEqual(res.exit_code, 0) + self.assertEqual(res.output, "not-a-question-but-a-statement\nquestion\nanswer\n") + def test_run_cmd_qa_buffering(self): """Test whether run_cmd_qa uses unbuffered output.""" @@ -803,6 +903,38 @@ def test_run_cmd_qa_buffering(self): self.assertEqual(ec, 1) self.assertEqual(out, "Hello, I am about to exit\nERROR: I failed\n") + def test_run_shell_cmd_qa_buffering(self): + """Test whether run_shell_cmd uses unbuffered output when running interactive commands.""" + + # command that generates a lot of output before waiting for input + # note: bug being fixed can be reproduced reliably using 100, but not with too high values like 100000! + cmd = 'for x in $(seq 100); do echo "This is a number you can pick: $x"; done; ' + cmd += 'echo "Pick a number: "; read number; echo "Picked number: $number"' + with self.mocked_stdout_stderr(): + res = run_shell_cmd(cmd, qa_patterns=[('Pick a number: ', '42')], qa_timeout=10) + + self.assertEqual(res.exit_code, 0) + regex = re.compile("Picked number: 42$") + self.assertTrue(regex.search(res.output), f"Pattern '{regex.pattern}' found in: {res.output}") + + # also test with script run as interactive command that quickly exits with non-zero exit code; + # see https://github.com/easybuilders/easybuild-framework/issues/3593 + script_txt = '\n'.join([ + "#/bin/bash", + "echo 'Hello, I am about to exit'", + "echo 'ERROR: I failed' >&2", + "exit 1", + ]) + script = os.path.join(self.test_prefix, 'test.sh') + write_file(script, script_txt) + adjust_permissions(script, stat.S_IXUSR) + + with self.mocked_stdout_stderr(): + res = run_shell_cmd(script, qa_patterns=[], fail_on_error=False) + + self.assertEqual(res.exit_code, 1) + self.assertEqual(res.output, "Hello, I am about to exit\nERROR: I failed\n") + def test_run_cmd_qa_log_all(self): """Test run_cmd_qa with log_output enabled""" with self.mocked_stdout_stderr(): @@ -816,13 +948,22 @@ def test_run_cmd_qa_log_all(self): extra_pref = "# output for interactive command: echo 'n: '; read n; seq 1 $n\n\n" self.assertEqual(run_cmd_log_txt, extra_pref + "n: \n1\n2\n3\n4\n5\n") + def test_run_shell_cmd_qa_log(self): + """Test temporary log file for run_shell_cmd with qa_patterns""" + with self.mocked_stdout_stderr(): + res = run_shell_cmd("echo 'n: '; read n; seq 1 $n", qa_patterns=[('n:', '5')]) + self.assertEqual(res.exit_code, 0) + self.assertEqual(res.output, "n: \n1\n2\n3\n4\n5\n") + + run_cmd_logs = glob.glob(os.path.join(tempfile.gettempdir(), 'run-shell-cmd-output', 'echo-*', 'out.txt')) + self.assertEqual(len(run_cmd_logs), 1) + run_cmd_log_txt = read_file(run_cmd_logs[0]) + self.assertEqual(run_cmd_log_txt, "n: \n1\n2\n3\n4\n5\n") + def test_run_cmd_qa_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}) + # --trace is enabled by default self.mock_stdout(True) self.mock_stderr(True) (out, ec) = run_cmd_qa("echo 'n: '; read n; seq 1 $n", {'n: ': '5'}) @@ -850,6 +991,37 @@ def test_run_cmd_qa_trace(self): self.assertEqual(stdout, '') self.assertEqual(stderr, '') + def test_run_shell_cmd_qa_trace(self): + """Test run_shell_cmd with qa_patterns under --trace""" + + # --trace is enabled by default + self.mock_stdout(True) + self.mock_stderr(True) + run_shell_cmd("echo 'n: '; read n; seq 1 $n", qa_patterns=[('n: ', '5')]) + stdout = self.get_stdout() + stderr = self.get_stderr() + self.mock_stdout(False) + self.mock_stderr(False) + self.assertEqual(stderr, '') + pattern = r"^ >> running interactive shell command:\n" + pattern += r"\techo \'n: \'; read n; seq 1 \$n\n" + pattern += r"\t\[started at: .*\]\n" + pattern += r"\t\[working dir: .*\]\n" + pattern += r"\t\[output saved to .*\]\n" + pattern += r' >> command completed: exit 0, ran in .*' + self.assertTrue(re.search(pattern, stdout), "Pattern '%s' found in: %s" % (pattern, stdout)) + + # trace output can be disabled on a per-command basis + self.mock_stdout(True) + self.mock_stderr(True) + run_shell_cmd("echo 'n: '; read n; seq 1 $n", qa_patterns=[('n: ', '5')], hidden=True) + stdout = self.get_stdout() + stderr = self.get_stderr() + self.mock_stdout(False) + self.mock_stderr(False) + self.assertEqual(stdout, '') + self.assertEqual(stderr, '') + def test_run_cmd_qa_answers(self): """Test providing list of answers in run_cmd_qa.""" cmd = "echo question; read x; echo $x; " * 2 @@ -875,6 +1047,28 @@ def test_run_cmd_qa_answers(self): self.assertEqual(out, "question\nanswer1\nquestion\nanswer2\n" * 2) self.assertEqual(ec, 0) + def test_run_shell_cmd_qa_answers(self): + """Test providing list of answers for a question in run_shell_cmd.""" + + cmd = "echo question; read x; echo $x; " * 2 + qa = [("question", ["answer1", "answer2"])] + + with self.mocked_stdout_stderr(): + res = run_shell_cmd(cmd, qa_patterns=qa) + self.assertEqual(res.output, "question\nanswer1\nquestion\nanswer2\n") + self.assertEqual(res.exit_code, 0) + + with self.mocked_stdout_stderr(): + self.assertErrorRegex(EasyBuildError, "Unknown type of answers encountered", run_shell_cmd, cmd, + qa_patterns=[('question', 1)]) + + # test cycling of answers + cmd = cmd * 2 + with self.mocked_stdout_stderr(): + res = run_shell_cmd(cmd, qa_patterns=qa) + self.assertEqual(res.output, "question\nanswer1\nquestion\nanswer2\n" * 2) + self.assertEqual(res.exit_code, 0) + def test_run_cmd_simple(self): """Test return value for run_cmd in 'simple' mode.""" with self.mocked_stdout_stderr(): @@ -1003,6 +1197,14 @@ def test_run_cmd_dry_run(self): self.assertEqual(read_file(outfile), "This is always echoed\n") # Q&A commands + self.mock_stdout(True) + run_shell_cmd("some_qa_cmd", qa_patterns=[('question1', 'answer1')]) + stdout = self.get_stdout() + self.mock_stdout(False) + + expected = """ running interactive shell command "some_qa_cmd"\n""" + self.assertIn(expected, stdout) + self.mock_stdout(True) run_cmd_qa("some_qa_cmd", {'question1': 'answer1'}) stdout = self.get_stdout() @@ -1444,6 +1646,17 @@ def post_run_shell_cmd_hook(cmd, *args, **kwargs): ]) self.assertEqual(stdout, expected_stdout) + with self.mocked_stdout_stderr(): + run_shell_cmd("sleep 2; make", qa_patterns=[('q', 'a')]) + stdout = self.get_stdout() + + expected_stdout = '\n'.join([ + "pre-run hook interactive 'sleep 2; make' in %s" % cwd, + "post-run hook interactive 'sleep 2; echo make' (exit code: 0, output: 'make\n')", + '', + ]) + self.assertEqual(stdout, expected_stdout) + with self.mocked_stdout_stderr(): run_cmd_qa("sleep 2; make", qa={}) stdout = self.get_stdout()