From 52a2f46af16ce040e97110b55dead36ab4d50f0f Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Fri, 22 Jan 2021 12:10:05 +0100 Subject: unittests: use utf-8 encoding for child processes Ensure that unit tests will be able to parse UTF-8 output of "meson test". --- run_unittests.py | 1 + 1 file changed, 1 insertion(+) diff --git a/run_unittests.py b/run_unittests.py index b244a07..8762b9c 100755 --- a/run_unittests.py +++ b/run_unittests.py @@ -1600,6 +1600,7 @@ class BasePlatformTests(unittest.TestCase): p = subprocess.run(command, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, env=env, + encoding='utf-8', universal_newlines=True, cwd=workdir, timeout=60 * 5) print(p.stdout) if p.returncode != 0: -- cgit v1.1 From 2386f336f18812058f15cc184cf8088cc6032a3c Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Fri, 22 Jan 2021 10:29:34 +0100 Subject: mtest: log in verbose mode, but not in gdb mode This is now possible because all stdout/stderr goes through asyncio pipes. However, logs make little sense in gdb mode. --- mesonbuild/mtest.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index d410dba..7c6043e 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -1578,7 +1578,7 @@ class TestHarness: l.flush() def open_logfiles(self) -> None: - if not self.options.logbase or self.options.verbose: + if not self.options.logbase or self.options.gdb: return namebase = None -- cgit v1.1 From a118cae9d29a172fac9e1fa7874902ab2475551d Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Fri, 15 Jan 2021 09:25:01 +0100 Subject: mtest: small refactoring of log printing Start moving console-specific code to ConsoleLogger, as well as moving code out of get_log(). --- mesonbuild/mtest.py | 57 ++++++++++++++++++++++++++++++++--------------------- 1 file changed, 34 insertions(+), 23 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 7c6043e..2dcc27d 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -140,12 +140,12 @@ def add_arguments(parser: argparse.ArgumentParser) -> None: '"subprojname:" to run all tests defined by "subprojname".') -def print_safe(s: str) -> None: +def print_safe(s: str, end: str = '\n') -> None: try: - print(s) + print(s, end=end) except UnicodeEncodeError: s = s.encode('ascii', errors='backslashreplace').decode('ascii') - print(s) + print(s, end=end) def join_lines(a: str, b: str) -> str: if not a: @@ -228,15 +228,18 @@ class TestResult(enum.Enum): def was_killed(self) -> bool: return self in (TestResult.TIMEOUT, TestResult.INTERRUPT) - def get_text(self, colorize: bool) -> str: - result_str = '{res:{reslen}}'.format(res=self.value, reslen=self.maxlen()) + def colorize(self, s: str) -> mlog.AnsiDecorator: if self.is_bad(): decorator = mlog.red elif self in (TestResult.SKIP, TestResult.EXPECTEDFAIL): decorator = mlog.yellow else: decorator = mlog.green - return decorator(result_str).get_text(colorize) + return decorator(s) + + def get_text(self, colorize: bool) -> str: + result_str = '{res:{reslen}}'.format(res=self.value, reslen=self.maxlen()) + return self.colorize(result_str).get_text(colorize) TYPE_TAPResult = T.Union['TAPParser.Test', 'TAPParser.Error', 'TAPParser.Version', 'TAPParser.Plan', 'TAPParser.Bailout'] @@ -553,6 +556,22 @@ class ConsoleLogger(TestLogger): self.running_tests.move_to_end(test, last=False) self.request_update() + def shorten_log(self, result: 'TestRun') -> str: + log = result.get_log() + lines = log.splitlines() + if len(lines) < 103: + return log + else: + log = '\n'.join(lines[:2]) + log += '\n--- Listing only the last 100 lines from a long log. ---\n' + log += lines[2] + '\n' + log += '\n'.join(lines[-100:]) + return log + + def print_log(self, result: 'TestRun', log: str) -> None: + print_safe(log, end='') + print(flush=True) + def log(self, harness: 'TestHarness', result: 'TestRun') -> None: self.running_tests.remove(result) if result.res is TestResult.TIMEOUT and harness.options.verbose: @@ -579,7 +598,7 @@ class ConsoleLogger(TestLogger): print('\n\nThe output from the failed tests:\n') for i, result in enumerate(harness.collected_failures, 1): print(harness.format(result, mlog.colorize_console())) - print_safe(result.get_log_short()) + self.print_log(result, self.shorten_log(result)) if i == 10: break @@ -813,6 +832,13 @@ class TestRun: self.stdo = stdo self.stde = stde + @property + def cmdline(self) -> T.Optional[str]: + if not self.cmd: + return None + test_only_env = set(self.env.items()) - set(os.environ.items()) + return env_tuple_to_str(test_only_env) + ' '.join(self.cmd) + def complete_skip(self, message: str) -> None: self.starttime = time.time() self._complete(GNU_SKIP_RETURNCODE, TestResult.SKIP, message, None) @@ -826,11 +852,8 @@ class TestRun: if self.cmd is None: res += 'NONE\n' else: - test_only_env = set(self.env.items()) - set(os.environ.items()) starttime_str = time.strftime("%H:%M:%S", time.gmtime(self.starttime)) - res += '{} {}{}\n'.format( - starttime_str, env_tuple_to_str(test_only_env), ' '.join(self.cmd) - ) + res += '{} {}\n'.format(starttime_str, self.cmdline) if self.stdo: res += '--- stdout ---\n' res += self.stdo @@ -844,18 +867,6 @@ class TestRun: res += '-------\n' return res - def get_log_short(self) -> str: - log = self.get_log() - lines = log.splitlines() - if len(lines) < 103: - return log - else: - log = '\n'.join(lines[:2]) - log += '\n--- Listing only the last 100 lines from a long log. ---\n' - log += lines[2] + '\n' - log += '\n'.join(lines[-100:]) - return log - @property def needs_parsing(self) -> bool: return False -- cgit v1.1 From 111f22a4f8c45e2191caeed42de739953a41d4fa Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 11:35:05 +0100 Subject: mtest: make log output more suitable for console Right now the same code is used to print the logs for both the console and the text log. Differentiating them lets the important bits of the console output stand out, and makes the console output a bit more readable. --- mesonbuild/mtest.py | 111 ++++++++++++++++++++++++++++++++++------------------ 1 file changed, 74 insertions(+), 37 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 2dcc27d..dd03515 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -154,6 +154,15 @@ def join_lines(a: str, b: str) -> str: return a return a + '\n' + b +def dashes(s: str, dash: str, cols: int) -> str: + if not s: + return dash * cols + s = ' ' + s + ' ' + width = uniwidth(s) + first = (cols - width) // 2 + s = dash * first + s + return s + dash * (cols - first - width) + 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 @@ -241,6 +250,9 @@ class TestResult(enum.Enum): result_str = '{res:{reslen}}'.format(res=self.value, reslen=self.maxlen()) return self.colorize(result_str).get_text(colorize) + def get_command_marker(self) -> str: + return str(self.colorize('>>> ')) + TYPE_TAPResult = T.Union['TAPParser.Test', 'TAPParser.Error', 'TAPParser.Version', 'TAPParser.Plan', 'TAPParser.Bailout'] @@ -452,6 +464,9 @@ class ConsoleLogger(TestLogger): SPINNER = "\U0001f311\U0001f312\U0001f313\U0001f314" + \ "\U0001f315\U0001f316\U0001f317\U0001f318" + SCISSORS = "\u2700 " + HLINE = "\u2015" + def __init__(self) -> None: self.update = asyncio.Event() self.running_tests = OrderedSet() # type: OrderedSet['TestRun'] @@ -464,6 +479,20 @@ class ConsoleLogger(TestLogger): self.test_count = 0 self.started_tests = 0 self.spinner_index = 0 + try: + self.cols, _ = os.get_terminal_size(1) + self.is_tty = True + except OSError: + self.cols = 80 + self.is_tty = False + + self.output_start = dashes(self.SCISSORS, self.HLINE, self.cols - 2) + self.output_end = dashes('', self.HLINE, self.cols - 2) + try: + self.output_start.encode(sys.stdout.encoding or 'ascii') + except UnicodeEncodeError: + self.output_start = dashes('8<', '-', self.cols - 2) + self.output_end = dashes('', '-', self.cols - 2) def flush(self) -> None: if self.should_erase_line: @@ -504,14 +533,6 @@ class ConsoleLogger(TestLogger): left=left, right=right) self.print_progress(line) - @staticmethod - def is_tty() -> bool: - try: - _, _ = os.get_terminal_size(1) - return True - except OSError: - return False - def start(self, harness: 'TestHarness') -> None: async def report_progress() -> None: loop = asyncio.get_event_loop() @@ -544,8 +565,9 @@ class ConsoleLogger(TestLogger): self.flush() self.test_count = harness.test_count + self.cols = max(self.cols, harness.max_left_width + 30) - if self.is_tty() and not harness.need_console: + 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()) @@ -557,19 +579,23 @@ class ConsoleLogger(TestLogger): self.request_update() def shorten_log(self, result: 'TestRun') -> str: - log = result.get_log() + log = result.get_log(mlog.colorize_console()) lines = log.splitlines() - if len(lines) < 103: + if len(lines) < 100: return log else: - log = '\n'.join(lines[:2]) - log += '\n--- Listing only the last 100 lines from a long log. ---\n' - log += lines[2] + '\n' - log += '\n'.join(lines[-100:]) - return log + return str(mlog.bold('Listing only the last 100 lines from a long log.\n')) + '\n'.join(lines[-100:]) def print_log(self, result: 'TestRun', log: str) -> None: - print_safe(log, end='') + cmdline = result.cmdline + if not cmdline: + print(result.res.get_command_marker() + result.stdo) + return + print(result.res.get_command_marker() + cmdline) + if log: + print(self.output_start) + print_safe(log, end='') + print(self.output_end) print(flush=True) def log(self, harness: 'TestHarness', result: 'TestRun') -> None: @@ -582,6 +608,8 @@ class ConsoleLogger(TestLogger): self.flush() print(harness.format(result, mlog.colorize_console(), max_left_width=self.max_left_width), flush=True) + if result.res.is_bad(): + self.print_log(result, '') self.request_update() async def finish(self, harness: 'TestHarness') -> None: @@ -616,8 +644,14 @@ class TextLogfileBuilder(TestFileLogger): self.file.write('Inherited environment: {}\n\n'.format(inherit_env)) def log(self, harness: 'TestHarness', result: 'TestRun') -> None: - self.file.write(harness.format(result, False)) - self.file.write("\n\n" + result.get_log() + "\n") + self.file.write(harness.format(result, False) + '\n') + cmdline = result.cmdline + if cmdline: + starttime_str = time.strftime("%H:%M:%S", time.gmtime(result.starttime)) + self.file.write(starttime_str + ' ' + cmdline + '\n') + self.file.write(dashes('output', '-', 78) + '\n') + self.file.write(result.get_log()) + self.file.write(dashes('', '-', 78) + '\n\n') async def finish(self, harness: 'TestHarness') -> None: if harness.collected_failures: @@ -847,24 +881,20 @@ class TestRun: stdo: T.Optional[str], stde: T.Optional[str]) -> None: self._complete(returncode, res, stdo, stde) - def get_log(self) -> str: - res = '--- command ---\n' - if self.cmd is None: - res += 'NONE\n' - else: - starttime_str = time.strftime("%H:%M:%S", time.gmtime(self.starttime)) - res += '{} {}\n'.format(starttime_str, self.cmdline) - if self.stdo: - res += '--- stdout ---\n' - res += self.stdo + def get_log(self, colorize: bool = False) -> str: if self.stde: - if res[-1:] != '\n': - res += '\n' - res += '--- stderr ---\n' + res = '' + if self.stdo: + res += mlog.cyan('stdout:').get_text(colorize) + '\n' + res += self.stdo + if res[-1:] != '\n': + res += '\n' + res += mlog.cyan('stderr:').get_text(colorize) + '\n' res += self.stde - if res[-1:] != '\n': + else: + res = self.stdo + if res and res[-1:] != '\n': res += '\n' - res += '-------\n' return res @property @@ -1418,21 +1448,28 @@ class TestHarness: for l in self.loggers: l.log(self, result) + @property + def numlen(self) -> int: + return len(str(self.test_count)) + + @property + def max_left_width(self) -> int: + return 2 * self.numlen + 2 + def format(self, result: TestRun, colorize: bool, max_left_width: int = 0, left: T.Optional[str] = None, right: T.Optional[str] = None) -> str: - numlen = len(str(self.test_count)) if left is None: left = '{num:{numlen}}/{testcount} '.format( - numlen=numlen, + numlen=self.numlen, num=result.num, testcount=self.test_count) # A non-default max_left_width lets the logger print more stuff before the # name, while ensuring that the rightmost columns remain aligned. - max_left_width = max(max_left_width, 2 * numlen + 2) + max_left_width = max(max_left_width, self.max_left_width) extra_name_width = max_left_width + self.name_max_len + 1 - uniwidth(result.name) - uniwidth(left) middle = result.name + (' ' * max(1, extra_name_width)) -- cgit v1.1 From 04bab9d595aea063bfe0cd832bbafb230184d7c3 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 13:29:53 +0100 Subject: mtest: include full environment in the TestRun object Ensure that all the required modifications are included in the logs. This makes it possible for users to cut-and-paste from the logs when trying to reproduce failures outside Meson. --- mesonbuild/mtest.py | 66 +++++++++++++++++++++++++++-------------------------- 1 file changed, 34 insertions(+), 32 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index dd03515..8bfacf3 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -1191,13 +1191,31 @@ class TestSubprocess: class SingleTestRunner: - def __init__(self, test: TestSerialisation, test_env: T.Dict[str, str], - env: T.Dict[str, str], name: str, + def __init__(self, test: TestSerialisation, env: T.Dict[str, str], name: str, options: argparse.Namespace): self.test = test - self.test_env = test_env - self.env = env self.options = options + self.cmd = self._get_cmd() + + if self.cmd and self.test.extra_paths: + env['PATH'] = os.pathsep.join(self.test.extra_paths + ['']) + env['PATH'] + winecmd = [] + for c in self.cmd: + winecmd.append(c) + if os.path.basename(c).startswith('wine'): + env['WINEPATH'] = get_wine_shortpath( + winecmd, + ['Z:' + p for p in self.test.extra_paths] + env.get('WINEPATH', '').split(';') + ) + break + + # If MALLOC_PERTURB_ is not set, or if it is set to an empty value, + # (i.e., the test or the environment don't explicitly set it), set + # it ourselves. We do this unconditionally for regular tests + # because it is extremely useful to have. + # Setting MALLOC_PERTURB_="0" will completely disable this feature. + if ('MALLOC_PERTURB_' not in env or not env['MALLOC_PERTURB_']) and not options.benchmark: + env['MALLOC_PERTURB_'] = str(random.randint(1, 255)) if self.options.gdb or self.test.timeout is None: timeout = None @@ -1206,7 +1224,7 @@ class SingleTestRunner: else: timeout = self.test.timeout - self.runobj = TestRun(test, test_env, name, timeout) + self.runobj = TestRun(test, env, name, timeout) if self.options.gdb: self.console_mode = ConsoleUser.GDB @@ -1215,7 +1233,7 @@ class SingleTestRunner: else: self.console_mode = ConsoleUser.LOGGER - def _get_cmd(self) -> T.Optional[T.List[str]]: + def _get_test_cmd(self) -> T.Optional[T.List[str]]: if self.test.fname[0].endswith('.jar'): return ['java', '-jar'] + self.test.fname elif not self.test.is_cross_built and run_with_mono(self.test.fname[0]): @@ -1235,6 +1253,12 @@ class SingleTestRunner: return self.test.exe_runner.get_command() + self.test.fname return self.test.fname + def _get_cmd(self) -> T.Optional[T.List[str]]: + test_cmd = self._get_test_cmd() + if not test_cmd: + return None + return TestHarness.get_wrapper(self.options) + test_cmd + @property def visible_name(self) -> str: return self.runobj.name @@ -1244,13 +1268,11 @@ class SingleTestRunner: return self.runobj.timeout async def run(self) -> TestRun: - cmd = self._get_cmd() - if cmd is None: + if self.cmd is None: skip_stdout = 'Not run because can not execute cross compiled binaries.' 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) + await self._run_cmd(self.cmd + self.test.cmd_args + self.options.test_args) return self.runobj async def _run_subprocess(self, args: T.List[str], *, @@ -1288,26 +1310,6 @@ class SingleTestRunner: 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: - self.env['PATH'] = os.pathsep.join(self.test.extra_paths + ['']) + self.env['PATH'] - winecmd = [] - for c in cmd: - winecmd.append(c) - if os.path.basename(c).startswith('wine'): - self.env['WINEPATH'] = get_wine_shortpath( - winecmd, - ['Z:' + p for p in self.test.extra_paths] + self.env.get('WINEPATH', '').split(';') - ) - break - - # If MALLOC_PERTURB_ is not set, or if it is set to an empty value, - # (i.e., the test or the environment don't explicitly set it), set - # it ourselves. We do this unconditionally for regular tests - # because it is extremely useful to have. - # Setting MALLOC_PERTURB_="0" will completely disable this feature. - 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) if self.console_mode is ConsoleUser.GDB: stdout = None @@ -1328,7 +1330,7 @@ class SingleTestRunner: p = await self._run_subprocess(cmd + extra_cmd, stdout=stdout, stderr=stderr, - env=self.env, + env=self.runobj.env, cwd=self.test.workdir) parse_task = None @@ -1425,7 +1427,7 @@ class TestHarness: if (test.is_cross_built and test.needs_exe_wrapper and test.exe_runner and test.exe_runner.found()): env['MESON_EXE_WRAPPER'] = join_args(test.exe_runner.get_command()) - return SingleTestRunner(test, test_env, env, name, options) + return SingleTestRunner(test, env, name, options) def process_test_result(self, result: TestRun) -> None: if result.res is TestResult.TIMEOUT: -- cgit v1.1 From a0da710172c4743abccaef774c99c0cef4b1d9c3 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 12:05:23 +0100 Subject: mtest: quote environment variable values and command line arguments --- mesonbuild/mtest.py | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 8bfacf3..e996931 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -30,6 +30,7 @@ import random import re import signal import subprocess +import shlex import sys import textwrap import time @@ -188,8 +189,13 @@ def returncode_to_status(retcode: int) -> str: signame = 'SIGinvalid' return '(exit status {} or signal {} {})'.format(retcode, signum, signame) +# TODO for Windows +sh_quote: T.Callable[[str], str] = lambda x: x +if not is_windows(): + sh_quote = shlex.quote + def env_tuple_to_str(env: T.Iterable[T.Tuple[str, str]]) -> str: - return ''.join(["{}='{}' ".format(k, v) for k, v in env]) + return ''.join(["{}={} ".format(k, sh_quote(v)) for k, v in env]) class TestException(MesonException): @@ -871,7 +877,8 @@ class TestRun: if not self.cmd: return None test_only_env = set(self.env.items()) - set(os.environ.items()) - return env_tuple_to_str(test_only_env) + ' '.join(self.cmd) + return env_tuple_to_str(test_only_env) + \ + ' '.join((sh_quote(x) for x in self.cmd)) def complete_skip(self, message: str) -> None: self.starttime = time.time() -- cgit v1.1 From 289cc2e2c5e807995a27488c1354e73286de0cdf Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 11:06:46 +0100 Subject: mtest: use buffered stdout/stderr in parallel mode Similar to ninja, buffer stdout/stderr even in verbose mode if more than one test is being run in parallel. --- mesonbuild/mtest.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index e996931..6169d7d 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -614,7 +614,9 @@ class ConsoleLogger(TestLogger): self.flush() print(harness.format(result, mlog.colorize_console(), max_left_width=self.max_left_width), flush=True) - if result.res.is_bad(): + if harness.options.verbose and harness.options.num_processes > 1: + self.print_log(result, result.get_log(mlog.colorize_console())) + elif result.res.is_bad(): self.print_log(result, '') self.request_update() @@ -1235,7 +1237,8 @@ class SingleTestRunner: if self.options.gdb: self.console_mode = ConsoleUser.GDB - elif self.options.verbose and not self.runobj.needs_parsing: + elif self.options.verbose and self.options.num_processes == 1 and \ + not self.runobj.needs_parsing: self.console_mode = ConsoleUser.STDOUT else: self.console_mode = ConsoleUser.LOGGER -- cgit v1.1 From 959e4b3a5e13f778892e9229bdb1fc3a6ad8d986 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Fri, 22 Jan 2021 09:20:57 +0100 Subject: mtest: call TestLogger.start_test when TestRun is in the RUNNING state --- mesonbuild/mtest.py | 21 +++++++++++++-------- 1 file changed, 13 insertions(+), 8 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 6169d7d..8c7ce59 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -442,7 +442,7 @@ class TestLogger: def start(self, harness: 'TestHarness') -> None: pass - def start_test(self, test: 'TestRun') -> None: + def start_test(self, harness: 'TestHarness', test: 'TestRun') -> None: pass def log(self, harness: 'TestHarness', result: 'TestRun') -> None: @@ -578,7 +578,7 @@ class ConsoleLogger(TestLogger): self.max_left_width = 3 * len(str(self.test_count)) + 8 self.progress_task = asyncio.ensure_future(report_progress()) - def start_test(self, test: 'TestRun') -> None: + def start_test(self, harness: 'TestHarness', test: 'TestRun') -> None: self.started_tests += 1 self.running_tests.add(test) self.running_tests.move_to_end(test, last=False) @@ -1277,12 +1277,16 @@ class SingleTestRunner: def timeout(self) -> T.Optional[int]: return self.runobj.timeout - async def run(self) -> TestRun: + async def run(self, harness: 'TestHarness') -> TestRun: if self.cmd is None: skip_stdout = 'Not run because can not execute cross compiled binaries.' + harness.log_start_test(self.runobj) self.runobj.complete_skip(skip_stdout) else: - await self._run_cmd(self.cmd + self.test.cmd_args + self.options.test_args) + cmd = self.cmd + self.test.cmd_args + self.options.test_args + self.runobj.start(cmd) + harness.log_start_test(self.runobj) + await self._run_cmd(cmd) return self.runobj async def _run_subprocess(self, args: T.List[str], *, @@ -1320,7 +1324,6 @@ class SingleTestRunner: postwait_fn=postwait_fn if not is_windows() else None) async def _run_cmd(self, cmd: T.List[str]) -> None: - self.runobj.start(cmd) if self.console_mode is ConsoleUser.GDB: stdout = None stderr = None @@ -1688,6 +1691,10 @@ class TestHarness: finally: self.close_logfiles() + def log_start_test(self, test: TestRun) -> None: + for l in self.loggers: + l.start_test(self, test) + async def _run_tests(self, runners: T.List[SingleTestRunner]) -> None: semaphore = asyncio.Semaphore(self.options.num_processes) futures = deque() # type: T.Deque[asyncio.Future] @@ -1699,9 +1706,7 @@ class TestHarness: async with semaphore: if interrupted or (self.options.repeat > 1 and self.fail_count): return - for l in self.loggers: - l.start_test(test.runobj) - res = await test.run() + res = await test.run(self) self.process_test_result(res) def test_done(f: asyncio.Future) -> None: -- cgit v1.1 From 4d6a0cc174c7374f398f33f56353334036c499b7 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 14 Jan 2021 11:37:34 +0100 Subject: mtest: log test start in verbose mode In non-parallel verbose mode the output of the test/benchmark is not buffered, therefore the command line is only printed by ConsoleLogger for failing tests and only after the test has run. Verbose mode is designed mostly for CI systems, where output must be human readable but is generally consumed from a browser with "Find" commands rather than from a terminal. With this usecase in mind, it is better to provide as much detail as possible, so add more output and just tell the user which tests have started. Do so, using the recently introduced TestResult.RUNNING state. --- mesonbuild/mtest.py | 50 +++++++++++++++++++++++++++++++++++++------------- 1 file changed, 37 insertions(+), 13 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 8c7ce59..657f284 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -240,6 +240,9 @@ class TestResult(enum.Enum): return self in {TestResult.FAIL, TestResult.TIMEOUT, TestResult.INTERRUPT, TestResult.UNEXPECTEDPASS, TestResult.ERROR} + def is_finished(self) -> bool: + return self not in {TestResult.PENDING, TestResult.RUNNING} + def was_killed(self) -> bool: return self in (TestResult.TIMEOUT, TestResult.INTERRUPT) @@ -248,8 +251,10 @@ class TestResult(enum.Enum): decorator = mlog.red elif self in (TestResult.SKIP, TestResult.EXPECTEDFAIL): decorator = mlog.yellow - else: + elif self.is_finished(): decorator = mlog.green + else: + decorator = mlog.blue return decorator(s) def get_text(self, colorize: bool) -> str: @@ -579,6 +584,17 @@ class ConsoleLogger(TestLogger): self.progress_task = asyncio.ensure_future(report_progress()) def start_test(self, harness: 'TestHarness', test: 'TestRun') -> None: + if harness.options.verbose and test.cmdline: + self.flush() + print(harness.format(test, mlog.colorize_console(), + max_left_width=self.max_left_width, + right=test.res.get_text(mlog.colorize_console()))) + print(test.res.get_command_marker() + test.cmdline) + if harness.options.num_processes == 1: + print(self.output_start, flush=True) + else: + print(flush=True) + self.started_tests += 1 self.running_tests.add(test) self.running_tests.move_to_end(test, last=False) @@ -592,12 +608,14 @@ class ConsoleLogger(TestLogger): else: return str(mlog.bold('Listing only the last 100 lines from a long log.\n')) + '\n'.join(lines[-100:]) - def print_log(self, result: 'TestRun', log: str) -> None: - cmdline = result.cmdline - if not cmdline: - print(result.res.get_command_marker() + result.stdo) - return - print(result.res.get_command_marker() + cmdline) + def print_log(self, harness: 'TestHarness', result: 'TestRun', log: str) -> None: + if not harness.options.verbose: + cmdline = result.cmdline + if not cmdline: + print(result.res.get_command_marker() + result.stdo) + return + print(result.res.get_command_marker() + cmdline) + if log: print(self.output_start) print_safe(log, end='') @@ -612,12 +630,18 @@ class ConsoleLogger(TestLogger): if not harness.options.quiet or not result.res.is_ok(): self.flush() - print(harness.format(result, mlog.colorize_console(), max_left_width=self.max_left_width), - flush=True) - if harness.options.verbose and harness.options.num_processes > 1: - self.print_log(result, result.get_log(mlog.colorize_console())) - elif result.res.is_bad(): - self.print_log(result, '') + if harness.options.verbose and harness.options.num_processes == 1 and result.cmdline: + print(self.output_end) + print(harness.format(result, mlog.colorize_console(), max_left_width=self.max_left_width)) + print(flush=True) + else: + print(harness.format(result, mlog.colorize_console(), max_left_width=self.max_left_width), + flush=True) + if harness.options.verbose: + self.print_log(harness, result, result.get_log(mlog.colorize_console())) + elif result.res.is_bad(): + self.print_log(harness, result, '') + self.request_update() async def finish(self, harness: 'TestHarness') -> None: -- cgit v1.1 From bb9d8b5b80e5f4aa421b4ad549d71fd103f2b1dc Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Fri, 22 Jan 2021 09:47:33 +0100 Subject: mtest: move --print-errorlogs output during the test run Print the (shortened) output of the failed tests as they happen. If neither --verbose nor --print-errorlogs was specified, omit the summary of failures, because it is pretty much the same as the earlier output of "meson test". --- mesonbuild/mtest.py | 31 +++++++++++++------------------ 1 file changed, 13 insertions(+), 18 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 657f284..494be8b 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -600,15 +600,21 @@ class ConsoleLogger(TestLogger): self.running_tests.move_to_end(test, last=False) self.request_update() - def shorten_log(self, result: 'TestRun') -> str: + def shorten_log(self, harness: 'TestHarness', result: 'TestRun') -> str: + if not harness.options.verbose and not harness.options.print_errorlogs: + return '' + log = result.get_log(mlog.colorize_console()) + if harness.options.verbose: + return log + lines = log.splitlines() if len(lines) < 100: return log else: return str(mlog.bold('Listing only the last 100 lines from a long log.\n')) + '\n'.join(lines[-100:]) - def print_log(self, harness: 'TestHarness', result: 'TestRun', log: str) -> None: + def print_log(self, harness: 'TestHarness', result: 'TestRun') -> None: if not harness.options.verbose: cmdline = result.cmdline if not cmdline: @@ -616,6 +622,7 @@ class ConsoleLogger(TestLogger): return print(result.res.get_command_marker() + cmdline) + log = self.shorten_log(harness, result) if log: print(self.output_start) print_safe(log, end='') @@ -637,10 +644,8 @@ class ConsoleLogger(TestLogger): else: print(harness.format(result, mlog.colorize_console(), max_left_width=self.max_left_width), flush=True) - if harness.options.verbose: - self.print_log(harness, result, result.get_log(mlog.colorize_console())) - elif result.res.is_bad(): - self.print_log(harness, result, '') + if harness.options.verbose or result.res.is_bad(): + self.print_log(harness, result) self.request_update() @@ -650,18 +655,8 @@ class ConsoleLogger(TestLogger): if self.progress_task: await self.progress_task - if harness.collected_failures: - if harness.options.print_errorlogs: - if len(harness.collected_failures) > 10: - print('\n\nThe output from 10 first failed tests:\n') - else: - print('\n\nThe output from the failed tests:\n') - for i, result in enumerate(harness.collected_failures, 1): - print(harness.format(result, mlog.colorize_console())) - self.print_log(result, self.shorten_log(result)) - if i == 10: - break - + if harness.collected_failures and \ + (harness.options.print_errorlogs or harness.options.verbose): print("\nSummary of Failures:\n") for i, result in enumerate(harness.collected_failures, 1): print(harness.format(result, mlog.colorize_console())) -- cgit v1.1 From 7b02abeac6541f045d41335c7d202919e8863e42 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Fri, 22 Jan 2021 09:45:31 +0100 Subject: mtest: infrastructure to print subtest results --- mesonbuild/mtest.py | 25 ++++++++++++++++++------- 1 file changed, 18 insertions(+), 7 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 494be8b..88e7f5d 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -450,6 +450,9 @@ class TestLogger: def start_test(self, harness: 'TestHarness', test: 'TestRun') -> None: pass + def log_subtest(self, harness: 'TestHarness', test: 'TestRun', s: str, res: TestResult) -> None: + pass + def log(self, harness: 'TestHarness', result: 'TestRun') -> None: pass @@ -929,7 +932,7 @@ class TestRun: def needs_parsing(self) -> bool: return False - async def parse(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: + async def parse(self, harness: 'TestHarness', lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: async for l in lines: pass return TestResult.OK, '' @@ -978,17 +981,19 @@ class TestRunTAP(TestRun): super().complete(returncode, res, stdo, stde) - async def parse(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: + async def parse(self, harness: 'TestHarness', 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 + harness.log_subtest(self, i.message, res) elif isinstance(i, TAPParser.Test): self.results.append(i) if i.result.is_bad(): res = TestResult.FAIL + harness.log_subtest(self, '{} {}'.format(i.number, i.name), i.result) elif isinstance(i, TAPParser.Error): error = '\nTAP parsing error: ' + i.message res = TestResult.ERROR @@ -1006,7 +1011,7 @@ class TestRunRust(TestRun): def needs_parsing(self) -> bool: return True - async def parse(self, lines: T.AsyncIterator[str]) -> T.Tuple[TestResult, str]: + async def parse(self, harness: 'TestHarness', 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) @@ -1022,7 +1027,9 @@ class TestRunRust(TestRun): 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)) + t = parse_res(n, name, result) + self.results.append(t) + harness.log_subtest(self, name, t.result) n += 1 if all(t.result is TestResult.SKIP for t in self.results): @@ -1305,7 +1312,7 @@ class SingleTestRunner: cmd = self.cmd + self.test.cmd_args + self.options.test_args self.runobj.start(cmd) harness.log_start_test(self.runobj) - await self._run_cmd(cmd) + await self._run_cmd(harness, cmd) return self.runobj async def _run_subprocess(self, args: T.List[str], *, @@ -1342,7 +1349,7 @@ class SingleTestRunner: 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: + async def _run_cmd(self, harness: 'TestHarness', cmd: T.List[str]) -> None: if self.console_mode is ConsoleUser.GDB: stdout = None stderr = None @@ -1367,7 +1374,7 @@ class SingleTestRunner: parse_task = None if self.runobj.needs_parsing: - parse_task = self.runobj.parse(p.stdout_lines(self.console_mode)) + parse_task = self.runobj.parse(harness, p.stdout_lines(self.console_mode)) stdo_task, stde_task = p.communicate(self.console_mode) returncode, result, additional_error = await p.wait(self.runobj.timeout) @@ -1710,6 +1717,10 @@ class TestHarness: finally: self.close_logfiles() + def log_subtest(self, test: TestRun, s: str, res: TestResult) -> None: + for l in self.loggers: + l.log_subtest(self, test, s, res) + def log_start_test(self, test: TestRun) -> None: for l in self.loggers: l.start_test(self, test) -- cgit v1.1 From 12b3d05d1ed530966659785ec784e6a4f97cb07b Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Fri, 22 Jan 2021 09:41:10 +0100 Subject: mtest: log individual TAP subtests --- mesonbuild/mtest.py | 45 ++++++++++++++++++++++++++++++++++----------- 1 file changed, 34 insertions(+), 11 deletions(-) diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 88e7f5d..b1d43bd 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -480,6 +480,7 @@ class ConsoleLogger(TestLogger): SCISSORS = "\u2700 " HLINE = "\u2015" + RTRI = "\u25B6 " def __init__(self) -> None: self.update = asyncio.Event() @@ -502,11 +503,13 @@ class ConsoleLogger(TestLogger): self.output_start = dashes(self.SCISSORS, self.HLINE, self.cols - 2) self.output_end = dashes('', self.HLINE, self.cols - 2) + self.sub = self.RTRI try: self.output_start.encode(sys.stdout.encoding or 'ascii') except UnicodeEncodeError: self.output_start = dashes('8<', '-', self.cols - 2) self.output_end = dashes('', '-', self.cols - 2) + self.sub = '| ' def flush(self) -> None: if self.should_erase_line: @@ -593,7 +596,9 @@ class ConsoleLogger(TestLogger): max_left_width=self.max_left_width, right=test.res.get_text(mlog.colorize_console()))) print(test.res.get_command_marker() + test.cmdline) - if harness.options.num_processes == 1: + if test.needs_parsing: + pass + elif harness.options.num_processes == 1: print(self.output_start, flush=True) else: print(flush=True) @@ -607,7 +612,8 @@ class ConsoleLogger(TestLogger): if not harness.options.verbose and not harness.options.print_errorlogs: return '' - log = result.get_log(mlog.colorize_console()) + log = result.get_log(mlog.colorize_console(), + stderr_only=result.needs_parsing) if harness.options.verbose: return log @@ -632,6 +638,16 @@ class ConsoleLogger(TestLogger): print(self.output_end) print(flush=True) + def log_subtest(self, harness: 'TestHarness', test: 'TestRun', s: str, result: TestResult) -> None: + if harness.options.verbose or (harness.options.print_errorlogs and result.is_bad()): + self.flush() + print(harness.format(test, mlog.colorize_console(), max_left_width=self.max_left_width, + prefix=self.sub, + middle=s, + right=result.get_text(mlog.colorize_console())), flush=True) + + self.request_update() + def log(self, harness: 'TestHarness', result: 'TestRun') -> None: self.running_tests.remove(result) if result.res is TestResult.TIMEOUT and harness.options.verbose: @@ -641,7 +657,8 @@ class ConsoleLogger(TestLogger): if not harness.options.quiet or not result.res.is_ok(): self.flush() if harness.options.verbose and harness.options.num_processes == 1 and result.cmdline: - print(self.output_end) + if not result.needs_parsing: + print(self.output_end) print(harness.format(result, mlog.colorize_console(), max_left_width=self.max_left_width)) print(flush=True) else: @@ -912,18 +929,19 @@ class TestRun: stdo: T.Optional[str], stde: T.Optional[str]) -> None: self._complete(returncode, res, stdo, stde) - def get_log(self, colorize: bool = False) -> str: + def get_log(self, colorize: bool = False, stderr_only: bool = False) -> str: + stdo = '' if stderr_only else self.stdo if self.stde: res = '' - if self.stdo: + if stdo: res += mlog.cyan('stdout:').get_text(colorize) + '\n' - res += self.stdo + res += stdo if res[-1:] != '\n': res += '\n' res += mlog.cyan('stderr:').get_text(colorize) + '\n' res += self.stde else: - res = self.stdo + res = stdo if res and res[-1:] != '\n': res += '\n' return res @@ -993,7 +1011,7 @@ class TestRunTAP(TestRun): self.results.append(i) if i.result.is_bad(): res = TestResult.FAIL - harness.log_subtest(self, '{} {}'.format(i.number, i.name), i.result) + harness.log_subtest(self, i.name or f'subtest {i.number}', i.result) elif isinstance(i, TAPParser.Error): error = '\nTAP parsing error: ' + i.message res = TestResult.ERROR @@ -1499,7 +1517,9 @@ class TestHarness: def format(self, result: TestRun, colorize: bool, max_left_width: int = 0, + prefix: str = '', left: T.Optional[str] = None, + middle: T.Optional[str] = None, right: T.Optional[str] = None) -> str: if left is None: @@ -1511,8 +1531,11 @@ class TestHarness: # A non-default max_left_width lets the logger print more stuff before the # name, while ensuring that the rightmost columns remain aligned. max_left_width = max(max_left_width, self.max_left_width) - extra_name_width = max_left_width + self.name_max_len + 1 - uniwidth(result.name) - uniwidth(left) - middle = result.name + (' ' * max(1, extra_name_width)) + + if middle is None: + middle = result.name + extra_mid_width = max_left_width + self.name_max_len + 1 - uniwidth(middle) - uniwidth(left) - uniwidth(prefix) + middle += ' ' * max(1, extra_mid_width) if right is None: right = '{res} {dur:{durlen}.2f}s'.format( @@ -1522,7 +1545,7 @@ class TestHarness: detail = result.detail if detail: right += ' ' + detail - return left + middle + right + return prefix + left + middle + right def summary(self) -> str: return textwrap.dedent(''' -- cgit v1.1 From ec02753fbf9c15389f953d9cfd040635f84779d9 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Wed, 20 Jan 2021 15:16:01 +0100 Subject: docs: add documentation snippet for meson test console output changes --- docs/markdown/snippets/meson_test_logs.md | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+) create mode 100644 docs/markdown/snippets/meson_test_logs.md diff --git a/docs/markdown/snippets/meson_test_logs.md b/docs/markdown/snippets/meson_test_logs.md new file mode 100644 index 0000000..b3f5a16 --- /dev/null +++ b/docs/markdown/snippets/meson_test_logs.md @@ -0,0 +1,29 @@ +## New logging format for `meson test` + +The console output format for `meson test` has changed in several ways. +The major changes are: + +* if stdout is a tty, `meson` includes a progress report. + +* if `--print-errorlogs` is specified, the logs are printed as test runs +rather than afterwards. All the error logs are printed rather than only +the first ten. + +* if `--verbose` is specified and `--num-processes` specifies more than +one concurrent test, test output is buffered and printed after the +test finishes + +* the console logs include a reproducer command. If `--verbose` is +specified, the command is printed for all tests at the time they starts; +otherwise, it is printed for failing tests at the time the test finishes + +* for TAP tests, Meson is able to report individual subtests. If +`--verbose` is specified, all tests are reported. If `--print-errorlogs` +is specified, only failures are. + +In addition, if `--verbose` was specified, Meson used not to generate +logs. This limitation has now been removed. + +These changes make the default `ninja test` output more readable, while +`--verbose` output is provides detailed but human-readable logs that +are well suited to CI environments. -- cgit v1.1