Bug 1209463 - [mozlog] Create a SummaryHandler class and refactor the 'mach' formatter to use it, r=jgraham

The mach formatter gathers result counts and unexpected messages during the run
to be dumped in a summary at the end. This is a pattern we'd like to repeat in
several other formatters as well. Rather than re-implementing, this creates a
handler class that does nothing but store the data. Formatters can then choose
how to format this data and when to print it.

MozReview-Commit-ID: HKtVr5PxfOy

--HG--
extra : rebase_source : 22789db1b2fea1e44f47ef1aa9b22b21a6e8649c
This commit is contained in:
Andrew Halberstadt 2017-11-29 12:00:30 -05:00
Родитель 3e46924759
Коммит 7f8e905fdb
5 изменённых файлов: 300 добавлений и 136 удалений

Просмотреть файл

@ -6,7 +6,6 @@
from __future__ import absolute_import
import time
from collections import defaultdict
try:
import blessings
@ -15,6 +14,7 @@ except ImportError:
from . import base
from .process import strstatus
from ..handlers import SummaryHandler
def format_seconds(total):
@ -35,7 +35,8 @@ class NullTerminal(object):
class MachFormatter(base.BaseFormatter):
def __init__(self, start_time=None, write_interval=False, write_times=True,
terminal=None, disable_colors=False):
terminal=None, disable_colors=False, **kwargs):
super(MachFormatter, self).__init__(**kwargs)
if disable_colors:
terminal = None
@ -55,16 +56,12 @@ class MachFormatter(base.BaseFormatter):
self.verbose = False
self._known_pids = set()
self.summary_values = {"tests": 0,
"subtests": 0,
"assertion_counts": 0,
"expected": 0,
"unexpected": defaultdict(int),
"skipped": 0}
self.summary_unexpected = []
self.summary = SummaryHandler()
def __call__(self, data):
s = base.BaseFormatter.__call__(self, data)
self.summary(data)
s = super(MachFormatter, self).__call__(data)
if s is None:
return
@ -117,78 +114,13 @@ class MachFormatter(base.BaseFormatter):
assert False, "unexpected test_id"
def suite_start(self, data):
self.summary_values = {"tests": 0,
"subtests": 0,
"assertion_counts": 0,
"expected": 0,
"unexpected": defaultdict(int),
"skipped": 0}
self.summary_unexpected = []
num_tests = reduce(lambda x, y: x + len(y), data['tests'].itervalues(), 0)
return "%i" % num_tests
def suite_end(self, data):
term = self.terminal if self.terminal is not None else NullTerminal()
return self._format_suite_summary(self.summary.current_suite, self.summary.current)
heading = "Summary"
rv = ["", heading, "=" * len(heading), ""]
has_subtests = self.summary_values["subtests"] > 0
has_assert_counts = self.summary_values["assertion_counts"] > 0
test_count = self.summary_values["tests"]
components = ["%i parents" % self.summary_values["tests"]]
if has_subtests:
test_count += self.summary_values["subtests"]
components.append("%i subtests" % self.summary_values["subtests"])
if has_assert_counts:
test_count += self.summary_values["assertion_counts"]
components.append("%i assertion counts" % self.summary_values["assertion_counts"])
summary = "Ran %i tests" % test_count
if len(components) > 1:
summary += " (%s)" % ", ".join(components)
rv.append(summary)
rv.append("Expected results: %i" % self.summary_values["expected"])
unexpected_count = sum(self.summary_values["unexpected"].values())
if unexpected_count > 0:
unexpected_str = " (%s)" % ", ".join("%s: %i" % (key, value) for key, value in
sorted(self.summary_values["unexpected"].items()))
else:
unexpected_str = ""
rv.append("Unexpected results: %i%s" % (unexpected_count, unexpected_str))
if self.summary_values["skipped"] > 0:
rv.append("Skipped: %i" % self.summary_values["skipped"])
rv.append("")
if not self.summary_values["unexpected"]:
rv.append(term.green("OK"))
else:
heading = "Unexpected Results"
rv.extend([heading, "=" * len(heading), ""])
if has_subtests:
for test_id, results in self.summary_unexpected:
test = self._get_file_name(test_id)
rv.extend([test, "-" * len(test)])
for name, status, expected, message in results:
if name is None:
name = "[Parent]"
rv.append("%s %s" % (self.format_expected(status, expected), name))
else:
for test_id, results in self.summary_unexpected:
test = self._get_file_name(test_id)
assert len(results) == 1
name, status, expected, messge = results[0]
assert name is None
rv.append("%s %s" % (self.format_expected(status, expected), test))
return "\n".join(rv)
def format_expected(self, status, expected):
def _format_expected(self, status, expected):
term = self.terminal if self.terminal is not None else NullTerminal()
if status == "ERROR":
color = term.red
@ -200,13 +132,76 @@ class MachFormatter(base.BaseFormatter):
return color("%s expected %s" % (status, expected))
def _format_suite_summary(self, suite, summary):
term = self.terminal if self.terminal is not None else NullTerminal()
count = summary['counts']
logs = summary['unexpected_logs']
rv = ["", suite, "~" * len(suite)]
# Format check counts
checks = self.summary.aggregate('count', count)
rv.append("Ran {} checks ({})".format(sum(checks.values()),
', '.join(['{} {}s'.format(v, k) for k, v in checks.items() if v])))
# Format expected counts
checks = self.summary.aggregate('expected', count, include_skip=False)
rv.append("Expected results: {}".format(sum(checks.values())))
# Format skip counts
skip_tests = count["test"]["expected"]["skip"]
skip_subtests = count["subtest"]["expected"]["skip"]
if skip_tests:
skipped = "Skipped: {} tests".format(skip_tests)
if skip_subtests:
skipped = "{}, {} subtests".format(skipped, skip_subtests)
rv.append(skipped)
# Format unexpected counts
checks = self.summary.aggregate('unexpected', count)
unexpected_count = sum(checks.values())
if unexpected_count:
rv.append("Unexpected results: {}".format(unexpected_count))
for key in ('test', 'subtest', 'assert'):
if not count[key]['unexpected']:
continue
status_str = ", ".join(["{} {}".format(n, s)
for s, n in count[key]['unexpected'].items()])
rv.append(" {}: {} ({})".format(
key, sum(count[key]['unexpected'].values()), status_str))
# Format status
if not any(count[key]["unexpected"] for key in ('test', 'subtest', 'assert')):
rv.append(term.green("OK"))
else:
heading = "Unexpected Logs"
rv.extend(["", heading, "-" * len(heading)])
if count['subtest']['count']:
for test_id, results in logs.items():
test = self._get_file_name(test_id)
rv.append(test)
for data in results:
name = data.get("subtest", "[Parent]")
rv.append(" %s %s" % (self._format_expected(
data["status"], data["expected"]), name))
else:
for test_id, results in logs.items():
test = self._get_file_name(test_id)
rv.append(test)
assert len(results) == 1
data = results[0]
assert "subtest" not in data
rv.append(" %s %s" % (self._format_expected(
data["status"], data["expected"]), test))
return "\n".join(rv)
def test_start(self, data):
self.summary_values["tests"] += 1
return "%s" % (self._get_test_id(data),)
def test_end(self, data):
subtests = self._get_subtest_data(data)
unexpected = subtests["unexpected"]
message = data.get("message", "")
if "stack" in data:
@ -218,39 +213,34 @@ class MachFormatter(base.BaseFormatter):
if "expected" in data:
parent_unexpected = True
expected_str = ", expected %s" % data["expected"]
unexpected.append((None, data["status"], data["expected"],
message))
else:
parent_unexpected = False
expected_str = ""
test = self._get_test_id(data)
if unexpected:
self.summary_unexpected.append((test, unexpected))
self._update_summary(data)
# Reset the counts to 0
self.status_buffer[test] = {"count": 0, "unexpected": [], "pass": 0}
self.has_unexpected[test] = bool(unexpected)
self.status_buffer[test] = {"count": 0, "unexpected": 0, "pass": 0}
self.has_unexpected[test] = bool(subtests['unexpected'])
if subtests["count"] != 0:
rv = "Harness %s%s. Subtests passed %i/%i. Unexpected %s" % (
rv = "Test %s%s. Subtests passed %i/%i. Unexpected %s" % (
data["status"], expected_str, subtests["pass"], subtests["count"],
len(unexpected))
subtests['unexpected'])
else:
rv = "%s%s" % (data["status"], expected_str)
unexpected = self.summary.current["unexpected_logs"].get(data["test"])
if unexpected:
rv += "\n"
if len(unexpected) == 1 and parent_unexpected:
rv += "%s" % unexpected[0][-1]
rv += "%s" % unexpected[0].get("message", "")
else:
for name, status, expected, message in unexpected:
if name is None:
name = "[Parent]"
expected_str = "Expected %s, got %s" % (expected, status)
rv += "%s\n" % ("\n".join([name, "-" * len(name), expected_str, message]))
for data in unexpected:
name = data.get("subtest", "[Parent]")
expected_str = "Expected %s, got %s" % (data["expected"], data["status"])
rv += "%s\n" % (
"\n".join([name, "-" * len(name), expected_str, data.get("message", "")]))
rv = rv[:-1]
return rv
@ -262,11 +252,9 @@ class MachFormatter(base.BaseFormatter):
return rv
def test_status(self, data):
self.summary_values["subtests"] += 1
test = self._get_test_id(data)
if test not in self.status_buffer:
self.status_buffer[test] = {"count": 0, "unexpected": [], "pass": 0}
self.status_buffer[test] = {"count": 0, "unexpected": 0, "pass": 0}
self.status_buffer[test]["count"] += 1
message = data.get("message", "")
@ -278,8 +266,6 @@ class MachFormatter(base.BaseFormatter):
if data["status"] == "PASS":
self.status_buffer[test]["pass"] += 1
self._update_summary(data)
rv = None
status, subtest = data["status"], data["subtest"]
unexpected = "expected" in data
@ -287,41 +273,23 @@ class MachFormatter(base.BaseFormatter):
if self.terminal is not None:
status = (self.terminal.red if unexpected else self.terminal.green)(status)
rv = " ".join([subtest, status, message])
elif unexpected:
# We only append an unexpected summary if it was not logged
# directly by verbose mode.
self.status_buffer[test]["unexpected"].append((subtest,
status,
data["expected"],
message))
if unexpected:
self.status_buffer[test]["unexpected"] += 1
return rv
def assertion_count(self, data):
self.summary_values["assertion_counts"] += 1
if data["min_expected"] <= data["count"] <= data["max_expected"]:
return
if data["min_expected"] != data["max_expected"]:
expected = "%i to %i" % (data["min_expected"],
data["max_expected"])
else:
expected = "%i" % data["min_expected"]
if data["min_expected"] <= data["count"] <= data["max_expected"]:
return
elif data["max_expected"] < data["count"]:
status = "FAIL"
else:
status = "PASS"
self.summary_values["unexpected"][status] += 1
return "Assertion count %i, expected %s assertions\n" % (data["count"], expected)
def _update_summary(self, data):
if "expected" in data:
self.summary_values["unexpected"][data["status"]] += 1
elif data["status"] == "SKIP":
self.summary_values["skipped"] += 1
else:
self.summary_values["expected"] += 1
def process_output(self, data):
rv = []
@ -421,7 +389,7 @@ class MachFormatter(base.BaseFormatter):
def _get_subtest_data(self, data):
test = self._get_test_id(data)
return self.status_buffer.get(test, {"count": 0, "unexpected": [], "pass": 0})
return self.status_buffer.get(test, {"count": 0, "unexpected": 0, "pass": 0})
def _time(self, data):
entry_time = data["time"]

