Backed out 5 changesets (bug 1421799) for failing browser-chrome on Linux and OSX and for failing autophone-mochitest on Android r=backout on a CLOSED TREE

Backed out changeset 7fb20bced076 (bug 1421799)
Backed out changeset 629e467a07be (bug 1421799)
Backed out changeset 2de335c0287a (bug 1421799)
Backed out changeset afe14ec646ab (bug 1421799)
Backed out changeset bbe4d2292f86 (bug 1421799)

layout/tools/reftest/output.py

@@ -128,7 +128,6 @@ class OutputHandler(object):
     def __init__(self, log, utilityPath, symbolsPath=None):
         self.stack_fixer_function = get_stack_fixer_function(utilityPath, symbolsPath)
         self.log = log
-        self.proc_name = None
 
     def __call__(self, line):
         # need to return processed messages to appease remoteautomation.py
@@ -152,5 +151,4 @@ class OutputHandler(object):
     def verbatim(self, line):
         if self.stack_fixer_function:
             line = self.stack_fixer_function(line)
-        name = self.proc_name or threading.current_thread().name
+        self.log.process_output(threading.current_thread().name, line)
-        self.log.process_output(name, line)

layout/tools/reftest/runreftest.py

@@ -713,7 +713,6 @@ class RefTest(object):
                      interactive=interactive,
                      outputTimeout=timeout)
         proc = runner.process_handler
-        outputHandler.proc_name = 'GECKO({})'.format(proc.pid)
 
         # Used to defer a possible IOError exception from Marionette
         marionette_exception = None
@@ -750,7 +749,6 @@ class RefTest(object):
 
         status = runner.wait()
         runner.process_handler = None
-        outputHandler.proc_name = None
 
         if status:
             msg = "TEST-UNEXPECTED-FAIL | %s | application terminated with exit code %s" % \

testing/mach_commands.py

@@ -64,29 +64,21 @@ class TestConfig(object):
         level_desc = "The default log level to use when running tests with `mach test`."
         level_choices = [l.lower() for l in log_levels]
         return [
-            ('test.format', 'string', format_desc, 'mach', {'choices': format_choices}),
+            ('test.format', 'string', format_desc, 'tbpl', {'choices': format_choices}),
             ('test.level', 'string', level_desc, 'info', {'choices': level_choices}),
         ]
 
 
-def get_test_parser():
-    from mozlog.commandline import add_logging_group
-    parser = argparse.ArgumentParser()
-    parser.add_argument('what', default=None, nargs='*', help=TEST_HELP)
-    parser.add_argument('extra_args', default=None, nargs=argparse.REMAINDER,
-                        help="Extra arguments to pass to the underlying test command(s). "
-                             "If an underlying command doesn't recognize the argument, it "
-                             "will fail.")
-    add_logging_group(parser)
-    return parser
-
-
 @CommandProvider
 class Test(MachCommandBase):
     @Command('test', category='testing',
-             description='Run tests (detects the kind of test and runs it).',
+             description='Run tests (detects the kind of test and runs it).')
-             parser=get_test_parser)
+    @CommandArgument('what', default=None, nargs='*', help=TEST_HELP)
-    def test(self, what, extra_args, **log_args):
+    @CommandArgument('extra_args', default=None, nargs=argparse.REMAINDER,
+                     help="Extra arguments to pass to the underlying test command(s). "
+                          "If an underlying command doesn't recognize the argument, it "
+                          "will fail.")
+    def test(self, what, extra_args):
         """Run tests from names or paths.
 
         mach test accepts arguments specifying which tests to run. Each argument
@@ -110,7 +102,9 @@ class Test(MachCommandBase):
         you specify a directory with xpcshell and browser chrome mochitests,
         both harnesses will be invoked.
         """
-        from mozlog.commandline import setup_logging
+        from mozlog.commandline import log_formatters
+        from mozlog.handlers import StreamHandler, LogLevelFilter
+        from mozlog.structuredlog import StructuredLogger
         from moztest.resolve import TestResolver, TEST_FLAVORS, TEST_SUITES
 
         resolver = self._spawn(TestResolver)
@@ -121,11 +115,12 @@ class Test(MachCommandBase):
             return 1
 
         # Create shared logger
