Bug 1445624 - [mozlog] Add some tests for the mach formatter, r?gbrown
This adds a basic test for the mach formatter. This will ensure that changes to
this format are intentional. It will also make it easier for reviewers of these
changes to see a diff of the old vs new format.
MozReview-Commit-ID: LBSfdyvOPVV
--- a/config/mozunit.py
+++ b/config/mozunit.py
@@ -227,14 +227,14 @@ def main(*args, **kwargs):
unittest.main(testRunner=MozTestRunner(), *args, **kwargs)
else:
args = list(args)
if os.environ.get('MACH_STDOUT_ISATTY') and not any(a.startswith('--color') for a in args):
args.append('--color=yes')
module = __import__('__main__')
args.extend([
- '--verbose',
+ '-vv',
'-p', 'mozlog.pytest_mozlog.plugin',
'-p', 'no:cacheprovider',
module.__file__,
])
sys.exit(pytest.main(args))
--- a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
@@ -18,30 +18,31 @@ def format_seconds(total):
"""Format number of seconds to MM:SS.DD form."""
minutes, seconds = divmod(total, 60)
return '%2d:%05.2f' % (minutes, seconds)
class MachFormatter(base.BaseFormatter):
def __init__(self, start_time=None, write_interval=False, write_times=True,
- terminal=None, disable_colors=False, summary_on_shutdown=False, **kwargs):
+ terminal=None, disable_colors=False, summary_on_shutdown=False,
+ verbose=False, **kwargs):
super(MachFormatter, self).__init__(**kwargs)
if start_time is None:
start_time = time.time()
start_time = int(start_time * 1000)
self.start_time = start_time
self.write_interval = write_interval
self.write_times = write_times
self.status_buffer = {}
self.has_unexpected = {}
self.last_time = None
self.term = Terminal(disable_styling=disable_colors)
- self.verbose = False
+ self.verbose = verbose
self._known_pids = set()
self.summary = SummaryHandler()
self.summary_on_shutdown = summary_on_shutdown
def __call__(self, data):
self.summary(data)
--- a/testing/mozbase/mozlog/tests/manifest.ini
+++ b/testing/mozbase/mozlog/tests/manifest.ini
@@ -1,5 +1,6 @@
[DEFAULT]
subsuite = mozbase, os == "linux"
[test_logger.py]
[test_logtypes.py]
+[test_formatters.py]
[test_structured.py]
new file mode 100644
--- /dev/null
+++ b/testing/mozbase/mozlog/tests/test_formatters.py
@@ -0,0 +1,219 @@
+# 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
+from mozlog.formatters import (
+ MachFormatter,
+)
+from mozlog.handlers import StreamHandler
+
+formatters = {
+ 'mach': MachFormatter,
+}
+
+FORMATS = {
+ # A list of tuples consisting of (name, options, expected string).
+ 'PASS': [
+ ('mach', {}, """
+ 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 (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 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)
+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_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_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
+---------------
+test_foo
+ FAIL [Parent]
+test_bar
+ FAIL a subtest
+ TIMEOUT another subtest
+test_baz
+ PASS expected FAIL [Parent]
+""".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_START: test_bar
+ 0:00.00 TEST_STATUS: a subtest FAIL 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 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
+---------------
+test_foo
+ FAIL [Parent]
+test_bar
+ FAIL a subtest
+ TIMEOUT another subtest
+test_baz
+ PASS expected FAIL [Parent]
+""".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.mark.parametrize("name,opts,expected", FORMATS['PASS'],
+ ids=ids('PASS'))
+def test_pass(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', '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()
+
+ 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(name, opts, expected):
+ stack = """
+ SimpleTest.is@SimpleTest/SimpleTest.js:312:5
+ @caps/tests/mochitest/test_bug246699.html:53:1
+""".strip('\n')
+
+ 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', '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()
+
+ result = buf.getvalue()
+ print("Dumping result for copy/paste:")
+ print(result)
+ assert result == expected
+
+
+if __name__ == '__main__':
+ mozunit.main()