Просмотреть файл

@ -6,8 +6,9 @@ from __future__ import absolute_import
from .base import LogLevelFilter, StreamHandler, BaseHandler
from .statushandler import StatusHandler
from .summaryhandler import SummaryHandler
from .bufferhandler import BufferHandler
from .valgrindhandler import ValgrindHandler
__all__ = ['LogLevelFilter', 'StreamHandler', 'BaseHandler',
'StatusHandler', 'BufferHandler', 'ValgrindHandler']
'StatusHandler', 'SummaryHandler', 'BufferHandler', 'ValgrindHandler']

Просмотреть файл

@ -7,7 +7,7 @@ from __future__ import absolute_import
from threading import Lock
import codecs
from ..structuredlog import log_levels
from mozlog.structuredlog import log_levels
class BaseHandler(object):

Просмотреть файл

@ -0,0 +1,154 @@
# This Source Code Form is subject to the terms of the Mozilla Public
# License, v. 2.0. If a copy of the MPL was not distributed with this
# file, You can obtain one at http://mozilla.org/MPL/2.0/.
from __future__ import absolute_import
from collections import (
defaultdict,
OrderedDict,
)
from ..reader import LogHandler
class SummaryHandler(LogHandler):
"""Handler class for storing suite summary information.
Can handle multiple suites in a single run. Summary
information is stored on the self.summary instance variable.
Per suite summary information can be obtained by calling 'get'
or iterating over this class.
"""
def __init__(self, **kwargs):
super(SummaryHandler, self).__init__(**kwargs)
self.summary = OrderedDict()
self.current_suite = None
@property
def current(self):
return self.summary.get(self.current_suite)
def __getitem__(self, suite):
"""Return summary information for the given suite.
The summary is of the form:
{
'counts': {
'<check>': {
'count': int,
'expected': {
'<status>': int,
},
'unexpected': {
'<status>': int,
},
},
},
'unexpected_logs': {
'<test>': [<data>]
}
}
Valid values for <check> are `test`, `subtest` and `assert`. Valid
<status> keys are defined in the :py:mod:`mozlog.logtypes` module. The
<test> key is the id as logged by `test_start`. Finally the <data>
field is the log data from any `test_end` or `test_status` log messages
that have an unexpected result.
"""
return self.summary[suite]
def __iter__(self):
"""Iterate over summaries.
Yields a tuple of (suite, summary). The summary returned is
the same format as returned by 'get'.
"""
for suite, data in self.summary.iteritems():
yield suite, data
@classmethod
def aggregate(cls, key, counts, include_skip=True):
"""Helper method for aggregating count data by 'key' instead of by 'check'."""
assert key in ('count', 'expected', 'unexpected')
res = defaultdict(int)
for check, val in counts.items():
if key == 'count':
res[check] += val[key]
continue
for status, num in val[key].items():
if not include_skip and status == 'skip':
continue
res[check] += num
return res
def suite_start(self, data):
self.current_suite = data.get('name', 'suite {}'.format(len(self.summary) + 1))
if self.current_suite not in self.summary:
self.summary[self.current_suite] = {
'counts': {
'test': {
'count': 0,
'expected': defaultdict(int),
'unexpected': defaultdict(int),
},
'subtest': {
'count': 0,
'expected': defaultdict(int),
'unexpected': defaultdict(int),
},
'assert': {
'count': 0,
'expected': defaultdict(int),
'unexpected': defaultdict(int),
}
},
'unexpected_logs': OrderedDict(),
}
def test_start(self, data):
self.current['counts']['test']['count'] += 1
def test_status(self, data):
logs = self.current['unexpected_logs']
count = self.current['counts']
count['subtest']['count'] += 1
if 'expected' in data:
count['subtest']['unexpected'][data['status'].lower()] += 1
if data['test'] not in logs:
logs[data['test']] = []
logs[data['test']].append(data)
else:
count['subtest']['expected'][data['status'].lower()] += 1
def test_end(self, data):
logs = self.current['unexpected_logs']
count = self.current['counts']
if 'expected' in data:
count['test']['unexpected'][data['status'].lower()] += 1
if data['test'] not in logs:
logs[data['test']] = []
logs[data['test']].append(data)
else:
count['test']['expected'][data['status'].lower()] += 1
def assertion_count(self, data):
count = self.current['counts']
count['assert']['count'] += 1
if data['min_expected'] <= data['count'] <= data['max_expected']:
if data['count'] > 0:
count['assert']['expected']['fail'] += 1
else:
count['assert']['expected']['pass'] += 1
elif data['max_expected'] < data['count']:
count['assert']['unexpected']['fail'] += 1
else:
count['assert']['unexpected']['pass'] += 1