-        default_format = self._mach_context.settings['test']['format']
+        formatter = log_formatters[self._mach_context.settings['test']['format']][0]()
-        default_level = self._mach_context.settings['test']['level']
+        formatter.summary_on_shutdown = True
-        log = setup_logging('mach-test', log_args, {default_format: sys.stdout},
+
-                            {'level': default_level})
+        level = self._mach_context.settings['test']['level']
-        log.handlers[0].formatter.inner.summary_on_shutdown = True
+        log = StructuredLogger('mach-test')
+        log.add_handler(StreamHandler(sys.stdout, LogLevelFilter(formatter, level)))
 
         status = None
         for suite_name in run_suites:

testing/mochitest/mach_commands.py

@@ -68,6 +68,13 @@ test path(s):
 Please check spelling and make sure the named tests exist.
 '''.lstrip()
 
+NOW_RUNNING = '''
+######
+### Now running mochitest-{}.
+######
+'''
+
+
 SUPPORTED_APPS = ['firefox', 'android']
 
 parser = None
@@ -279,7 +286,9 @@ class MachCommands(MachCommandBase):
              parser=setup_argument_parser)
     def run_mochitest_general(self, flavor=None, test_objects=None, resolve_tests=True, **kwargs):
         from mochitest_options import ALL_FLAVORS
-        from mozlog.commandline import setup_logging
+        from mozlog.commandline import log_formatters
+        from mozlog.handlers import StreamHandler, LogLevelFilter
+        from mozlog.structuredlog import StructuredLogger
 
         buildapp = None
         for app in SUPPORTED_APPS:
@@ -300,11 +309,12 @@ class MachCommands(MachCommandBase):
 
         if not kwargs.get('log'):
             # Create shared logger
-            default_format = self._mach_context.settings['test']['format']
+            formatter = log_formatters[self._mach_context.settings['test']['format']][0]()
-            default_level = self._mach_context.settings['test']['level']
+            formatter.summary_on_shutdown = True
-            kwargs['log'] = setup_logging('mach-mochitest', kwargs, {default_format: sys.stdout},
+
-                                          {'level': default_level})
+            level = self._mach_context.settings['test']['level']
-            kwargs['log'].handlers[0].formatter.inner.summary_on_shutdown = True
+            kwargs['log'] = StructuredLogger('mach-mochitest')
+            kwargs['log'].add_handler(StreamHandler(sys.stdout, LogLevelFilter(formatter, level)))
 
         from mozbuild.controller.building import BuildDriver
         self._ensure_state_subdir_exists('.')
@@ -399,6 +409,10 @@ class MachCommands(MachCommandBase):
         overall = None
         for (flavor, subsuite), tests in sorted(suites.items()):
             fobj = ALL_FLAVORS[flavor]
+            msg = fobj['aliases'][0]
+            if subsuite:
+                msg = '{} with subsuite {}'.format(msg, subsuite)
+            print(NOW_RUNNING.format(msg))
 
             harness_args = kwargs.copy()
             harness_args['subsuite'] = subsuite

testing/mozbase/mozlog/mozlog/formatters/machformatter.py

@@ -7,7 +7,10 @@ from __future__ import absolute_import
 
 import time
 
-from mozterm import Terminal
+try:
+    import blessings
+except ImportError:
+    blessings = None
 
 from . import base
 from .process import strstatus
@@ -20,12 +23,26 @@ def format_seconds(total):
     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)
@@ -35,7 +52,7 @@ class MachFormatter(base.BaseFormatter):
         self.status_buffer = {}
         self.has_unexpected = {}
         self.last_time = None
-        self.term = Terminal(disable_styling=disable_colors)
+        self.terminal = terminal
         self.verbose = False
         self._known_pids = set()
 
@@ -49,8 +66,38 @@ class MachFormatter(base.BaseFormatter):
         if s is None:
             return
 
-        time = self.term.dim_blue(format_seconds(self._time(data)))
+        time = format_seconds(self._time(data))
-        return "%s %s\n" % (time, s)
+        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)
 
     def _get_test_id(self, data):
         test_id = data.get("test")
@@ -69,31 +116,31 @@ class MachFormatter(base.BaseFormatter):
 
     def suite_start(self, data):
         num_tests = reduce(lambda x, y: x + len(y), data['tests'].itervalues(), 0)
-        action = self.term.yellow(data['action'].upper())
+        return "%i" % num_tests
-        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:
-            rv.append(self._format_suite_summary(self.summary.current_suite, self.summary.current))
+            return 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
+        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 _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 = ["", self.term.yellow(suite), self.term.yellow("~" * len(suite))]
+        rv = ["", suite, "~" * len(suite)]
 
         # Format check counts
         checks = self.summary.aggregate('count', count)
@@ -128,7 +175,7 @@ class MachFormatter(base.BaseFormatter):
 
         # Format status
         if not any(count[key]["unexpected"] for key in ('test', 'subtest', 'assert')):
-            rv.append(self.term.green("OK"))
+            rv.append(term.green("OK"))
         else:
             heading = "Unexpected Logs"
             rv.extend(["", heading, "-" * len(heading)])
@@ -148,13 +195,12 @@ class MachFormatter(base.BaseFormatter):
                     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):
-        action = self.term.yellow(data['action'].upper())
+        return "%s" % (self._get_test_id(data),)
-        return "%s: %s" % (action, self._get_test_id(data))
 
     def test_end(self, data):
         subtests = self._get_subtest_data(data)
@@ -198,13 +244,7 @@ class MachFormatter(base.BaseFormatter):
                     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"
@@ -232,14 +272,13 @@ class MachFormatter(base.BaseFormatter):
         status, subtest = data["status"], data["subtest"]
         unexpected = "expected" in data
         if self.verbose:
-            status = (self.term.red if unexpected else self.term.green)(status)
+            if self.terminal is not None:
+                status = (self.terminal.red if unexpected else self.terminal.green)(status)
             rv = " ".join([subtest, status, message])
 
         if unexpected:
             self.status_buffer[test]["unexpected"] += 1
-        if rv:
+        return 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"]:
@@ -251,9 +290,7 @@ class MachFormatter(base.BaseFormatter):
         else:
             expected = "%i" % data["min_expected"]
 
-        action = self.term.red("ASSERT")
+        return "Assertion count %i, expected %s assertions\n" % (data["count"], expected)
-        return "%s: Assertion count %i, expected %i assertions\n" % (
-                action, data["count"], expected)
 
     def process_output(self, data):
         rv = []
@@ -261,13 +298,12 @@ class MachFormatter(base.BaseFormatter):
         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):
@@ -301,8 +337,7 @@ class MachFormatter(base.BaseFormatter):
         if not rv[-1] == "\n":
             rv += "\n"
 
-        action = self.term.red(data['action'].upper())
+        return rv
-        return "%s: %s" % (action, rv)
 
     def process_start(self, data):
         rv = "Started process `%s`" % data['process']
@@ -317,12 +352,13 @@ class MachFormatter(base.BaseFormatter):
     def log(self, data):
         level = data.get("level").upper()
 
-        if level in ("CRITICAL", "ERROR"):
+        if self.terminal is not None:
-            level = self.term.red(level)
+            if level in ("CRITICAL", "ERROR"):
-        elif level == "WARNING":
+                level = self.terminal.red(level)
-            level = self.term.yellow(level)
+            elif level == "WARNING":
-        elif level == "INFO":
+                level = self.terminal.yellow(level)
-            level = self.term.blue(level)
+            elif level == "INFO":
+                level = self.terminal.blue(level)
 
         if data.get('component'):
             rv = " ".join([data["component"], level, data["message"]])
@@ -335,13 +371,14 @@ class MachFormatter(base.BaseFormatter):
         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=self.term.normal,
+            normal=term.normal,
-            c1=self.term.grey,
+            c1=term.grey,
-            c2=self.term.red if data["level"] == 'error' else self.term.yellow,
+            c2=term.red if data["level"] == 'error' else term.yellow,
             lineno=str(data["lineno"]),
             column=(":" + str(data["column"])) if data.get("column") else "",
             level=data["level"],
@@ -357,7 +394,7 @@ class MachFormatter(base.BaseFormatter):
             return
 
         heading = "Overall Summary"
-        rv = ["", self.term.bold_yellow(heading), self.term.bold_yellow("=" * len(heading))]
+        rv = ["", heading, "=" * len(heading)]
         for suite, summary in self.summary:
             rv.append(self._format_suite_summary(suite, summary))
         return "\n".join(rv)