Bug 1046242 - Provide a run summary in the structuredlog mach formatter, r=chmanchester
authorJames Graham <james@hoppipolla.co.uk>
Thu, 07 Aug 2014 22:32:43 +0100
changeset 198592 ac00c8a8a7a6aedc219624b14480a38bb70d05c4
parent 198499 96a566fa1599b55e019a7172d93a458002300237
child 198593 0556ee388f90414dda51f5d427b79bba5e0c5943
push id27278
push userkwierso@gmail.com
push dateFri, 08 Aug 2014 21:34:41 +0000
treeherdermozilla-central@a6424bfa8f39 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerschmanchester
bugs1046242
milestone34.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 1046242 - Provide a run summary in the structuredlog mach formatter, r=chmanchester
testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
testing/mozbase/mozlog/tests/test_structured.py
--- a/testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
+++ b/testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
@@ -1,26 +1,33 @@
 # 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/.
 
 import time
+from collections import defaultdict
 
 try:
     import blessings
 except ImportError:
     blessings = None
 
 import base
 
 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 NullTerminal(object):
+    def __getattr__(self, name):
+        return self._id
+
+    def _id(self, value):
+        return value
 
 class MachFormatter(base.BaseFormatter):
     def __init__(self, start_time=None, write_interval=False, write_times=True,
                  terminal=None, disable_colors=False):
 
         if disable_colors:
             terminal = None
         elif terminal is None and blessings is not None:
@@ -32,25 +39,34 @@ class MachFormatter(base.BaseFormatter):
         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.terminal = terminal
 
+        self.summary_values = {"tests": 0,
+                               "subtests": 0,
+                               "expected": 0,
+                               "unexpected": defaultdict(int),
+                               "skipped": 0}
+        self.summary_unexpected = []
+
     def __call__(self, data):
         s = base.BaseFormatter.__call__(self, data)
         if s is None:
             return
 
         time = format_seconds(self._time(data))
         action = data["action"].upper()
         thread = data["thread"]
 
+        # Not using the NullTerminal here is a small optimisation to cut the number of
+        # function calls
         if self.terminal is not None:
             test = self._get_test_id(data)
 
             time = self.terminal.blue(time)
 
             color = None
 
             if data["action"] == "test_end":
@@ -68,77 +84,161 @@ class MachFormatter(base.BaseFormatter):
 
     def _get_test_id(self, data):
         test_id = data.get("test")
         if isinstance(test_id, list):
             test_id = tuple(test_id)
         return test_id
 
     def suite_start(self, data):
+        self.summary_values = {"tests": 0,
+                               "subtests": 0,
+                               "expected": 0,
+                               "unexpected": defaultdict(int),
+                               "skipped": 0}
+        self.summary_unexpected = []
         return "%i" % len(data["tests"])
 
     def suite_end(self, data):
-        return ""
+        term = self.terminal if self.terminal is not None else NullTerminal()
+
+        heading = "Summary"
+        rv = ["", heading, "=" * len(heading), ""]
+
+        has_subtests = self.summary_values["subtests"] > 0
+
+        if has_subtests:
+            rv.append("Ran %i tests (%i parents, %i subtests)" %
+                      (self.summary_values["tests"] + self.summary_values["subtests"],
+                       self.summary_values["tests"],
+                       self.summary_values["subtests"]))
+        else:
+            rv.append("Ran %i tests" % self.summary_values["tests"])
+
+        rv.append("Expected results: %i" % self.summary_values["expected"])
+
+        unexpected_count = sum(self.summary_values["unexpected"].values())
+        if unexpected_count > 0:
+            unexpected_str = " (%s)" % ", ".join("%s: %i" % (key, value) for key, value in
+                                              sorted(self.summary_values["unexpected"].items()))
+        else:
+            unexpected_str = ""
+
+        rv.append("Unexpected results: %i%s" % (unexpected_count, unexpected_str))
+
+        if self.summary_values["skipped"] > 0:
+            rv.append("Skipped: %i" % self.summary_values["skipped"])
+        rv.append("")
+
+        if not self.summary_values["unexpected"]:
+            rv.append(term.green("OK"))
+        else:
+            heading = "Unexpected Results"
+            rv.extend([heading, "=" * len(heading), ""])
+            if has_subtests:
+                for test, results in self.summary_unexpected:
+                    rv.extend([test, "-" * len(test)])
+                    for name, status, expected, message in results:
+                        if name is None:
+                            name = "[Parent]"
+                        rv.append("%s %s" % (self.format_expected(status, expected), name))
+            else:
+                for test, results in self.summary_unexpected:
+                    assert len(results) == 1
+                    name, status, expected, messge = results[0]
+                    assert name is None
+                    rv.append("%s %s" % (self.format_expected(status, expected), test))
+
+        return "\n".join(rv)
+
+    def format_expected(self, status, expected):
+        term = self.terminal if self.terminal is not None else NullTerminal()
+        if status == "ERROR":
+            color = term.red
+        else:
+            color = term.yellow
+
+        if expected in ("PASS", "OK"):
+            return color(status)
+
+        return color("%s expected %s" % (status, expected))
 
     def test_start(self, data):
+        self.summary_values["tests"] += 1
         return "%s" % (self._get_test_id(data),)
 
     def test_end(self, data):
         subtests = self._get_subtest_data(data)
         unexpected = subtests["unexpected"]
         if "expected" in data:
             parent_unexpected = True
             expected_str = ", expected %s" % data["expected"]
