Bug 1421799 - [mozlog] Improve the 'mach' formatter r=gbrown
☠☠ backed out by 9dcfb0365f3c ☠ ☠
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Thu, 30 Nov 2017 09:31:36 -0500
changeset 449357 18b4fa2419365231eb7f2fcf581112ce8f8f3e2e
parent 449356 88dca5c8cfac95561af3d6f36389e3f16460ffdc
child 449358 f9f32474fdaf5914832d256293ee1f98c6bf2561
push id8527
push userCallek@gmail.com
push dateThu, 11 Jan 2018 21:05:50 +0000
treeherdermozilla-beta@95342d212a7a [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersgbrown
bugs1421799
milestone59.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 1421799 - [mozlog] Improve the 'mach' formatter r=gbrown This makes several changes to make the 'mach' format cleaner and easier to read. Some of the changes include: * No longer print the 'action' no matter what. Printing the action for things like 'log' or 'process_output' was redundant and caused verbosity. Now this is done on a case by case basis (things like TEST-START/TEST-END will still have their actions printed). * Color coded the process id for 'process_output' actions. This is a dim cyan to avoid conflicts with other actions. * No longer quoting 'process_output' messages * No longer printing thread information. In 99% of the case, this was just dumping 'MainThread' over and over again. Perhaps printing this could be an option on the formatter. * Muted timestamps to help the important parts stand out better * Colorized suite summary headings * Unexpected statuses in _format_expected() are always red (never yellow). This is to help make it stand out from all the other yellow text that gets printed. * Internal cleanup/refactoring MozReview-Commit-ID: LAuYfqYkUPe
testing/mozbase/mozlog/mozlog/formatters/machformatter.py
--- a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
@@ -2,107 +2,60 @@
 # 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/.
 
 
 from __future__ import absolute_import
 
 import time
 
-try:
-    import blessings
-except ImportError:
-    blessings = None
+from mozterm import Terminal
 
 from . import base
 from .process import strstatus
 from ..handlers import SummaryHandler
 
 
 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, summary_on_shutdown=False, **kwargs):
         super(MachFormatter, self).__init__(**kwargs)
 
-        if disable_colors:
-            terminal = None
-        elif terminal is None and blessings is not None:
-            terminal = blessings.Terminal()
-
         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.terminal = terminal
+        self.term = Terminal(disable_styling=disable_colors)
         self.verbose = False
         self._known_pids = set()
 
         self.summary = SummaryHandler()
         self.summary_on_shutdown = summary_on_shutdown
 
     def __call__(self, data):
         self.summary(data)
 
         s = super(MachFormatter, self).__call__(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":
-                if "expected" not in data and not self.has_unexpected[test]:
-                    color = self.terminal.green
-                else:
-                    color = self.terminal.red
-            elif data["action"] in ("suite_start", "suite_end",
-                                    "test_start", "test_status"):
-                color = self.terminal.yellow
-            elif data["action"] == "crash":
-                color = self.terminal.red
-            elif data["action"] == "assertion_count":
-                if (data["count"] > data["max_expected"] or
-                    data["count"] < data["min_expected"]):
-                    color = self.terminal.red
-
-            if color is not None:
-                action = color(action)
-
-        return "%s %s: %s %s\n" % (time, action, thread, s)
+        time = self.term.dim_blue(format_seconds(self._time(data)))
+        return "%s %s\n" % (time, s)
 
     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 _get_file_name(self, test_id):
@@ -111,41 +64,41 @@ class MachFormatter(base.BaseFormatter):
 
         if isinstance(test_id, tuple):
             return "".join(test_id)
 
         assert False, "unexpected test_id"
 
     def suite_start(self, data):
         num_tests = reduce(lambda x, y: x + len(y), data['tests'].itervalues(), 0)
-        return "%i" % num_tests
+        action = self.term.yellow(data['action'].upper())
+        name = ""
+        if 'name' in data:
+            name = " %s -" % (data['name'],)
+        return "%s:%s running %i tests" % (action, name, num_tests)
 
     def suite_end(self, data):
+        action = self.term.yellow(data['action'].upper())
+        rv = [action]
         if not self.summary_on_shutdown:
-            return self._format_suite_summary(self.summary.current_suite, self.summary.current)
+            rv.append(self._format_suite_summary(self.summary.current_suite, self.summary.current))
+        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
-
+        color = self.term.red
         if expected in ("PASS", "OK"):
             return color(status)
 
         return color("%s expected %s" % (status, expected))
 
     def _format_suite_summary(self, suite, summary):
-        term = self.terminal if self.terminal is not None else NullTerminal()
-
         count = summary['counts']
         logs = summary['unexpected_logs']
 
-        rv = ["", suite, "~" * len(suite)]
+        rv = ["", self.term.yellow(suite), self.term.yellow("~" * len(suite))]
 
         # Format check counts
         checks = self.summary.aggregate('count', count)
         rv.append("Ran {} checks ({})".format(sum(checks.values()),
                   ', '.join(['{} {}s'.format(v, k) for k, v in checks.items() if v])))
 
         # Format expected counts
         checks = self.summary.aggregate('expected', count, include_skip=False)
@@ -170,17 +123,17 @@ class MachFormatter(base.BaseFormatter):
                     continue
                 status_str = ", ".join(["{} {}".format(n, s)
                                         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(term.green("OK"))
+            rv.append(self.term.green("OK"))
         else:
             heading = "Unexpected Logs"
             rv.extend(["", heading, "-" * len(heading)])
             if count['subtest']['count']:
                 for test_id, results in logs.items():
                     test = self._get_file_name(test_id)
                     rv.append(test)
                     for data in results:
@@ -190,22 +143,23 @@ class MachFormatter(base.BaseFormatter):
             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))
+                                           data["status"], data["expected"]), test))
 
         return "\n".join(rv)
 
     def test_start(self, data):
