Bug 1445624 - [mozlog] Add some tests for the mach formatter, r=gbrown
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Mon, 19 Mar 2018 11:55:31 -0400
changeset 409558 96e150823d3209ed19820f3d17a84cc902f27800
parent 409557 c6b39a06d68001398d36c05136b9b44614630702
child 409559 61a14c8bcfcf095c16caf4564fdc7d879386e2ca
push id101247
push usernerli@mozilla.com
push dateThu, 22 Mar 2018 23:00:51 +0000
treeherdermozilla-inbound@02e384bdf97d [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersgbrown
bugs1445624
milestone61.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
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
config/mozunit.py
testing/mozbase/mozlog/mozlog/formatters/machformatter.py
testing/mozbase/mozlog/tests/manifest.ini
testing/mozbase/mozlog/tests/test_formatters.py
--- 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()