Bug 1445624 - [mozlog] Add some tests for the mach formatter, r?gbrown draft
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Mon, 19 Mar 2018 11:55:31 -0400
changeset 770592 210908a248b0a0bc98c759aed268e15683bd8724
parent 770502 e636edf00e6fbdc3206c9df4a1548ae38b3d13fa
child 770593 bbd78e0d4554725a08cc5cb6f29bd62bc8be2eb9
push id103442
push userahalberstadt@mozilla.com
push dateWed, 21 Mar 2018 15:02:29 +0000
reviewersgbrown
bugs1445624
milestone61.0a1
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()