Bug 957768 - Add option to hide subtests in mochitest, r=jmaher, a=test-only
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Tue, 14 Jan 2014 10:32:43 +0800
changeset 175706 2f7db1f0276a29f00c3a5cc88b39502a8a604955
parent 175705 35cf0f10b3a6d18e8e5205a4961dfd07dfa54f8d
child 175707 29c5b8def4082b7f83919001c01566109b3095d1
push id445
push userffxbld
push dateMon, 10 Mar 2014 22:05:19 +0000
treeherdermozilla-release@dc38b741b04e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjmaher, test-only
bugs957768
milestone28.0a2
Bug 957768 - Add option to hide subtests in mochitest, r=jmaher, a=test-only
build/automation.py.in
testing/mochitest/mach_commands.py
testing/mochitest/mochitest_options.py
testing/mochitest/runtests.py
--- a/build/automation.py.in
+++ b/build/automation.py.in
@@ -847,17 +847,17 @@ class Automation(object):
   def checkForCrashes(self, minidumpDir, symbolsPath):
     return mozcrash.check_for_crashes(minidumpDir, symbolsPath, test_name=self.lastTestSeen)
 
   def runApp(self, testURL, env, app, profileDir, extraArgs,
              runSSLTunnel = False, utilityPath = None,
              xrePath = None, certPath = None,
              debuggerInfo = None, symbolsPath = None,
              timeout = -1, maxTime = None, onLaunch = None,
-             webapprtChrome = False):
+             webapprtChrome = False, hide_subtests=None):
     """
     Run the app, log the duration it took to execute, return the status code.
     Kills the app if it runs for longer than |maxTime| seconds, or outputs nothing for |timeout| seconds.
     """
 
     if utilityPath == None:
       utilityPath = self.DIST_BIN
     if xrePath == None:
