Bug 1445624 - [mozlog] Various improvements and fixes to the mach formatter, r?gbrown draft
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Mon, 19 Mar 2018 11:55:39 -0400
changeset 770593 bbd78e0d4554725a08cc5cb6f29bd62bc8be2eb9
parent 770592 210908a248b0a0bc98c759aed268e15683bd8724
child 770594 0bced5a71f959f52fa558c947af3557d4dc8e4ec
push id103442
push userahalberstadt@mozilla.com
push dateWed, 21 Mar 2018 15:02:29 +0000
reviewersgbrown
bugs1445624
milestone61.0a1
Bug 1445624 - [mozlog] Various improvements and fixes to the mach formatter, r?gbrown This consolidates the printing of status logs, which was previously handled differently in 3-4 places. This also fixes a few of the annoyances listed in the bug 1445624 description. Finally this also fixes a few edge cases that I noticed when writing the tests. MozReview-Commit-ID: APudT8yBqVS
testing/mozbase/mozlog/mozlog/formatters/machformatter.py
testing/mozbase/mozlog/tests/test_formatters.py
testing/mozbase/mozlog/tests/test_structured.py
--- a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
@@ -79,21 +79,37 @@ class MachFormatter(base.BaseFormatter):
     def suite_end(self, data):
         action = self.term.yellow(data['action'].upper())
         rv = [action]
         if not self.summary_on_shutdown:
             rv.append(self._format_suite_summary(self.summary.current_suite, self.summary.current))
         return "\n".join(rv)
 
     def _format_expected(self, status, expected):
-        color = self.term.red
-        if expected in ("PASS", "OK"):
-            return color(status)
+        if status == expected:
+            color = self.term.green
+            if expected not in ("PASS", "OK"):
+                color = self.term.yellow
+                status = "EXPECTED-%s" % status
+        else:
+            color = self.term.red
+            if status in ("PASS", "OK"):
+                status = "UNEXPECTED-%s" % status
+        return color(status)
 
-        return color("%s expected %s" % (status, expected))
+    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)
+        if 'message' in data:
+            rv += " - %s" % data['message']
+
+        if 'stack' in data:
+            rv += "\n%s\n" % self.term.dim(data['stack'].strip('\n'))
+        return rv
 
     def _format_suite_summary(self, suite, summary):
         count = summary['counts']
         logs = summary['unexpected_logs']
 
         rv = ["", self.term.yellow(suite), self.term.yellow("~" * len(suite))]
 
         # Format check counts
@@ -126,52 +142,41 @@ class MachFormatter(base.BaseFormatter):
                                         for s, n in count[key]['unexpected'].items()])
                 rv.append("  {}: {} ({})".format(
                           key, sum(count[key]['unexpected'].values()), status_str))
 
         # Format status
         if not any(count[key]["unexpected"] for key in ('test', 'subtest', 'assert')):
             rv.append(self.term.green("OK"))
         else:
-            heading = "Unexpected Logs"
-            rv.extend(["", heading, "-" * len(heading)])
+            heading = "Unexpected Results"
+            rv.extend(["", self.term.yellow(heading), self.term.yellow("-" * len(heading))])
             if count['subtest']['count']:
                 for test_id, results in logs.items():
                     test = self._get_file_name(test_id)
-                    rv.append(test)
+                    rv.append(self.term.bold(test))
                     for data in results:
-                        name = data.get("subtest", "[Parent]")
-                        rv.append("  %s %s" % (self._format_expected(
-                                             data["status"], data["expected"]), name))
+                        rv.append("  %s" % self._format_status(test, data).rstrip())
             else:
                 for test_id, results in logs.items():
                     test = self._get_file_name(test_id)
-                    rv.append(test)
                     assert len(results) == 1
                     data = results[0]
                     assert "subtest" not in data
-                    rv.append("  %s %s" % (self._format_expected(
-                                           data["status"], data["expected"]), test))
+                    rv.append(self._format_status(test, data).rstrip())
 
         return "\n".join(rv)
 
     def test_start(self, data):
         action = self.term.yellow(data['action'].upper())
         return "%s: %s" % (action, self._get_test_id(data))
 
     def test_end(self, data):
         subtests = self._get_subtest_data(data)
 
-        message = data.get("message", "")
-        if "stack" in data:
-            stack = data["stack"]
-            if stack and stack[-1] != "\n":
-                stack += "\n"
-            message = stack + message
-
         if "expected" in data:
             parent_unexpected = True
             expected_str = ", expected %s" % data["expected"]
         else:
             parent_unexpected = False
             expected_str = ""
 
         test = self._get_test_id(data)
