Bug 857984 - mach mochitest now colorizes and prints failure summary; r=Ms2ger

python/mach/mach/logging.py

@@ -34,7 +34,7 @@ class ConvertToStructuredFilter(logging.Filter):
             return True
 
         record.action = 'unstructured'
-        record.params = {'msg': record.msg}
+        record.params = {'msg': record.getMessage()}
         record.msg = '{msg}'
 
         return True
@@ -61,12 +61,16 @@ class StructuredHumanFormatter(logging.Formatter):
     Because of this limitation, format() will fail with a KeyError if an
     unstructured record is passed or if the structured message is malformed.
     """
-    def __init__(self, start_time, write_interval=False):
+    def __init__(self, start_time, write_interval=False, write_times=True):
         self.start_time = start_time
         self.write_interval = write_interval
+        self.write_times = write_times
         self.last_time = None
 
     def format(self, record):
+        if not self.write_times:
+            return record.msg.format(**record.params)
+
         elapsed = self._time(record)
 
         return '%s %s' % (format_seconds(elapsed),

testing/mochitest/mach_commands.py

@@ -4,6 +4,7 @@
 
 from __future__ import unicode_literals
 
+import logging
 import mozpack.path
 import os
 import platform
@@ -20,6 +21,14 @@ from mach.decorators import (
     Command,
 )
 
+from mach.logging import StructuredHumanFormatter
+
+
+class UnexpectedFilter(logging.Filter):
+    def filter(self, record):
+        msg = getattr(record, 'params', {}).get('msg', '')
+        return 'TEST-UNEXPECTED-' in msg
+
 
 class MochitestRunner(MozbuildObject):
     """Easily run mochitests.
@@ -70,6 +79,7 @@ class MochitestRunner(MozbuildObject):
             print('No failure file present. Did you run mochitests before?')
             return 1
 
+        from StringIO import StringIO
         from automation import Automation
 
         # runtests.py is ambiguous, so we load the file/module manually.
@@ -86,6 +96,14 @@ class MochitestRunner(MozbuildObject):
         os.chdir(self.topobjdir)
 
         automation = Automation()
+
+        # Automation installs its own stream handler to stdout. Since we want
+        # all logging to go through us, we just remove their handler.
+        remove_handlers = [l for l in logging.getLogger().handlers
+            if isinstance(l, logging.StreamHandler)]
+        for handler in remove_handlers:
+            logging.getLogger().removeHandler(handler)
+
         runner = mochitest.Mochitest(automation)
 
         opts = mochitest.MochitestOptions(automation, tests_dir)
@@ -144,7 +162,34 @@ class MochitestRunner(MozbuildObject):
         if debugger:
             options.debugger = debugger
 
-        return runner.runTests(options)
+        # We need this to enable colorization of output.
+        self.log_manager.enable_unstructured()
+
+        # Output processing is a little funky here. The old make targets
+        # grepped the log output from TEST-UNEXPECTED-* and printed these lines
+        # after test execution. Ideally the test runner would expose a Python
+        # API for obtaining test results and we could just format failures
+        # appropriately. Unfortunately, it doesn't yet do that. So, we capture
+        # all output to a buffer then "grep" the buffer after test execution.
+        # Bug 858197 tracks a Python API that would facilitate this.
+        test_output = StringIO()
+        handler = logging.StreamHandler(test_output)
+        handler.addFilter(UnexpectedFilter())
+        handler.setFormatter(StructuredHumanFormatter(0, write_times=False))
+        logging.getLogger().addHandler(handler)
+
+        result = runner.runTests(options)
+
+        # Need to remove our buffering handler before we echo failures or else
+        # it will catch them again!
+        logging.getLogger().removeHandler(handler)
+        self.log_manager.disable_unstructured()
+
+        if test_output.getvalue():
+            for line in test_output.getvalue().splitlines():
+                self.log(logging.INFO, 'unexpected', {'msg': line}, '{msg}')
+
+        return result
 
 
 def MochitestCommand(func):