зеркало из https://github.com/mozilla/gecko-dev.git
Bug 1552914 - [mozlog] Update formatters to reflect new known_intermittent field. r=jgraham
The in-tree log formatters have been updated to reflect the new `known_intermittent` field, ensuring that a status matching a `known_intermittent` status is not logged as an unexpected failure. A message is printed when there is a test status that matches this. A test for known intermittents has been added to the test_formatters, following the same testing style for pass or fail. Differential Revision: https://phabricator.services.mozilla.com/D32174 --HG-- extra : moz-landing-system : lando
This commit is contained in:
Nikki S
Родитель
4eddbb64f5
Коммит
7e9e422495
|
|
@ -19,6 +19,7 @@ color_dict = {
|
|||
'log_process_output': 'blue',
|
||||
'log_test_status_pass': 'green',
|
||||
'log_test_status_unexpected_fail': 'red',
|
||||
'log_test_status_known_intermittent': 'orange',
|
||||
'time': 'cyan',
|
||||
'action': 'yellow',
|
||||
'pid': 'cyan',
|
||||
|
|
@ -136,22 +137,28 @@ class MachFormatter(base.BaseFormatter):
|
|||
self.summary.current))
|
||||
return "\n".join(rv)
|
||||
|
||||
def _format_expected(self, status, expected):
|
||||
def _format_expected(self, status, expected, known_intermittent=[]):
|
||||
if status == expected:
|
||||
color = self.color_formatter.log_test_status_pass
|
||||
if expected not in ("PASS", "OK"):
|
||||
color = self.color_formatter.log_test_status_fail
|
||||
status = "EXPECTED-%s" % status
|
||||
else:
|
||||
color = self.color_formatter.log_test_status_fail
|
||||
if status in ("PASS", "OK"):
|
||||
status = "UNEXPECTED-%s" % status
|
||||
if status in known_intermittent:
|
||||
color = self.color_formatter.log_test_status_known_intermittent
|
||||
status = "KNOWN-INTERMITTENT-%s" % status
|
||||
else:
|
||||
color = self.color_formatter.log_test_status_fail
|
||||
if status in ("PASS", "OK"):
|
||||
status = "UNEXPECTED-%s" % status
|
||||
return color(status)
|
||||
|
||||
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)
|
||||
rv = "%s %s" % (self._format_expected(data["status"],
|
||||
data.get("expected", data["status"]),
|
||||
data.get("known_intermittent", [])),
|
||||
name)
|
||||
if "message" in data:
|
||||
rv += " - %s" % data["message"]
|
||||
if "stack" in data:
|
||||
|
|
@ -164,6 +171,7 @@ class MachFormatter(base.BaseFormatter):
|
|||
def _format_suite_summary(self, suite, summary):
|
||||
count = summary['counts']
|
||||
logs = summary['unexpected_logs']
|
||||
intermittent_logs = summary['intermittent_logs']
|
||||
|
||||
rv = [
|
||||
"",
|
||||
|
|
@ -178,7 +186,11 @@ class MachFormatter(base.BaseFormatter):
|
|||
|
||||
# Format expected counts
|
||||
checks = self.summary.aggregate('expected', count, include_skip=False)
|
||||
rv.append("Expected results: {}".format(sum(checks.values())))
|
||||
intermittent_checks = self.summary.aggregate('known_intermittent',
|
||||
count, include_skip=False)
|
||||
intermittents = sum(intermittent_checks.values())
|
||||
known = " ({} known intermittents)".format(intermittents) if intermittents else ""
|
||||
rv.append("Expected results: {}{}".format(sum(checks.values()), known))
|
||||
|
||||
# Format skip counts
|
||||
skip_tests = count["test"]["expected"]["skip"]
|
||||
|
|
@ -192,8 +204,8 @@ class MachFormatter(base.BaseFormatter):
|
|||
# Format unexpected counts
|
||||
checks = self.summary.aggregate('unexpected', count)
|
||||
unexpected_count = sum(checks.values())
|
||||
rv.append("Unexpected results: {}".format(unexpected_count))
|
||||
if unexpected_count:
|
||||
rv.append("Unexpected results: {}".format(unexpected_count))
|
||||
for key in ('test', 'subtest', 'assert'):
|
||||
if not count[key]['unexpected']:
|
||||
continue
|
||||
|
|
@ -203,6 +215,24 @@ class MachFormatter(base.BaseFormatter):
|
|||
key, sum(count[key]['unexpected'].values()), status_str))
|
||||
|
||||
# Format status
|
||||
if intermittents > 0:
|
||||
heading = "Known Intermittent Results"
|
||||
rv.extend(["", self.color_formatter.heading(heading),
|
||||
self.color_formatter.heading("-" * len(heading))])
|
||||
if count['subtest']['count']:
|
||||
for test_id, results in intermittent_logs.items():
|
||||
test = self._get_file_name(test_id)
|
||||
rv.append(self.color_formatter.bold(test))
|
||||
for data in results:
|
||||
rv.append(" %s" % self._format_status(test, data).rstrip())
|
||||
else:
|
||||
for test_id, results in intermittent_logs.items():
|
||||
test = self._get_file_name(test_id)
|
||||
assert len(results) == 1
|
||||
data = results[0]
|
||||
assert "subtest" not in data
|
||||
rv.append(self._format_status(test, data).rstrip())
|
||||
|
||||
if not any(count[key]["unexpected"] for key in ('test', 'subtest', 'assert')):
|
||||
rv.append(self.color_formatter.log_test_status_pass("OK"))
|
||||
else:
|
||||
|
|
@ -232,7 +262,8 @@ class MachFormatter(base.BaseFormatter):
|
|||
def test_end(self, data):
|
||||
subtests = self._get_subtest_data(data)
|
||||
|
||||
if "expected" in data:
|
||||
if ("expected" in data and
|
||||
data["status"] not in data.get("known_intermittent", [])):
|
||||
parent_unexpected = True
|
||||
expected_str = ", expected %s" % data["expected"]
|
||||
else:
|
||||
|
|
@ -267,6 +298,12 @@ class MachFormatter(base.BaseFormatter):
|
|||
for d in unexpected:
|
||||
rv += self._format_status(data['test'], d)
|
||||
|
||||
intermittents = self.summary.current["intermittent_logs"].get(data["test"])
|
||||
if intermittents:
|
||||
rv += "\n"
|
||||
for d in intermittents:
|
||||
rv += self._format_status(data['test'], d)
|
||||
|
||||
if "expected" not in data and not bool(subtests['unexpected']):
|
||||
color = self.color_formatter.log_test_status_pass
|
||||
else:
|
||||
|
|
@ -357,8 +394,10 @@ class MachFormatter(base.BaseFormatter):
|
|||
if data["status"] == "PASS":
|
||||
self.status_buffer[test]["pass"] += 1
|
||||
|
||||
if 'expected' in data:
|
||||
if ('expected' in data and
|
||||
data["status"] not in data.get("known_intermittent", [])):
|
||||
self.status_buffer[test]["unexpected"] += 1
|
||||
|
||||
if self.verbose:
|
||||
return self._format_status(test, data).rstrip('\n')
|
||||
|
||||
|
|
|
|||
|
|
@ -180,19 +180,24 @@ class TbplFormatter(BaseFormatter):
|
|||
if message and message[-1] == "\n":
|
||||
message = message[:-1]
|
||||
|
||||
status = data["status"]
|
||||
|
||||
if "expected" in data:
|
||||
if not message:
|
||||
message = "- expected %s" % data["expected"]
|
||||
failure_line = "TEST-UNEXPECTED-%s | %s | %s %s\n" % (
|
||||
data["status"], data["test"], data["subtest"],
|
||||
message)
|
||||
if data["expected"] != "PASS":
|
||||
info_line = "TEST-INFO | expected %s\n" % data["expected"]
|
||||
return failure_line + info_line
|
||||
return failure_line
|
||||
if status in data.get("known_intermittent", []):
|
||||
status = "TEST-KNOWN-INTERMITTENT-%s" % status
|
||||
else:
|
||||
if not message:
|
||||
message = "- expected %s" % data["expected"]
|
||||
failure_line = "TEST-UNEXPECTED-%s | %s | %s %s\n" % (
|
||||
status, data["test"], data["subtest"],
|
||||
message)
|
||||
if data["expected"] != "PASS":
|
||||
info_line = "TEST-INFO | expected %s\n" % data["expected"]
|
||||
return failure_line + info_line
|
||||
return failure_line
|
||||
|
||||
return "TEST-%s | %s | %s %s\n" % (
|
||||
data["status"], data["test"], data["subtest"],
|
||||
status, data["test"], data["subtest"],
|
||||
message)
|
||||
|
||||
def test_end(self, data):
|
||||
|
|
@ -226,29 +231,34 @@ class TbplFormatter(BaseFormatter):
|
|||
screenshot_msg = ("\nREFTEST IMAGE: data:image/png;base64,%s" %
|
||||
screenshots[0]["screenshot"])
|
||||
|
||||
status = data['status']
|
||||
|
||||
if "expected" in data:
|
||||
message = data.get("message", "")
|
||||
if not message:
|
||||
message = "expected %s" % data["expected"]
|
||||
if "stack" in data:
|
||||
message += "\n%s" % data["stack"]
|
||||
if message and message[-1] == "\n":
|
||||
message = message[:-1]
|
||||
|
||||
message += screenshot_msg
|
||||
|
||||
failure_line = "TEST-UNEXPECTED-%s | %s | %s\n" % (
|
||||
data["status"], test_id, message)
|
||||
|
||||
if data["expected"] not in ("PASS", "OK"):
|
||||
expected_msg = "expected %s | " % data["expected"]
|
||||
if status in data.get("known_intermittent", []):
|
||||
status = "TEST-KNOWN-INTERMITTENT-%s" % status
|
||||
else:
|
||||
expected_msg = ""
|
||||
info_line = "TEST-INFO %s%s\n" % (expected_msg, duration_msg)
|
||||
message = data.get("message", "")
|
||||
if not message:
|
||||
message = "expected %s" % data["expected"]
|
||||
if "stack" in data:
|
||||
message += "\n%s" % data["stack"]
|
||||
if message and message[-1] == "\n":
|
||||
message = message[:-1]
|
||||
|
||||
return failure_line + info_line
|
||||
message += screenshot_msg
|
||||
|
||||
sections = ["TEST-%s" % data['status'], test_id]
|
||||
failure_line = "TEST-UNEXPECTED-%s | %s | %s\n" % (
|
||||
data["status"], test_id, message)
|
||||
|
||||
if data["expected"] not in ("PASS", "OK"):
|
||||
expected_msg = "expected %s | " % data["expected"]
|
||||
else:
|
||||
expected_msg = ""
|
||||
info_line = "TEST-INFO %s%s\n" % (expected_msg, duration_msg)
|
||||
|
||||
return failure_line + info_line
|
||||
|
||||
sections = ["TEST-%s" % status, test_id]
|
||||
if duration_msg:
|
||||
sections.append(duration_msg)
|
||||
rv.append(' | '.join(sections) + '\n')
|
||||
|
|
|
|||
|
|
@ -48,10 +48,16 @@ class SummaryHandler(LogHandler):
|
|||
'unexpected': {
|
||||
'<status>': int,
|
||||
},
|
||||
'known_intermittent': {
|
||||
'<status>': int,
|
||||
},
|
||||
},
|
||||
},
|
||||
'unexpected_logs': {
|
||||
'<test>': [<data>]
|
||||
},
|
||||
'intermittent_logs': {
|
||||
'<test>': [<data>]
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -60,6 +66,11 @@ class SummaryHandler(LogHandler):
|
|||
<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.
|
||||
|
||||
Mozlog's structuredlog has a `known_intermittent` field indicating if a
|
||||
`test` and `subtest` <status> are expected to arise intermittently.
|
||||
Known intermittent results are logged as both as `expected` and
|
||||
`known_intermittent`.
|
||||
"""
|
||||
return self.summary[suite]
|
||||
|
||||
|
|
@ -75,7 +86,7 @@ class SummaryHandler(LogHandler):
|
|||
@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')
|
||||
assert key in ('count', 'expected', 'unexpected', 'known_intermittent')
|
||||
|
||||
res = defaultdict(int)
|
||||
for check, val in counts.items():
|
||||
|
|
@ -98,19 +109,23 @@ class SummaryHandler(LogHandler):
|
|||
'count': 0,
|
||||
'expected': defaultdict(int),
|
||||
'unexpected': defaultdict(int),
|
||||
'known_intermittent': defaultdict(int),
|
||||
},
|
||||
'subtest': {
|
||||
'count': 0,
|
||||
'expected': defaultdict(int),
|
||||
'unexpected': defaultdict(int),
|
||||
'known_intermittent': defaultdict(int),
|
||||
},
|
||||
'assert': {
|
||||
'count': 0,
|
||||
'expected': defaultdict(int),
|
||||
'unexpected': defaultdict(int),
|
||||
'known_intermittent': defaultdict(int),
|
||||
}
|
||||
},
|
||||
'unexpected_logs': OrderedDict(),
|
||||
'intermittent_logs': OrderedDict(),
|
||||
}
|
||||
|
||||
def test_start(self, data):
|
||||
|
|
@ -118,25 +133,41 @@ class SummaryHandler(LogHandler):
|
|||
|
||||
def test_status(self, data):
|
||||
logs = self.current['unexpected_logs']
|
||||
intermittent_logs = self.current['intermittent_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)
|
||||
if data['status'] not in data.get('known_intermittent', []):
|
||||
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
|
||||
count['subtest']['known_intermittent'][data['status'].lower()] += 1
|
||||
if data['test'] not in intermittent_logs:
|
||||
intermittent_logs[data['test']] = []
|
||||
intermittent_logs[data['test']].append(data)
|
||||
else:
|
||||
count['subtest']['expected'][data['status'].lower()] += 1
|
||||
|
||||
def test_end(self, data):
|
||||
logs = self.current['unexpected_logs']
|
||||
intermittent_logs = self.current['intermittent_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)
|
||||
if data['status'] not in data.get('known_intermittent', []):
|
||||
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
|
||||
count['test']['known_intermittent'][data['status'].lower()] += 1
|
||||
if data['test'] not in intermittent_logs:
|
||||
intermittent_logs[data['test']] = []
|
||||
intermittent_logs[data['test']].append(data)
|
||||
else:
|
||||
count['test']['expected'][data['status'].lower()] += 1
|
||||
|
||||
|
|
|
|||
|
|
@ -36,6 +36,8 @@ Allowed actions, and subfields:
|
|||
expected [As for status] - Status that the test was expected to get,
|
||||
or absent if the test got the expected status
|
||||
extra - Dictionary of harness-specific extra information e.g. debug info
|
||||
known_intermittent - List of known intermittent statuses that should
|
||||
not fail a test. eg. ['FAIL', 'TIMEOUT']
|
||||
|
||||
test_status
|
||||
test - ID for the test
|
||||
|
|
@ -43,6 +45,8 @@ Allowed actions, and subfields:
|
|||
status [PASS | FAIL | TIMEOUT | NOTRUN | SKIP] - test status
|
||||
expected [As for status] - Status that the subtest was expected to get,
|
||||
or absent if the subtest got the expected status
|
||||
known_intermittent - List of known intermittent statuses that should
|
||||
not fail a test. eg. ['FAIL', 'TIMEOUT']
|
||||
|
||||
process_output
|
||||
process - PID of the process
|
||||
|
|
@ -356,7 +360,7 @@ class StructuredLogger(object):
|
|||
Unicode("message", default=None, optional=True),
|
||||
Unicode("stack", default=None, optional=True),
|
||||
Dict(Any, "extra", default=None, optional=True),
|
||||
List(SubStatus, "expected_intermittent", default=None,
|
||||
List(SubStatus, "known_intermittent", default=None,
|
||||
optional=True))
|
||||
def test_status(self, data):
|
||||
"""
|
||||
|
|
@ -389,7 +393,7 @@ class StructuredLogger(object):
|
|||
Unicode("message", default=None, optional=True),
|
||||
Unicode("stack", default=None, optional=True),
|
||||
Dict(Any, "extra", default=None, optional=True),
|
||||
List(Status, "expected_intermittent", default=None,
|
||||
List(Status, "known_intermittent", default=None,
|
||||
optional=True))
|
||||
def test_end(self, data):
|
||||
"""
|
||||
|
|
|
|||
|
|
@ -35,6 +35,7 @@ suite 1
|
|||
~~~~~~~
|
||||
Ran 4 checks (1 subtests, 3 tests)
|
||||
Expected results: 4
|
||||
Unexpected results: 0
|
||||
OK
|
||||
""".lstrip(b'\n')),
|
||||
('mach', {'verbose': True}, b"""
|
||||
|
|
@ -52,6 +53,7 @@ suite 1
|
|||
~~~~~~~
|
||||
Ran 4 checks (1 subtests, 3 tests)
|
||||
Expected results: 4
|
||||
Unexpected results: 0
|
||||
OK
|
||||
""".lstrip(b'\n')),
|
||||
],
|
||||
|
|
@ -124,6 +126,62 @@ test_bar
|
|||
TIMEOUT another subtest
|
||||
test_baz
|
||||
UNEXPECTED-PASS test_baz
|
||||
""".lstrip(b'\n')),
|
||||
],
|
||||
|
||||
'KNOWN-INTERMITTENT': [
|
||||
('mach', {}, b"""
|
||||
0:00.00 SUITE_START: running 3 tests
|
||||
0:00.00 TEST_START: test_foo
|
||||
0:00.00 TEST_END: FAIL
|
||||
KNOWN-INTERMITTENT-FAIL test_foo
|
||||
0:00.00 TEST_START: test_bar
|
||||
0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0
|
||||
KNOWN-INTERMITTENT-PASS a subtest
|
||||
0:00.00 TEST_START: test_baz
|
||||
0:00.00 TEST_END: FAIL
|
||||
0:00.00 SUITE_END
|
||||
|
||||
suite 1
|
||||
~~~~~~~
|
||||
Ran 4 checks (1 subtests, 3 tests)
|
||||
Expected results: 4 (2 known intermittents)
|
||||
Unexpected results: 0
|
||||
|
||||
Known Intermittent Results
|
||||
--------------------------
|
||||
test_foo
|
||||
KNOWN-INTERMITTENT-FAIL test_foo
|
||||
test_bar
|
||||
KNOWN-INTERMITTENT-PASS a subtest
|
||||
OK
|
||||
""".lstrip(b'\n')),
|
||||
('mach', {'verbose': True}, b"""
|
||||
0:00.00 SUITE_START: running 3 tests
|
||||
0:00.00 TEST_START: test_foo
|
||||
0:00.00 TEST_END: FAIL
|
||||
KNOWN-INTERMITTENT-FAIL test_foo
|
||||
0:00.00 TEST_START: test_bar
|
||||
0:00.00 KNOWN-INTERMITTENT-PASS a subtest
|
||||
0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0
|
||||
KNOWN-INTERMITTENT-PASS a subtest
|
||||
0:00.00 TEST_START: test_baz
|
||||
0:00.00 TEST_END: FAIL
|
||||
0:00.00 SUITE_END
|
||||
|
||||
suite 1
|
||||
~~~~~~~
|
||||
Ran 4 checks (1 subtests, 3 tests)
|
||||
Expected results: 4 (2 known intermittents)
|
||||
Unexpected results: 0
|
||||
|
||||
Known Intermittent Results
|
||||
--------------------------
|
||||
test_foo
|
||||
KNOWN-INTERMITTENT-FAIL test_foo
|
||||
test_bar
|
||||
KNOWN-INTERMITTENT-PASS a subtest
|
||||
OK
|
||||
""".lstrip(b'\n')),
|
||||
],
|
||||
}
|
||||
|
|
@ -201,6 +259,31 @@ def test_fail(name, opts, expected):
|
|||
print(result)
|
||||
assert result == expected
|
||||
|
||||
@pytest.mark.parametrize("name,opts,expected", FORMATS['KNOWN-INTERMITTENT'],
|
||||
ids=ids('KNOWN-INTERMITTENT'))
|
||||
def test_known_intermittent(name, opts, expected):
|
||||
buf = BytesIO()
|
||||
fmt = formatters[name](**opts)
|
||||
logger = StructuredLogger('test_logger')
|
||||
logger.add_handler(StreamHandler(buf, fmt))
|
||||
|
||||
logger.suite_start(['test_foo', 'test_bar', 'test_baz'])
|
||||
logger.test_start('test_foo')
|
||||
logger.test_end('test_foo', 'FAIL', 'PASS', known_intermittent=['FAIL'])
|
||||
logger.test_start('test_bar')
|
||||
logger.test_status('test_bar', 'a subtest', 'PASS', 'FAIL',
|
||||
known_intermittent=['PASS'])
|
||||
logger.test_end('test_bar', 'OK')
|
||||
logger.test_start('test_baz')
|
||||
logger.test_end('test_baz', 'FAIL', 'FAIL', 'expected 0 got 1',
|
||||
known_intermittent=['PASS'])
|
||||
logger.suite_end()
|
||||
|
||||
result = buf.getvalue()
|
||||
print("Dumping result for copy/paste:")
|
||||
print(result)
|
||||
assert result == expected
|
||||
|
||||
|
||||
if __name__ == '__main__':
|
||||
mozunit.main()
|
||||
|
|
|
|||
|
|
@ -239,15 +239,16 @@ class TestStructuredLog(BaseStructuredTest):
|
|||
self.logger.test_end("test1", "OK")
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_status_expected_intermittent(self):
|
||||
def test_status_known_intermittent(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test1")
|
||||
self.logger.test_status("test1", "subtest name", "fail", expected_intermittent=["FAIL"])
|
||||
self.logger.test_status("test1", "subtest name", "fail",
|
||||
known_intermittent=["FAIL"])
|
||||
self.assert_log_equals({"action": "test_status",
|
||||
"subtest": "subtest name",
|
||||
"status": "FAIL",
|
||||
"expected": "PASS",
|
||||
"expected_intermittent": ["FAIL"],
|
||||
"known_intermittent": ["FAIL"],
|
||||
"test": "test1"})
|
||||
self.logger.test_end("test1", "OK")
|
||||
self.logger.suite_end()
|
||||
|
|
@ -874,7 +875,7 @@ Unexpected results: 3
|
|||
|
||||
self.assertIn("OK", self.loglines)
|
||||
self.assertIn("Expected results: 5", self.loglines)
|
||||
self.assertNotIn("Unexpected results: 0", self.loglines)
|
||||
self.assertIn("Unexpected results: 0", self.loglines)
|
||||
|
||||
def test_process_start(self):
|
||||
self.logger.process_start(1234)
|
||||
|
|
|
|||
Загрузка…
Ссылка в новой задаче