Bug 1445624 - [mozlog] Various improvements and fixes to the mach formatter, r?gbrown
This consolidates the printing of status logs, which was previously handled
differently in 3-4 places. This also fixes a few of the annoyances listed in
the
bug 1445624 description. Finally this also fixes a few edge cases that I
noticed when writing the tests.
MozReview-Commit-ID: APudT8yBqVS
--- a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
@@ -79,21 +79,37 @@ class MachFormatter(base.BaseFormatter):
def suite_end(self, data):
action = self.term.yellow(data['action'].upper())
rv = [action]
if not self.summary_on_shutdown:
rv.append(self._format_suite_summary(self.summary.current_suite, self.summary.current))
return "\n".join(rv)
def _format_expected(self, status, expected):
- color = self.term.red
- if expected in ("PASS", "OK"):
- return color(status)
+ if status == expected:
+ color = self.term.green
+ if expected not in ("PASS", "OK"):
+ color = self.term.yellow
+ status = "EXPECTED-%s" % status
+ else:
+ color = self.term.red
+ if status in ("PASS", "OK"):
+ status = "UNEXPECTED-%s" % status
+ return color(status)
- return color("%s expected %s" % (status, expected))
+ def _format_status(self, test, data):
+ name = data.get("subtest", test)
+ rv = "%s %s" % (self._format_expected(
+ data["status"], data.get("expected", data["status"])), name)
+ if 'message' in data:
+ rv += " - %s" % data['message']
+
+ if 'stack' in data:
+ rv += "\n%s\n" % self.term.dim(data['stack'].strip('\n'))
+ return rv
def _format_suite_summary(self, suite, summary):
count = summary['counts']
logs = summary['unexpected_logs']
rv = ["", self.term.yellow(suite), self.term.yellow("~" * len(suite))]
# Format check counts
@@ -126,52 +142,41 @@ class MachFormatter(base.BaseFormatter):
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(self.term.green("OK"))
else:
- heading = "Unexpected Logs"
- rv.extend(["", heading, "-" * len(heading)])
+ heading = "Unexpected Results"
+ rv.extend(["", self.term.yellow(heading), self.term.yellow("-" * len(heading))])
if count['subtest']['count']:
for test_id, results in logs.items():
test = self._get_file_name(test_id)
- rv.append(test)
+ rv.append(self.term.bold(test))
for data in results:
- name = data.get("subtest", "[Parent]")
- rv.append(" %s %s" % (self._format_expected(
- data["status"], data["expected"]), name))
+ rv.append(" %s" % self._format_status(test, data).rstrip())
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))
+ rv.append(self._format_status(test, data).rstrip())
return "\n".join(rv)
def test_start(self, data):
action = self.term.yellow(data['action'].upper())
return "%s: %s" % (action, self._get_test_id(data))
def test_end(self, data):
subtests = self._get_subtest_data(data)
- 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"]
else:
parent_unexpected = False
expected_str = ""
test = self._get_test_id(data)
@@ -184,68 +189,53 @@ class MachFormatter(base.BaseFormatter):
rv = "Test %s%s. Subtests passed %i/%i. Unexpected %s" % (
data["status"], expected_str, subtests["pass"], subtests["count"],
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].get("message", "")
- else:
- 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]
+ message = unexpected[0].get("message", "")
+ if message:
+ rv += " - %s" % message
+ elif not self.verbose:
+ rv += "\n"
+ for d in unexpected:
+ rv += self._format_status(data['test'], d)
if "expected" not in data and not bool(subtests['unexpected']):
color = self.term.green
else:
color = self.term.red
+
action = color(data['action'].upper())
return "%s: %s" % (action, 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):
test = self._get_test_id(data)
if test not in self.status_buffer:
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
- rv = None
- status, subtest = data["status"], data["subtest"]
- unexpected = "expected" in data
+ if 'expected' in data:
+ self.status_buffer[test]["unexpected"] += 1
if self.verbose:
- status = (self.term.red if unexpected else self.term.green)(status)
- rv = " ".join([subtest, status, message])
-
- if unexpected:
- self.status_buffer[test]["unexpected"] += 1
- if rv:
- action = self.term.yellow(data['action'].upper())
- return "%s: %s" % (action, rv)
+ return self._format_status(test, data).rstrip('\n')
def assertion_count(self, data):
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"])
--- a/testing/mozbase/mozlog/tests/test_formatters.py
+++ b/testing/mozbase/mozlog/tests/test_formatters.py
@@ -1,12 +1,11 @@
# 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/.
-# flake8: noqa
from __future__ import absolute_import, print_function, unicode_literals
import mozunit
import pytest
from io import BytesIO
from mozlog.structuredlog import StructuredLogger
@@ -38,17 +37,17 @@ Ran 4 checks (3 tests, 1 subtests)
Expected results: 4
OK
""".lstrip('\n')),
('mach', {'verbose': True}, """
0:00.00 SUITE_START: running 3 tests
0:00.00 TEST_START: test_foo
0:00.00 TEST_END: OK
0:00.00 TEST_START: test_bar
- 0:00.00 TEST_STATUS: a subtest PASS
+ 0:00.00 PASS a subtest
0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0
0:00.00 TEST_START: test_baz
0:00.00 TEST_END: FAIL
0:00.00 SUITE_END
suite 1
~~~~~~~
Ran 4 checks (3 tests, 1 subtests)
@@ -56,92 +55,80 @@ Expected results: 4
OK
""".lstrip('\n')),
],
'FAIL': [
('mach', {}, """
0:00.00 SUITE_START: running 3 tests
0:00.00 TEST_START: test_foo
- 0:00.00 TEST_END: FAIL, expected PASS
-expected 0 got 1
+ 0:00.00 TEST_END: FAIL, expected PASS - expected 0 got 1
0:00.00 TEST_START: test_bar
- 0:00.00 TEST_STATUS: Test OK. Subtests passed 0/2. Unexpected 2
-a subtest
----------
-Expected PASS, got FAIL
-expected 0 got 1
-another subtest
----------------
-Expected PASS, got TIMEOUT
-
+ 0:00.00 TEST_END: Test OK. Subtests passed 0/2. Unexpected 2
+FAIL a subtest - expected 0 got 1
+ SimpleTest.is@SimpleTest/SimpleTest.js:312:5
+ @caps/tests/mochitest/test_bug246699.html:53:1
+TIMEOUT another subtest
0:00.00 TEST_START: test_baz
0:00.00 TEST_END: PASS, expected FAIL
-
0:00.00 SUITE_END
suite 1
~~~~~~~
Ran 5 checks (3 tests, 2 subtests)
Expected results: 1
Unexpected results: 4
test: 2 (1 fail, 1 pass)
subtest: 2 (1 fail, 1 timeout)
-Unexpected Logs
----------------
+Unexpected Results
+------------------
test_foo
- FAIL [Parent]
+ FAIL test_foo - expected 0 got 1
test_bar
- FAIL a subtest
+ FAIL a subtest - expected 0 got 1
+ SimpleTest.is@SimpleTest/SimpleTest.js:312:5
+ @caps/tests/mochitest/test_bug246699.html:53:1
TIMEOUT another subtest
test_baz
- PASS expected FAIL [Parent]
+ UNEXPECTED-PASS test_baz
""".lstrip('\n')),
('mach', {'verbose': True}, """
0:00.00 SUITE_START: running 3 tests
0:00.00 TEST_START: test_foo
- 0:00.00 TEST_END: FAIL, expected PASS
-expected 0 got 1
+ 0:00.00 TEST_END: FAIL, expected PASS - expected 0 got 1
0:00.00 TEST_START: test_bar
- 0:00.00 TEST_STATUS: a subtest FAIL expected 0 got 1
+ 0:00.00 FAIL a subtest - expected 0 got 1
SimpleTest.is@SimpleTest/SimpleTest.js:312:5
@caps/tests/mochitest/test_bug246699.html:53:1
- 0:00.00 TEST_STATUS: another subtest TIMEOUT
- 0:00.00 TEST_STATUS: Test OK. Subtests passed 0/2. Unexpected 2
-a subtest
----------
-Expected PASS, got FAIL
-expected 0 got 1
-another subtest
----------------
-Expected PASS, got TIMEOUT
-
+ 0:00.00 TIMEOUT another subtest
+ 0:00.00 TEST_END: Test OK. Subtests passed 0/2. Unexpected 2
0:00.00 TEST_START: test_baz
0:00.00 TEST_END: PASS, expected FAIL
-
0:00.00 SUITE_END
suite 1
~~~~~~~
Ran 5 checks (3 tests, 2 subtests)
Expected results: 1
Unexpected results: 4
test: 2 (1 fail, 1 pass)
subtest: 2 (1 fail, 1 timeout)
-Unexpected Logs
----------------
+Unexpected Results
+------------------
test_foo
- FAIL [Parent]
+ FAIL test_foo - expected 0 got 1
test_bar
- FAIL a subtest
+ FAIL a subtest - expected 0 got 1
+ SimpleTest.is@SimpleTest/SimpleTest.js:312:5
+ @caps/tests/mochitest/test_bug246699.html:53:1
TIMEOUT another subtest
test_baz
- PASS expected FAIL [Parent]
+ UNEXPECTED-PASS test_baz
""".lstrip('\n')),
],
}
def ids(test):
ids = []
for value in FORMATS[test]:
--- a/testing/mozbase/mozlog/tests/test_structured.py
+++ b/testing/mozbase/mozlog/tests/test_structured.py
@@ -773,18 +773,18 @@ class TestMachFormatter(FormatterTest):
self.assertIn("Ran 3 checks (3 tests)", self.loglines)
self.assertIn("Expected results: 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("UNEXPECTED-PASS 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")