Bug 1034290 - Use structured log output for test results in reftest, …

…r=jmaher

Structured logs bring many benefits. We can stop parsing the logs for magic strings, we
can modify the format without breaking things, and we can stream results into systems like
ActiveData. The structured logs originate primarily in reftest.js. StructuredLog.jsm is
used to generate the JSON-based log stream. Finally OutputHandler in the python harness
reads structured output from stdout, and formats it into human readable form.

MozReview-Commit-ID: G3ZLkMRl6p7

build/automation.py.in

@@ -396,7 +396,7 @@ class Automation(object):
     self.log.info("Can't trigger Breakpad, just killing process")
     self.killPid(processPID)
 
-  def waitForFinish(self, proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath):
+  def waitForFinish(self, proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath, outputHandler=None):
     """ Look for timeout or crashes and return the status after the process terminates """
     stackFixerFunction = None
     didTimeout = False
@@ -436,7 +436,12 @@ class Automation(object):
       while line != "" and not didTimeout:
         if stackFixerFunction:
           line = stackFixerFunction(line)
-        self.log.info(line.rstrip().decode("UTF-8", "ignore"))
+
+        if outputHandler is None:
+            self.log.info(line.rstrip().decode("UTF-8", "ignore"))
+        else:
+            outputHandler(line)
+
         if "TEST-START" in line and "|" in line:
           self.lastTestSeen = line.split("|")[1].strip()
         if not debuggerInfo and "TEST-UNEXPECTED-FAIL" in line and "Test timed out" in line:
@@ -530,7 +535,7 @@ class Automation(object):
              debuggerInfo = None, symbolsPath = None,
              timeout = -1, maxTime = None, onLaunch = None,
              detectShutdownLeaks = False, screenshotOnFail=False, testPath=None, bisectChunk=None,
-             valgrindPath=None, valgrindArgs=None, valgrindSuppFiles=None):
+             valgrindPath=None, valgrindArgs=None, valgrindSuppFiles=None, outputHandler=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.
@@ -579,7 +584,8 @@ class Automation(object):
       # app is launched.
       onLaunch()
 
-    status = self.waitForFinish(proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath)
+    status = self.waitForFinish(proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath,
+                                outputHandler=outputHandler)
     self.log.info("INFO | automation.py | Application ran for: %s", str(datetime.now() - startTime))
 
     # Do a final check for zombie child processes.

build/mobile/b2gautomation.py

@@ -209,23 +209,31 @@ def buildCommandLine(self, app, debuggerInfo, profileDir, testURL, extraArgs):
         return app, args
 
     def waitForFinish(self, proc, utilityPath, timeout, maxTime, startTime,
-                      debuggerInfo, symbolsPath):
+                      debuggerInfo, symbolsPath, outputHandler=None):
         """ Wait for tests to finish (as evidenced by a signature string
             in logcat), or for a given amount of time to elapse with no
             output.
         """
         timeout = timeout or 120
         while True:
-            currentlog = proc.getStdoutLines(timeout)
-            if currentlog:
-                print currentlog
+            lines = proc.getStdoutLines(timeout)
+            if lines:
+                currentlog = '\n'.join(lines)
+
+                if outputHandler:
+                    for line in lines:
+                        outputHandler(line)
+                else:
+                    print(currentlog)
+
                 # Match the test filepath from the last TEST-START line found in the new
                 # log content. These lines are in the form:
                 # ... INFO TEST-START | /filepath/we/wish/to/capture.html\n
                 testStartFilenames = re.findall(r"TEST-START \| ([^\s]*)", currentlog)
                 if testStartFilenames:
                     self.lastTestSeen = testStartFilenames[-1]