-        return "%s" % (self._get_test_id(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":
@@ -239,17 +193,23 @@ class MachFormatter(base.BaseFormatter):
                 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]
-        return rv
+
+        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
 
@@ -267,48 +227,52 @@ class MachFormatter(base.BaseFormatter):
 
         if data["status"] == "PASS":
             self.status_buffer[test]["pass"] += 1
 
         rv = None
         status, subtest = data["status"], data["subtest"]
         unexpected = "expected" in data
         if self.verbose:
-            if self.terminal is not None:
-                status = (self.terminal.red if unexpected else self.terminal.green)(status)
+            status = (self.term.red if unexpected else self.term.green)(status)
             rv = " ".join([subtest, status, message])
 
         if unexpected:
             self.status_buffer[test]["unexpected"] += 1
-        return rv
+        if rv:
+            action = self.term.yellow(data['action'].upper())
+            return "%s: %s" % (action, rv)
 
     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"])
         else:
             expected = "%i" % data["min_expected"]
 
-        return "Assertion count %i, expected %s assertions\n" % (data["count"], expected)
+        action = self.term.red("ASSERT")
+        return "%s: Assertion count %i, expected %i assertions\n" % (
+                action, data["count"], expected)
 
     def process_output(self, data):
         rv = []
 
         pid = data['process']
         if pid.isdigit():
             pid = 'pid:%s' % pid
+        pid = self.term.dim_cyan(pid)
 
         if "command" in data and data["process"] not in self._known_pids:
             self._known_pids.add(data["process"])
-            rv.append('(%s) Full command: %s' % (pid, data["command"]))
+            rv.append('%s Full command: %s' % (pid, data["command"]))
 
-        rv.append('(%s) "%s"' % (pid, data["data"]))
+        rv.append('%s %s' % (pid, data["data"]))
         return "\n".join(rv)
 
     def crash(self, data):
         test = self._get_test_id(data)
 
         if data.get("stackwalk_returncode", 0) != 0 and not data.get("stackwalk_stderr"):
             success = True
         else:
@@ -332,74 +296,73 @@ class MachFormatter(base.BaseFormatter):
 
         if data.get("stackwalk_errors"):
             rv.extend(data.get("stackwalk_errors"))
 
         rv = "\n".join(rv)
         if not rv[-1] == "\n":
             rv += "\n"
 
-        return rv
+        action = self.term.red(data['action'].upper())
+        return "%s: %s" % (action, rv)
 
     def process_start(self, data):
         rv = "Started process `%s`" % data['process']
         desc = data.get('command')
         if desc:
             rv = '%s (%s)' % (rv, desc)
         return rv
 
     def process_exit(self, data):
         return "%s: %s" % (data['process'], strstatus(data['exitcode']))
 
     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":
-                level = self.terminal.yellow(level)
-            elif level == "INFO":
-                level = self.terminal.blue(level)
+        if level in ("CRITICAL", "ERROR"):
+            level = self.term.red(level)
+        elif level == "WARNING":
+            level = self.term.yellow(level)
+        elif level == "INFO":
+            level = self.term.blue(level)
 
         if data.get('component'):
             rv = " ".join([data["component"], level, data["message"]])
         else:
             rv = "%s %s" % (level, data["message"])
 
         if "stack" in data:
             rv += "\n%s" % data["stack"]
 
         return rv
 
     def lint(self, data):
-        term = self.terminal if self.terminal is not None else NullTerminal()
         fmt = "{path}  {c1}{lineno}{column}  {c2}{level}{normal}  {message}" \
               "  {c1}{rule}({linter}){normal}"
         message = fmt.format(
             path=data["path"],
-            normal=term.normal,
-            c1=term.grey,
-            c2=term.red if data["level"] == 'error' else term.yellow,
+            normal=self.term.normal,
+            c1=self.term.grey,
+            c2=self.term.red if data["level"] == 'error' else self.term.yellow,
             lineno=str(data["lineno"]),
             column=(":" + str(data["column"])) if data.get("column") else "",
             level=data["level"],
             message=data["message"],
             rule='{} '.format(data["rule"]) if data.get("rule") else "",
             linter=data["linter"].lower() if data.get("linter") else "",
         )
 
         return message
 
     def shutdown(self, data):
         if not self.summary_on_shutdown:
             return
 
         heading = "Overall Summary"
-        rv = ["", heading, "=" * len(heading)]
+        rv = ["", self.term.bold_yellow(heading), self.term.bold_yellow("=" * len(heading))]
         for suite, summary in self.summary:
             rv.append(self._format_suite_summary(suite, summary))
         return "\n".join(rv)
 
     def _get_subtest_data(self, data):
         test = self._get_test_id(data)
         return self.status_buffer.get(test, {"count": 0, "unexpected": 0, "pass": 0})