-            unexpected.append(("[Parent]", data["status"], data["expected"],
+            unexpected.append((None, data["status"], data["expected"],
                                data.get("message", "")))
         else:
             parent_unexpected = False
             expected_str = ""
 
+        test = self._get_test_id(data)
+
+        if unexpected:
+            self.summary_unexpected.append((test, unexpected))
+        self._update_summary(data)
+
         #Reset the counts to 0
-        test = self._get_test_id(data)
         self.status_buffer[test] = {"count": 0, "unexpected": [], "pass": 0}
         self.has_unexpected[test] = bool(unexpected)
 
         if subtests["count"] != 0:
             rv = "Harness %s%s. Subtests passed %i/%i. Unexpected %s" % (
                 data["status"], expected_str, subtests["pass"], subtests["count"],
                 len(unexpected))
         else:
             rv = "%s%s" % (data["status"], expected_str)
 
         if unexpected:
             rv += "\n"
             if len(unexpected) == 1 and parent_unexpected:
                 rv += "%s" % unexpected[0][-1]
             else:
                 for name, status, expected, message in unexpected:
+                    if name is None:
+                        name = "[Parent]"
                     expected_str = "Expected %s, got %s" % (expected, status)
                     rv += "%s\n" % ("\n".join([name, "-" * len(name), expected_str, message]))
                 rv = rv[:-1]
         return rv
 
     def test_status(self, data):
+        self.summary_values["subtests"] += 1
+
         test = self._get_test_id(data)
         if test not in self.status_buffer:
             self.status_buffer[test] = {"count": 0, "unexpected": [], "pass": 0}
         self.status_buffer[test]["count"] += 1
 
         if "expected" in data:
             self.status_buffer[test]["unexpected"].append((data["subtest"],
                                                            data["status"],
                                                            data["expected"],
                                                            data.get("message", "")))
-        if data["status"] == "PASS":
-            self.status_buffer[test]["pass"] += 1
+        self._update_summary(data)
+
+    def _update_summary(self, data):
+        if "expected" in data:
+            self.summary_values["unexpected"][data["status"]] += 1
+        elif data["status"] == "SKIP":
+            self.summary_values["skipped"] += 1
+        else:
+            self.summary_values["expected"] += 1
 
     def process_output(self, data):
         return '"%s" (pid:%s command:%s)' % (data["data"],
                                              data["process"],
-                                             data["command"])
+                                             data.get("command", ""))
 
     def log(self, data):
         level = data.get("level").upper()
 
         if self.terminal is not None:
             if level in ("CRITICAL", "ERROR"):
                 level = self.terminal.red(level)
             elif level == "WARNING":
--- a/testing/mozbase/mozlog/tests/test_structured.py
+++ b/testing/mozbase/mozlog/tests/test_structured.py
@@ -319,16 +319,17 @@ class TestStructuredLog(BaseStructuredTe
                                 "message": "line 3"})
 
         file_like.write("line 4\r\n")
 
         self.assert_log_equals({"action": "log",
                                 "level": "INFO",
                                 "message": "line 4"})
 
+
 class TestTypeconversions(BaseStructuredTest):
     def test_raw(self):
         self.logger.log_raw({"action":"suite_start", "tests":[1], "time": "1234"})
         self.assert_log_equals({"action": "suite_start",
                                 "tests":["1"],
                                 "time": 1234})
         self.logger.suite_end()
 
@@ -387,16 +388,99 @@ class TestTypeconversions(BaseStructured
                                 "data": "data"})
         self.assertRaises(TypeError, self.logger.test_status, subtest="subtest2",
                           status="FAIL", expected="PASS")
         self.assertRaises(TypeError, self.logger.test_status, "test1", "subtest1",
                           "PASS", "FAIL", "message", "stack", {}, "unexpected")
         self.assertRaises(TypeError, self.logger.test_status, "test1", test="test2")
         self.logger.suite_end()
 
+
+class TestMachFormatter(unittest.TestCase):
+    def setUp(self):
+        self.logger = structuredlog.StructuredLogger("test")
+        self.output_file = StringIO.StringIO()
+        self.handler = handlers.StreamHandler(
+            self.output_file, formatters.MachFormatter(disable_colors=True))
+        self.logger.add_handler(self.handler)
+
+    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")
+
+        position = self.output_file.tell()
+
+        self.logger.suite_end()
+
+        self.output_file.seek(position)
+        lines = self.output_file.read().split("\n")
+
+        self.assertIn("Ran 3 tests", lines)
+        self.assertIn("Expected results: 1", lines)
+        self.assertIn("Unexpected results: 2 (FAIL: 1, PASS: 1)", lines)
+        self.assertNotIn("test1", lines)
+        self.assertIn("PASS expected TIMEOUT test2", lines)
+        self.assertIn("FAIL test3", lines)
+
+    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")
+
+        position = self.output_file.tell()
+
+        self.logger.suite_end()
+
+        self.output_file.seek(position)
+        lines = self.output_file.read().split("\n")
+
+        self.assertIn("Ran 5 tests (2 parents, 3 subtests)", lines)
+        self.assertIn("Expected results: 2", lines)
+        self.assertIn("Unexpected results: 3 (FAIL: 1, TIMEOUT: 2)", lines)
+
+    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")
+
+        position = self.output_file.tell()
+
+        self.logger.suite_end()
+
+        self.output_file.seek(position)
+        lines = self.output_file.read().split("\n")
+
+        self.assertIn("OK", lines)
+        self.assertIn("Expected results: 5", lines)
+        self.assertIn("Unexpected results: 0", lines)
+
+
 class TestCommandline(unittest.TestCase):
 
     def setUp(self):
         self.logfile = mozfile.NamedTemporaryFile()
 
     @property
     def loglines(self):
         self.logfile.seek(0)