--- a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
@@ -1,25 +1,25 @@
# 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
import time
-from collections import defaultdict
try:
import blessings
except ImportError:
blessings = None
from . import base
from .process import strstatus
+from ..handlers import SummaryHandler
def format_seconds(total):
"""Format number of seconds to MM:SS.DD form."""
minutes, seconds = divmod(total, 60)
return '%2d:%05.2f' % (minutes, seconds)
@@ -30,17 +30,18 @@ class NullTerminal(object):
def _id(self, value):
return value
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
elif terminal is None and blessings is not None:
terminal = blessings.Terminal()
if start_time is None:
start_time = time.time()
@@ -50,26 +51,22 @@ class MachFormatter(base.BaseFormatter):
self.write_times = write_times
self.status_buffer = {}
self.has_unexpected = {}
self.last_time = None
self.terminal = terminal
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
time = format_seconds(self._time(data))
action = data["action"].upper()
thread = data["thread"]
# Not using the NullTerminal here is a small optimisation to cut the number of
@@ -112,221 +109,192 @@ class MachFormatter(base.BaseFormatter):
return test_id
if isinstance(test_id, tuple):
return "".join(test_id)
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()
-
- 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 = ""
+ return self._format_suite_summary(self.summary.current_suite, self.summary.current)
- 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
else:
color = term.yellow
if expected in ("PASS", "OK"):
return color(status)
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:
stack = data["stack"]
if stack and stack[-1] != "\n":
stack += "\n"
message = stack + message
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
def valgrind_error(self, data):
rv = " " + data['primary'] + "\n"
for line in data['secondary']:
rv = rv + line + "\n"
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", "")
if "stack" in data:
if message:
message += "\n"
message += data["stack"]
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
if self.verbose:
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 = []
pid = data['process']
if pid.isdigit():
pid = 'pid:%s' % pid
if "command" in data and data["process"] not in self._known_pids:
@@ -416,17 +384,17 @@ class MachFormatter(base.BaseFormatter):
rule='{} '.format(data["rule"]) if data.get("rule") else "",
linter=data["linter"].lower() if data.get("linter") else "",
)
return message
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"]
if self.write_interval and self.last_time is not None:
t = entry_time - self.last_time
self.last_time = entry_time
else:
t = entry_time - self.start_time
--- a/testing/mozbase/mozlog/mozlog/handlers/__init__.py
+++ b/testing/mozbase/mozlog/mozlog/handlers/__init__.py
@@ -1,13 +1,14 @@
# 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 .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']
--- a/testing/mozbase/mozlog/mozlog/handlers/base.py
+++ b/testing/mozbase/mozlog/mozlog/handlers/base.py
@@ -2,17 +2,17 @@
# 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 threading import Lock
import codecs
-from ..structuredlog import log_levels
+from mozlog.structuredlog import log_levels
class BaseHandler(object):
"""A base handler providing message handling facilities to
derived classes.
:param inner: A handler-like callable that may receive messages
from a log user.
new file mode 100644
--- /dev/null
+++ b/testing/mozbase/mozlog/mozlog/handlers/summaryhandler.py
@@ -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
--- a/testing/mozbase/mozlog/tests/test_structured.py
+++ b/testing/mozbase/mozlog/tests/test_structured.py
@@ -103,16 +103,52 @@ class TestStatusHandler(BaseStructuredTe
self.logger.suite_end()
summary = self.handler.summarize()
self.assertIn('ERROR', summary.log_level_counts)
self.assertEqual(1, summary.log_level_counts['ERROR'])
self.assertIn('OK', summary.expected_statuses)
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):
self.logger.suite_start(["test"], "logtest")
self.assert_log_equals({"action": "suite_start",
"name": "logtest",
"tests": {"default": ["test"]}})
self.logger.suite_end()
@@ -729,23 +765,25 @@ class TestMachFormatter(FormatterTest):
self.logger.test_end("test2", status="PASS", expected="TIMEOUT")
self.logger.test_start("test3")
self.logger.test_end("test3", status="FAIL", expected="PASS")
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([])
self.logger.test_start("test1")
self.logger.test_status("test1", "subtest1", status="PASS")
self.logger.test_status("test1", "subtest2", status="FAIL")
self.logger.test_end("test1", status="OK", expected="OK")
@@ -753,20 +791,23 @@ class TestMachFormatter(FormatterTest):
self.logger.test_start("test2")
self.logger.test_status("test2", "subtest1",
status="TIMEOUT", expected="PASS")
self.logger.test_end("test2", status="TIMEOUT", expected="OK")
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([])
self.logger.test_start("test1")
self.logger.test_status("test1", "subtest1", status="PASS")
self.logger.test_status("test1", "subtest2", status="PASS")
self.logger.test_end("test1", status="OK", expected="OK")
@@ -776,17 +817,17 @@ class TestMachFormatter(FormatterTest):
status="PASS", expected="PASS")
self.logger.test_end("test2", status="OK", expected="OK")
self.set_position()
self.logger.suite_end()
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)
self.assertIn("Started process `1234`", self.loglines[0])
def test_process_start_with_command(self):
self.logger.process_start(1234, command='test cmd')
self.assertIn("Started process `1234` (test cmd)", self.loglines[0])