--- a/testing/mochitest/mach_commands.py
+++ b/testing/mochitest/mach_commands.py
@@ -193,17 +193,17 @@ class MochitestRunner(MozbuildObject):
         return mochitest.run_remote_mochitests(parser, options)
 
     def run_desktop_test(self, suite=None, test_file=None, debugger=None,
         debugger_args=None, shuffle=False, keep_open=False, rerun_failures=False,
         no_autorun=False, repeat=0, run_until_failure=False, slow=False,
         chunk_by_dir=0, total_chunks=None, this_chunk=None, jsdebugger=False,
         debug_on_failure=False, start_at=None, end_at=None, e10s=False,
         dmd=False, dump_output_directory=None, dump_about_memory_after_test=False,
-        dump_dmd_after_test=False):
+        dump_dmd_after_test=False, **kwargs):
         """Runs a mochitest.
 
         test_file is a path to a test file. It can be a relative path from the
         top source directory, an absolute filename, or a directory containing
         test files.
 
         suite is the type of mochitest to run. It can be one of ('plain',
         'chrome', 'browser', 'metro', 'a11y').
@@ -308,16 +308,19 @@ class MochitestRunner(MozbuildObject):
         options.e10s = e10s
         options.dumpAboutMemoryAfterTest = dump_about_memory_after_test
         options.dumpDMDAfterTest = dump_dmd_after_test
         options.dumpOutputDirectory = dump_output_directory
         mozinfo.update({"e10s": e10s}) # for test manifest parsing.
 
         options.failureFile = failure_file_path
 
+        for k, v in kwargs.iteritems():
+            setattr(options, k, v)
+
         if test_path:
             test_root = runner.getTestRoot(options)
             test_root_file = mozpack.path.join(self.mochitest_dir, test_root, test_path)
             if not os.path.exists(test_root_file):
                 print('Specified test path does not exist: %s' % test_root_file)
                 print('You may need to run |mach build| to build the test files.')
                 return 1
 
@@ -440,16 +443,20 @@ def MochitestCommand(func):
     chunk_total = CommandArgument('--total-chunks', type=int,
         help='Total number of chunks to split tests into.')
     func = chunk_total(func)
 
     this_chunk = CommandArgument('--this-chunk', type=int,
         help='If running tests by chunks, the number of the chunk to run.')
     func = this_chunk(func)
 
+    hide_subtests = CommandArgument('--hide-subtests', action='store_true',
+        help='If specified, will only log subtest results on failure or timeout.')
+    func = hide_subtests(func)
+
     debug_on_failure = CommandArgument('--debug-on-failure', action='store_true',
         help='Breaks execution and enters the JS debugger on a test failure. ' \
              'Should be used together with --jsdebugger.')
     func = debug_on_failure(func)
 
     jsdebugger = CommandArgument('--jsdebugger', action='store_true',
         help='Start the browser JS debugger before running the test. Implies --no-autorun.')
     func = jsdebugger(func)
@@ -523,16 +530,20 @@ def B2GCommand(func):
     chunk_total = CommandArgument('--total-chunks', type=int,
         help='Total number of chunks to split tests into.')
     func = chunk_total(func)
 
     this_chunk = CommandArgument('--this-chunk', type=int,
         help='If running tests by chunks, the number of the chunk to run.')
     func = this_chunk(func)
 
+    hide_subtests = CommandArgument('--hide-subtests', action='store_true',
+        help='If specified, will only log subtest results on failure or timeout.')
+    func = hide_subtests(func)
+
     path = CommandArgument('test_file', default=None, nargs='?',
         metavar='TEST',
         help='Test to run. Can be specified as a single file, a ' \
             'directory, or omitted. If omitted, the entire test suite is ' \
             'executed.')
     func = path(func)
 
     return func
--- a/testing/mochitest/mochitest_options.py
+++ b/testing/mochitest/mochitest_options.py
@@ -64,16 +64,22 @@ class MochitestOptions(optparse.OptionPa
         [["--log-file"],
         { "action": "store",
           "type": "string",
           "dest": "logFile",
           "metavar": "FILE",
           "help": "file to which logging occurs",
           "default": "",
         }],
+        [["--hide-subtests"],
+        { "action": "store_true",
+          "dest": "hide_subtests",
+          "help": "only show subtest log output if there was a failure",
+          "default": False,
+        }],
         [["--autorun"],
         { "action": "store_true",
           "dest": "autorun",
           "help": "start running tests when the application starts",
           "default": False,
         }],
         [["--timeout"],
         { "type": "int",
--- a/testing/mochitest/runtests.py
+++ b/testing/mochitest/runtests.py
@@ -10,17 +10,16 @@ from __future__ import with_statement
 import os
 import sys
 SCRIPT_DIR = os.path.abspath(os.path.realpath(os.path.dirname(__file__)))
 sys.path.insert(0, SCRIPT_DIR);
 
 import json
 import mozcrash
 import mozinfo
-import mozlog
 import mozprocess
 import mozrunner
 import optparse
 import re
 import shutil
 import signal
 import subprocess
 import tempfile
@@ -756,17 +755,18 @@ class Mochitest(MochitestUtilsMixin):
              extraArgs,
              utilityPath,
              xrePath,
              certPath,
              debuggerInfo=None,
              symbolsPath=None,
              timeout=-1,
              onLaunch=None,
-             webapprtChrome=False):
+             webapprtChrome=False,
+             hide_subtests=False):
     """
     Run the app, log the duration it took to execute, return the status code.
     Kills the app if it runs for longer than |maxTime| seconds, or outputs nothing for |timeout| seconds.
     """
 
     # debugger information
     interactive = False
     debug_args = None
@@ -844,20 +844,22 @@ class Mochitest(MochitestUtilsMixin):
     else:
       shutdownLeaks = None
 
     # create an instance to process the output
     outputHandler = self.OutputHandler(harness=self,
                                        utilityPath=utilityPath,
                                        symbolsPath=symbolsPath,
                                        dump_screen_on_timeout=not debuggerInfo,
+                                       hide_subtests=hide_subtests,
                                        shutdownLeaks=shutdownLeaks,
       )
 
     def timeoutHandler():
+      outputHandler.log_output_buffer()
       browserProcessId = outputHandler.browserProcessId
       self.handleTimeout(timeout, proc, utilityPath, debuggerInfo, browserProcessId)
     kp_kwargs = {'kill_on_timeout': False,
                  'onTimeout': [timeoutHandler]}
     # if the output handler is a pipe, it will process output via the subprocess
     if not outputHandler.pipe:
       kp_kwargs['processOutputLine'] = [outputHandler]
 
@@ -1021,17 +1023,18 @@ class Mochitest(MochitestUtilsMixin):
                            extraArgs=options.browserArgs,
                            utilityPath=options.utilityPath,
                            xrePath=options.xrePath,
                            certPath=options.certPath,
                            debuggerInfo=debuggerInfo,
                            symbolsPath=options.symbolsPath,
                            timeout=timeout,
                            onLaunch=onLaunch,
-                           webapprtChrome=options.webapprtChrome
+                           webapprtChrome=options.webapprtChrome,
+                           hide_subtests=options.hide_subtests
                            )
     except KeyboardInterrupt:
       log.info("runtests.py | Received keyboard interrupt.\n");
       status = -1
     except:
       traceback.print_exc()
       log.error("Automation Error: Received unexpected exception while running application\n")
       status = 1
@@ -1055,25 +1058,29 @@ class Mochitest(MochitestUtilsMixin):
     log.info("TEST-UNEXPECTED-FAIL | %s | application timed out after %d seconds with no output", self.lastTestSeen, int(timeout))
     browserProcessId = browserProcessId or proc.pid
     self.killAndGetStack(browserProcessId, utilityPath, debuggerInfo, dump_screen=not debuggerInfo)
 
   ### output processing
 
   class OutputHandler(object):
     """line output handler for mozrunner"""
-    def __init__(self, harness, utilityPath, symbolsPath=None, dump_screen_on_timeout=True, shutdownLeaks=None):
+    def __init__(self, harness, utilityPath, symbolsPath=None, dump_screen_on_timeout=True,
+                 hide_subtests=False, shutdownLeaks=None):
       """
       harness -- harness instance
       dump_screen_on_timeout -- whether to dump the screen on timeout
       """
       self.harness = harness
+      self.output_buffer = []
+      self.running_test = False
       self.utilityPath = utilityPath
       self.symbolsPath = symbolsPath
       self.dump_screen_on_timeout = dump_screen_on_timeout
+      self.hide_subtests = hide_subtests
       self.shutdownLeaks = shutdownLeaks
 
       # perl binary to use
       self.perl = which('perl')
 
       # With metro browser runs this script launches the metro test harness which launches the browser.
       # The metro test harness hands back the real browser process id via log output which we need to
       # pick up on and parse out. This variable tracks the real browser process id if we find it.
@@ -1091,21 +1098,22 @@ class Mochitest(MochitestUtilsMixin):
       for handler in self.outputHandlers():
         line = handler(line)
     __call__ = processOutputLine
 
     def outputHandlers(self):
       """returns ordered list of output handlers"""
       return [self.fix_stack,
               self.format,
-              self.record_last_test,
               self.dumpScreenOnTimeout,
               self.metro_subprocess_id,
               self.trackShutdownLeaks,
+              self.check_test_failure,
               self.log,
+              self.record_last_test,
               ]
 
     def stackFixer(self):
       """
       return 2-tuple, (stackFixerFunction, StackFixerProcess),
       if any, to use on the output lines
       """
 
@@ -1146,37 +1154,36 @@ class Mochitest(MochitestUtilsMixin):
       if self.stackFixerProcess:
         status = self.stackFixerProcess.wait()
         if status and not didTimeout:
           log.info("TEST-UNEXPECTED-FAIL | runtests.py | Stack fixer process exited with code %d during test run", status)
 
       if self.shutdownLeaks:
         self.shutdownLeaks.process()
 
+    def log_output_buffer(self):
+        if self.output_buffer:
+            lines = ['  %s' % line for line in self.output_buffer]
+            log.info("Buffered test output:\n%s" % '\n'.join(lines))
 
     # output line handlers:
     # these take a line and return a line
 
     def fix_stack(self, line):
       if self.stackFixerFunction:
         return self.stackFixerFunction(line)
       return line
 
     def format(self, line):
       """format the line"""
       return line.rstrip().decode("UTF-8", "ignore")
 
-    def record_last_test(self, line):
-      """record last test on harness"""
-      if "TEST-START" in line and "|" in line:
-        self.harness.lastTestSeen = line.split("|")[1].strip()
-      return line
-
     def dumpScreenOnTimeout(self, line):
       if self.dump_screen_on_timeout and "TEST-UNEXPECTED-FAIL" in line and "Test timed out" in line:
+        self.log_output_buffer()
         self.harness.dumpScreen(self.utilityPath)
       return line
 
     def metro_subprocess_id(self, line):
       """look for metro browser subprocess id"""
       if "METRO_BROWSER_PROCESS" in line:
         index = line.find("=")
         if index != -1:
@@ -1184,18 +1191,40 @@ class Mochitest(MochitestUtilsMixin):
           log.info("INFO | runtests.py | metro browser sub process id detected: %s", self.browserProcessId)
       return line
 
     def trackShutdownLeaks(self, line):
       if self.shutdownLeaks:
         self.shutdownLeaks.log(line)
       return line
 
+    def check_test_failure(self, line):
+      if 'TEST-END' in line:
+        self.running_test = False
+        if any('TEST-UNEXPECTED' in l for l in self.output_buffer):
+          self.log_output_buffer()
+      return line
+
     def log(self, line):
-      log.info(line)
+      if self.hide_subtests and self.running_test:
+        self.output_buffer.append(line)
+      else:
+        # hack to make separators align nicely, remove when we use mozlog
+        if self.hide_subtests and 'TEST-END' in line:
+            index = line.index('TEST-END') + len('TEST-END')
+            line = line[:index] + ' ' * (len('TEST-START')-len('TEST-END')) + line[index:]
+        log.info(line)
+      return line
+
+    def record_last_test(self, line):
+      """record last test on harness"""
+      if "TEST-START" in line and "|" in line:
+        self.output_buffer = []
+        self.running_test = True
+        self.harness.lastTestSeen = line.split("|")[1].strip()
       return line
 
 
   def makeTestConfig(self, options):
     "Creates a test configuration file for customizing test execution."
     def jsonString(val):
       if isinstance(val, bool):
         if val: