From 458c3125e0d7db9dbc9fcb73c5309174b2b1d19a Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 09:50:14 +0100 Subject: [PATCH 01/11] mtest: do not print time out message twice Rebase mistake in "mtest: move timeout message to ConsoleLogger". --- mesonbuild/mtest.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 7e2d22192..5a0af47eb 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -1204,8 +1204,6 @@ class SingleTestRunner: stde_task = p.stderr.read(-1) returncode, result, additional_error = await p.wait(self.runobj.timeout) - if result is TestResult.TIMEOUT and self.options.verbose: - print('{} time out (After {} seconds)'.format(self.test.name, self.runobj.timeout)) if stdo_task is not None: stdo = decode(await stdo_task) From 51e1f01c85276f356c0dab84a46f15d29529fb17 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 12:08:45 +0100 Subject: [PATCH 02/11] mtest: store the environment in the TestRun The test_env was lost from the TestRun object in commit 30741a0f2 ("mtest: create TestRun object early on"). Fix things. --- mesonbuild/mtest.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 5a0af47eb..303058820 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -746,7 +746,7 @@ class TestRun: self.stdo = None # type: T.Optional[str] self.stde = None # type: T.Optional[str] self.cmd = None # type: T.Optional[T.List[str]] - self.env = dict() # type: T.Dict[str, str] + self.env = test_env # type: T.Dict[str, str] self.should_fail = test.should_fail self.project = test.project_name self.junit = None # type: T.Optional[et.ElementTree] From c544529faa85e557956d7bd5aed15ecbf44b8353 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 10:33:11 +0100 Subject: [PATCH 03/11] mtest: simplify complete_exitcode There is no need anymore to pass the JUnit XML down to complete_exitcode. Just set self.junit in complete_gtest instead. --- mesonbuild/mtest.py | 13 +++++-------- 1 file changed, 5 insertions(+), 8 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 303058820..b5c42e7ac 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -761,21 +761,19 @@ class TestRun: filename = '{}.xml'.format(self.test.name) if self.test.workdir: filename = os.path.join(self.test.workdir, filename) - tree = et.parse(filename) - - self.complete_exitcode(returncode, stdo, stde, cmd, junit=tree) + self.junit = et.parse(filename) + self.complete_exitcode(returncode, stdo, stde, cmd) def complete_exitcode(self, returncode: int, stdo: T.Optional[str], stde: T.Optional[str], - cmd: T.List[str], - **kwargs: T.Any) -> None: + cmd: T.List[str]) -> None: if returncode == GNU_SKIP_RETURNCODE: res = TestResult.SKIP elif returncode == GNU_ERROR_RETURNCODE: res = TestResult.ERROR else: res = TestResult.FAIL if bool(returncode) else TestResult.OK - self.complete(returncode, res, stdo, stde, cmd, **kwargs) + self.complete(returncode, res, stdo, stde, cmd) async def parse_tap(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: res = TestResult.OK @@ -858,7 +856,7 @@ class TestRun: def complete(self, returncode: int, res: TestResult, stdo: T.Optional[str], stde: T.Optional[str], - cmd: T.List[str], *, junit: T.Optional[et.ElementTree] = None) -> None: + cmd: T.List[str]) -> None: assert isinstance(res, TestResult) if self.should_fail and res in (TestResult.OK, TestResult.FAIL): res = TestResult.UNEXPECTEDPASS if res.is_ok() else TestResult.EXPECTEDFAIL @@ -869,7 +867,6 @@ class TestRun: self.stdo = stdo self.stde = stde self.cmd = cmd - self.junit = junit def get_log(self) -> str: res = '--- command ---\n' From 1f5634f15d161762902bb99bbd68f5d3cd714ba5 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 14:23:07 +0100 Subject: [PATCH 04/11] mtest: add complete_skip to TestRun --- mesonbuild/mtest.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index b5c42e7ac..09df7612a 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -868,6 +868,9 @@ class TestRun: self.stde = stde self.cmd = cmd + def complete_skip(self, message: str) -> None: + self.complete(GNU_SKIP_RETURNCODE, TestResult.SKIP, message, None, None) + def get_log(self) -> str: res = '--- command ---\n' if self.cmd is None: @@ -1091,7 +1094,7 @@ class SingleTestRunner: self.runobj.start() if cmd is None: skip_stdout = 'Not run because can not execute cross compiled binaries.' - self.runobj.complete(GNU_SKIP_RETURNCODE, TestResult.SKIP, skip_stdout, None, None) + self.runobj.complete_skip(skip_stdout) else: wrap = TestHarness.get_wrapper(self.options) await self._run_cmd(wrap + cmd + self.test.cmd_args + self.options.test_args) From 9e42048e3caf86b9981d3a9a43ec6eeb1fe316f5 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 11:47:26 +0100 Subject: [PATCH 05/11] mtest: pass command line to TestRun.start The command line is already available when the test is started. Pass it to TestRun.start instead of TestRun.complete*. --- mesonbuild/mtest.py | 34 ++++++++++++++++------------------ 1 file changed, 16 insertions(+), 18 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 09df7612a..ecdffd684 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -751,29 +751,28 @@ class TestRun: self.project = test.project_name self.junit = None # type: T.Optional[et.ElementTree] - def start(self) -> None: + def start(self, cmd: T.List[str]) -> None: self.res = TestResult.RUNNING self.starttime = time.time() + self.cmd = cmd def complete_gtest(self, returncode: int, - stdo: T.Optional[str], stde: T.Optional[str], - cmd: T.List[str]) -> None: + stdo: T.Optional[str], stde: T.Optional[str]) -> None: filename = '{}.xml'.format(self.test.name) if self.test.workdir: filename = os.path.join(self.test.workdir, filename) self.junit = et.parse(filename) - self.complete_exitcode(returncode, stdo, stde, cmd) + self.complete_exitcode(returncode, stdo, stde) def complete_exitcode(self, returncode: int, - stdo: T.Optional[str], stde: T.Optional[str], - cmd: T.List[str]) -> None: + stdo: T.Optional[str], stde: T.Optional[str]) -> None: if returncode == GNU_SKIP_RETURNCODE: res = TestResult.SKIP elif returncode == GNU_ERROR_RETURNCODE: res = TestResult.ERROR else: res = TestResult.FAIL if bool(returncode) else TestResult.OK - self.complete(returncode, res, stdo, stde, cmd) + self.complete(returncode, res, stdo, stde) async def parse_tap(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: res = TestResult.OK @@ -796,12 +795,12 @@ class TestRun: return res, error def complete_tap(self, returncode: int, res: TestResult, - stdo: str, stde: str, cmd: T.List[str]) -> None: + stdo: str, stde: str) -> None: if returncode != 0 and not res.was_killed(): res = TestResult.ERROR stde += '\n(test program exited with status code {})'.format(returncode,) - self.complete(returncode, res, stdo, stde, cmd) + self.complete(returncode, res, stdo, stde) async def parse_rust(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: def parse_res(n: int, name: str, result: str) -> TAPParser.Test: @@ -855,8 +854,7 @@ class TestRun: return '' def complete(self, returncode: int, res: TestResult, - stdo: T.Optional[str], stde: T.Optional[str], - cmd: T.List[str]) -> None: + stdo: T.Optional[str], stde: T.Optional[str]) -> None: assert isinstance(res, TestResult) if self.should_fail and res in (TestResult.OK, TestResult.FAIL): res = TestResult.UNEXPECTEDPASS if res.is_ok() else TestResult.EXPECTEDFAIL @@ -866,10 +864,10 @@ class TestRun: self.duration = time.time() - self.starttime self.stdo = stdo self.stde = stde - self.cmd = cmd def complete_skip(self, message: str) -> None: - self.complete(GNU_SKIP_RETURNCODE, TestResult.SKIP, message, None, None) + self.starttime = time.time() + self.complete(GNU_SKIP_RETURNCODE, TestResult.SKIP, message, None) def get_log(self) -> str: res = '--- command ---\n' @@ -1091,7 +1089,6 @@ class SingleTestRunner: async def run(self) -> TestRun: cmd = self._get_cmd() - self.runobj.start() if cmd is None: skip_stdout = 'Not run because can not execute cross compiled binaries.' self.runobj.complete_skip(skip_stdout) @@ -1154,6 +1151,7 @@ class SingleTestRunner: if ('MALLOC_PERTURB_' not in self.env or not self.env['MALLOC_PERTURB_']) and not self.options.benchmark: self.env['MALLOC_PERTURB_'] = str(random.randint(1, 255)) + self.runobj.start(cmd) stdout = None stderr = None if self.test.protocol is TestProtocol.TAP: @@ -1219,15 +1217,15 @@ class SingleTestRunner: stde += '\n' + error result = result or res if self.test.protocol is TestProtocol.TAP: - self.runobj.complete_tap(returncode, result, stdo, stde, cmd) + self.runobj.complete_tap(returncode, result, stdo, stde) return if result: - self.runobj.complete(returncode, result, stdo, stde, cmd) + self.runobj.complete(returncode, result, stdo, stde) elif self.test.protocol is TestProtocol.EXITCODE: - self.runobj.complete_exitcode(returncode, stdo, stde, cmd) + self.runobj.complete_exitcode(returncode, stdo, stde) elif self.test.protocol is TestProtocol.GTEST: - self.runobj.complete_gtest(returncode, stdo, stde, cmd) + self.runobj.complete_gtest(returncode, stdo, stde) class TestHarness: From 1f52e2fa45396046d1694fcbccf15ba2f8381ce2 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 09:43:46 +0100 Subject: [PATCH 06/11] mtest: turn TestRun into a hierarchy Make SimpleTestRunner oblivious of the various test protocols. All the different "complete_*" and "parse_*" methods move to the subclasses of TestRun. --- mesonbuild/mtest.py | 219 ++++++++++++++++++++++++++------------------ 1 file changed, 128 insertions(+), 91 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index ecdffd684..63fa5b455 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -731,6 +731,10 @@ class JunitBuilder(TestLogger): class TestRun: TEST_NUM = 0 + PROTOCOL_TO_CLASS: T.Dict[TestProtocol, T.Type['TestRun']] = {} + + def __new__(cls, test: TestSerialisation, *args: T.Any, **kwargs: T.Any) -> T.Any: + return super().__new__(TestRun.PROTOCOL_TO_CLASS[test.protocol]) def __init__(self, test: TestSerialisation, test_env: T.Dict[str, str], name: str, timeout: T.Optional[int]): @@ -756,80 +760,6 @@ class TestRun: self.starttime = time.time() self.cmd = cmd - def complete_gtest(self, returncode: int, - stdo: T.Optional[str], stde: T.Optional[str]) -> None: - filename = '{}.xml'.format(self.test.name) - if self.test.workdir: - filename = os.path.join(self.test.workdir, filename) - self.junit = et.parse(filename) - self.complete_exitcode(returncode, stdo, stde) - - def complete_exitcode(self, returncode: int, - stdo: T.Optional[str], stde: T.Optional[str]) -> None: - if returncode == GNU_SKIP_RETURNCODE: - res = TestResult.SKIP - elif returncode == GNU_ERROR_RETURNCODE: - res = TestResult.ERROR - else: - res = TestResult.FAIL if bool(returncode) else TestResult.OK - self.complete(returncode, res, stdo, stde) - - async def parse_tap(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: - res = TestResult.OK - error = '' - - async for i in TAPParser().parse_async(lines): - if isinstance(i, TAPParser.Bailout): - res = TestResult.ERROR - elif isinstance(i, TAPParser.Test): - self.results.append(i) - if i.result.is_bad(): - res = TestResult.FAIL - elif isinstance(i, TAPParser.Error): - error = '\nTAP parsing error: ' + i.message - res = TestResult.ERROR - - if all(t.result is TestResult.SKIP for t in self.results): - # This includes the case where self.results is empty - res = TestResult.SKIP - return res, error - - def complete_tap(self, returncode: int, res: TestResult, - stdo: str, stde: str) -> None: - if returncode != 0 and not res.was_killed(): - res = TestResult.ERROR - stde += '\n(test program exited with status code {})'.format(returncode,) - - self.complete(returncode, res, stdo, stde) - - async def parse_rust(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: - def parse_res(n: int, name: str, result: str) -> TAPParser.Test: - if result == 'ok': - return TAPParser.Test(n, name, TestResult.OK, None) - elif result == 'ignored': - return TAPParser.Test(n, name, TestResult.SKIP, None) - elif result == 'FAILED': - return TAPParser.Test(n, name, TestResult.FAIL, None) - return TAPParser.Test(n, name, TestResult.ERROR, - 'Unsupported output from rust test: {}'.format(result)) - - n = 1 - async for line in lines: - if line.startswith('test ') and not line.startswith('test result'): - _, name, _, result = line.rstrip().split(' ') - name = name.replace('::', '.') - self.results.append(parse_res(n, name, result)) - n += 1 - - if all(t.result is TestResult.SKIP for t in self.results): - # This includes the case where self.results is empty - return TestResult.SKIP, '' - elif any(t.result is TestResult.ERROR for t in self.results): - return TestResult.ERROR, '' - elif any(t.result is TestResult.FAIL for t in self.results): - return TestResult.FAIL, '' - return TestResult.OK, '' - @property def num(self) -> int: if self._num is None: @@ -853,8 +783,8 @@ class TestRun: return '{}/{} subtests passed'.format(passed, ran) return '' - def complete(self, returncode: int, res: TestResult, - stdo: T.Optional[str], stde: T.Optional[str]) -> None: + def _complete(self, returncode: int, res: TestResult, + stdo: T.Optional[str], stde: T.Optional[str]) -> None: assert isinstance(res, TestResult) if self.should_fail and res in (TestResult.OK, TestResult.FAIL): res = TestResult.UNEXPECTEDPASS if res.is_ok() else TestResult.EXPECTEDFAIL @@ -867,7 +797,11 @@ class TestRun: def complete_skip(self, message: str) -> None: self.starttime = time.time() - self.complete(GNU_SKIP_RETURNCODE, TestResult.SKIP, message, None) + self._complete(GNU_SKIP_RETURNCODE, TestResult.SKIP, message, None) + + def complete(self, returncode: int, res: TestResult, + stdo: T.Optional[str], stde: T.Optional[str]) -> None: + self._complete(returncode, res, stdo, stde) def get_log(self) -> str: res = '--- command ---\n' @@ -904,6 +838,118 @@ class TestRun: log += '\n'.join(lines[-100:]) return log + @property + def needs_parsing(self) -> bool: + return False + + async def parse(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: + async for l in lines: + pass + return TestResult.OK, '' + + +class TestRunExitCode(TestRun): + + def complete(self, returncode: int, res: TestResult, + stdo: T.Optional[str], stde: T.Optional[str]) -> None: + if res: + pass + elif returncode == GNU_SKIP_RETURNCODE: + res = TestResult.SKIP + elif returncode == GNU_ERROR_RETURNCODE: + res = TestResult.ERROR + else: + res = TestResult.FAIL if bool(returncode) else TestResult.OK + super().complete(returncode, res, stdo, stde) + +TestRun.PROTOCOL_TO_CLASS[TestProtocol.EXITCODE] = TestRunExitCode + + +class TestRunGTest(TestRunExitCode): + def complete(self, returncode: int, res: TestResult, + stdo: T.Optional[str], stde: T.Optional[str]) -> None: + filename = '{}.xml'.format(self.test.name) + if self.test.workdir: + filename = os.path.join(self.test.workdir, filename) + + self.junit = et.parse(filename) + super().complete(returncode, res, stdo, stde) + +TestRun.PROTOCOL_TO_CLASS[TestProtocol.GTEST] = TestRunGTest + + +class TestRunTAP(TestRun): + @property + def needs_parsing(self) -> bool: + return True + + def complete(self, returncode: int, res: TestResult, + stdo: str, stde: str) -> None: + if returncode != 0 and not res.was_killed(): + res = TestResult.ERROR + stde += '\n(test program exited with status code {})'.format(returncode,) + + super().complete(returncode, res, stdo, stde) + + async def parse(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: + res = TestResult.OK + error = '' + + async for i in TAPParser().parse_async(lines): + if isinstance(i, TAPParser.Bailout): + res = TestResult.ERROR + elif isinstance(i, TAPParser.Test): + self.results.append(i) + if i.result.is_bad(): + res = TestResult.FAIL + elif isinstance(i, TAPParser.Error): + error = '\nTAP parsing error: ' + i.message + res = TestResult.ERROR + + if all(t.result is TestResult.SKIP for t in self.results): + # This includes the case where self.results is empty + res = TestResult.SKIP + return res, error + +TestRun.PROTOCOL_TO_CLASS[TestProtocol.TAP] = TestRunTAP + + +class TestRunRust(TestRun): + @property + def needs_parsing(self) -> bool: + return True + + async def parse(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: + def parse_res(n: int, name: str, result: str) -> TAPParser.Test: + if result == 'ok': + return TAPParser.Test(n, name, TestResult.OK, None) + elif result == 'ignored': + return TAPParser.Test(n, name, TestResult.SKIP, None) + elif result == 'FAILED': + return TAPParser.Test(n, name, TestResult.FAIL, None) + return TAPParser.Test(n, name, TestResult.ERROR, + 'Unsupported output from rust test: {}'.format(result)) + + n = 1 + async for line in lines: + if line.startswith('test ') and not line.startswith('test result'): + _, name, _, result = line.rstrip().split(' ') + name = name.replace('::', '.') + self.results.append(parse_res(n, name, result)) + n += 1 + + if all(t.result is TestResult.SKIP for t in self.results): + # This includes the case where self.results is empty + return TestResult.SKIP, '' + elif any(t.result is TestResult.ERROR for t in self.results): + return TestResult.ERROR, '' + elif any(t.result is TestResult.FAIL for t in self.results): + return TestResult.FAIL, '' + return TestResult.OK, '' + +TestRun.PROTOCOL_TO_CLASS[TestProtocol.RUST] = TestRunRust + + def decode(stream: T.Union[None, bytes]) -> str: if stream is None: return '' @@ -1154,7 +1200,7 @@ class SingleTestRunner: self.runobj.start(cmd) stdout = None stderr = None - if self.test.protocol is TestProtocol.TAP: + if self.runobj.needs_parsing: stdout = asyncio.subprocess.PIPE stderr = None if self.options.verbose else asyncio.subprocess.PIPE elif not self.options.verbose: @@ -1192,10 +1238,9 @@ class SingleTestRunner: nonlocal stdo stdo = ''.join(stdo_lines) - if self.test.protocol is TestProtocol.TAP: - parse_task = self.runobj.parse_tap(lines()) - elif self.test.protocol is TestProtocol.RUST: - parse_task = self.runobj.parse_rust(lines()) + parse_task = None + if self.runobj.needs_parsing: + parse_task = self.runobj.parse(lines()) elif stdout is not None: stdo_task = p.stdout.read(-1) if stderr is not None and stderr != asyncio.subprocess.STDOUT: @@ -1216,16 +1261,8 @@ class SingleTestRunner: if error: stde += '\n' + error result = result or res - if self.test.protocol is TestProtocol.TAP: - self.runobj.complete_tap(returncode, result, stdo, stde) - return - if result: - self.runobj.complete(returncode, result, stdo, stde) - elif self.test.protocol is TestProtocol.EXITCODE: - self.runobj.complete_exitcode(returncode, stdo, stde) - elif self.test.protocol is TestProtocol.GTEST: - self.runobj.complete_gtest(returncode, stdo, stde) + self.runobj.complete(returncode, result, stdo, stde) class TestHarness: From c1c1408fae067d0a24c30c72a1e310c4a09a62be Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 11:00:12 +0100 Subject: [PATCH 07/11] mtest: introduce ConsoleUser This new enum can be used by TestSubprocess and TestHarness to understand (at a higher level) how SingleTestRunner sets up stdout/stderr redirection. --- mesonbuild/mtest.py | 24 ++++++++++++++++++++++-- 1 file changed, 22 insertions(+), 2 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 63fa5b455..8b132a9e7 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -180,6 +180,19 @@ class TestException(MesonException): pass +@enum.unique +class ConsoleUser(enum.Enum): + + # the logger can use the console + LOGGER = 0 + + # the console is used by gdb + GDB = 1 + + # the console is used to write stdout/stderr + STDOUT = 2 + + @enum.unique class TestResult(enum.Enum): @@ -1105,6 +1118,13 @@ class SingleTestRunner: self.runobj = TestRun(test, test_env, name, timeout) + if self.options.gdb: + self.console_mode = ConsoleUser.GDB + elif self.options.verbose and not self.runobj.needs_parsing: + self.console_mode = ConsoleUser.STDOUT + else: + self.console_mode = ConsoleUser.LOGGER + def _get_cmd(self) -> T.Optional[T.List[str]]: if self.test.fname[0].endswith('.jar'): return ['java', '-jar'] + self.test.fname @@ -1203,7 +1223,7 @@ class SingleTestRunner: if self.runobj.needs_parsing: stdout = asyncio.subprocess.PIPE stderr = None if self.options.verbose else asyncio.subprocess.PIPE - elif not self.options.verbose: + elif self.console_mode is ConsoleUser.LOGGER: stdout = asyncio.subprocess.PIPE stderr = asyncio.subprocess.PIPE if self.options.split else asyncio.subprocess.STDOUT @@ -1231,7 +1251,7 @@ class SingleTestRunner: while not reader.at_eof(): line = decode(await reader.readline()) stdo_lines.append(line) - if self.options.verbose: + if self.console_mode is ConsoleUser.STDOUT: print(line, end='') yield line From 90ea0dc5835426c61a002b78a9691b451e055342 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 10:26:21 +0100 Subject: [PATCH 08/11] mtest: disable the progress report in gdb mode Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 8b132a9e7..f112177df 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -535,9 +535,7 @@ class ConsoleLogger(TestLogger): self.test_count = harness.test_count - # In verbose mode, the progress report gets in the way of the tests' - # stdout and stderr. - if self.is_tty() and not harness.options.verbose: + if self.is_tty() and not harness.need_console: # Account for "[aa-bb/cc] OO " in the progress report self.max_left_width = 3 * len(str(self.test_count)) + 8 self.progress_task = asyncio.ensure_future(report_progress()) @@ -1300,6 +1298,7 @@ class TestHarness: self.is_run = False self.loggers = [] # type: T.List[TestLogger] self.loggers.append(ConsoleLogger()) + self.need_console = False if self.options.benchmark: self.tests = load_benchmarks(options.wd) @@ -1450,6 +1449,9 @@ class TestHarness: runners = [self.get_test_runner(test) for test in tests] self.duration_max_len = max([len(str(int(runner.timeout or 99))) for runner in runners]) + # Disable the progress report if it gets in the way + self.need_console = any((runner.console_mode is not ConsoleUser.LOGGER + for runner in runners)) self.run_tests(runners) finally: os.chdir(startdir) From 401464c61a7dce3819539398a59ff3fcce88d0ca Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 10:19:40 +0100 Subject: [PATCH 09/11] mtest: tweak the gathering of stdo_task/stde_task results After the next patch, we will need to complete parse_task before stdo_task (because parse_task will not set the "stdo" variable anymore but it will still collect stdout just like now). Do the change now to isolate the more complicated changes. --- mesonbuild/mtest.py | 23 ++++++++++++++--------- 1 file changed, 14 insertions(+), 9 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index f112177df..300eb11cf 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -147,6 +147,13 @@ def print_safe(s: str) -> None: s = s.encode('ascii', errors='backslashreplace').decode('ascii') print(s) +def join_lines(a: str, b: str) -> str: + if not a: + return b + if not b: + return a + return a + '\n' + b + def returncode_to_status(retcode: int) -> str: # Note: We can't use `os.WIFSIGNALED(result.returncode)` and the related # functions here because the status returned by subprocess is munged. It @@ -1266,20 +1273,18 @@ class SingleTestRunner: returncode, result, additional_error = await p.wait(self.runobj.timeout) - if stdo_task is not None: - stdo = decode(await stdo_task) - if stde_task is not None: - stde = decode(await stde_task) - - if additional_error is not None: - stde += '\n' + additional_error - if parse_task is not None: res, error = await parse_task if error: - stde += '\n' + error + additional_error = join_lines(additional_error, error) result = result or res + if stdo_task is not None: + stdo = decode(await stdo_task) + if stde_task is not None: + stde = decode(await stde_task) + + stde = join_lines(stde, additional_error) self.runobj.complete(returncode, result, stdo, stde) From e7c85555751399506e3f967e044f3d327abd3a14 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 10:03:16 +0100 Subject: [PATCH 10/11] mtest: move I/O handling to TestSubprocess Move the logic to start the read/decode tasks to TestSubprocess and keep SingleTestRunner simple. The lines() inner function is tweaked to produce stdout as a future. This removes the nonlocal access (which is not possible anymore when the code is moved out of _run_cmd), and also lets _run_cmd use "await stdo_task" for both parsed and unparsed output. --- mesonbuild/mtest.py | 80 +++++++++++++++++++++++++-------------------- 1 file changed, 44 insertions(+), 36 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 300eb11cf..dd7f926b7 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -976,6 +976,27 @@ def decode(stream: T.Union[None, bytes]) -> str: except UnicodeDecodeError: return stream.decode('iso-8859-1', errors='ignore') +async def read_decode(reader: asyncio.StreamReader) -> str: + return decode(await reader.read(-1)) + +# Extract lines out of the StreamReader. Print them +# along the way if requested, and at the end collect +# them all into a future. +async def read_decode_lines(reader: asyncio.StreamReader, f: 'asyncio.Future[str]', + console_mode: ConsoleUser) -> T.AsyncIterator[str]: + stdo_lines = [] + try: + while not reader.at_eof(): + line = decode(await reader.readline()) + stdo_lines.append(line) + if console_mode is ConsoleUser.STDOUT: + print(line, end='', flush=True) + yield line + except Exception as e: + f.set_exception(e) + finally: + f.set_result(''.join(stdo_lines)) + def run_with_mono(fname: str) -> bool: return fname.endswith('.exe') and not (is_windows() or is_cygwin()) @@ -1033,17 +1054,27 @@ async def complete_all(futures: T.Iterable[asyncio.Future]) -> None: f.result() class TestSubprocess: - def __init__(self, p: asyncio.subprocess.Process, postwait_fn: T.Callable[[], None] = None): + def __init__(self, p: asyncio.subprocess.Process, + stdout: T.Optional[int], stderr: T.Optional[int], + postwait_fn: T.Callable[[], None] = None): self._process = p + self.stdout = stdout + self.stderr = stderr + self.stdo_task = None # type: T.Optional[T.Awaitable[str]] + self.stde_task = None # type: T.Optional[T.Awaitable[str]] self.postwait_fn = postwait_fn # type: T.Callable[[], None] - @property - def stdout(self) -> T.Optional[asyncio.StreamReader]: - return self._process.stdout + def stdout_lines(self, console_mode: ConsoleUser) -> T.AsyncIterator[str]: + self.stdo_task = asyncio.get_event_loop().create_future() + return read_decode_lines(self._process.stdout, self.stdo_task, console_mode) - @property - def stderr(self) -> T.Optional[asyncio.StreamReader]: - return self._process.stderr + def communicate(self) -> T.Tuple[T.Optional[T.Awaitable[str]], + T.Optional[T.Awaitable[str]]]: + if self.stdo_task is None and self.stdout is not None: + self.stdo_task = read_decode(self._process.stdout) + if self.stderr is not None and self.stderr != asyncio.subprocess.STDOUT: + self.stde_task = read_decode(self._process.stderr) + return self.stdo_task, self.stde_task async def _kill(self) -> T.Optional[str]: # Python does not provide multiplatform support for @@ -1199,7 +1230,8 @@ class SingleTestRunner: env=env, cwd=cwd, preexec_fn=preexec_fn if not is_windows() else None) - return TestSubprocess(p, postwait_fn=postwait_fn if not is_windows() else None) + return TestSubprocess(p, stdout=stdout, stderr=stderr, + postwait_fn=postwait_fn if not is_windows() else None) async def _run_cmd(self, cmd: T.List[str]) -> None: if self.test.extra_paths: @@ -1245,32 +1277,11 @@ class SingleTestRunner: env=self.env, cwd=self.test.workdir) - stdo = stde = '' - stdo_task = stde_task = parse_task = None - - # Extract lines out of the StreamReader and print them - # along the way if requested - async def lines() -> T.AsyncIterator[str]: - stdo_lines = [] - reader = p.stdout - while not reader.at_eof(): - line = decode(await reader.readline()) - stdo_lines.append(line) - if self.console_mode is ConsoleUser.STDOUT: - print(line, end='') - yield line - - nonlocal stdo - stdo = ''.join(stdo_lines) - parse_task = None if self.runobj.needs_parsing: - parse_task = self.runobj.parse(lines()) - elif stdout is not None: - stdo_task = p.stdout.read(-1) - if stderr is not None and stderr != asyncio.subprocess.STDOUT: - stde_task = p.stderr.read(-1) + parse_task = self.runobj.parse(p.stdout_lines(self.console_mode)) + stdo_task, stde_task = p.communicate() returncode, result, additional_error = await p.wait(self.runobj.timeout) if parse_task is not None: @@ -1279,11 +1290,8 @@ class SingleTestRunner: additional_error = join_lines(additional_error, error) result = result or res - if stdo_task is not None: - stdo = decode(await stdo_task) - if stde_task is not None: - stde = decode(await stde_task) - + stdo = await stdo_task if stdo_task else '' + stde = await stde_task if stde_task else '' stde = join_lines(stde, additional_error) self.runobj.complete(returncode, result, stdo, stde) From 2e982a38643dfc869cb91b49d3f44ee271a7062d Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 09:57:59 +0100 Subject: [PATCH 11/11] mtest: collect stdout/stderr even in verbose mode Using verbose mode dropped stdout/stderr from the logs, because it was not captured. Now that we can easily stick code in the middle of the reading of stdout/stderr, use that to print stdout and stderr on the fly while also capturing them for the logs. The output is line-buffered. As a side effect, this also fixes a possible deadlock due to not using ensure_future around stdo_task and stde_task. In particular: - the stdo_task coroutine would not terminate until the test closed stdo_task - the stde_task coroutine would not start until the stdo_task coroutine finished Therefore, the test could get stuck waiting for its parent to read the contents of stderr, but that would not happen because Meson was still in the stdo_task coroutine. --- mesonbuild/mtest.py | 41 +++++++++++++++++++++++++++-------------- 1 file changed, 27 insertions(+), 14 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index dd7f926b7..d410dbac4 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -976,8 +976,16 @@ def decode(stream: T.Union[None, bytes]) -> str: except UnicodeDecodeError: return stream.decode('iso-8859-1', errors='ignore') -async def read_decode(reader: asyncio.StreamReader) -> str: - return decode(await reader.read(-1)) +async def read_decode(reader: asyncio.StreamReader, console_mode: ConsoleUser) -> str: + if console_mode is not ConsoleUser.STDOUT: + return decode(await reader.read(-1)) + + stdo_lines = [] + while not reader.at_eof(): + line = decode(await reader.readline()) + stdo_lines.append(line) + print(line, end='', flush=True) + return ''.join(stdo_lines) # Extract lines out of the StreamReader. Print them # along the way if requested, and at the end collect @@ -1068,12 +1076,17 @@ class TestSubprocess: self.stdo_task = asyncio.get_event_loop().create_future() return read_decode_lines(self._process.stdout, self.stdo_task, console_mode) - def communicate(self) -> T.Tuple[T.Optional[T.Awaitable[str]], - T.Optional[T.Awaitable[str]]]: + def communicate(self, console_mode: ConsoleUser) -> T.Tuple[T.Optional[T.Awaitable[str]], + T.Optional[T.Awaitable[str]]]: + # asyncio.ensure_future ensures that printing can + # run in the background, even before it is awaited if self.stdo_task is None and self.stdout is not None: - self.stdo_task = read_decode(self._process.stdout) + decode_task = read_decode(self._process.stdout, console_mode) + self.stdo_task = asyncio.ensure_future(decode_task) if self.stderr is not None and self.stderr != asyncio.subprocess.STDOUT: - self.stde_task = read_decode(self._process.stderr) + decode_task = read_decode(self._process.stderr, console_mode) + self.stde_task = asyncio.ensure_future(decode_task) + return self.stdo_task, self.stde_task async def _kill(self) -> T.Optional[str]: @@ -1255,14 +1268,14 @@ class SingleTestRunner: self.env['MALLOC_PERTURB_'] = str(random.randint(1, 255)) self.runobj.start(cmd) - stdout = None - stderr = None - if self.runobj.needs_parsing: - stdout = asyncio.subprocess.PIPE - stderr = None if self.options.verbose else asyncio.subprocess.PIPE - elif self.console_mode is ConsoleUser.LOGGER: + if self.console_mode is ConsoleUser.GDB: + stdout = None + stderr = None + else: stdout = asyncio.subprocess.PIPE - stderr = asyncio.subprocess.PIPE if self.options.split else asyncio.subprocess.STDOUT + stderr = asyncio.subprocess.STDOUT \ + if not self.options.split and not self.runobj.needs_parsing \ + else asyncio.subprocess.PIPE extra_cmd = [] # type: T.List[str] if self.test.protocol is TestProtocol.GTEST: @@ -1281,7 +1294,7 @@ class SingleTestRunner: if self.runobj.needs_parsing: parse_task = self.runobj.parse(p.stdout_lines(self.console_mode)) - stdo_task, stde_task = p.communicate() + stdo_task, stde_task = p.communicate(self.console_mode) returncode, result, additional_error = await p.wait(self.runobj.timeout) if parse_task is not None: