Bug 1270507 - Elide subtest results from web-platform-tests on treeherder when they match expectations, r=ahal
authorJames Graham <james@hoppipolla.co.uk>
Tue, 03 May 2016 23:21:07 +0100
changeset 296648 0a84159395221fe92580c66a89e207005bc61325
parent 296647 37073e486aca054d969f7390985b14ef24cfedc7
child 296649 0c26faffd7e6ad64df8b4fba8b90cee0133be268
push id30245
push usercbook@mozilla.com
push dateTue, 10 May 2016 10:06:29 +0000
treeherdermozilla-central@1579b9e2e50f [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersahal
bugs1270507
milestone49.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 1270507 - Elide subtest results from web-platform-tests on treeherder when they match expectations, r=ahal MozReview-Commit-ID: DyatYcpdjvQ
testing/mozbase/mozlog/mozlog/commandline.py
testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
testing/mozharness/mozharness/mozilla/structuredlog.py
testing/mozharness/scripts/web_platform_tests.py
--- a/testing/mozbase/mozlog/mozlog/commandline.py
+++ b/testing/mozbase/mozlog/mozlog/commandline.py
@@ -27,16 +27,20 @@ TEXT_FORMATTERS = ('raw', 'mach')
 
 def level_filter_wrapper(formatter, level):
     return handlers.LogLevelFilter(formatter, level)
 
 def verbose_wrapper(formatter, verbose):
     formatter.verbose = verbose
     return formatter
 
+def compact_wrapper(formatter, compact):
+    formatter.compact = compact
+    return formatter
+
 def buffer_handler_wrapper(handler, buffer_limit):
     if buffer_limit == "UNLIMITED":
         buffer_limit = None
     else:
         buffer_limit = int(buffer_limit)
     return handlers.BufferHandler(handler, buffer_limit)
 
 def valgrind_handler_wrapper(handler):
@@ -58,16 +62,19 @@ def default_formatter_options(log_type, 
     return rv
 
 fmt_options = {
     # <option name>: (<wrapper function>, description, <applicable formatters>, action)
     # "action" is used by the commandline parser in use.
     'verbose': (verbose_wrapper,
                 "Enables verbose mode for the given formatter.",
                 ["mach"], "store_true"),
+    'compact': (compact_wrapper,
+                "Enables compact mode for the given formatter.",
+                ["tbpl"], "store_true"),
     'level': (level_filter_wrapper,
               "A least log level to subscribe to for the given formatter (debug, info, error, etc.)",
               ["mach", "raw", "tbpl"], "store"),
     'buffer': (buffer_handler_wrapper,
                "If specified, enables message buffering at the given buffer size limit.",
                ["mach", "tbpl"], "store"),
 }
 
--- a/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
@@ -1,52 +1,96 @@
 # 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 functools
+from collections import deque
+
 from .base import BaseFormatter
 from .process import strstatus
 
+def output_subtests(func):
+    @functools.wraps(func)
+    def inner(self, data):
+        if self.subtests_count:
+            return self._format_subtests(data.get("component")) + func(self, data)
+        else:
+            return func(self, data)
+    return inner
+
 
 class TbplFormatter(BaseFormatter):
     """Formatter that formats logs in the legacy formatting format used by TBPL
     This is intended to be used to preserve backward compatibility with existing tools
     hand-parsing this format.
     """
-    def __init__(self):
+    def __init__(self, compact=False):
         self.suite_start_time = None
         self.test_start_times = {}
+        self.buffer = None
+        self.compact = compact
+        self.subtests_count = 0
+
+    @property
+    def compact(self):
+        return self._compact
+
+    @compact.setter
+    def compact(self, value):
+        self._compact = value
+        if value:
+            self.buffer = deque([], 10)
+        else:
+            self.buffer = None
 
     def __call__(self, data):
         return getattr(self, data["action"])(data)
 
+    def _format_subtests(self, component, subtract_context=False):
+        count = self.subtests_count
+        if subtract_context:
+            count -= len(self.buffer)
+        self.subtests_count = 0
+        return self._log({"level": "INFO",
+                          "message": "." * count,
+                          "component": component})
+
+    @output_subtests
     def log(self, data):
+        return self._log(data)
+
+    def _log(self, data):
         if data.get('component'):
             message = "%s %s" % (data["component"], data["message"])
         else:
             message = data["message"]
 
         if "stack" in data:
             message += "\n%s" % data["stack"]
 
         return "%s\n" % message
 
+    @output_subtests
     def process_output(self, data):
         return "PROCESS | %(process)s | %(data)s\n" % data
 
+    @output_subtests
     def process_start(self, data):
         msg = "TEST-INFO | started process %s" % data['process']
         if 'command' in data:
             msg = '%s (%s)' % (msg, data['command'])
         return msg + '\n'
 
+    @output_subtests
     def process_exit(self, data):
         return "TEST-INFO | %s: %s\n" % (data['process'],
                                          strstatus(data['exitcode']))
 
+    @output_subtests
     def crash(self, data):
         id = self.id_str(data["test"]) if "test" in data else "pid: %s" % data["process"]
 
         signature = data["signature"] if data["signature"] else "unknown top frame"
         rv = ["PROCESS-CRASH | %s | application crashed [%s]" % (id, signature)]
 
         if data.get("minidump_path"):
             rv.append("Crash dump filename: %s" % data["minidump_path"])
@@ -75,16 +119,31 @@ class TbplFormatter(BaseFormatter):
         return "SUITE-START | Running %i tests\n" % len(data["tests"])
 
     def test_start(self, data):
         self.test_start_times[self.test_id(data["test"])] = data["time"]
 
         return "TEST-START | %s\n" % self.id_str(data["test"])
 
     def test_status(self, data):
+        if self.compact:
+            if "expected" in data:
+                rv = []
+                rv.append(self._format_subtests(data.get("component"), subtract_context=True))
+                rv.extend(self._format_status(item) for item in self.buffer)
+                rv.append(self._format_status(data))
+                self.buffer.clear()
+                return "".join(rv)
+            else:
+                self.subtests_count += 1
+                self.buffer.append(data)
+        else:
+            return self._format_status(data)
+
+    def _format_status(self, data):
         message = "- " + data["message"] if "message" in data else ""
         if "stack" in data:
             message += "\n%s" % data["stack"]
         if message and message[-1] == "\n":
             message = message[:-1]
 
         if "expected" in data:
             if not message:
@@ -97,16 +156,25 @@ class TbplFormatter(BaseFormatter):
                 return failure_line + info_line
             return failure_line
 
         return "TEST-%s | %s | %s %s\n" % (
             data["status"], self.id_str(data["test"]), data["subtest"],
             message)
 
     def test_end(self, data):
+        rv = []
+        if self.compact and self.subtests_count:
+            print_context = "expected" in data
+            rv.append(self._format_subtests(data.get("component"),
+                                            subtract_context=print_context))
+            if print_context:
+                rv.extend(self._format_status(item) for item in self.buffer)
+            self.buffer.clear()
+
         test_id = self.test_id(data["test"])
         duration_msg = ""
 
         if test_id in self.test_start_times:
             start_time = self.test_start_times.pop(test_id)
             time = data["time"] - start_time
             duration_msg = "took %ims" % time
 
@@ -128,17 +196,18 @@ class TbplFormatter(BaseFormatter):
                 expected_msg = ""
             info_line = "TEST-INFO %s%s\n" % (expected_msg, duration_msg)
 
             return failure_line + info_line
 
         sections = ["TEST-%s" % data['status'], self.id_str(test_id)]
         if duration_msg:
             sections.append(duration_msg)
-        return ' | '.join(sections) + '\n'
+        rv.append(' | '.join(sections) + '\n')
+        return "".join(rv)
 
     def suite_end(self, data):
         start_time = self.suite_start_time
         time = int((data["time"] - start_time) / 1000)
 
         return "SUITE-END | took %is\n" % time
 
     def test_id(self, test_id):
@@ -148,14 +217,15 @@ class TbplFormatter(BaseFormatter):
             return tuple(test_id)
 
     def id_str(self, test_id):
         if isinstance(test_id, (str, unicode)):
             return test_id
         else:
             return " ".join(test_id)
 
+    @output_subtests
     def valgrind_error(self, data):
         rv = "TEST-UNEXPECTED-VALGRIND-ERROR | " + data['primary'] + "\n"
         for line in data['secondary']:
             rv = rv + line + "\n"
 
         return rv
--- a/testing/mozharness/mozharness/mozilla/structuredlog.py
+++ b/testing/mozharness/mozharness/mozilla/structuredlog.py
@@ -23,20 +23,21 @@ class StructuredOutputParser(OutputParse
         # to detect additional failure output from the harness process.
         if 'strict' in kwargs:
             self.strict = kwargs.pop('strict')
         else:
             self.strict = True
 
         self.suite_category = kwargs.pop('suite_category', None)
 
+        tbpl_compact = kwargs.pop("log_compact", False)
         super(StructuredOutputParser, self).__init__(**kwargs)
 
         mozlog = self._get_mozlog_module()
-        self.formatter = mozlog.formatters.TbplFormatter()
+        self.formatter = mozlog.formatters.TbplFormatter(compact=tbpl_compact)
         self.handler = mozlog.handlers.StatusHandler()
         self.log_actions = mozlog.structuredlog.log_actions()
 
         self.worst_log_level = INFO
         self.tbpl_status = TBPL_SUCCESS
 
     def _get_mozlog_module(self):
         try:
@@ -77,18 +78,20 @@ class StructuredOutputParser(OutputParse
             return
 
         self.handler(data)
 
         action = data["action"]
         if action == "log":
             level = getattr(log, data["level"].upper())
 
-        self.log(self.formatter(data), level=level)
-        self.update_levels(tbpl_level, level)
+        log_data = self.formatter(data)
+        if log_data is not None:
+            self.log(log_data, level=level)
+            self.update_levels(tbpl_level, level)
 
     def evaluate_parser(self, return_code, success_codes=None):
         success_codes = success_codes or [0]
         summary = self.handler.summarize()
 
         fail_pair = TBPL_WARNING, WARNING
         error_pair = TBPL_FAILURE, ERROR
 
--- a/testing/mozharness/scripts/web_platform_tests.py
+++ b/testing/mozharness/scripts/web_platform_tests.py
@@ -174,17 +174,18 @@ class WebPlatformTest(TestingMixin, Merc
                                "web-platform/*"],
             suite_categories=["web-platform"])
 
     def run_tests(self):
         dirs = self.query_abs_dirs()
         cmd = self._query_cmd()
 
         parser = StructuredOutputParser(config=self.config,
-                                        log_obj=self.log_obj)
+                                        log_obj=self.log_obj,
+                                        log_compact=True)
 
         env = {'MINIDUMP_SAVE_PATH': dirs['abs_blob_upload_dir']}
         env = self.query_env(partial_env=env, log_level=INFO)
 
         return_code = self.run_command(cmd,
                                        cwd=dirs['abs_work_dir'],
                                        output_timeout=1000,
                                        output_parser=parser,