diff options
| -rw-r--r-- | docs/markdown/snippets/meson_test_logs.md | 29 | ||||
| -rw-r--r-- | mesonbuild/mtest.py | 350 | ||||
| -rwxr-xr-x | run_unittests.py | 1 |
3 files changed, 264 insertions, 116 deletions
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. diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 3525189..24db5ce 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 @@ -140,12 +141,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: @@ -154,6 +155,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 @@ -179,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): @@ -225,18 +240,29 @@ 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) - 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: + elif self.is_finished(): decorator = mlog.green - return decorator(result_str).get_text(colorize) + else: + decorator = mlog.blue + 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) + + def get_command_marker(self) -> str: + return str(self.colorize('>>> ')) TYPE_TAPResult = T.Union['TAPParser.Test', 'TAPParser.Error', 'TAPParser.Version', 'TAPParser.Plan', 'TAPParser.Bailout'] @@ -421,7 +447,10 @@ 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_subtest(self, harness: 'TestHarness', test: 'TestRun', s: str, res: TestResult) -> None: pass def log(self, harness: 'TestHarness', result: 'TestRun') -> None: @@ -449,6 +478,10 @@ class ConsoleLogger(TestLogger): SPINNER = "\U0001f311\U0001f312\U0001f313\U0001f314" + \ "\U0001f315\U0001f316\U0001f317\U0001f318" + SCISSORS = "\u2700 " + HLINE = "\u2015" + RTRI = "\u25B6 " + def __init__(self) -> None: self.update = asyncio.Event() self.running_tests = OrderedSet() # type: OrderedSet['TestRun'] @@ -461,6 +494,22 @@ 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) + 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: @@ -501,14 +550,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() @@ -541,18 +582,72 @@ 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()) - def start_test(self, test: 'TestRun') -> None: + 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 test.needs_parsing: + pass + elif 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) self.request_update() + 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(), + stderr_only=result.needs_parsing) + 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') -> 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) + + log = self.shorten_log(harness, result) + if log: + print(self.output_start) + print_safe(log, end='') + 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: @@ -561,8 +656,17 @@ 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 and result.cmdline: + 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: + print(harness.format(result, mlog.colorize_console(), max_left_width=self.max_left_width), + flush=True) + if harness.options.verbose or result.res.is_bad(): + self.print_log(harness, result) + self.request_update() async def finish(self, harness: 'TestHarness') -> None: @@ -571,18 +675,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())) - print_safe(result.get_log_short()) - 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())) @@ -597,8 +691,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: @@ -813,6 +913,14 @@ 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((sh_quote(x) for x in self.cmd)) + def complete_skip(self, message: str) -> None: self.starttime = time.time() self._complete(GNU_SKIP_RETURNCODE, TestResult.SKIP, message, None) @@ -821,46 +929,28 @@ 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: - 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) - ) - if self.stdo: - res += '--- stdout ---\n' - res += self.stdo + def get_log(self, colorize: bool = False, stderr_only: bool = False) -> str: + stdo = '' if stderr_only else self.stdo if self.stde: - if res[-1:] != '\n': - res += '\n' - res += '--- stderr ---\n' + res = '' + if stdo: + res += mlog.cyan('stdout:').get_text(colorize) + '\n' + res += stdo + if res[-1:] != '\n': + res += '\n' + res += mlog.cyan('stderr:').get_text(colorize) + '\n' res += self.stde - if res[-1:] != '\n': + else: + res = stdo + if res and res[-1:] != '\n': res += '\n' - 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 - 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, '' @@ -909,17 +999,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, i.name or f'subtest {i.number}', i.result) elif isinstance(i, TAPParser.Error): error = '\nTAP parsing error: ' + i.message res = TestResult.ERROR @@ -937,7 +1029,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) @@ -953,7 +1045,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): @@ -1150,13 +1244,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 or self.test.timeout <= 0: timeout = None @@ -1167,16 +1279,17 @@ class SingleTestRunner: else: timeout = self.test.timeout * self.options.timeout_multiplier - self.runobj = TestRun(test, test_env, name, timeout) + self.runobj = TestRun(test, env, name, timeout) 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 - 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]): @@ -1196,6 +1309,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 @@ -1204,14 +1323,16 @@ class SingleTestRunner: def timeout(self) -> T.Optional[int]: return self.runobj.timeout - async def run(self) -> TestRun: - cmd = self._get_cmd() - if cmd is None: + 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: - wrap = TestHarness.get_wrapper(self.options) - await self._run_cmd(wrap + 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(harness, cmd) return self.runobj async def _run_subprocess(self, args: T.List[str], *, @@ -1248,28 +1369,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: - 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) + async def _run_cmd(self, harness: 'TestHarness', cmd: T.List[str]) -> None: if self.console_mode is ConsoleUser.GDB: stdout = None stderr = None @@ -1289,12 +1389,12 @@ 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 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) @@ -1386,7 +1486,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: @@ -1409,23 +1509,35 @@ 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, + prefix: str = '', left: T.Optional[str] = None, + middle: 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) - extra_name_width = max_left_width + self.name_max_len + 1 - uniwidth(result.name) - uniwidth(left) - middle = result.name + (' ' * max(1, extra_name_width)) + max_left_width = max(max_left_width, self.max_left_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( @@ -1435,7 +1547,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(''' @@ -1580,7 +1692,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 @@ -1630,6 +1742,14 @@ 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) + async def _run_tests(self, runners: T.List[SingleTestRunner]) -> None: semaphore = asyncio.Semaphore(self.options.num_processes) futures = deque() # type: T.Deque[asyncio.Future] @@ -1641,9 +1761,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: diff --git a/run_unittests.py b/run_unittests.py index e2c108f..2a14f78 100755 --- a/run_unittests.py +++ b/run_unittests.py @@ -1603,6 +1603,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: |