From 30741a0f202cf6cdf3c84645978bc7b38ed24b28 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 09:52:23 +0100 Subject: mtest: create TestRun object early on This will provide a way to pass more information from the TestHarness local variables to the SingleTestRunner and use them outside the run_test function. For example, the name could be used to report progress while the tests are running. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 99 ++++++++++++++++++++++++++++------------------------- 1 file changed, 52 insertions(+), 47 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 4f687a5..34e4943 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -166,6 +166,8 @@ class TestException(MesonException): @enum.unique class TestResult(enum.Enum): + PENDING = 'PENDING' + RUNNING = 'RUNNING' OK = 'OK' TIMEOUT = 'TIMEOUT' INTERRUPT = 'INTERRUPT' @@ -450,40 +452,50 @@ class JunitBuilder: class TestRun: - @classmethod - def make_gtest(cls, test: TestSerialisation, test_env: T.Dict[str, str], - returncode: int, starttime: float, duration: float, - stdo: T.Optional[str], stde: T.Optional[str], - cmd: T.Optional[T.List[str]]) -> 'TestRun': - filename = '{}.xml'.format(test.name) - if test.workdir: - filename = os.path.join(test.workdir, filename) + def __init__(self, test: TestSerialisation, test_env: T.Dict[str, str]): + self.res = TestResult.PENDING + self.test = test + self.results = list() # type: T.List[TestResult] + self.returncode = 0 + self.starttime = None # type: T.Optional[float] + self.duration = None # type: T.Optional[float] + 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.should_fail = test.should_fail + self.project = test.project_name + self.junit = None # type: T.Optional[et.ElementTree] + + def start(self) -> None: + self.res = TestResult.RUNNING + self.starttime = time.time() + + def complete_gtest(self, returncode: int, + stdo: T.Optional[str], stde: T.Optional[str], + cmd: T.List[str]) -> None: + filename = '{}.xml'.format(self.test.name) + if self.test.workdir: + filename = os.path.join(self.test.workdir, filename) tree = et.parse(filename) - return cls.make_exitcode( - test, test_env, returncode, starttime, duration, stdo, stde, cmd, - junit=tree) + self.complete_exitcode(returncode, stdo, stde, cmd, junit=tree) - @classmethod - def make_exitcode(cls, test: TestSerialisation, test_env: T.Dict[str, str], - returncode: int, starttime: float, duration: float, - stdo: T.Optional[str], stde: T.Optional[str], - cmd: T.Optional[T.List[str]], **kwargs: T.Any) -> 'TestRun': + def complete_exitcode(self, returncode: int, + stdo: T.Optional[str], stde: T.Optional[str], + cmd: T.List[str], + **kwargs: T.Any) -> None: if returncode == GNU_SKIP_RETURNCODE: res = TestResult.SKIP elif returncode == GNU_ERROR_RETURNCODE: res = TestResult.ERROR - elif test.should_fail: + elif self.should_fail: res = TestResult.EXPECTEDFAIL if bool(returncode) else TestResult.UNEXPECTEDPASS else: res = TestResult.FAIL if bool(returncode) else TestResult.OK - return cls(test, test_env, res, [], returncode, starttime, duration, stdo, stde, cmd, **kwargs) + self.complete(res, [], returncode, stdo, stde, cmd, **kwargs) - @classmethod - def make_tap(cls, test: TestSerialisation, test_env: T.Dict[str, str], - returncode: int, starttime: float, duration: float, - stdo: str, stde: str, - cmd: T.Optional[T.List[str]]) -> 'TestRun': + def complete_tap(self, returncode: int, stdo: str, stde: str, cmd: T.List[str]) -> None: res = None # type: T.Optional[TestResult] results = [] # type: T.List[TestResult] failed = False @@ -510,30 +522,25 @@ class TestRun: if all(t is TestResult.SKIP for t in results): # This includes the case where num_tests is zero res = TestResult.SKIP - elif test.should_fail: + elif self.should_fail: res = TestResult.EXPECTEDFAIL if failed else TestResult.UNEXPECTEDPASS else: res = TestResult.FAIL if failed else TestResult.OK - return cls(test, test_env, res, results, returncode, starttime, duration, stdo, stde, cmd) + self.complete(res, results, returncode, stdo, stde, cmd) - def __init__(self, test: TestSerialisation, test_env: T.Dict[str, str], - res: TestResult, results: T.List[TestResult], returncode: - int, starttime: float, duration: float, + def complete(self, res: TestResult, results: T.List[TestResult], + returncode: int, stdo: T.Optional[str], stde: T.Optional[str], - cmd: T.Optional[T.List[str]], *, junit: T.Optional[et.ElementTree] = None): + cmd: T.List[str], *, junit: T.Optional[et.ElementTree] = None) -> None: assert isinstance(res, TestResult) self.res = res - self.results = results # May be an empty list + self.results = results self.returncode = returncode - self.starttime = starttime - self.duration = duration + self.duration = time.time() - self.starttime self.stdo = stdo self.stde = stde self.cmd = cmd - self.env = test_env - self.should_fail = test.should_fail - self.project = test.project_name self.junit = junit def get_log(self) -> str: @@ -645,6 +652,7 @@ class SingleTestRunner: self.test_env = test_env self.env = env self.options = options + self.runobj = TestRun(test, test_env) def _get_cmd(self) -> T.Optional[T.List[str]]: if self.test.fname[0].endswith('.jar'): @@ -668,14 +676,16 @@ 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.' - return TestRun(self.test, self.test_env, TestResult.SKIP, [], GNU_SKIP_RETURNCODE, time.time(), 0.0, skip_stdout, None, None) + self.runobj.complete(TestResult.SKIP, [], GNU_SKIP_RETURNCODE, skip_stdout, None, None) else: wrap = TestHarness.get_wrapper(self.options) if self.options.gdb: self.test.timeout = None - return await self._run_cmd(wrap + cmd + self.test.cmd_args + self.options.test_args) + await self._run_cmd(wrap + cmd + self.test.cmd_args + self.options.test_args) + return self.runobj async def _run_subprocess(self, args: T.List[str], *, timeout: T.Optional[int], stdout: T.IO, stderr: T.IO, @@ -762,9 +772,7 @@ class SingleTestRunner: return p.returncode or 0, result, additional_error - async def _run_cmd(self, cmd: T.List[str]) -> TestRun: - starttime = time.time() - + 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 = [] @@ -813,8 +821,6 @@ class SingleTestRunner: stderr=stderr, env=self.env, cwd=self.test.workdir) - endtime = time.time() - duration = endtime - starttime if additional_error is None: if stdout is None: stdo = '' @@ -830,17 +836,16 @@ class SingleTestRunner: stdo = "" stde = additional_error if result: - return TestRun(self.test, self.test_env, result, [], returncode, starttime, duration, stdo, stde, cmd) + self.runobj.complete(result, [], returncode, stdo, stde, cmd) else: if self.test.protocol is TestProtocol.EXITCODE: - return TestRun.make_exitcode(self.test, self.test_env, returncode, starttime, duration, stdo, stde, cmd) + self.runobj.complete_exitcode(returncode, stdo, stde, cmd) elif self.test.protocol is TestProtocol.GTEST: - return TestRun.make_gtest(self.test, self.test_env, returncode, starttime, duration, stdo, stde, cmd) + self.runobj.complete_gtest(returncode, stdo, stde, cmd) else: if self.options.verbose: print(stdo, end='') - return TestRun.make_tap(self.test, self.test_env, returncode, starttime, duration, stdo, stde, cmd) - + self.runobj.complete_tap(returncode, stdo, stde, cmd) class TestHarness: def __init__(self, options: argparse.Namespace): -- cgit v1.1 From 3f8c9012459d4923cc3167bf4859e2f8a6794f96 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 10:08:07 +0100 Subject: mtest: add name and number to TestRun Place in TestRun everything that is needed in order to format the result. This avoids passing around the number and visible test name as arguments. Test numbers are assigned the first time they are used. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 56 +++++++++++++++++++++++++++++++---------------------- 1 file changed, 33 insertions(+), 23 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 34e4943..c754309 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -353,12 +353,12 @@ class JunitBuilder: 'testsuites', tests='0', errors='0', failures='0') self.suites = {} # type: T.Dict[str, et.Element] - def log(self, name: str, test: 'TestRun') -> None: + def log(self, test: 'TestRun') -> None: """Log a single test case.""" if test.junit is not None: for suite in test.junit.findall('.//testsuite'): # Assume that we don't need to merge anything here... - suite.attrib['name'] = '{}.{}.{}'.format(test.project, name, suite.attrib['name']) + suite.attrib['name'] = '{}.{}.{}'.format(test.project, test.name, suite.attrib['name']) # GTest can inject invalid attributes for case in suite.findall('.//testcase[@result]'): @@ -372,7 +372,7 @@ class JunitBuilder: # We want to record this so that each result is recorded # separately if test.results: - suitename = '{}.{}'.format(test.project, name) + suitename = '{}.{}'.format(test.project, test.name) assert suitename not in self.suites, 'duplicate suite' suite = self.suites[suitename] = et.Element( @@ -420,7 +420,7 @@ class JunitBuilder: suite = self.suites[test.project] suite.attrib['tests'] = str(int(suite.attrib['tests']) + 1) - testcase = et.SubElement(suite, 'testcase', name=name, classname=name) + testcase = et.SubElement(suite, 'testcase', name=test.name, classname=test.name) if test.res is TestResult.SKIP: et.SubElement(testcase, 'skipped') suite.attrib['skipped'] = str(int(suite.attrib['skipped']) + 1) @@ -451,10 +451,14 @@ class JunitBuilder: class TestRun: + TEST_NUM = 0 - def __init__(self, test: TestSerialisation, test_env: T.Dict[str, str]): + def __init__(self, test: TestSerialisation, test_env: T.Dict[str, str], + name: str): self.res = TestResult.PENDING self.test = test + self._num = None # type: T.Optional[int] + self.name = name self.results = list() # type: T.List[TestResult] self.returncode = 0 self.starttime = None # type: T.Optional[float] @@ -529,6 +533,13 @@ class TestRun: self.complete(res, results, returncode, stdo, stde, cmd) + @property + def num(self) -> int: + if self._num is None: + TestRun.TEST_NUM += 1 + self._num = TestRun.TEST_NUM + return self._num + def complete(self, res: TestResult, results: T.List[TestResult], returncode: int, stdo: T.Optional[str], stde: T.Optional[str], @@ -574,8 +585,8 @@ def decode(stream: T.Union[None, bytes]) -> str: except UnicodeDecodeError: return stream.decode('iso-8859-1', errors='ignore') -def write_json_log(jsonlogfile: T.TextIO, test_name: str, result: TestRun) -> None: - jresult = {'name': test_name, +def write_json_log(jsonlogfile: T.TextIO, result: TestRun) -> None: + jresult = {'name': result.name, 'stdout': result.stdo, 'result': result.res.value, 'starttime': result.starttime, @@ -647,12 +658,13 @@ async def complete_all(futures: T.Iterable[asyncio.Future]) -> None: class SingleTestRunner: def __init__(self, test: TestSerialisation, test_env: T.Dict[str, str], - env: T.Dict[str, str], options: argparse.Namespace): + 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.runobj = TestRun(test, test_env) + self.runobj = TestRun(test, test_env, name) def _get_cmd(self) -> T.Optional[T.List[str]]: if self.test.fname[0].endswith('.jar'): @@ -915,7 +927,7 @@ class TestHarness: options.wrapper = current.exe_wrapper return current.env.get_env(os.environ.copy()) - def get_test_runner(self, test: TestSerialisation) -> SingleTestRunner: + def get_test_runner(self, test: TestSerialisation, name: str) -> SingleTestRunner: options = deepcopy(self.options) if not options.setup: options.setup = self.build_data.test_setup_default_name @@ -928,7 +940,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, options) + return SingleTestRunner(test, test_env, env, name, options) def process_test_result(self, result: TestRun) -> None: if result.res is TestResult.TIMEOUT: @@ -947,17 +959,16 @@ class TestHarness: sys.exit('Unknown test result encountered: {}'.format(result.res)) def print_stats(self, test_count: int, name_max_len: int, - tests: T.List[TestSerialisation], - name: str, result: TestRun, i: int) -> None: + result: TestRun) -> None: ok_statuses = (TestResult.OK, TestResult.EXPECTEDFAIL) bad_statuses = (TestResult.FAIL, TestResult.TIMEOUT, TestResult.INTERRUPT, TestResult.UNEXPECTEDPASS, TestResult.ERROR) result_str = '{num:{numlen}}/{testcount} {name:{name_max_len}} {res:{reslen}} {dur:.2f}s'.format( numlen=len(str(test_count)), - num=i, + num=result.num, testcount=test_count, name_max_len=name_max_len, - name=name, + name=result.name, reslen=TestResult.maxlen(), res=result.res.value, dur=result.duration) @@ -979,9 +990,9 @@ class TestHarness: if self.logfile: self.logfile.write(result_str) if self.jsonlogfile: - write_json_log(self.jsonlogfile, name, result) + write_json_log(self.jsonlogfile, result) if self.junit: - self.junit.log(name, result) + self.junit.log(result) def print_summary(self) -> None: # Prepend a list of failures @@ -1201,14 +1212,13 @@ class TestHarness: self.build_data = build.load(os.getcwd()) interrupted = False - async def run_test(test: SingleTestRunner, - name: str, index: int) -> None: + async def run_test(test: SingleTestRunner) -> None: async with semaphore: if interrupted or (self.options.repeat > 1 and self.fail_count): return res = await test.run() self.process_test_result(res) - self.print_stats(test_count, name_max_len, tests, name, res, index) + self.print_stats(test_count, name_max_len, res) def test_done(f: asyncio.Future) -> None: if not f.cancelled(): @@ -1253,13 +1263,13 @@ class TestHarness: asyncio.get_event_loop().add_signal_handler(signal.SIGTERM, sigterm_handler) try: for _ in range(self.options.repeat): - for i, test in enumerate(tests, 1): + for test in tests: visible_name = self.get_pretty_suite(test) - single_test = self.get_test_runner(test) + single_test = self.get_test_runner(test, visible_name) if not test.is_parallel or single_test.options.gdb: await complete_all(futures) - future = asyncio.ensure_future(run_test(single_test, visible_name, i)) + future = asyncio.ensure_future(run_test(single_test)) futures.append(future) running_tests[future] = visible_name future.add_done_callback(test_done) -- cgit v1.1 From 9d29bd022502d1f3a0bc64e40da84fc61a5a3843 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 09:10:58 +0100 Subject: mtest: move test_count and name_max_len to TestHarness class Avoid passing them around as parameters; this will be useful when logging is moved out of TestHarness, because individual loggers will call back into TestHarness to do common formatting chores. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index c754309..4685b7d 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -870,13 +870,15 @@ class TestHarness: self.success_count = 0 self.skip_count = 0 self.timeout_count = 0 + self.test_count = 0 + self.name_max_len = 0 self.is_run = False - self.tests = None self.results = [] # type: T.List[TestRun] self.logfilename = None # type: T.Optional[str] self.logfile = None # type: T.Optional[T.TextIO] self.jsonlogfile = None # type: T.Optional[T.TextIO] self.junit = None # type: T.Optional[JunitBuilder] + if self.options.benchmark: self.tests = load_benchmarks(options.wd) else: @@ -958,16 +960,15 @@ class TestHarness: else: sys.exit('Unknown test result encountered: {}'.format(result.res)) - def print_stats(self, test_count: int, name_max_len: int, - result: TestRun) -> None: + def print_stats(self, result: TestRun) -> None: ok_statuses = (TestResult.OK, TestResult.EXPECTEDFAIL) bad_statuses = (TestResult.FAIL, TestResult.TIMEOUT, TestResult.INTERRUPT, TestResult.UNEXPECTEDPASS, TestResult.ERROR) result_str = '{num:{numlen}}/{testcount} {name:{name_max_len}} {res:{reslen}} {dur:.2f}s'.format( - numlen=len(str(test_count)), + numlen=len(str(self.test_count)), num=result.num, - testcount=test_count, - name_max_len=name_max_len, + testcount=self.test_count, + name_max_len=self.name_max_len, name=result.name, reslen=TestResult.maxlen(), res=result.res.value, @@ -1051,6 +1052,8 @@ class TestHarness: # wrapper script. sys.exit(125) + self.test_count = len(tests) + self.name_max_len = max([len(self.get_pretty_suite(test)) for test in tests]) self.run_tests(tests) return self.total_failure_count() @@ -1203,8 +1206,6 @@ class TestHarness: semaphore = asyncio.Semaphore(self.options.num_processes) futures = deque() # type: T.Deque[asyncio.Future] running_tests = dict() # type: T.Dict[asyncio.Future, str] - test_count = len(tests) - name_max_len = max([len(self.get_pretty_suite(test)) for test in tests]) self.open_log_files() startdir = os.getcwd() if self.options.wd: @@ -1218,7 +1219,7 @@ class TestHarness: return res = await test.run() self.process_test_result(res) - self.print_stats(test_count, name_max_len, res) + self.print_stats(res) def test_done(f: asyncio.Future) -> None: if not f.cancelled(): -- cgit v1.1 From eadbf3dbf5e69f263e0a8e40aa07ee6419481b30 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Wed, 18 Nov 2020 14:24:59 +0100 Subject: mtest: add test methods to TestResult Keep the list of "ok" and "bad" statuses close to the definition of the enum. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 4685b7d..f1a45b7 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -181,6 +181,13 @@ class TestResult(enum.Enum): def maxlen() -> int: return 14 # len(UNEXPECTEDPASS) + def is_ok(self) -> bool: + return self in {TestResult.OK, TestResult.EXPECTEDFAIL} + + def is_bad(self) -> bool: + return self in {TestResult.FAIL, TestResult.TIMEOUT, TestResult.INTERRUPT, + TestResult.UNEXPECTEDPASS, TestResult.ERROR} + class TAPParser: Plan = namedtuple('Plan', ['count', 'late', 'skipped', 'explanation']) @@ -961,9 +968,6 @@ class TestHarness: sys.exit('Unknown test result encountered: {}'.format(result.res)) def print_stats(self, result: TestRun) -> None: - ok_statuses = (TestResult.OK, TestResult.EXPECTEDFAIL) - bad_statuses = (TestResult.FAIL, TestResult.TIMEOUT, TestResult.INTERRUPT, - TestResult.UNEXPECTEDPASS, TestResult.ERROR) result_str = '{num:{numlen}}/{testcount} {name:{name_max_len}} {res:{reslen}} {dur:.2f}s'.format( numlen=len(str(self.test_count)), num=result.num, @@ -975,17 +979,17 @@ class TestHarness: dur=result.duration) if result.res is TestResult.FAIL: result_str += ' ' + returncode_to_status(result.returncode) - if result.res in bad_statuses: + if result.res.is_bad(): self.collected_failures.append(result_str) - if not self.options.quiet or result.res not in ok_statuses: + if not self.options.quiet or not result.res.is_ok(): decorator = mlog.plain - if result.res in bad_statuses: + if result.res.is_bad(): decorator = mlog.red elif result.res is TestResult.SKIP: decorator = mlog.yellow print(decorator(result_str).get_text(mlog.colorize_console())) result_str += "\n\n" + result.get_log() - if result.res in bad_statuses: + if result.res.is_bad(): if self.options.print_errorlogs: self.collected_logs.append(result_str) if self.logfile: -- cgit v1.1 From 7b3cca5047993d7051b1d991ba6707b07c39a60b Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 09:23:47 +0100 Subject: mtest: store TestRuns in collected_failures Instead of storing the string, store the whole TestRun. In the next patches we'll use this to colorize the summary of failures, and to allow a few more simplifications. There is some code duplication between the console and logfile code, but it won't matter as soon as console and logfile output will be in two completely separate classes. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 37 ++++++++++++++++++++++++------------- 1 file changed, 24 insertions(+), 13 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index f1a45b7..ad8ad62 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -870,7 +870,7 @@ class TestHarness: def __init__(self, options: argparse.Namespace): self.options = options self.collected_logs = [] # type: T.List[str] - self.collected_failures = [] # type: T.List[str] + self.collected_failures = [] # type: T.List[TestRun] self.fail_count = 0 self.expectedfail_count = 0 self.unexpectedpass_count = 0 @@ -880,7 +880,6 @@ class TestHarness: self.test_count = 0 self.name_max_len = 0 self.is_run = False - self.results = [] # type: T.List[TestRun] self.logfilename = None # type: T.Optional[str] self.logfile = None # type: T.Optional[T.TextIO] self.jsonlogfile = None # type: T.Optional[T.TextIO] @@ -967,7 +966,7 @@ class TestHarness: else: sys.exit('Unknown test result encountered: {}'.format(result.res)) - def print_stats(self, result: TestRun) -> None: + def format(self, result: TestRun, colorize: bool) -> str: result_str = '{num:{numlen}}/{testcount} {name:{name_max_len}} {res:{reslen}} {dur:.2f}s'.format( numlen=len(str(self.test_count)), num=result.num, @@ -979,15 +978,19 @@ class TestHarness: dur=result.duration) if result.res is TestResult.FAIL: result_str += ' ' + returncode_to_status(result.returncode) + decorator = mlog.plain if result.res.is_bad(): - self.collected_failures.append(result_str) + decorator = mlog.red + elif result.res is TestResult.SKIP: + decorator = mlog.yellow + return decorator(result_str).get_text(colorize) + + def print_stats(self, result: TestRun) -> None: + if result.res.is_bad(): + self.collected_failures.append(result) if not self.options.quiet or not result.res.is_ok(): - decorator = mlog.plain - if result.res.is_bad(): - decorator = mlog.red - elif result.res is TestResult.SKIP: - decorator = mlog.yellow - print(decorator(result_str).get_text(mlog.colorize_console())) + print(self.format(result, mlog.colorize_console())) + result_str = self.format(result, False) result_str += "\n\n" + result.get_log() if result.res.is_bad(): if self.options.print_errorlogs: @@ -1001,9 +1004,16 @@ class TestHarness: def print_summary(self) -> None: # Prepend a list of failures - msg = '' if len(self.collected_failures) < 1 else "\nSummary of Failures:\n\n" - msg += '\n'.join(self.collected_failures) - msg += textwrap.dedent(''' + if self.collected_failures: + print("\nSummary of Failures:\n") + if self.logfile: + self.logfile.write("\nSummary of Failures:\n\n") + for i, result in enumerate(self.collected_failures, 1): + print(self.format(result, False)) + if self.logfile: + self.logfile.write(self.format(result, False) + '\n') + + msg = textwrap.dedent(''' Ok: {:<4} Expected Fail: {:<4} @@ -1016,6 +1026,7 @@ class TestHarness: print(msg) if self.logfile: self.logfile.write(msg) + if self.junit: self.junit.write() -- cgit v1.1 From 2201e2bca66603a33d0341a11427f09872eddfcf Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 10:20:46 +0100 Subject: mtest: improve colorization Instead of colorizing the whole status line, only colorize the word representing the outcome of the test (SKIP, OK, FAIL, etc.). This is less intrusive, so the patch also does the following changes: - colorize OK and EXPECTEDFAIL, respectively as green and yellow - colorize the summary of failures as well. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 24 ++++++++++++++---------- 1 file changed, 14 insertions(+), 10 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index ad8ad62..b8db80d 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -188,6 +188,16 @@ class TestResult(enum.Enum): return self in {TestResult.FAIL, TestResult.TIMEOUT, TestResult.INTERRUPT, TestResult.UNEXPECTEDPASS, TestResult.ERROR} + def get_text(self, colorize: bool) -> str: + result_str = '{res:{reslen}}'.format(res=self.value, reslen=self.maxlen()) + 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) + class TAPParser: Plan = namedtuple('Plan', ['count', 'late', 'skipped', 'explanation']) @@ -967,23 +977,17 @@ class TestHarness: sys.exit('Unknown test result encountered: {}'.format(result.res)) def format(self, result: TestRun, colorize: bool) -> str: - result_str = '{num:{numlen}}/{testcount} {name:{name_max_len}} {res:{reslen}} {dur:.2f}s'.format( + result_str = '{num:{numlen}}/{testcount} {name:{name_max_len}} {res} {dur:.2f}s'.format( numlen=len(str(self.test_count)), num=result.num, testcount=self.test_count, name_max_len=self.name_max_len, name=result.name, - reslen=TestResult.maxlen(), - res=result.res.value, + res=result.res.get_text(colorize), dur=result.duration) if result.res is TestResult.FAIL: result_str += ' ' + returncode_to_status(result.returncode) - decorator = mlog.plain - if result.res.is_bad(): - decorator = mlog.red - elif result.res is TestResult.SKIP: - decorator = mlog.yellow - return decorator(result_str).get_text(colorize) + return result_str def print_stats(self, result: TestRun) -> None: if result.res.is_bad(): @@ -1009,7 +1013,7 @@ class TestHarness: if self.logfile: self.logfile.write("\nSummary of Failures:\n\n") for i, result in enumerate(self.collected_failures, 1): - print(self.format(result, False)) + print(self.format(result, mlog.colorize_console())) if self.logfile: self.logfile.write(self.format(result, False) + '\n') -- cgit v1.1 From 414aee63285585e94bbb8d10c26f0aceb7fa60ca Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Fri, 20 Nov 2020 09:07:03 +0100 Subject: mtest: use backslash replace when printing error logs If there's an UnicodeEncodeError while printing the error logs, TestHarness tries an encode/decode pair to get rid of anything that is not a 7-bit ASCII character; this however results in "?" characters that are not very clear. To make it easier to understand what is going on, use backslashreplace instead. While at it, fix the decode to use a matching encoding. This will only matter in the rare case of sys.stdout.encoding not being an ASCII superset, but that should not matter. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index b8db80d..acd3612 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -1050,7 +1050,7 @@ class TestHarness: try: print(line) except UnicodeEncodeError: - line = line.encode('ascii', errors='replace').decode() + line = line.encode('ascii', errors='backslashreplace').decode('ascii') print(line) def total_failure_count(self) -> int: -- cgit v1.1 From 109cde4ddca2ee59d71f5ee751797d26eb316f77 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 12:25:46 +0100 Subject: mtest: remove collected_logs Just reuse the collected_failures collection now that it contains TestRun objects. Move the code to generate the short form of the log to TestRun. Note that the first line of the error log is not included in get_log()'s return value, so the magic "first four lines are passed unscathed" is changed to three lines only. The resulting output is like this: --- command --- --- Listing only the last 100 lines from a long log. --- --- stdout --- ... Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 58 ++++++++++++++++++++++++++++++----------------------- 1 file changed, 33 insertions(+), 25 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index acd3612..d284326 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -130,6 +130,13 @@ def add_arguments(parser: argparse.ArgumentParser) -> None: '"subprojname:" to run all tests defined by "subprojname".') +def print_safe(s: str) -> None: + try: + print(s) + except UnicodeEncodeError: + s = s.encode('ascii', errors='backslashreplace').decode('ascii') + print(s) + 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 @@ -591,9 +598,21 @@ class TestRun: res += self.stde if res[-1:] != '\n': res += '\n' - res += '-------\n\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 + def decode(stream: T.Union[None, bytes]) -> str: if stream is None: return '' @@ -879,7 +898,6 @@ class SingleTestRunner: class TestHarness: def __init__(self, options: argparse.Namespace): self.options = options - self.collected_logs = [] # type: T.List[str] self.collected_failures = [] # type: T.List[TestRun] self.fail_count = 0 self.expectedfail_count = 0 @@ -994,13 +1012,9 @@ class TestHarness: self.collected_failures.append(result) if not self.options.quiet or not result.res.is_ok(): print(self.format(result, mlog.colorize_console())) - result_str = self.format(result, False) - result_str += "\n\n" + result.get_log() - if result.res.is_bad(): - if self.options.print_errorlogs: - self.collected_logs.append(result_str) if self.logfile: - self.logfile.write(result_str) + self.logfile.write(self.format(result, False)) + self.logfile.write("\n\n" + result.get_log() + "\n") if self.jsonlogfile: write_json_log(self.jsonlogfile, result) if self.junit: @@ -1035,23 +1049,16 @@ class TestHarness: self.junit.write() def print_collected_logs(self) -> None: - if self.collected_logs: - if len(self.collected_logs) > 10: - print('\nThe output from 10 first failed tests:\n') + if self.collected_failures: + if len(self.collected_failures) > 10: + print('\n\nThe output from 10 first failed tests:\n') else: - print('\nThe output from the failed tests:\n') - for log in self.collected_logs[:10]: - lines = log.splitlines() - if len(lines) > 104: - print('\n'.join(lines[0:4])) - print('--- Listing only the last 100 lines from a long log. ---') - lines = lines[-100:] - for line in lines: - try: - print(line) - except UnicodeEncodeError: - line = line.encode('ascii', errors='backslashreplace').decode('ascii') - print(line) + print('\n\nThe output from the failed tests:\n') + for i, result in enumerate(self.collected_failures, 1): + print(self.format(result, mlog.colorize_console())) + print_safe(result.get_log_short()) + if i == 10: + break def total_failure_count(self) -> int: return self.fail_count + self.unexpectedpass_count + self.timeout_count @@ -1299,7 +1306,8 @@ class TestHarness: break await complete_all(futures) - self.print_collected_logs() + if self.options.print_errorlogs: + self.print_collected_logs() self.print_summary() if self.logfilename: -- cgit v1.1 From a166df1f96d09d0785ec7b170e2fcac8d7b97b9a Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Fri, 20 Nov 2020 08:57:24 +0100 Subject: mtest: do not use __del__ Use try/finally instead of destructors to ensure that log files are closed. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index d284326..8956dd8 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -923,9 +923,6 @@ class TestHarness: ss.add(s) self.suites = list(ss) - def __del__(self) -> None: - self.close_logfiles() - def __enter__(self) -> 'TestHarness': return self @@ -1173,7 +1170,7 @@ class TestHarness: return tests - def open_log_files(self) -> None: + def open_logfiles(self) -> None: if not self.options.logbase or self.options.verbose: return @@ -1224,15 +1221,18 @@ class TestHarness: return test.name def run_tests(self, tests: T.List[TestSerialisation]) -> None: - # Replace with asyncio.run once we can require Python 3.7 - loop = asyncio.get_event_loop() - loop.run_until_complete(self._run_tests(tests)) + try: + self.open_logfiles() + # Replace with asyncio.run once we can require Python 3.7 + loop = asyncio.get_event_loop() + loop.run_until_complete(self._run_tests(tests)) + finally: + self.close_logfiles() async def _run_tests(self, tests: T.List[TestSerialisation]) -> None: semaphore = asyncio.Semaphore(self.options.num_processes) futures = deque() # type: T.Deque[asyncio.Future] running_tests = dict() # type: T.Dict[asyncio.Future, str] - self.open_log_files() startdir = os.getcwd() if self.options.wd: os.chdir(self.options.wd) -- cgit v1.1 From fb02b5e8588fa5543dead80f70cded44fcd7047f Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 10:44:41 +0100 Subject: mtest: introduce TestLogger The TestLogger class lets us move the code for all those log files out of TestHarness. The interface is based on JunitBuilder, which is converted already in this commit. Over the next commits, we will also convert JSON, text and console output. The main difference with JunitBuilder is that the completion method is asynchronous. This can be useful if the logger needs to clean up after itself and wait for asyncio tasks. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 38 ++++++++++++++++++++++++++++---------- 1 file changed, 28 insertions(+), 10 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 8956dd8..565f64f 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -354,7 +354,21 @@ class TAPParser: yield self.Error('Too many tests run (expected {}, got {})'.format(plan.count, num_tests)) -class JunitBuilder: +class TestLogger: + def start(self, harness: 'TestHarness') -> None: + pass + + def log(self, harness: 'TestHarness', result: 'TestRun') -> None: + pass + + async def finish(self, harness: 'TestHarness') -> None: + pass + + def close(self) -> None: + pass + + +class JunitBuilder(TestLogger): """Builder for Junit test results. @@ -377,7 +391,7 @@ class JunitBuilder: 'testsuites', tests='0', errors='0', failures='0') self.suites = {} # type: T.Dict[str, et.Element] - def log(self, test: 'TestRun') -> None: + def log(self, harness: 'TestHarness', test: 'TestRun') -> None: """Log a single test case.""" if test.junit is not None: for suite in test.junit.findall('.//testsuite'): @@ -461,7 +475,7 @@ class JunitBuilder: err = et.SubElement(testcase, 'system-err') err.text = test.stde.rstrip() - def write(self) -> None: + async def finish(self, harness: 'TestHarness') -> None: """Calculate total test counts and write out the xml result.""" for suite in self.suites.values(): self.root.append(suite) @@ -911,7 +925,7 @@ class TestHarness: self.logfilename = None # type: T.Optional[str] self.logfile = None # type: T.Optional[T.TextIO] self.jsonlogfile = None # type: T.Optional[T.TextIO] - self.junit = None # type: T.Optional[JunitBuilder] + self.loggers = [] # type: T.List[TestLogger] if self.options.benchmark: self.tests = load_benchmarks(options.wd) @@ -935,6 +949,8 @@ class TestHarness: if lfile: lfile.close() setattr(self, f, None) + for l in self.loggers: + l.close() def merge_suite_options(self, options: argparse.Namespace, test: TestSerialisation) -> T.Dict[str, str]: if ':' in options.setup: @@ -1014,8 +1030,8 @@ class TestHarness: self.logfile.write("\n\n" + result.get_log() + "\n") if self.jsonlogfile: write_json_log(self.jsonlogfile, result) - if self.junit: - self.junit.log(result) + for l in self.loggers: + l.log(self, result) def print_summary(self) -> None: # Prepend a list of failures @@ -1042,9 +1058,6 @@ class TestHarness: if self.logfile: self.logfile.write(msg) - if self.junit: - self.junit.write() - def print_collected_logs(self) -> None: if self.collected_failures: if len(self.collected_failures) > 10: @@ -1185,7 +1198,7 @@ class TestHarness: if namebase: logfile_base += '-' + namebase.replace(' ', '_') - self.junit = JunitBuilder(logfile_base + '.junit.xml') + self.loggers.append(JunitBuilder(logfile_base + '.junit.xml')) self.logfilename = logfile_base + '.txt' self.jsonlogfilename = logfile_base + '.json' @@ -1285,6 +1298,9 @@ class TestHarness: mlog.warning('CTRL-C detected, exiting') interrupted = True + for l in self.loggers: + l.start(self) + if sys.platform != 'win32': asyncio.get_event_loop().add_signal_handler(signal.SIGINT, sigint_handler) asyncio.get_event_loop().add_signal_handler(signal.SIGTERM, sigterm_handler) @@ -1316,6 +1332,8 @@ class TestHarness: if sys.platform != 'win32': asyncio.get_event_loop().remove_signal_handler(signal.SIGINT) asyncio.get_event_loop().remove_signal_handler(signal.SIGTERM) + for l in self.loggers: + await l.finish(self) os.chdir(startdir) def list_tests(th: TestHarness) -> bool: -- cgit v1.1 From 119a928f9f608dff5f1578698bf643e84d6bbcb9 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 10:55:49 +0100 Subject: mtest: convert jsonlogfile to TestLogger Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 47 +++++++++++++++++++++++++++-------------------- 1 file changed, 27 insertions(+), 20 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 565f64f..be985bc 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -368,6 +368,31 @@ class TestLogger: pass +class TestFileLogger(TestLogger): + def __init__(self, filename: str, errors: str = 'replace') -> None: + self.file = open(filename, 'w', encoding='utf8', errors=errors) + + def close(self) -> None: + if self.file: + self.file.close() + self.file = None + + +class JsonLogfileBuilder(TestFileLogger): + def log(self, harness: 'TestHarness', result: 'TestRun') -> None: + jresult = {'name': result.name, + 'stdout': result.stdo, + 'result': result.res.value, + 'starttime': result.starttime, + 'duration': result.duration, + 'returncode': result.returncode, + 'env': result.env, + 'command': result.cmd} # type: T.Dict[str, T.Any] + if result.stde: + jresult['stderr'] = result.stde + self.file.write(json.dumps(jresult) + '\n') + + class JunitBuilder(TestLogger): """Builder for Junit test results. @@ -635,19 +660,6 @@ def decode(stream: T.Union[None, bytes]) -> str: except UnicodeDecodeError: return stream.decode('iso-8859-1', errors='ignore') -def write_json_log(jsonlogfile: T.TextIO, result: TestRun) -> None: - jresult = {'name': result.name, - 'stdout': result.stdo, - 'result': result.res.value, - 'starttime': result.starttime, - 'duration': result.duration, - 'returncode': result.returncode, - 'env': result.env, - 'command': result.cmd} # type: T.Dict[str, T.Any] - if result.stde: - jresult['stderr'] = result.stde - jsonlogfile.write(json.dumps(jresult) + '\n') - def run_with_mono(fname: str) -> bool: return fname.endswith('.exe') and not (is_windows() or is_cygwin()) @@ -924,7 +936,6 @@ class TestHarness: self.is_run = False self.logfilename = None # type: T.Optional[str] self.logfile = None # type: T.Optional[T.TextIO] - self.jsonlogfile = None # type: T.Optional[T.TextIO] self.loggers = [] # type: T.List[TestLogger] if self.options.benchmark: @@ -944,7 +955,7 @@ class TestHarness: self.close_logfiles() def close_logfiles(self) -> None: - for f in ['logfile', 'jsonlogfile']: + for f in ['logfile']: lfile = getattr(self, f) if lfile: lfile.close() @@ -1028,8 +1039,6 @@ class TestHarness: if self.logfile: self.logfile.write(self.format(result, False)) self.logfile.write("\n\n" + result.get_log() + "\n") - if self.jsonlogfile: - write_json_log(self.jsonlogfile, result) for l in self.loggers: l.log(self, result) @@ -1199,11 +1208,9 @@ class TestHarness: logfile_base += '-' + namebase.replace(' ', '_') self.loggers.append(JunitBuilder(logfile_base + '.junit.xml')) + self.loggers.append(JsonLogfileBuilder(logfile_base + '.json')) self.logfilename = logfile_base + '.txt' - self.jsonlogfilename = logfile_base + '.json' - - self.jsonlogfile = open(self.jsonlogfilename, 'w', encoding='utf-8', errors='replace') self.logfile = open(self.logfilename, 'w', encoding='utf-8', errors='surrogateescape') self.logfile.write('Log of Meson test suite run on {}\n\n'.format(datetime.datetime.now().isoformat())) -- cgit v1.1 From 240036bced5a0872f4383e993d243b68f8432cff Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 12:29:04 +0100 Subject: mtest: convert logfile to TestLogger Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 68 ++++++++++++++++++++++++++--------------------------- 1 file changed, 33 insertions(+), 35 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index be985bc..b65beaa 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -370,6 +370,7 @@ class TestLogger: class TestFileLogger(TestLogger): def __init__(self, filename: str, errors: str = 'replace') -> None: + self.filename = filename self.file = open(filename, 'w', encoding='utf8', errors=errors) def close(self) -> None: @@ -378,6 +379,26 @@ class TestFileLogger(TestLogger): self.file = None +class TextLogfileBuilder(TestFileLogger): + def start(self, harness: 'TestHarness') -> None: + self.file.write('Log of Meson test suite run on {}\n\n'.format(datetime.datetime.now().isoformat())) + inherit_env = env_tuple_to_str(os.environ.items()) + 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") + + async def finish(self, harness: 'TestHarness') -> None: + if harness.collected_failures: + self.file.write("\nSummary of Failures:\n\n") + for i, result in enumerate(harness.collected_failures, 1): + self.file.write(harness.format(result, False) + '\n') + self.file.write(harness.summary()) + + print('Full log written to {}'.format(self.filename)) + + class JsonLogfileBuilder(TestFileLogger): def log(self, harness: 'TestHarness', result: 'TestRun') -> None: jresult = {'name': result.name, @@ -934,8 +955,6 @@ class TestHarness: self.test_count = 0 self.name_max_len = 0 self.is_run = False - self.logfilename = None # type: T.Optional[str] - self.logfile = None # type: T.Optional[T.TextIO] self.loggers = [] # type: T.List[TestLogger] if self.options.benchmark: @@ -955,11 +974,6 @@ class TestHarness: self.close_logfiles() def close_logfiles(self) -> None: - for f in ['logfile']: - lfile = getattr(self, f) - if lfile: - lfile.close() - setattr(self, f, None) for l in self.loggers: l.close() @@ -1036,24 +1050,11 @@ class TestHarness: self.collected_failures.append(result) if not self.options.quiet or not result.res.is_ok(): print(self.format(result, mlog.colorize_console())) - if self.logfile: - self.logfile.write(self.format(result, False)) - self.logfile.write("\n\n" + result.get_log() + "\n") for l in self.loggers: l.log(self, result) - def print_summary(self) -> None: - # Prepend a list of failures - if self.collected_failures: - print("\nSummary of Failures:\n") - if self.logfile: - self.logfile.write("\nSummary of Failures:\n\n") - for i, result in enumerate(self.collected_failures, 1): - print(self.format(result, mlog.colorize_console())) - if self.logfile: - self.logfile.write(self.format(result, False) + '\n') - - msg = textwrap.dedent(''' + def summary(self) -> str: + return textwrap.dedent(''' Ok: {:<4} Expected Fail: {:<4} @@ -1063,9 +1064,15 @@ class TestHarness: Timeout: {:<4} ''').format(self.success_count, self.expectedfail_count, self.fail_count, self.unexpectedpass_count, self.skip_count, self.timeout_count) - print(msg) - if self.logfile: - self.logfile.write(msg) + + def print_summary(self) -> None: + # Prepend a list of failures + if self.collected_failures: + print("\nSummary of Failures:\n") + for i, result in enumerate(self.collected_failures, 1): + print(self.format(result, mlog.colorize_console())) + + print(self.summary()) def print_collected_logs(self) -> None: if self.collected_failures: @@ -1209,13 +1216,7 @@ class TestHarness: self.loggers.append(JunitBuilder(logfile_base + '.junit.xml')) self.loggers.append(JsonLogfileBuilder(logfile_base + '.json')) - - self.logfilename = logfile_base + '.txt' - self.logfile = open(self.logfilename, 'w', encoding='utf-8', errors='surrogateescape') - - self.logfile.write('Log of Meson test suite run on {}\n\n'.format(datetime.datetime.now().isoformat())) - inherit_env = env_tuple_to_str(os.environ.items()) - self.logfile.write('Inherited environment: {}\n\n'.format(inherit_env)) + self.loggers.append(TextLogfileBuilder(logfile_base + '.txt', errors='surrogateescape')) @staticmethod def get_wrapper(options: argparse.Namespace) -> T.List[str]: @@ -1332,9 +1333,6 @@ class TestHarness: if self.options.print_errorlogs: self.print_collected_logs() self.print_summary() - - if self.logfilename: - print('Full log written to {}'.format(self.logfilename)) finally: if sys.platform != 'win32': asyncio.get_event_loop().remove_signal_handler(signal.SIGINT) -- cgit v1.1 From df0d5ce34eec1f9758b741261dd6bb30a7f9819a Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 12:30:17 +0100 Subject: mtest: convert console output to TestLogger Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 52 ++++++++++++++++++++++++++-------------------------- 1 file changed, 26 insertions(+), 26 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index b65beaa..8cdcba9 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -379,6 +379,31 @@ class TestFileLogger(TestLogger): self.file = None +class ConsoleLogger(TestLogger): + def log(self, harness: 'TestHarness', result: 'TestRun') -> None: + if not harness.options.quiet or not result.res.is_ok(): + print(harness.format(result, mlog.colorize_console())) + + async def finish(self, harness: 'TestHarness') -> None: + 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 + + print("\nSummary of Failures:\n") + for i, result in enumerate(harness.collected_failures, 1): + print(harness.format(result, mlog.colorize_console())) + + print(harness.summary()) + + class TextLogfileBuilder(TestFileLogger): def start(self, harness: 'TestHarness') -> None: self.file.write('Log of Meson test suite run on {}\n\n'.format(datetime.datetime.now().isoformat())) @@ -956,6 +981,7 @@ class TestHarness: self.name_max_len = 0 self.is_run = False self.loggers = [] # type: T.List[TestLogger] + self.loggers.append(ConsoleLogger()) if self.options.benchmark: self.tests = load_benchmarks(options.wd) @@ -1048,8 +1074,6 @@ class TestHarness: def print_stats(self, result: TestRun) -> None: if result.res.is_bad(): self.collected_failures.append(result) - if not self.options.quiet or not result.res.is_ok(): - print(self.format(result, mlog.colorize_console())) for l in self.loggers: l.log(self, result) @@ -1065,27 +1089,6 @@ class TestHarness: ''').format(self.success_count, self.expectedfail_count, self.fail_count, self.unexpectedpass_count, self.skip_count, self.timeout_count) - def print_summary(self) -> None: - # Prepend a list of failures - if self.collected_failures: - print("\nSummary of Failures:\n") - for i, result in enumerate(self.collected_failures, 1): - print(self.format(result, mlog.colorize_console())) - - print(self.summary()) - - def print_collected_logs(self) -> None: - if self.collected_failures: - if len(self.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(self.collected_failures, 1): - print(self.format(result, mlog.colorize_console())) - print_safe(result.get_log_short()) - if i == 10: - break - def total_failure_count(self) -> int: return self.fail_count + self.unexpectedpass_count + self.timeout_count @@ -1330,9 +1333,6 @@ class TestHarness: break await complete_all(futures) - if self.options.print_errorlogs: - self.print_collected_logs() - self.print_summary() finally: if sys.platform != 'win32': asyncio.get_event_loop().remove_signal_handler(signal.SIGINT) -- cgit v1.1 From aa03c06ffb6ca4c932edf14a0731e28937c6c094 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 12:01:09 +0100 Subject: mtest: merge print_stats and process_test_result Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 8cdcba9..4a45624 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -1058,6 +1058,11 @@ class TestHarness: else: sys.exit('Unknown test result encountered: {}'.format(result.res)) + if result.res.is_bad(): + self.collected_failures.append(result) + for l in self.loggers: + l.log(self, result) + def format(self, result: TestRun, colorize: bool) -> str: result_str = '{num:{numlen}}/{testcount} {name:{name_max_len}} {res} {dur:.2f}s'.format( numlen=len(str(self.test_count)), @@ -1071,12 +1076,6 @@ class TestHarness: result_str += ' ' + returncode_to_status(result.returncode) return result_str - def print_stats(self, result: TestRun) -> None: - if result.res.is_bad(): - self.collected_failures.append(result) - for l in self.loggers: - l.log(self, result) - def summary(self) -> str: return textwrap.dedent(''' @@ -1269,7 +1268,6 @@ class TestHarness: return res = await test.run() self.process_test_result(res) - self.print_stats(res) def test_done(f: asyncio.Future) -> None: if not f.cancelled(): -- cgit v1.1 From 4cfd1e638ce40df34fe6ac9b652ff58440d8df31 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 11:43:34 +0100 Subject: mtest: add progress report Add a progress report in the style of "yum". Every second the report prints a different test among the ones that are running. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 108 +++++++++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 107 insertions(+), 1 deletion(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 4a45624..252e39b 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -44,7 +44,7 @@ from . import mlog from .coredata import major_versions_differ, MesonVersionMismatchException from .coredata import version as coredata_version from .dependencies import ExternalProgram -from .mesonlib import MesonException, get_wine_shortpath, split_args, join_args +from .mesonlib import MesonException, OrderedSet, get_wine_shortpath, split_args, join_args from .mintro import get_infodir, load_info_file from .backend.backends import TestProtocol, TestSerialisation @@ -358,6 +358,9 @@ class TestLogger: def start(self, harness: 'TestHarness') -> None: pass + def start_test(self, test: 'TestRun') -> None: + pass + def log(self, harness: 'TestHarness', result: 'TestRun') -> None: pass @@ -380,11 +383,112 @@ class TestFileLogger(TestLogger): class ConsoleLogger(TestLogger): + SPINNER = "\U0001f311\U0001f312\U0001f313\U0001f314" + \ + "\U0001f315\U0001f316\U0001f317\U0001f318" + + def __init__(self) -> None: + self.update = asyncio.Event() + self.running_tests = OrderedSet() # type: OrderedSet['TestRun'] + self.progress_test = None # type: T.Optional['TestRun'] + self.progress_task = None # type: T.Optional[asyncio.Future] + self.stop = False + self.update = asyncio.Event() + self.should_erase_line = '' + self.test_count = 0 + self.started_tests = 0 + self.spinner_index = 0 + + def clear_progress(self) -> None: + if self.should_erase_line: + print(self.should_erase_line, end='') + self.should_erase_line = '' + + def print_progress(self, line: str) -> None: + print(self.should_erase_line, line, sep='', end='\r') + self.should_erase_line = '\x1b[K' + + def request_update(self) -> None: + self.update.set() + + def emit_progress(self) -> None: + if self.progress_test is None: + self.clear_progress() + return + + if len(self.running_tests) == 1: + count = '{}/{}'.format(self.started_tests, self.test_count) + else: + count = '{}-{}/{}'.format(self.started_tests - len(self.running_tests) + 1, + self.started_tests, self.test_count) + + line = '[{}] {} {}'.format(count, self.SPINNER[self.spinner_index], self.progress_test.name) + self.spinner_index = (self.spinner_index + 1) % len(self.SPINNER) + 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() + next_update = 0.0 + self.request_update() + while not self.stop: + await self.update.wait() + self.update.clear() + + # We may get here simply because the progress line has been + # overwritten, so do not always switch. Only do so every + # second, or if the printed test has finished + if loop.time() >= next_update: + self.progress_test = None + next_update = loop.time() + 1 + loop.call_at(next_update, self.request_update) + + if (self.progress_test and + self.progress_test.res is not TestResult.RUNNING): + self.progress_test = None + + if not self.progress_test: + if not self.running_tests: + continue + # Pick a test in round robin order + self.progress_test = self.running_tests.pop(last=False) + self.running_tests.add(self.progress_test) + + self.emit_progress() + self.clear_progress() + + 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: + self.progress_task = asyncio.ensure_future(report_progress()) + + def start_test(self, test: 'TestRun') -> None: + self.started_tests += 1 + self.running_tests.add(test) + self.running_tests.move_to_end(test, last=False) + self.request_update() + def log(self, harness: 'TestHarness', result: 'TestRun') -> None: + self.running_tests.remove(result) if not harness.options.quiet or not result.res.is_ok(): + self.clear_progress() print(harness.format(result, mlog.colorize_console())) + self.request_update() async def finish(self, harness: 'TestHarness') -> None: + self.stop = True + self.request_update() + if self.progress_task: + await self.progress_task + if harness.collected_failures: if harness.options.print_errorlogs: if len(harness.collected_failures) > 10: @@ -1266,6 +1370,8 @@ 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() self.process_test_result(res) -- cgit v1.1 From 80ba69606693508804df0d8917051aaaef854665 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 19 Nov 2020 15:44:16 +0100 Subject: mtest: flush stdout after printing test results Flush after each output line, even if printing to a file, so that each result is immediately visible down a pipeline. Signed-off-by: Paolo Bonzini --- mesonbuild/mtest.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 252e39b..484f432 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -480,7 +480,7 @@ class ConsoleLogger(TestLogger): self.running_tests.remove(result) if not harness.options.quiet or not result.res.is_ok(): self.clear_progress() - print(harness.format(result, mlog.colorize_console())) + print(harness.format(result, mlog.colorize_console()), flush=True) self.request_update() async def finish(self, harness: 'TestHarness') -> None: -- cgit v1.1 From 5d97bf615f9de1476910e084e3f580b44bc4f632 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Wed, 25 Nov 2020 15:24:09 +0100 Subject: mtest: flush progress report before warning --- mesonbuild/mtest.py | 18 ++++++++++++++---- 1 file changed, 14 insertions(+), 4 deletions(-) (limited to 'mesonbuild/mtest.py') diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py index 484f432..7e3ebea 100644 --- a/mesonbuild/mtest.py +++ b/mesonbuild/mtest.py @@ -355,6 +355,9 @@ class TAPParser: class TestLogger: + def flush(self) -> None: + pass + def start(self, harness: 'TestHarness') -> None: pass @@ -398,7 +401,7 @@ class ConsoleLogger(TestLogger): self.started_tests = 0 self.spinner_index = 0 - def clear_progress(self) -> None: + def flush(self) -> None: if self.should_erase_line: print(self.should_erase_line, end='') self.should_erase_line = '' @@ -412,7 +415,7 @@ class ConsoleLogger(TestLogger): def emit_progress(self) -> None: if self.progress_test is None: - self.clear_progress() + self.flush() return if len(self.running_tests) == 1: @@ -462,7 +465,7 @@ class ConsoleLogger(TestLogger): self.running_tests.add(self.progress_test) self.emit_progress() - self.clear_progress() + self.flush() self.test_count = harness.test_count # In verbose mode, the progress report gets in the way of the tests' @@ -479,7 +482,7 @@ class ConsoleLogger(TestLogger): def log(self, harness: 'TestHarness', result: 'TestRun') -> None: self.running_tests.remove(result) if not harness.options.quiet or not result.res.is_ok(): - self.clear_progress() + self.flush() print(harness.format(result, mlog.colorize_console()), flush=True) self.request_update() @@ -1305,6 +1308,10 @@ class TestHarness: return tests + def flush_logfiles(self) -> None: + for l in self.loggers: + l.flush() + def open_logfiles(self) -> None: if not self.options.logbase or self.options.verbose: return @@ -1388,6 +1395,7 @@ class TestHarness: future = futures.popleft() futures.append(future) if warn: + self.flush_logfiles() mlog.warning('CTRL-C detected, interrupting {}'.format(running_tests[future])) del running_tests[future] future.cancel() @@ -1397,6 +1405,7 @@ class TestHarness: if interrupted: return interrupted = True + self.flush_logfiles() mlog.warning('Received SIGTERM, exiting') while running_tests: cancel_one_test(False) @@ -1410,6 +1419,7 @@ class TestHarness: if running_tests: cancel_one_test(True) else: + self.flush_logfiles() mlog.warning('CTRL-C detected, exiting') interrupted = True -- cgit v1.1