@@ -184,68 +189,53 @@ class MachFormatter(base.BaseFormatter):
             rv = "Test %s%s. Subtests passed %i/%i. Unexpected %s" % (
                 data["status"], expected_str, subtests["pass"], subtests["count"],
                 subtests['unexpected'])
         else:
             rv = "%s%s" % (data["status"], expected_str)
 
         unexpected = self.summary.current["unexpected_logs"].get(data["test"])
         if unexpected:
-            rv += "\n"
             if len(unexpected) == 1 and parent_unexpected:
-                rv += "%s" % unexpected[0].get("message", "")
-            else:
-                for data in unexpected:
-                    name = data.get("subtest", "[Parent]")
-                    expected_str = "Expected %s, got %s" % (data["expected"], data["status"])
-                    rv += "%s\n" % (
-                        "\n".join([name, "-" * len(name), expected_str, data.get("message", "")]))
-                rv = rv[:-1]
+                message = unexpected[0].get("message", "")
+                if message:
+                    rv += " - %s" % message
+            elif not self.verbose:
+                rv += "\n"
+                for d in unexpected:
+                    rv += self._format_status(data['test'], d)
 
         if "expected" not in data and not bool(subtests['unexpected']):
             color = self.term.green
         else:
             color = self.term.red
+
         action = color(data['action'].upper())
         return "%s: %s" % (action, rv)
 
     def valgrind_error(self, data):
         rv = " " + data['primary'] + "\n"
         for line in data['secondary']:
             rv = rv + line + "\n"
 
         return rv
 
     def test_status(self, data):
         test = self._get_test_id(data)
         if test not in self.status_buffer:
             self.status_buffer[test] = {"count": 0, "unexpected": 0, "pass": 0}
         self.status_buffer[test]["count"] += 1
 
-        message = data.get("message", "")
-        if "stack" in data:
-            if message:
-                message += "\n"
-            message += data["stack"]
-
         if data["status"] == "PASS":
             self.status_buffer[test]["pass"] += 1
 
-        rv = None
-        status, subtest = data["status"], data["subtest"]
-        unexpected = "expected" in data
+        if 'expected' in data:
+            self.status_buffer[test]["unexpected"] += 1
         if self.verbose:
-            status = (self.term.red if unexpected else self.term.green)(status)
-            rv = " ".join([subtest, status, message])
-
-        if unexpected:
-            self.status_buffer[test]["unexpected"] += 1
-        if rv:
-            action = self.term.yellow(data['action'].upper())
-            return "%s: %s" % (action, rv)
+            return self._format_status(test, data).rstrip('\n')
 
     def assertion_count(self, data):
         if data["min_expected"] <= data["count"] <= data["max_expected"]:
             return
 
         if data["min_expected"] != data["max_expected"]:
             expected = "%i to %i" % (data["min_expected"],
                                      data["max_expected"])
--- a/testing/mozbase/mozlog/tests/test_formatters.py
+++ b/testing/mozbase/mozlog/tests/test_formatters.py
@@ -1,12 +1,11 @@
 # 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
@@ -38,17 +37,17 @@ 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 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 (3 tests, 1 subtests)
@@ -56,92 +55,80 @@ 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_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_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 (3 tests, 2 subtests)
 Expected results: 1
 Unexpected results: 4
   test: 2 (1 fail, 1 pass)
   subtest: 2 (1 fail, 1 timeout)
 
-Unexpected Logs
----------------
+Unexpected Results
+------------------
 test_foo
-  FAIL [Parent]
+  FAIL test_foo - expected 0 got 1
 test_bar
-  FAIL a subtest
+  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
-  PASS expected FAIL [Parent]
+  UNEXPECTED-PASS test_baz
 """.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_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
+ 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 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 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 (3 tests, 2 subtests)
 Expected results: 1
 Unexpected results: 4
   test: 2 (1 fail, 1 pass)
   subtest: 2 (1 fail, 1 timeout)
 
-Unexpected Logs
----------------
+Unexpected Results
+------------------
 test_foo
-  FAIL [Parent]
+  FAIL test_foo - expected 0 got 1
 test_bar
-  FAIL a subtest
+  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
-  PASS expected FAIL [Parent]
+  UNEXPECTED-PASS test_baz
 """.lstrip('\n')),
     ],
 }
 
 
 def ids(test):
     ids = []
     for value in FORMATS[test]:
--- a/testing/mozbase/mozlog/tests/test_structured.py
+++ b/testing/mozbase/mozlog/tests/test_structured.py
@@ -773,18 +773,18 @@ class TestMachFormatter(FormatterTest):
 
         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("  PASS expected TIMEOUT test2", self.loglines)
-        self.assertIn("  FAIL test3", 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")