diff options
Diffstat (limited to 'testing/mozbase/mozlog/tests/test_formatters.py')
| -rw-r--r-- | testing/mozbase/mozlog/tests/test_formatters.py | 852 |
1 files changed, 852 insertions, 0 deletions
diff --git a/testing/mozbase/mozlog/tests/test_formatters.py b/testing/mozbase/mozlog/tests/test_formatters.py new file mode 100644 index 0000000000..5192f97b21 --- /dev/null +++ b/testing/mozbase/mozlog/tests/test_formatters.py @@ -0,0 +1,852 @@ +# encoding: utf-8 + +# 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, print_function, unicode_literals + +import json +import os +import signal +import time +import unittest +import xml.etree.ElementTree as ET +from textwrap import dedent + +import mozunit +import pytest +from six import StringIO, ensure_text, unichr + +from mozlog.structuredlog import StructuredLogger +from mozlog.formatters import ( + MachFormatter, + TbplFormatter, + HTMLFormatter, + XUnitFormatter, + GroupingFormatter, + ErrorSummaryFormatter, +) +from mozlog.handlers import StreamHandler + +formatters = { + "mach": MachFormatter, + "errorsummary": ErrorSummaryFormatter, +} + +FORMATS = { + # A list of tuples consisting of (name, options, expected string). + "PASS": [ + ( + "mach", + {}, + dedent( + """ + 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_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 (1 subtests, 3 tests) + Expected results: 4 + Unexpected results: 0 + OK + """ + ).lstrip("\n"), + ), + ( + "mach", + {"verbose": True}, + dedent( + """ + 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 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 (1 subtests, 3 tests) + Expected results: 4 + Unexpected results: 0 + OK + """ + ).lstrip("\n"), + ), + ], + "FAIL": [ + ( + "mach", + {}, + dedent( + """ + 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_START: test_bar + 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 (2 subtests, 3 tests) + Expected results: 1 + Unexpected results: 4 + test: 2 (1 fail, 1 pass) + subtest: 2 (1 fail, 1 timeout) + + Unexpected Results + ------------------ + test_foo + FAIL test_foo - expected 0 got 1 + test_bar + 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 + UNEXPECTED-PASS test_baz + """ + ).lstrip("\n"), + ), + ( + "mach", + {"verbose": True}, + dedent( + """ + 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_START: test_bar + 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 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 (2 subtests, 3 tests) + Expected results: 1 + Unexpected results: 4 + test: 2 (1 fail, 1 pass) + subtest: 2 (1 fail, 1 timeout) + + Unexpected Results + ------------------ + test_foo + FAIL test_foo - expected 0 got 1 + test_bar + 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 + UNEXPECTED-PASS test_baz + """ + ).lstrip("\n"), + ), + ], + "PRECONDITION_FAILED": [ + ( + "mach", + {}, + dedent( + """ + 0:00.00 SUITE_START: running 2 tests + 0:00.00 TEST_START: test_foo + 0:00.00 TEST_END: PRECONDITION_FAILED, expected OK + 0:00.00 TEST_START: test_bar + 0:00.00 TEST_END: Test OK. Subtests passed 1/2. Unexpected 1 + PRECONDITION_FAILED another subtest + 0:00.00 SUITE_END + + suite 1 + ~~~~~~~ + Ran 4 checks (2 subtests, 2 tests) + Expected results: 2 + Unexpected results: 2 + test: 1 (1 precondition_failed) + subtest: 1 (1 precondition_failed) + + Unexpected Results + ------------------ + test_foo + PRECONDITION_FAILED test_foo + test_bar + PRECONDITION_FAILED another subtest + """ + ).lstrip("\n"), + ), + ( + "mach", + {"verbose": True}, + dedent( + """ + 0:00.00 SUITE_START: running 2 tests + 0:00.00 TEST_START: test_foo + 0:00.00 TEST_END: PRECONDITION_FAILED, expected OK + 0:00.00 TEST_START: test_bar + 0:00.00 PASS a subtest + 0:00.00 PRECONDITION_FAILED another subtest + 0:00.00 TEST_END: Test OK. Subtests passed 1/2. Unexpected 1 + 0:00.00 SUITE_END + + suite 1 + ~~~~~~~ + Ran 4 checks (2 subtests, 2 tests) + Expected results: 2 + Unexpected results: 2 + test: 1 (1 precondition_failed) + subtest: 1 (1 precondition_failed) + + Unexpected Results + ------------------ + test_foo + PRECONDITION_FAILED test_foo + test_bar + PRECONDITION_FAILED another subtest + """ + ).lstrip("\n"), + ), + ], + "KNOWN-INTERMITTENT": [ + ( + "mach", + {}, + dedent( + """ + 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("\n"), + ), + ( + "mach", + {"verbose": True}, + dedent( + """ + 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("\n"), + ), + ], + "ERRORSUMMARY": [ + ( + "errorsummary", + {}, + dedent( + """ + {"groups": ["manifestA", "manifestB"], "action": "test_groups", "line": 0} + {"test": "test_baz", "subtest": null, "group": "manifestA", "status": "PASS", "expected": "FAIL", "message": null, "stack": null, "known_intermittent": [], "action": "test_result", "line": 8} + {"group": "manifestA", "status": "ERROR", "duration": 70, "action": "group_result", "line": 9} + {"group": "manifestB", "status": "OK", "duration": 10, "action": "group_result", "line": 9} + """ + ).lstrip("\n"), + ), + ], +} + + +def ids(test): + ids = [] + for value in FORMATS[test]: + args = ", ".join(["{}={}".format(k, v) for k, v in value[1].items()]) + if args: + args = "-{}".format(args) + ids.append("{}{}".format(value[0], args)) + return ids + + +@pytest.fixture(autouse=True) +def timestamp(monkeypatch): + def fake_time(*args, **kwargs): + return 0 + + monkeypatch.setattr(MachFormatter, "_time", fake_time) + + +@pytest.fixture +def get_logger(): + # Ensure a new state instance is created for each test function. + StructuredLogger._logger_states = {} + + def inner(name, **fmt_args): + buf = StringIO() + fmt = formatters[name](**fmt_args) + logger = StructuredLogger("test_logger") + logger.add_handler(StreamHandler(buf, fmt)) + return logger + + return inner + + +@pytest.mark.parametrize("name,opts,expected", FORMATS["PASS"], ids=ids("PASS")) +def test_pass(get_logger, name, opts, expected): + logger = get_logger(name, **opts) + + logger.suite_start(["test_foo", "test_bar", "test_baz"]) + logger.test_start("test_foo") + logger.test_end("test_foo", "OK") + logger.test_start("test_bar") + logger.test_status("test_bar", "a subtest", "PASS") + logger.test_end("test_bar", "OK") + logger.test_start("test_baz") + logger.test_end("test_baz", "FAIL", "FAIL", "expected 0 got 1") + logger.suite_end() + + buf = logger.handlers[0].stream + result = buf.getvalue() + print("Dumping result for copy/paste:") + print(result) + assert result == expected + + +@pytest.mark.parametrize("name,opts,expected", FORMATS["FAIL"], ids=ids("FAIL")) +def test_fail(get_logger, name, opts, expected): + stack = """ + SimpleTest.is@SimpleTest/SimpleTest.js:312:5 + @caps/tests/mochitest/test_bug246699.html:53:1 +""".strip( + "\n" + ) + + logger = get_logger(name, **opts) + + logger.suite_start(["test_foo", "test_bar", "test_baz"]) + logger.test_start("test_foo") + logger.test_end("test_foo", "FAIL", "PASS", "expected 0 got 1") + logger.test_start("test_bar") + logger.test_status( + "test_bar", "a subtest", "FAIL", "PASS", "expected 0 got 1", stack + ) + logger.test_status("test_bar", "another subtest", "TIMEOUT") + logger.test_end("test_bar", "OK") + logger.test_start("test_baz") + logger.test_end("test_baz", "PASS", "FAIL") + logger.suite_end() + + buf = logger.handlers[0].stream + result = buf.getvalue() + print("Dumping result for copy/paste:") + print(result) + assert result == expected + + +@pytest.mark.parametrize( + "name,opts,expected", FORMATS["PRECONDITION_FAILED"], ids=ids("PRECONDITION_FAILED") +) +def test_precondition_failed(get_logger, name, opts, expected): + logger = get_logger(name, **opts) + + logger.suite_start(["test_foo", "test_bar"]) + logger.test_start("test_foo") + logger.test_end("test_foo", "PRECONDITION_FAILED") + logger.test_start("test_bar") + logger.test_status("test_bar", "a subtest", "PASS") + logger.test_status("test_bar", "another subtest", "PRECONDITION_FAILED") + logger.test_end("test_bar", "OK") + logger.suite_end() + + buf = logger.handlers[0].stream + result = buf.getvalue() + print("Dumping result for copy/paste:") + print(result) + assert result == expected + + +@pytest.mark.parametrize( + "name,opts,expected", FORMATS["KNOWN-INTERMITTENT"], ids=ids("KNOWN-INTERMITTENT") +) +def test_known_intermittent(get_logger, name, opts, expected): + logger = get_logger(name, **opts) + + 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() + + buf = logger.handlers[0].stream + result = buf.getvalue() + print("Dumping result for copy/paste:") + print(result) + assert result == expected + + +@pytest.mark.parametrize( + "name,opts,expected", FORMATS["ERRORSUMMARY"], ids=ids("ERRORSUMMARY") +) +def test_errorsummary(monkeypatch, get_logger, name, opts, expected): + + ts = {"ts": 0} # need to use dict since 'nonlocal' doesn't exist on PY2 + + def fake_time(): + ts["ts"] += 0.01 + return ts["ts"] + + monkeypatch.setattr(time, "time", fake_time) + logger = get_logger(name, **opts) + + logger.suite_start( + { + "manifestA": ["test_foo", "test_bar", "test_baz"], + "manifestB": ["test_something"], + } + ) + logger.test_start("test_foo") + logger.test_end("test_foo", "SKIP") + logger.test_start("test_bar") + logger.test_end("test_bar", "OK") + logger.test_start("test_something") + logger.test_end("test_something", "OK") + logger.test_start("test_baz") + logger.test_end("test_baz", "PASS", "FAIL") + logger.suite_end() + + buf = logger.handlers[0].stream + result = buf.getvalue() + print("Dumping result for copy/paste:") + print(result) + + expected = expected.split("\n") + for i, line in enumerate(result.split("\n")): + if not line: + continue + + data = json.loads(line) + assert data == json.loads(expected[i]) + + +class FormatterTest(unittest.TestCase): + def setUp(self): + self.position = 0 + self.logger = StructuredLogger("test_%s" % type(self).__name__) + self.output_file = StringIO() + self.handler = StreamHandler(self.output_file, self.get_formatter()) + self.logger.add_handler(self.handler) + + def set_position(self, pos=None): + if pos is None: + pos = self.output_file.tell() + self.position = pos + + def get_formatter(self): + raise NotImplementedError( + "FormatterTest subclasses must implement get_formatter" + ) + + @property + def loglines(self): + self.output_file.seek(self.position) + return [ensure_text(line.rstrip()) for line in self.output_file.readlines()] + + +class TestHTMLFormatter(FormatterTest): + def get_formatter(self): + return HTMLFormatter() + + def test_base64_string(self): + self.logger.suite_start([]) + self.logger.test_start("string_test") + self.logger.test_end("string_test", "FAIL", extra={"data": "foobar"}) + self.logger.suite_end() + self.assertIn("data:text/html;charset=utf-8;base64,Zm9vYmFy", self.loglines[-3]) + + def test_base64_unicode(self): + self.logger.suite_start([]) + self.logger.test_start("unicode_test") + self.logger.test_end("unicode_test", "FAIL", extra={"data": unichr(0x02A9)}) + self.logger.suite_end() + self.assertIn("data:text/html;charset=utf-8;base64,yqk=", self.loglines[-3]) + + def test_base64_other(self): + self.logger.suite_start([]) + self.logger.test_start("int_test") + self.logger.test_end("int_test", "FAIL", extra={"data": {"foo": "bar"}}) + self.logger.suite_end() + self.assertIn( + "data:text/html;charset=utf-8;base64,eyJmb28iOiAiYmFyIn0=", + self.loglines[-3], + ) + + +class TestTBPLFormatter(FormatterTest): + def get_formatter(self): + return TbplFormatter() + + def test_unexpected_message(self): + self.logger.suite_start([]) + self.logger.test_start("timeout_test") + self.logger.test_end("timeout_test", "TIMEOUT", message="timed out") + self.assertIn( + "TEST-UNEXPECTED-TIMEOUT | timeout_test | timed out", self.loglines + ) + self.logger.suite_end() + + def test_default_unexpected_end_message(self): + self.logger.suite_start([]) + self.logger.test_start("timeout_test") + self.logger.test_end("timeout_test", "TIMEOUT") + self.assertIn( + "TEST-UNEXPECTED-TIMEOUT | timeout_test | expected OK", self.loglines + ) + self.logger.suite_end() + + def test_default_unexpected_status_message(self): + self.logger.suite_start([]) + self.logger.test_start("timeout_test") + self.logger.test_status("timeout_test", "subtest", status="TIMEOUT") + self.assertIn( + "TEST-UNEXPECTED-TIMEOUT | timeout_test | subtest - expected PASS", + self.loglines, + ) + self.logger.test_end("timeout_test", "OK") + self.logger.suite_end() + + def test_known_intermittent_end(self): + self.logger.suite_start([]) + self.logger.test_start("intermittent_test") + self.logger.test_end( + "intermittent_test", + status="FAIL", + expected="PASS", + known_intermittent=["FAIL"], + ) + # test_end log format: + # "TEST-KNOWN-INTERMITTENT-<STATUS> | <test> | took <duration>ms" + # where duration may be different each time + self.assertIn( + "TEST-KNOWN-INTERMITTENT-FAIL | intermittent_test | took ", self.loglines[2] + ) + self.assertIn("ms", self.loglines[2]) + self.logger.suite_end() + + def test_known_intermittent_status(self): + self.logger.suite_start([]) + self.logger.test_start("intermittent_test") + self.logger.test_status( + "intermittent_test", + "subtest", + status="FAIL", + expected="PASS", + known_intermittent=["FAIL"], + ) + self.assertIn( + "TEST-KNOWN-INTERMITTENT-FAIL | intermittent_test | subtest", self.loglines + ) + self.logger.test_end("intermittent_test", "OK") + self.logger.suite_end() + + def test_single_newline(self): + self.logger.suite_start([]) + self.logger.test_start("test1") + self.set_position() + self.logger.test_status("test1", "subtest", status="PASS", expected="FAIL") + self.logger.test_end("test1", "OK") + self.logger.suite_end() + + # This sequence should not produce blanklines + for line in self.loglines: + self.assertNotEqual("", line) + + def test_process_exit(self): + self.logger.process_exit(1234, 0) + self.assertIn("TEST-INFO | 1234: exit 0", self.loglines) + + @unittest.skipUnless(os.name == "posix", "posix only") + def test_process_exit_with_sig(self): + # subprocess return code is negative when process + # has been killed by signal on posix. + self.logger.process_exit(1234, -signal.SIGTERM) + self.assertIn("TEST-INFO | 1234: killed by SIGTERM", self.loglines) + + +class TestTBPLFormatterWithShutdown(FormatterTest): + def get_formatter(self): + return TbplFormatter(summary_on_shutdown=True) + + def test_suite_summary_on_shutdown(self): + self.logger.suite_start([]) + self.logger.test_start("summary_test") + self.logger.test_status( + "summary_test", "subtest", "FAIL", "PASS", known_intermittent=["FAIL"] + ) + self.logger.test_end("summary_test", "FAIL", "OK", known_intermittent=["FAIL"]) + self.logger.suite_end() + self.logger.shutdown() + + self.assertIn("suite 1: 2/2 (2 known intermittent tests)", self.loglines) + self.assertIn("Known Intermittent tests:", self.loglines) + self.assertIn( + "TEST-KNOWN-INTERMITTENT-FAIL | summary_test | subtest", self.loglines + ) + + +class TestMachFormatter(FormatterTest): + def get_formatter(self): + return MachFormatter(disable_colors=True) + + def test_summary(self): + self.logger.suite_start([]) + + # Some tests that pass + self.logger.test_start("test1") + self.logger.test_end("test1", status="PASS", expected="PASS") + + self.logger.test_start("test2") + 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 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("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") + + 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 checks (3 subtests, 2 tests)", self.loglines) + self.assertIn("Expected results: 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") + + self.logger.test_start("test2") + self.logger.test_status("test2", "subtest1", 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) + + 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]) + + def test_process_exit(self): + self.logger.process_exit(1234, 0) + self.assertIn("1234: exit 0", self.loglines[0]) + + @unittest.skipUnless(os.name == "posix", "posix only") + def test_process_exit_with_sig(self): + # subprocess return code is negative when process + # has been killed by signal on posix. + self.logger.process_exit(1234, -signal.SIGTERM) + self.assertIn("1234: killed by SIGTERM", self.loglines[0]) + + +class TestGroupingFormatter(FormatterTest): + def get_formatter(self): + return GroupingFormatter() + + def test_results_total(self): + self.logger.suite_start([]) + + self.logger.test_start("test1") + self.logger.test_status("test1", "subtest1", status="PASS") + self.logger.test_status("test1", "subtest1", status="PASS") + self.logger.test_end("test1", status="OK") + + self.logger.test_start("test2") + self.logger.test_status( + "test2", + "subtest2", + status="FAIL", + expected="PASS", + known_intermittent=["FAIL"], + ) + self.logger.test_end("test2", status="FAIL", expected="OK") + + self.set_position() + self.logger.suite_end() + + self.assertIn("Ran 2 tests finished in 0.0 seconds.", self.loglines) + self.assertIn(" \u2022 1 ran as expected. 0 tests skipped.", self.loglines) + self.assertIn(" \u2022 1 known intermittent results.", self.loglines) + self.assertIn(" \u2022 1 tests failed unexpectedly", self.loglines) + self.assertIn(" \u25B6 FAIL [expected OK] test2", self.loglines) + self.assertIn( + " \u25B6 FAIL [expected PASS, known intermittent [FAIL] test2, subtest2", + self.loglines, + ) + + +class TestXUnitFormatter(FormatterTest): + def get_formatter(self): + return XUnitFormatter() + + def log_as_xml(self): + return ET.fromstring("\n".join(self.loglines)) + + def test_stacktrace_is_present(self): + self.logger.suite_start([]) + self.logger.test_start("test1") + self.logger.test_end( + "test1", "fail", message="Test message", stack="this\nis\na\nstack" + ) + self.logger.suite_end() + + root = self.log_as_xml() + self.assertIn("this\nis\na\nstack", root.find("testcase/failure").text) + + def test_failure_message(self): + self.logger.suite_start([]) + self.logger.test_start("test1") + self.logger.test_end("test1", "fail", message="Test message") + self.logger.suite_end() + + root = self.log_as_xml() + self.assertEquals( + "Expected OK, got FAIL", root.find("testcase/failure").get("message") + ) + + def test_suite_attrs(self): + self.logger.suite_start([]) + self.logger.test_start("test1") + self.logger.test_end("test1", "ok", message="Test message") + self.logger.suite_end() + + root = self.log_as_xml() + self.assertEqual(root.get("skips"), "0") + self.assertEqual(root.get("failures"), "0") + self.assertEqual(root.get("errors"), "0") + self.assertEqual(root.get("tests"), "1") + self.assertEqual(root.get("time"), "0.00") + + def test_time_is_not_rounded(self): + # call formatter directly, it is easier here + formatter = self.get_formatter() + formatter.suite_start(dict(time=55000)) + formatter.test_start(dict(time=55100)) + formatter.test_end( + dict(time=55558, test="id", message="message", status="PASS") + ) + xml_string = formatter.suite_end(dict(time=55559)) + + root = ET.fromstring(xml_string) + self.assertEqual(root.get("time"), "0.56") + self.assertEqual(root.find("testcase").get("time"), "0.46") + + +if __name__ == "__main__": + mozunit.main() |