-                if hasattr(self, 'logFinish') and self.logFinish in currentlog:
+                if (outputHandler and outputHandler.suite_finished) or (
+                        hasattr(self, 'logFinish') and self.logFinish in currentlog):
                     return 0
             else:
                 self.log.info("TEST-UNEXPECTED-FAIL | %s | application timed "
@@ -434,11 +442,12 @@ def getStdoutLines(self, timeout):
                     break
 
             # wait 'timeout' for any additional lines
-            try:
-                lines.append(self.queue.get(True, timeout))
-            except Queue.Empty:
-                pass
-            return '\n'.join(lines)
+            if not lines:
+                try:
+                    lines.append(self.queue.get(True, timeout))
+                except Queue.Empty:
+                    pass
+            return lines
 
         def wait(self, timeout=None):
             # this should never happen

build/mobile/remoteautomation.py

@@ -95,7 +95,7 @@ def environment(self, env=None, xrePath=None, crashreporter=True, debugger=False
 
         return env
 
-    def waitForFinish(self, proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath):
+    def waitForFinish(self, proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath, outputHandler=None):
         """ Wait for tests to finish.
             If maxTime seconds elapse or no output is detected for timeout
             seconds, kill the process and fail the test.
@@ -307,20 +307,21 @@ def pid(self):
             return pid
 
         def read_stdout(self):
-            """ Fetch the full remote log file using devicemanager and return just
-                the new log entries since the last call (as a list of messages or lines).
+            """
+            Fetch the full remote log file using devicemanager, process them and
+            return whether there were any new log entries since the last call.
             """
             if not self.dm.fileExists(self.proc):
-                return []
+                return False
             try:
                 newLogContent = self.dm.pullFile(self.proc, self.stdoutlen)
             except DMError:
                 # we currently don't retry properly in the pullFile
                 # function in dmSUT, so an error here is not necessarily
                 # the end of the world
-                return []
+                return False
             if not newLogContent:
-                return []
+                return False
 
             self.stdoutlen += len(newLogContent)
 
@@ -329,26 +330,27 @@ def read_stdout(self):
                 if testStartFilenames:
                     self.lastTestSeen = testStartFilenames[-1]
                 print newLogContent
-                return [newLogContent]
+                return True
 
             self.logBuffer += newLogContent
             lines = self.logBuffer.split('\n')
+
+            if lines:
+                # We only keep the last (unfinished) line in the buffer
+                self.logBuffer = lines[-1]
+                del lines[-1]
+
             if not lines:
-                return
+                return False
 
-            # We only keep the last (unfinished) line in the buffer
-            self.logBuffer = lines[-1]
-            del lines[-1]
-            messages = []
             for line in lines:
                 # This passes the line to the logger (to be logged or buffered)
                 # and returns a list of structured messages (dict)
                 parsed_messages = self.messageLogger.write(line)
                 for message in parsed_messages:
-                    if message['action'] == 'test_start':
+                    if isinstance(message, dict) and message.get('action') == 'test_start':
                         self.lastTestSeen = message['test']
-                messages += parsed_messages
-            return messages
+            return True
 
         @property
         def getLastTestSeen(self):
@@ -374,10 +376,10 @@ def wait(self, timeout = None, noOutputTimeout = None):
                 # too long, only do it every 60 seconds
                 if (not slowLog) or (timer % 60 == 0):
                     startRead = datetime.datetime.now()
-                    messages = self.read_stdout()
+                    hasOutput = self.read_stdout()
                     if (datetime.datetime.now() - startRead) > datetime.timedelta(seconds=5):
                         slowLog = True
-                    if messages:
+                    if hasOutput:
                         noOutputTimer = 0
                 time.sleep(interval)
                 timer += interval

layout/tools/reftest/Makefile.in

@@ -12,6 +12,7 @@ _HARNESS_FILES = \
   $(srcdir)/runreftestb2g.py \
   $(srcdir)/runreftestmulet.py \
   $(srcdir)/gaia_lock_screen.js \
+  $(srcdir)/output.py \
   automation.py \
   $(topsrcdir)/testing/mozbase/mozdevice/mozdevice/devicemanager.py \
   $(topsrcdir)/testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py \

layout/tools/reftest/jar.mn

@@ -2,6 +2,7 @@ reftest.jar:
 % content reftest %content/
 *  content/reftest-content.js (reftest-content.js)
   content/httpd.jsm (../../../netwerk/test/httpserver/httpd.js)
+  content/StructuredLog.jsm (../../../testing/modules/StructuredLog.jsm)
 #ifdef BOOTSTRAP
 *  content/reftest.jsm (reftest.js)
 #else

layout/tools/reftest/mach_commands.py

@@ -203,8 +203,6 @@ def run_desktop_test(self, **kwargs):
         if not kwargs["runTestsInParallel"]:
             kwargs["logFile"] = "%s.log" % kwargs["suite"]
 
-        # Remove the stdout handler from the internal logger and let mach deal with it
-        runreftest.log.removeHandler(runreftest.log.handlers[0])
         self.log_manager.enable_unstructured()
         try:
             rv = runreftest.run(**kwargs)

layout/tools/reftest/output.py

@@ -0,0 +1,144 @@
+# 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 json
+import os
+import threading
+
+from mozlog.formatters import TbplFormatter
+from mozrunner.utils import get_stack_fixer_function
+
+
+class ReftestFormatter(TbplFormatter):
+    """
+    Formatter designed to preserve the legacy "tbpl" format in reftest.
+
+    This is needed for both the reftest-analyzer and mozharness log parsing.
+    We can change this format when both reftest-analyzer and mozharness have
+    been changed to read structured logs.
+    """
+
+    def __call__(self, data):
+        if 'component' in data and data['component'] == 'mozleak':
+            # Output from mozleak requires that no prefix be added
+            # so that mozharness will pick up these failures.
+            return "%s\n" % data['message']
+
+        formatted = TbplFormatter.__call__(self, data)
+        if data['action'] == 'process_output':
+            return formatted
+        return 'REFTEST %s' % formatted
+
+    def log(self, data):
+        prefix = "%s |" % data['level'].upper()
+        return "%s %s\n" % (prefix, data['message'])
+
+    def test_end(self, data):
+        extra = data.get('extra', {})
+        status = data['status']
+
+        status_msg = "TEST-"
+        if 'expected' in data:
+            status_msg += "UNEXPECTED-%s" % status
+        else:
+            if status != "PASS":
+                status_msg += "KNOWN-"
+            status_msg += status
+            if extra.get('status_msg') == 'Random':
+                status_msg += "(EXPECTED RANDOM)"
+        test = self.id_str(data['test'])
+        if 'message' in data:
+            status_details = data['message']
+        elif isinstance(data['test'], tuple):
+            status_details = 'image comparison ({})'.format(data['test'][1])
+        else:
+            status_details = '(LOAD ONLY)'
+
+        output_text = "%s | %s | %s" % (status_msg, test, status_details)
+        if 'differences' in extra:
+            diff_msg = (", max difference: %(max_difference)s"
+                        ", number of differing pixels: %(differences)s") % extra
+            diagnostic_data = ("REFTEST   IMAGE 1 (TEST): %(image1)s\n"
+                               "REFTEST   IMAGE 2 (REFERENCE): %(image2)s") % extra
+            output_text += '%s\n%s' % (diff_msg, diagnostic_data)
+        elif "image1" in extra:
+            diagnostic_data = "REFTEST   IMAGE: %(image1)s" % extra
+            output_text += '\n%s' % diagnostic_data
+
+        output_text += "\nREFTEST TEST-END | %s" % test
+        return "%s\n" % output_text
+
+    def process_output(self, data):
+        return "%s\n" % data["data"]
+
+    def suite_end(self, data):
+        lines = []
+        summary = data['extra']['results']
+        summary['success'] = summary['Pass'] + summary['LoadOnly']
+        lines.append("Successful: %(success)s (%(Pass)s pass, %(LoadOnly)s load only)" %
+                     summary)
+        summary['unexpected'] = (summary['Exception'] + summary['FailedLoad'] +
+                                 summary['UnexpectedFail'] + summary['UnexpectedPass'] +
+                                 summary['AssertionUnexpected'] +
+                                 summary['AssertionUnexpectedFixed'])
+        lines.append(("Unexpected: %(unexpected)s (%(UnexpectedFail)s unexpected fail, "
+                      "%(UnexpectedPass)s unexpected pass, "
+                      "%(AssertionUnexpected)s unexpected asserts, "
+                      "%(FailedLoad)s failed load, "
+                      "%(Exception)s exception)") % summary)
+        summary['known'] = (summary['KnownFail'] + summary['AssertionKnown'] +
+                            summary['Random'] + summary['Skip'] + summary['Slow'])
+        lines.append(("Known problems: %(known)s (" +
+                      "%(KnownFail)s known fail, " +
+                      "%(AssertionKnown)s known asserts, " +
+                      "%(Random)s random, " +
+                      "%(Skip)s skipped, " +
+                      "%(Slow)s slow)") % summary)
+        lines = ["REFTEST INFO | %s" % s for s in lines]
+        lines.append("REFTEST SUITE-END | Shutdown")
+        return "INFO | Result summary:\n{}\n".format('\n'.join(lines))
+
+    def id_str(self, test_id):
+        if isinstance(test_id, basestring):
+            return test_id
+        return test_id[0]
+
+
+class OutputHandler(object):
+    """Process the output of a process during a test run and translate
+    raw data logged from reftest.js to an appropriate structured log action,
+    where applicable.
+    """
+
+    def __init__(self, log, utilityPath, symbolsPath=None):
+        self.stack_fixer_function = get_stack_fixer_function(utilityPath, symbolsPath)
+        self.log = log
+        # needed for b2gautomation.py
+        self.suite_finished = False
+
+    def __call__(self, line):
+        # need to return processed messages to appease remoteautomation.py
+        if not line.strip():
+            return []
+
+        try:
+            data = json.loads(line)
+        except ValueError:
+            self.verbatim(line)
+            return [line]
+
+        if isinstance(data, dict) and 'action' in data:
+            if data['action'] == 'suite_end':
+                self.suite_finished = True
+
+            self.log.log_raw(data)
+        else:
+            self.verbatim(json.dumps(data))
+
+        return [data]
+
+    def verbatim(self, line):
+        if self.stack_fixer_function:
+            line = self.stack_fixer_function(line)
+        self.log.process_output(threading.current_thread().name, line)