Просмотреть файл

@ -108,6 +108,42 @@ class TestStatusHandler(BaseStructuredTest):
self.assertEqual(2, summary.expected_statuses['OK'])
class TestSummaryHandler(BaseStructuredTest):
def setUp(self):
super(TestSummaryHandler, self).setUp()
self.handler = handlers.SummaryHandler()
self.logger.add_handler(self.handler)
def test_failure_run(self):
self.logger.suite_start([])
self.logger.test_start("test1")
self.logger.test_status("test1", "sub1", status='PASS')
self.logger.test_status("test1", "sub2", status='TIMEOUT')
self.logger.assertion_count("test1", 5, 1, 10)
self.logger.assertion_count("test1", 5, 10, 15)
self.logger.test_end("test1", status='OK')
self.logger.suite_end()
counts = self.handler.current['counts']
self.assertIn('timeout', counts['subtest']['unexpected'])
self.assertEqual(1, counts['subtest']['unexpected']['timeout'])
self.assertIn('pass', counts['subtest']['expected'])
self.assertEqual(1, counts['subtest']['expected']['pass'])
self.assertIn('ok', counts['test']['expected'])
self.assertEqual(1, counts['test']['expected']['ok'])
self.assertIn('pass', counts['assert']['unexpected'])
self.assertEqual(1, counts['assert']['unexpected']['pass'])
self.assertIn('fail', counts['assert']['expected'])
self.assertEqual(1, counts['assert']['expected']['fail'])
logs = self.handler.current['unexpected_logs']
self.assertEqual(1, len(logs))
self.assertIn('test1', logs)
self.assertEqual(1, len(logs['test1']))
self.assertEqual('sub2', logs['test1'][0]['subtest'])
class TestStructuredLog(BaseStructuredTest):
def test_suite_start(self):
@ -734,13 +770,15 @@ class TestMachFormatter(FormatterTest):
self.set_position()
self.logger.suite_end()
self.assertIn("Ran 3 tests", self.loglines)
self.assertIn("Ran 3 checks (3 tests)", self.loglines)
self.assertIn("Expected results: 1", self.loglines)
self.assertIn(
"Unexpected results: 2 (FAIL: 1, PASS: 1)", self.loglines)
self.assertIn("""
Unexpected results: 2
test: 2 (1 fail, 1 pass)
""".strip(), "\n".join(self.loglines))
self.assertNotIn("test1", self.loglines)
self.assertIn("PASS expected TIMEOUT test2", self.loglines)
self.assertIn("FAIL test3", self.loglines)
self.assertIn(" PASS expected TIMEOUT test2", self.loglines)
self.assertIn(" FAIL test3", self.loglines)
def test_summary_subtests(self):
self.logger.suite_start([])
@ -758,10 +796,13 @@ class TestMachFormatter(FormatterTest):
self.set_position()
self.logger.suite_end()
self.assertIn("Ran 5 tests (2 parents, 3 subtests)", self.loglines)
self.assertIn("Ran 5 checks (2 tests, 3 subtests)", self.loglines)
self.assertIn("Expected results: 2", self.loglines)
self.assertIn(
"Unexpected results: 3 (FAIL: 1, TIMEOUT: 2)", self.loglines)
self.assertIn("""
Unexpected results: 3
test: 1 (1 timeout)
subtest: 2 (1 fail, 1 timeout)
""".strip(), "\n".join(self.loglines))
def test_summary_ok(self):
self.logger.suite_start([])
@ -781,7 +822,7 @@ class TestMachFormatter(FormatterTest):
self.assertIn("OK", self.loglines)
self.assertIn("Expected results: 5", self.loglines)
self.assertIn("Unexpected results: 0", self.loglines)
self.assertNotIn("Unexpected results: 0", self.loglines)
def test_process_start(self):
self.logger.process_start(1234)