Bug 1034290 - Use structured log output for test results in reftest, r=jmaher, a=test-only
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Fri, 05 Feb 2016 15:44:20 -0500
changeset 317427 58b097f959c080b5ff824d1d6025d6fdc67060cc
parent 317426 382ab24a1a557bde03d38d167e68f0b9ca9fda61
child 317428 420638b9199d44c5de0058c46b80c0c11b3e2330
push id5736
push userahalberstadt@mozilla.com
push dateMon, 14 Mar 2016 18:21:53 +0000
treeherdermozilla-beta@da36b86c9204 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjmaher, test-only
bugs1034290
milestone46.0
Bug 1034290 - Use structured log output for test results in reftest, r=jmaher, a=test-only 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
build/mobile/b2gautomation.py
build/mobile/remoteautomation.py
layout/tools/reftest/Makefile.in
layout/tools/reftest/jar.mn
layout/tools/reftest/mach_commands.py
layout/tools/reftest/output.py
layout/tools/reftest/reftest.js
layout/tools/reftest/reftestcommandline.py
layout/tools/reftest/remotereftest.py
layout/tools/reftest/runreftest.py
layout/tools/reftest/runreftestb2g.py
layout/tools/reftest/runreftestmulet.py
testing/modules/StructuredLog.jsm
testing/mozbase/mozleak/mozleak/leaklog.py
testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
testing/mozbase/mozlog/mozlog/logtypes.py
testing/mozbase/mozlog/mozlog/structuredlog.py
--- a/build/automation.py.in
+++ b/build/automation.py.in
@@ -391,17 +391,17 @@ class Automation(object):
         if os.path.exists(crashinject):
           status = subprocess.Popen([crashinject, str(processPID)]).wait()
           printstatus("crashinject", status)
           if status == 0:
             return
     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
     hitMaxTime = False
     if proc.stdout is None:
       self.log.info("TEST-INFO: Not logging stdout or stderr due to debugger connection")
     else:
       logsource = proc.stdout
@@ -431,17 +431,22 @@ class Automation(object):
       # 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.
       browserProcessId = -1
 
       (line, didTimeout) = self.readWithTimeout(logsource, timeout)
       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:
           self.dumpScreen(utilityPath)
 
         (line, didTimeout) = self.readWithTimeout(logsource, timeout)
 
         if not hitMaxTime and maxTime and datetime.now() - startTime > timedelta(seconds = maxTime):
@@ -525,17 +530,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, utilityPath = None,
              xrePath = None, certPath = None,
              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.
     """
 
     if utilityPath == None:
       utilityPath = self.DIST_BIN
     if xrePath == None:
@@ -574,17 +579,18 @@ class Automation(object):
                  stderr = subprocess.STDOUT)
     self.log.info("INFO | automation.py | Application pid: %d", proc.pid)
 
     if onLaunch is not None:
       # Allow callers to specify an onLaunch callback to be fired after the
       # 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.
     zombieProcesses = self.checkForZombies(processLog, utilityPath, debuggerInfo)
 
     crashed = self.checkForCrashes(os.path.join(profileDir, "minidumps"), symbolsPath)
 
     if crashed or zombieProcesses:
--- a/build/mobile/b2gautomation.py
+++ b/build/mobile/b2gautomation.py
@@ -204,33 +204,41 @@ class B2GRemoteAutomation(Automation):
         if (self._remoteProfile):
             profileDir = self._remoteProfile
 
         cmd, args = Automation.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 "
                               "out after %d seconds with no output",
                               self.lastTestSeen, int(timeout))
                 self._devicemanager.killProcess('/system/b2g/b2g', sig=signal.SIGABRT)
 
                 timeout = 10 # seconds
@@ -429,21 +437,22 @@ class B2GRemoteAutomation(Automation):
             # get all of the lines that are currently available
             while True:
                 try:
                     lines.append(self.queue.get_nowait())
                 except Queue.Empty:
                     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
             raise Exception("'wait' called on B2GInstance")
 
         def kill(self):
             # this should never happen
             raise Exception("'kill' called on B2GInstance")
--- a/build/mobile/remoteautomation.py
+++ b/build/mobile/remoteautomation.py
@@ -91,17 +91,17 @@ class RemoteAutomation(Automation):
         # standard WebRTC setting for NSPR_LOG_MODULES is not available.
         # env.setdefault('NSPR_LOG_MODULES', 'signaling:5,mtransport:5,datachannel:5,jsep:5,MediaPipelineFactory:5')
         env.setdefault('R_LOG_LEVEL', '6')
         env.setdefault('R_LOG_DESTINATION', 'stderr')
         env.setdefault('R_LOG_VERBOSE', '1')
 
         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.
         """
         # maxTime is used to override the default timeout, we should honor that
         status = proc.wait(timeout = maxTime, noOutputTimeout = timeout)
         self.lastTestSeen = proc.getLastTestSeen
 
@@ -303,58 +303,60 @@ class RemoteAutomation(Automation):
             # running processes for the remote case, but for now we'll assume
             # that this method can be called when nothing exists and it is not
             # an error
             if pid is None:
                 return 0
             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)
 
             if self.messageLogger is None:
                 testStartFilenames = re.findall(r"TEST-START \| ([^\s]*)", newLogContent)
                 if testStartFilenames:
                     self.lastTestSeen = testStartFilenames[-1]
                 print newLogContent
-                return [newLogContent]
+                return True
 
             self.logBuffer += newLogContent
             lines = self.logBuffer.split('\n')
-            if not lines:
-                return
 
-            # We only keep the last (unfinished) line in the buffer
-            self.logBuffer = lines[-1]
-            del lines[-1]
-            messages = []
+            if lines:
+                # We only keep the last (unfinished) line in the buffer
+                self.logBuffer = lines[-1]
+                del lines[-1]
+
+            if not lines:
+                return False
+
             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):
             return self.lastTestSeen
 
         # Wait for the remote process to end (or for its activity to go to background).
         # While waiting, periodically retrieve the process output and print it.
         # If the process is still running after *timeout* seconds, return 1;
@@ -370,20 +372,20 @@ class RemoteAutomation(Automation):
             status = 0
             top = self.procName
             slowLog = False
             while (top == self.procName):
                 # Get log updates on each interval, but if it is taking
                 # 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
                 noOutputTimer += interval
                 if (timer > timeout):
                     status = 1
                     break
                 if (noOutputTimeout and noOutputTimer > noOutputTimeout):
--- a/layout/tools/reftest/Makefile.in
+++ b/layout/tools/reftest/Makefile.in
@@ -7,16 +7,17 @@
 
 _HARNESS_FILES = \
   $(srcdir)/runreftest.py \
   $(srcdir)/reftestcommandline.py \
   $(srcdir)/remotereftest.py \
   $(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 \
   $(topsrcdir)/testing/mozbase/mozdevice/mozdevice/devicemanagerSUT.py \
   $(topsrcdir)/testing/mozbase/mozdevice/mozdevice/droid.py \
   $(topsrcdir)/testing/mozbase/mozdevice/mozdevice/version_codes.py \
   $(topsrcdir)/testing/mozbase/mozdevice/mozdevice/Zeroconf.py \
   $(topsrcdir)/testing/mozbase/moznetwork/moznetwork/moznetwork.py \
--- a/layout/tools/reftest/jar.mn
+++ b/layout/tools/reftest/jar.mn
@@ -1,10 +1,11 @@
 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
 *  content/reftest.js (reftest.js)
   content/reftest.xul (reftest.xul)
 #endif
--- a/layout/tools/reftest/mach_commands.py
+++ b/layout/tools/reftest/mach_commands.py
@@ -198,18 +198,16 @@ class ReftestRunner(MozbuildObject):
         if kwargs["suite"] == "jstestbrowser":
             kwargs["extraProfileFiles"].append(os.path.join(self.topobjdir, "dist",
                                                             "test-stage", "jsreftest",
                                                             "tests", "user.js"))
 
         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)
         finally:
             self.log_manager.disable_unstructured()
 
         return rv
 
new file mode 100644
--- /dev/null
+++ b/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)
--- a/layout/tools/reftest/reftest.js
+++ b/layout/tools/reftest/reftest.js
@@ -33,16 +33,17 @@ const NS_XREAPPINFO_CONTRACTID =
           "@mozilla.org/xre/app-info;1";
 const NS_DIRECTORY_SERVICE_CONTRACTID =
           "@mozilla.org/file/directory_service;1";
 const NS_OBSERVER_SERVICE_CONTRACTID =
           "@mozilla.org/observer-service;1";
 
 CU.import("resource://gre/modules/FileUtils.jsm");
 CU.import("chrome://reftest/content/httpd.jsm", this);
+CU.import("chrome://reftest/content/StructuredLog.jsm", this);
 CU.import("resource://gre/modules/Services.jsm");
 CU.import("resource://gre/modules/NetUtil.jsm");
 
 var gLoadTimeout = 0;
 var gTimeoutHook = null;
 var gRemote = false;
 var gIgnoreWindowSize = false;
 var gShuffle = false;
@@ -94,16 +95,17 @@ var gTestResults = {
   Random : 0,
   Skip: 0,
   Slow: 0,
 };
 var gTotalTests = 0;
 var gState;
 var gCurrentURL;
 var gTestLog = [];
+var gLogLevel;
 var gServer;
 var gCount = 0;
 var gAssertionCount = 0;
 
 var gIOService;
 var gDebug;
 var gWindowUtils;
 
@@ -158,53 +160,51 @@ var gHttpServerPort = -1;
 // whether to run slow tests or not
 var gRunSlowTests = true;
 
 // whether we should skip caching canvases
 var gNoCanvasCache = false;
 
 var gRecycledCanvases = new Array();
 
-// By default we just log to stdout
-var gDumpLog = dump;
-var gVerbose = false;
-
 // Only dump the sandbox once, because it doesn't depend on the
 // manifest URL (yet!).
 var gDumpedConditionSandbox = false;
 
 function HasUnexpectedResult()
 {
     return gTestResults.Exception > 0 ||
            gTestResults.FailedLoad > 0 ||
            gTestResults.UnexpectedFail > 0 ||
            gTestResults.UnexpectedPass > 0 ||
            gTestResults.AssertionUnexpected > 0 ||
            gTestResults.AssertionUnexpectedFixed > 0;
 }
 
-function LogWarning(str)
+// By default we just log to stdout
+var gDumpFn = dump;
+var gDumpRawLog = function(record) {
+  // Dump JSON representation of data on a single line
+  var line = JSON.stringify(record);
+  gDumpFn("\n" + line + "\n");
+}
+var logger = new StructuredLogger('reftest', gDumpRawLog);
+
+function TestBuffer(str)
 {
-    gDumpLog("REFTEST INFO | " + str + "\n");
+    logger.debug(str);
     gTestLog.push(str);
 }
 
-function LogInfo(str)
+function FlushTestBuffer()
 {
-    if (gVerbose)
-        gDumpLog("REFTEST INFO | " + str + "\n");
-    gTestLog.push(str);
-}
-
-function FlushTestLog()
-{
-    if (!gVerbose) {
-        // In verbose mode, we've dumped all these messages already.
+    // In debug mode, we've dumped all these messages already.
+    if (gLogLevel !== 'debug') {
         for (var i = 0; i < gTestLog.length; ++i) {
-            gDumpLog("REFTEST INFO | Saved log: " + gTestLog[i] + "\n");
+            logger.info("Saved log: " + gTestLog[i]);
         }
     }
     gTestLog = [];
 }
 
 function AllocateCanvas()
 {
     if (gRecycledCanvases.length > 0)
@@ -239,30 +239,29 @@ function getTestPlugin(aName) {
   var tags = ph.getPluginTags();
 
   // Find the test plugin
   for (var i = 0; i < tags.length; i++) {
     if (tags[i].name == aName)
       return tags[i];
   }
 
-  LogWarning("Failed to find the test-plugin.");
+  logger.warning("Failed to find the test-plugin.");
   return null;
 }
 
 this.OnRefTestLoad = function OnRefTestLoad(win)
 {
     gCrashDumpDir = CC[NS_DIRECTORY_SERVICE_CONTRACTID]
                     .getService(CI.nsIProperties)
                     .get("ProfD", CI.nsIFile);
     gCrashDumpDir.append("minidumps");
 
     var env = CC["@mozilla.org/process/environment;1"].
               getService(CI.nsIEnvironment);
-    gVerbose = !!env.get("MOZ_REFTEST_VERBOSE");
 
     var prefs = Components.classes["@mozilla.org/preferences-service;1"].
                 getService(Components.interfaces.nsIPrefBranch);
     try {
         gBrowserIsRemote = prefs.getBoolPref("browser.tabs.remote.autostart");
     } catch (e) {
         gBrowserIsRemote = false;
     }
@@ -274,16 +273,22 @@ this.OnRefTestLoad = function OnRefTestL
     }
 
     try {
       gBrowserIsIframe = prefs.getBoolPref("reftest.browser.iframe.enabled");
     } catch (e) {
       gBrowserIsIframe = false;
     }
 
+    try {
+      gLogLevel = prefs.getCharPref("reftest.logLevel");
+    } catch (e) {
+      gLogLevel ='info';
+    }
+
     if (win === undefined || win == null) {
       win = window;
     }
     if (gContainingWindow == null && win != null) {
       gContainingWindow = win;
     }
 
     if (gBrowserIsIframe) {
@@ -317,34 +322,34 @@ this.OnRefTestLoad = function OnRefTestL
     // reftests should have the test plugins enabled, not click-to-play
     let plugin1 = getTestPlugin("Test Plug-in");
     let plugin2 = getTestPlugin("Second Test Plug-in");
     if (plugin1 && plugin2) {
       gTestPluginEnabledStates = [plugin1.enabledState, plugin2.enabledState];
       plugin1.enabledState = CI.nsIPluginTag.STATE_ENABLED;
       plugin2.enabledState = CI.nsIPluginTag.STATE_ENABLED;
     } else {
-      LogWarning("Could not get test plugin tags.");
+      logger.warning("Could not get test plugin tags.");
     }
 
     gBrowserMessageManager = gBrowser.QueryInterface(CI.nsIFrameLoaderOwner)
                                      .frameLoader.messageManager;
     // The content script waits for the initial onload, then notifies
     // us.
     RegisterMessageListenersAndLoadContentScript();
 }
 
 function InitAndStartRefTests()
 {
     /* These prefs are optional, so we don't need to spit an error to the log */
     try {
         var prefs = Components.classes["@mozilla.org/preferences-service;1"].
                     getService(Components.interfaces.nsIPrefBranch);
     } catch(e) {
-        gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | | EXCEPTION: " + e + "\n");
+        logger.error("EXCEPTION: " + e);
     }
 
     try {
       prefs.setBoolPref("android.widget_paints_background", false);
     } catch (e) {}
 
     /* set the gLoadTimeout */
     try {
@@ -356,32 +361,32 @@ function InitAndStartRefTests()
     /* Get the logfile for android tests */
     try {
         var logFile = prefs.getCharPref("reftest.logFile");
         if (logFile) {
             try {
                 var f = FileUtils.File(logFile);
                 var mfl = FileUtils.openFileOutputStream(f, FileUtils.MODE_WRONLY | FileUtils.MODE_CREATE);
                 // Set to mirror to stdout as well as the file
-                gDumpLog = function (msg) {
+                gDumpFn = function (msg) {
 #ifdef BOOTSTRAP
 #ifdef REFTEST_B2G
                     dump(msg);
 #else
                     //NOTE: on android-xul, we have a libc crash if we do a dump with %7s in the string
 #endif
 #else
                     dump(msg);
 #endif
                     mfl.write(msg, msg.length);
                 };
             }
             catch(e) {
                 // If there is a problem, just use stdout
-                gDumpLog = dump;
+                gDumpFn = dump;
             }
         }
     } catch(e) {}
 
     try {
         gRemote = prefs.getBoolPref("reftest.remote");
     } catch(e) {
         gRemote = false;
@@ -422,17 +427,17 @@ function InitAndStartRefTests()
         gServer = new HttpServer();
     }
     try {
         if (gServer)
             StartHTTPServer();
     } catch (ex) {
         //gBrowser.loadURI('data:text/plain,' + ex);
         ++gTestResults.Exception;
-        gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | | EXCEPTION: " + ex + "\n");
+        logger.error("EXCEPTION: " + ex);
         DoneTests();
     }
 
     // Focus the content browser.
     if (gFocusFilterMode != FOCUS_FILTER_NON_NEEDS_FOCUS_TESTS) {
         gBrowser.focus();
     }
 
@@ -460,17 +465,17 @@ function Shuffle(array)
 function StartTests()
 {
     var manifests;
     /* These prefs are optional, so we don't need to spit an error to the log */
     try {
         var prefs = Components.classes["@mozilla.org/preferences-service;1"].
                     getService(Components.interfaces.nsIPrefBranch);
     } catch(e) {
-        gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | | EXCEPTION: " + e + "\n");
+        logger.error("EXCEPTION: " + e);
     }
 
     try {
         gNoCanvasCache = prefs.getIntPref("reftest.nocache");
     } catch(e) {
         gNoCanvasCache = false;
     }
 
@@ -508,97 +513,99 @@ function StartTests()
 
     gURLs = [];
     gManifestsLoaded = {};
 
     try {
         var manifests = JSON.parse(prefs.getCharPref("reftest.manifests"));
         gURLFilterRegex = manifests[null];
     } catch(e) {
-        gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | | Unable to find reftest.manifests pref.  Please ensure your profile is setup properly\n");
+        logger.error("Unable to find reftest.manifests pref.  Please ensure your profile is setup properly");
         DoneTests();
     }
 
     try {
         var globalFilter = manifests.hasOwnProperty("") ? new RegExp(manifests[""]) : null;
         var manifestURLs = Object.keys(manifests);
 
         // Ensure we read manifests from higher up the directory tree first so that we
         // process includes before reading the included manifest again
         manifestURLs.sort(function(a,b) {return a.length - b.length})
         manifestURLs.forEach(function(manifestURL) {
-            gDumpLog("Reading manifest " + manifestURL + "\n");
+            logger.info("Reading manifest " + manifestURL);
             var filter = manifests[manifestURL] ? new RegExp(manifests[manifestURL]) : null;
             ReadTopManifest(manifestURL, [globalFilter, filter, false]);
         });
         BuildUseCounts();
 
         // Filter tests which will be skipped to get a more even distribution when chunking
         // tURLs is a temporary array containing all active tests
         var tURLs = new Array();
+        var tIDs = new Array();
         for (var i = 0; i < gURLs.length; ++i) {
             if (gURLs[i].expected == EXPECTED_DEATH)
                 continue;
 
             if (gURLs[i].needsFocus && !Focus())
                 continue;
 
             if (gURLs[i].slow && !gRunSlowTests)
                 continue;
 
             tURLs.push(gURLs[i]);
+            tIDs.push(gURLs[i].identifier);
         }
 
-        gDumpLog("REFTEST INFO | Discovered " + gURLs.length + " tests, after filtering SKIP tests, we have " + tURLs.length + "\n");
+        logger.suiteStart(tIDs, {"skipped": gURLs.length - tURLs.length});
 
         if (gTotalChunks > 0 && gThisChunk > 0) {
             // Calculate start and end indices of this chunk if tURLs array were
             // divided evenly
             var testsPerChunk = tURLs.length / gTotalChunks;
             var start = Math.round((gThisChunk-1) * testsPerChunk);
             var end = Math.round(gThisChunk * testsPerChunk);
 
             // Map these indices onto the gURLs array. This avoids modifying the
             // gURLs array which prevents skipped tests from showing up in the log
             start = gThisChunk == 1 ? 0 : gURLs.indexOf(tURLs[start]);
             end = gThisChunk == gTotalChunks ? gURLs.length : gURLs.indexOf(tURLs[end + 1]) - 1;
             gURLs = gURLs.slice(start, end);
 
-            gDumpLog("REFTEST INFO | Running chunk " + gThisChunk + " out of " + gTotalChunks + " chunks.  ");
-            gDumpLog("tests " + (start+1) + "-" + end + "/" + gURLs.length + "\n");
+            logger.info("Running chunk " + gThisChunk + " out of " + gTotalChunks + " chunks.  " +
+                "tests " + (start+1) + "-" + end + "/" + gURLs.length);
         }
 
         if (gShuffle) {
             Shuffle(gURLs);
         }
 
         gTotalTests = gURLs.length;
 
         if (!gTotalTests)
             throw "No tests to run";
 
         gURICanvases = {};
         StartCurrentTest();
     } catch (ex) {
         //gBrowser.loadURI('data:text/plain,' + ex);
         ++gTestResults.Exception;
-        gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | | EXCEPTION: " + ex + "\n");
+        logger.error("EXCEPTION: " + ex);
         DoneTests();
     }
 }
 
 function OnRefTestUnload()
 {
   let plugin1 = getTestPlugin("Test Plug-in");
   let plugin2 = getTestPlugin("Second Test Plug-in");
   if (plugin1 && plugin2) {
     plugin1.enabledState = gTestPluginEnabledStates[0];
     plugin2.enabledState = gTestPluginEnabledStates[1];
   } else {
-    LogWarning("Failed to get test plugin tags.");
+    logger.warning("Failed to get test plugin tags.");
   }
 }
 
 // Read all available data from an input stream and return it
 // as a string.
 function getStreamContent(inputStream)
 {
     var streamBuf = "";
@@ -744,18 +751,18 @@ function BuildConditionSandbox(aURL) {
     }
     try {
         sandbox.asyncZoom = sandbox.asyncPan && prefs.getBoolPref("apz.allow_zooming");
     } catch (e) {
         sandbox.asyncZoom = false;
     }
 
     if (!gDumpedConditionSandbox) {
-        dump("REFTEST INFO | Dumping JSON representation of sandbox \n");
-        dump("REFTEST INFO | " + JSON.stringify(CU.waiveXrays(sandbox)) + " \n");
+        logger.info("Dumping JSON representation of sandbox");
+        logger.info(JSON.stringify(CU.waiveXrays(sandbox)));
         gDumpedConditionSandbox = true;
     }
 
     // Graphics features
     sandbox.usesRepeatResampling = sandbox.d2d;
     return sandbox;
 }
 
@@ -806,16 +813,22 @@ function AddTestItem(aTest, aFilter)
          !(invertManifest ^ manifestFilter.test(aTest.url1.spec))))
         return;
     if (gFocusFilterMode == FOCUS_FILTER_NEEDS_FOCUS_TESTS &&
         !aTest.needsFocus)
         return;
     if (gFocusFilterMode == FOCUS_FILTER_NON_NEEDS_FOCUS_TESTS &&
         aTest.needsFocus)
         return;
+
+    if (aTest.url2 !== null)
+        aTest.identifier = [aTest.prettyPath, aTest.type, aTest.url2.spec];
+    else
+        aTest.identifier = aTest.prettyPath;
+
     gURLs.push(aTest);
 }
 
 // Note: If you materially change the reftest manifest parsing,
 // please keep the parser in print-manifest-dirs.py in sync.
 function ReadManifest(aURL, inherited_status, aFilter)
 {
     // Ensure each manifest is only read once. This assumes that manifests that are
@@ -832,18 +845,17 @@ function ReadManifest(aURL, inherited_st
     var secMan = CC[NS_SCRIPTSECURITYMANAGER_CONTRACTID]
                      .getService(CI.nsIScriptSecurityManager);
 
     var listURL = aURL;
     var channel = NetUtil.newChannel({uri: aURL, loadUsingSystemPrincipal: true});
     var inputStream = channel.open2();
     if (channel instanceof Components.interfaces.nsIHttpChannel
         && channel.responseStatus != 200) {
-      gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | | HTTP ERROR : " +
-        channel.responseStatus + "\n");
+      logger.error("HTTP ERROR : " + channel.responseStatus);
     }
     var streamBuf = getStreamContent(inputStream);
     inputStream.close();
     var lines = streamBuf.split(/\n|\r|\r\n/);
 
     // Build the sandbox for fails-if(), etc., condition evaluation.
     var sandbox = BuildConditionSandbox(aURL);
     var lineNo = 0;
@@ -1233,45 +1245,45 @@ function Blur()
 
 function StartCurrentTest()
 {
     gTestLog = [];
 
     // make sure we don't run tests that are expected to kill the browser
     while (gURLs.length > 0) {
         var test = gURLs[0];
+        logger.testStart(test.identifier);
         if (test.expected == EXPECTED_DEATH) {
             ++gTestResults.Skip;
-            gDumpLog("REFTEST TEST-KNOWN-FAIL | " + test.url1.spec + " | (SKIP)\n");
+            logger.testEnd(test.identifier, "SKIP");
             gURLs.shift();
         } else if (test.needsFocus && !Focus()) {
             // FIXME: Marking this as a known fail is dangerous!  What
             // if it starts failing all the time?
             ++gTestResults.Skip;
-            gDumpLog("REFTEST TEST-KNOWN-FAIL | " + test.url1.spec + " | (SKIPPED; COULDN'T GET FOCUS)\n");
+            logger.testEnd(test.identifier, "SKIP", null, "(COULDN'T GET FOCUS)");
             gURLs.shift();
         } else if (test.slow && !gRunSlowTests) {
             ++gTestResults.Slow;
-            gDumpLog("REFTEST TEST-KNOWN-SLOW | " + test.url1.spec + " | (SLOW)\n");
+            logger.testEnd(test.identifier, "SKIP", null, "(SLOW)");
             gURLs.shift();
         } else {
             break;
         }
     }
 
     if ((gURLs.length == 0 && gRepeat == 0) ||
         (gRunUntilFailure && HasUnexpectedResult())) {
         RestoreChangedPreferences();
         DoneTests();
     } else if (gURLs.length == 0 && gRepeat > 0) {
         // Repeat
         gRepeat--;
         StartTests();
     } else {
-        gDumpLog("REFTEST TEST-START | " + gURLs[0].prettyPath + "\n");
         if (gURLs[0].chaosMode) {
             gWindowUtils.enterChaosMode();
         }
         if (!gURLs[0].needsFocus) {
             Blur();
         }
         var currentTest = gTotalTests - gURLs.length;
         gContainingWindow.document.title = "reftest: " + currentTest + " / " + gTotalTests +
@@ -1327,99 +1339,72 @@ function StartCurrentURI(aState)
                     if (ps.type == PREF_BOOLEAN) {
                         prefs.setBoolPref(ps.name, value);
                     } else if (ps.type == PREF_STRING) {
                         prefs.setCharPref(ps.name, value);
                         value = '"' + value + '"';
                     } else if (ps.type == PREF_INTEGER) {
                         prefs.setIntPref(ps.name, value);
                     }
-                    gDumpLog("SET PREFERENCE pref(" + ps.name + "," + value + ")\n");
+                    logger.info("SET PREFERENCE pref(" + ps.name + "," + value + ")");
                 }
             });
         } catch (e) {
             if (e == "bad pref") {
                 var test = gURLs[0];
                 if (test.expected == EXPECTED_FAIL) {
-                    gDumpLog("REFTEST TEST-KNOWN-FAIL | " + test.url1.spec +
-                             " | (SKIPPED; " + badPref + " not known or wrong type)\n");
+                    logger.testEnd(test.identifier, "FAIL", "FAIL",
+                                   "(SKIPPED; " + badPref + " not known or wrong type)");
                     ++gTestResults.Skip;
                 } else {
-                    gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | " + test.url1.spec +
-                             " | " + badPref + " not known or wrong type\n");
+                    logger.testEnd(test.identifier, "FAIL", "PASS",
+                                   badPref + " not known or wrong type");
                     ++gTestResults.UnexpectedFail;
                 }
+
+                // skip the test that had a bad preference
+                gURLs.shift();
+                StartCurrentTest();
+                return;
             } else {
                 throw e;
             }
         }
-        if (badPref != undefined) {
-            // skip the test that had a bad preference
-            gURLs.shift();
-
-            StartCurrentTest();
-            return;
-        }
     }
 
     if (prefSettings.length == 0 &&
         gURICanvases[gCurrentURL] &&
         (gURLs[0].type == TYPE_REFTEST_EQUAL ||
          gURLs[0].type == TYPE_REFTEST_NOTEQUAL) &&
         gURLs[0].maxAsserts == 0) {
         // Pretend the document loaded --- RecordResult will notice
         // there's already a canvas for this URL
         gContainingWindow.setTimeout(RecordResult, 0);
     } else {
         var currentTest = gTotalTests - gURLs.length;
-        gDumpLog("REFTEST TEST-LOAD | " + gCurrentURL + " | " + currentTest + " / " + gTotalTests +
-            " (" + Math.floor(100 * (currentTest / gTotalTests)) + "%)\n");
-        LogInfo("START " + gCurrentURL);
+        // Log this to preserve the same overall log format,
+        // should be removed if the format is updated
+        gDumpFn("REFTEST TEST-LOAD | " + gCurrentURL + " | " + currentTest + " / " + gTotalTests +
+                " (" + Math.floor(100 * (currentTest / gTotalTests)) + "%)\n");
+        TestBuffer("START " + gCurrentURL);
         var type = gURLs[0].type
         if (TYPE_SCRIPT == type) {
             SendLoadScriptTest(gCurrentURL, gLoadTimeout);
         } else {
             SendLoadTest(type, gCurrentURL, gLoadTimeout);
         }
     }
 }
 
 function DoneTests()
 {
-    gDumpLog("REFTEST FINISHED: Slowest test took " + gSlowestTestTime +
-         "ms (" + gSlowestTestURL + ")\n");
+    logger.suiteEnd(extra={'results': gTestResults});
+    logger.info("Slowest test took " + gSlowestTestTime + "ms (" + gSlowestTestURL + ")");
+    logger.info("Total canvas count = " + gRecycledCanvases.length);
 
-    gDumpLog("REFTEST INFO | Result summary:\n");
-    var count = gTestResults.Pass + gTestResults.LoadOnly;
-    gDumpLog("REFTEST INFO | Successful: " + count + " (" +
-             gTestResults.Pass + " pass, " +
-             gTestResults.LoadOnly + " load only)\n");
-    count = gTestResults.Exception + gTestResults.FailedLoad +
-            gTestResults.UnexpectedFail + gTestResults.UnexpectedPass +
-            gTestResults.AssertionUnexpected +
-            gTestResults.AssertionUnexpectedFixed;
-    gDumpLog("REFTEST INFO | Unexpected: " + count + " (" +
-             gTestResults.UnexpectedFail + " unexpected fail, " +
-             gTestResults.UnexpectedPass + " unexpected pass, " +
-             gTestResults.AssertionUnexpected + " unexpected asserts, " +
-             gTestResults.AssertionUnexpectedFixed + " unexpected fixed asserts, " +
-             gTestResults.FailedLoad + " failed load, " +
-             gTestResults.Exception + " exception)\n");
-    count = gTestResults.KnownFail + gTestResults.AssertionKnown +
-            gTestResults.Random + gTestResults.Skip + gTestResults.Slow;
-    gDumpLog("REFTEST INFO | Known problems: " + count + " (" +
-             gTestResults.KnownFail + " known fail, " +
-             gTestResults.AssertionKnown + " known asserts, " +
-             gTestResults.Random + " random, " +
-             gTestResults.Skip + " skipped, " +
-             gTestResults.Slow + " slow)\n");
-
-    gDumpLog("REFTEST INFO | Total canvas count = " + gRecycledCanvases.length + "\n");
-
-    gDumpLog("REFTEST TEST-START | Shutdown\n");
     function onStopped() {
         let appStartup = CC["@mozilla.org/toolkit/app-startup;1"].getService(CI.nsIAppStartup);
         appStartup.quit(CI.nsIAppStartup.eForceQuit);
     }
     if (gServer) {
         gServer.stop(onStopped);
     }
     else {
@@ -1457,45 +1442,44 @@ function DoDrawWindow(ctx, x, y, w, h)
          0 <= testRect.top &&
          gContainingWindow.innerWidth >= testRect.right &&
          gContainingWindow.innerHeight >= testRect.bottom)) {
         // We can use the window's retained layer manager
         // because the window is big enough to display the entire
         // browser element
         flags |= ctx.DRAWWINDOW_USE_WIDGET_LAYERS;
     } else if (gBrowserIsRemote) {
-        gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | " + gCurrentURL + " | can't drawWindow remote content\n");
+        logger.error(gCurrentURL + " | can't drawWindow remote content");
         ++gTestResults.Exception;
     }
 
     if (gDrawWindowFlags != flags) {
         // Every time the flags change, dump the new state.
         gDrawWindowFlags = flags;
         var flagsStr = "DRAWWINDOW_DRAW_CARET | DRAWWINDOW_DRAW_VIEW";
         if (flags & ctx.DRAWWINDOW_USE_WIDGET_LAYERS) {
             flagsStr += " | DRAWWINDOW_USE_WIDGET_LAYERS";
         } else {
             // Output a special warning because we need to be able to detect
             // this whenever it happens.
-            gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | WARNING: USE_WIDGET_LAYERS disabled\n");
+            logger.error("WARNING: USE_WIDGET_LAYERS disabled");
         }
-        gDumpLog("REFTEST INFO | drawWindow flags = " + flagsStr +
-                 "; window size = " + gContainingWindow.innerWidth + "," + gContainingWindow.innerHeight +
-                 "; test browser size = " + testRect.width + "," + testRect.height +
-                 "\n");
+        logger.info("drawWindow flags = " + flagsStr +
+                    "; window size = " + gContainingWindow.innerWidth + "," + gContainingWindow.innerHeight +
+                    "; test browser size = " + testRect.width + "," + testRect.height);
     }
 
-    LogInfo("DoDrawWindow " + x + "," + y + "," + w + "," + h);
+    TestBuffer("DoDrawWindow " + x + "," + y + "," + w + "," + h);
     ctx.drawWindow(gContainingWindow, x, y, w, h, "rgb(255,255,255)",
                    gDrawWindowFlags);
 }
 
 function InitCurrentCanvasWithSnapshot()
 {
-    LogInfo("Initializing canvas snapshot");
+    TestBuffer("Initializing canvas snapshot");
 
     if (gURLs[0].type == TYPE_LOAD || gURLs[0].type == TYPE_SCRIPT) {
         // We don't want to snapshot this kind of test
         return false;
     }
 
     if (!gCurrentCanvas) {
         gCurrentCanvas = AllocateCanvas();
@@ -1503,17 +1487,17 @@ function InitCurrentCanvasWithSnapshot()
 
     var ctx = gCurrentCanvas.getContext("2d");
     DoDrawWindow(ctx, 0, 0, gCurrentCanvas.width, gCurrentCanvas.height);
     return true;
 }
 
 function UpdateCurrentCanvasForInvalidation(rects)
 {
-    LogInfo("Updating canvas for invalidation");
+    TestBuffer("Updating canvas for invalidation");
 
     if (!gCurrentCanvas) {
         return;
     }
 
     var ctx = gCurrentCanvas.getContext("2d");
     for (var i = 0; i < rects.length; ++i) {
         var r = rects[i];
@@ -1533,58 +1517,58 @@ function UpdateCurrentCanvasForInvalidat
         ctx.translate(left, top);
         DoDrawWindow(ctx, left, top, right - left, bottom - top);
         ctx.restore();
     }
 }
 
 function UpdateWholeCurrentCanvasForInvalidation()
 {
-    LogInfo("Updating entire canvas for invalidation");
+    TestBuffer("Updating entire canvas for invalidation");
 
     if (!gCurrentCanvas) {
         return;
     }
 
     var ctx = gCurrentCanvas.getContext("2d");
     DoDrawWindow(ctx, 0, 0, gCurrentCanvas.width, gCurrentCanvas.height);
 }
 
 function RecordResult(testRunTime, errorMsg, scriptResults)
 {
-    LogInfo("RecordResult fired");
+    TestBuffer("RecordResult fired");
 
     // Keep track of which test was slowest, and how long it took.
     if (testRunTime > gSlowestTestTime) {
         gSlowestTestTime = testRunTime;
         gSlowestTestURL  = gCurrentURL;
     }
 
     // Not 'const ...' because of 'EXPECTED_*' value dependency.
     var outputs = {};
-    const randomMsg = "(EXPECTED RANDOM)";
     outputs[EXPECTED_PASS] = {
-        true:  {s: "TEST-PASS"                  , n: "Pass"},
-        false: {s: "TEST-UNEXPECTED-FAIL"       , n: "UnexpectedFail"}
+        true:  {s: ["PASS", "PASS"], n: "Pass"},
+        false: {s: ["FAIL", "PASS"], n: "UnexpectedFail"}
     };
     outputs[EXPECTED_FAIL] = {
-        true:  {s: "TEST-UNEXPECTED-PASS"       , n: "UnexpectedPass"},
-        false: {s: "TEST-KNOWN-FAIL"            , n: "KnownFail"}
+        true:  {s: ["PASS", "FAIL"], n: "UnexpectedPass"},
+        false: {s: ["FAIL", "FAIL"], n: "KnownFail"}
     };
     outputs[EXPECTED_RANDOM] = {
-        true:  {s: "TEST-PASS" + randomMsg      , n: "Random"},
-        false: {s: "TEST-KNOWN-FAIL" + randomMsg, n: "Random"}
+        true:  {s: ["PASS", "PASS"], n: "Random"},
+        false: {s: ["FAIL", "FAIL"], n: "Random"}
     };
     outputs[EXPECTED_FUZZY] = outputs[EXPECTED_PASS];
 
     var output;
+    var extra;
 
     if (gURLs[0].type == TYPE_LOAD) {
         ++gTestResults.LoadOnly;
-        gDumpLog("REFTEST TEST-PASS | " + gURLs[0].prettyPath + " | (LOAD ONLY)\n");
+        logger.testEnd(gURLs[0].identifier, "PASS", "PASS", "(LOAD ONLY)");
         gCurrentCanvas = null;
         FinishTestItem();
         return;
     }
     if (gURLs[0].type == TYPE_SCRIPT) {
         var expected = gURLs[0].expected;
 
         if (errorMsg) {
@@ -1592,27 +1576,24 @@ function RecordResult(testRunTime, error
             expected = EXPECTED_PASS;
         } else if (scriptResults.length == 0) {
              // This failure may be due to a JavaScript Engine bug causing
              // early termination of the test. If we do not allow silent
              // failure, report an error.
              if (!gURLs[0].allowSilentFail)
                  errorMsg = "No test results reported. (SCRIPT)\n";
              else
-                 gDumpLog("REFTEST INFO | An expected silent failure occurred \n");
+                 logger.info("An expected silent failure occurred");
         }
 
         if (errorMsg) {
             output = outputs[expected][false];
+            extra = { status_msg: output.n };
             ++gTestResults[output.n];
-            var result = "REFTEST " + output.s + " | " +
-                gURLs[0].prettyPath + " | " + // the URL being tested
-                errorMsg;
-
-            gDumpLog(result);
+            logger.testEnd(gURLs[0].identifier, output.s[0], output.s[1], errorMsg, null, extra);
             FinishTestItem();
             return;
         }
 
         var anyFailed = scriptResults.some(function(result) { return !result.passed; });
         var outputPair;
         if (anyFailed && expected == EXPECTED_FAIL) {
             // If we're marked as expected to fail, and some (but not all) tests
@@ -1622,38 +1603,37 @@ function RecordResult(testRunTime, error
             outputPair = { true: outputs[EXPECTED_RANDOM][true],
                            false: outputs[expected][false] };
         } else {
             outputPair = outputs[expected];
         }
         var index = 0;
         scriptResults.forEach(function(result) {
                 var output = outputPair[result.passed];
+                var extra = { status_msg: output.n };
 
                 ++gTestResults[output.n];
-                result = "REFTEST " + output.s + " | " +
-                    gURLs[0].prettyPath + " | " + // the URL being tested
-                    result.description + " item " + (++index) + "\n";
-                gDumpLog(result);
+                logger.testEnd(gURLs[0].identifier, output.s[0], output.s[1],
+                               result.description + " item " + (++index), null, extra);
             });
 
         if (anyFailed && expected == EXPECTED_PASS) {
-            FlushTestLog();
+            FlushTestBuffer();
         }
 
         FinishTestItem();
         return;
     }
 
     if (gURLs[0]["prefSettings" + gState].length == 0 &&
         gURICanvases[gCurrentURL]) {
         gCurrentCanvas = gURICanvases[gCurrentURL];
     }
     if (gCurrentCanvas == null) {
-        gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | " + gCurrentURL + " | program error managing snapshots\n");
+        logger.error(gCurrentURL, "program error managing snapshots");
         ++gTestResults.Exception;
     }
     if (gState == 1) {
         gCanvas1 = gCurrentCanvas;
     } else {
         gCanvas2 = gCurrentCanvas;
     }
     gCurrentCanvas = null;
@@ -1686,25 +1666,26 @@ function RecordResult(testRunTime, error
             var expected = gURLs[0].expected;
 
             if (maxDifference.value > 0 && maxDifference.value <= gURLs[0].fuzzyMaxDelta &&
                 differences <= gURLs[0].fuzzyMaxPixels) {
                 if (equal) {
                     throw "Inconsistent result from compareCanvases.";
                 }
                 equal = expected == EXPECTED_FUZZY;
-                gDumpLog("REFTEST fuzzy match\n");
+                logger.info("REFTEST fuzzy match");
             }
 
             var failedExtraCheck = gFailedNoPaint || gFailedOpaqueLayer || gFailedAssignedLayer;
 
             // whether the comparison result matches what is in the manifest
             var test_passed = (equal == (gURLs[0].type == TYPE_REFTEST_EQUAL)) && !failedExtraCheck;
 
             output = outputs[expected][test_passed];
+            extra = { status_msg: output.n };
 
             ++gTestResults[output.n];
 
             // It's possible that we failed both an "extra check" and the normal comparison, but we don't
             // have a way to annotate these separately, so just print an error for the extra check failures.
             if (failedExtraCheck) {
                 var failures = [];
                 if (gFailedNoPaint) {
@@ -1713,81 +1694,62 @@ function RecordResult(testRunTime, error
                 // The gFailed*Messages arrays will contain messages from both the test and the reference.
                 if (gFailedOpaqueLayer) {
                     failures.push("failed reftest-opaque-layer: " + gFailedOpaqueLayerMessages.join(", "));
                 }
                 if (gFailedAssignedLayer) {
                     failures.push("failed reftest-assigned-layer: " + gFailedAssignedLayerMessages.join(", "));
                 }
                 var failureString = failures.join(", ");
-                if (expected == EXPECTED_FAIL) {
-                    gDumpLog("REFTEST TEST-KNOWN-FAIL | " + gURLs[0].prettyPath + " | " + failureString + "\n");
-                } else {
-                    gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | " + gURLs[0].prettyPath + " | " + failureString + "\n");
-                }
+                logger.testEnd(gURLs[0].identifier, output.s[0], output.s[1], failureString, null, extra);
             } else {
-                var result = "REFTEST " + output.s + " | " +
-                             gURLs[0].prettyPath + " | "; // the URL being tested
-                switch (gURLs[0].type) {
-                    case TYPE_REFTEST_NOTEQUAL:
-                        result += "image comparison (!=)";
-                        break;
-                    case TYPE_REFTEST_EQUAL:
-                        result += "image comparison (==)";
-                        break;
-                }
-
                 if (!test_passed && expected == EXPECTED_PASS ||
                     !test_passed && expected == EXPECTED_FUZZY ||
                     test_passed && expected == EXPECTED_FAIL) {
                     if (!equal) {
-                        result += ", max difference: " + maxDifference.value + ", number of differing pixels: " + differences + "\n";
-                        result += "REFTEST   IMAGE 1 (TEST): " + gCanvas1.toDataURL() + "\n";
-                        result += "REFTEST   IMAGE 2 (REFERENCE): " + gCanvas2.toDataURL() + "\n";
+                        extra.max_difference = maxDifference.value;
+                        extra.differences = differences;
+                        extra.image1 = gCanvas1.toDataURL();
+                        extra.image2 = gCanvas2.toDataURL();
                     } else {
-                        result += "\n";
-                        result += "REFTEST   IMAGE: " + gCanvas1.toDataURL() + "\n";
+                        extra.image1 = gCanvas1.toDataURL();
                     }
-                } else {
-                    result += "\n";
                 }
-
-                gDumpLog(result);
+                logger.testEnd(gURLs[0].identifier, output.s[0], output.s[1], null, null, extra);
 
                 if (gURLs[0].prefSettings1.length == 0) {
                     UpdateCanvasCache(gURLs[0].url1, gCanvas1);
                 }
                 if (gURLs[0].prefSettings2.length == 0) {
                     UpdateCanvasCache(gURLs[0].url2, gCanvas2);
                 }
             }
 
             if ((!test_passed && expected == EXPECTED_PASS) || (test_passed && expected == EXPECTED_FAIL)) {
-                FlushTestLog();
+                FlushTestBuffer();
             }
 
             CleanUpCrashDumpFiles();
             FinishTestItem();
             break;
         default:
             throw "Unexpected state.";
     }
 }
 
 function LoadFailed(why)
 {
     ++gTestResults.FailedLoad;
     // Once bug 896840 is fixed, this can go away, but for now it will give log
     // output that is TBPL starable for bug 789751 and bug 720452.
     if (!why) {
-        gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | load failed with unknown reason\n");
+        logger.error("load failed with unknown reason");
     }
-    gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | " +
-         gURLs[0]["url" + gState].spec + " | load failed: " + why + "\n");
-    FlushTestLog();
+    logger.testEnd(gURLs[0]["url" + gState].spec, "FAIL", "PASS", "load failed: " + why);
+    FlushTestBuffer();
     FinishTestItem();
 }
 
 function RemoveExpectedCrashDumpFiles()
 {
     if (gExpectingProcessCrash) {
         for (let crashFilename of gExpectedCrashDumpFiles) {
             let file = gCrashDumpDir.clone();
@@ -1814,38 +1776,36 @@ function FindUnexpectedCrashDumpFiles()
     let foundCrashDumpFile = false;
     while (entries.hasMoreElements()) {
         let file = entries.getNext().QueryInterface(CI.nsIFile);
         let path = String(file.path);
         if (path.match(/\.(dmp|extra)$/) && !gUnexpectedCrashDumpFiles[path]) {
             if (!foundCrashDumpFile) {
                 ++gTestResults.UnexpectedFail;
                 foundCrashDumpFile = true;
-                gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | " + gCurrentURL +
-                         " | This test left crash dumps behind, but we weren't expecting it to!\n");
+                logger.testEnd(gCurrentURL, "FAIL", "PASS", "This test left crash dumps behind, but we weren't expecting it to!");
             }
-            gDumpLog("REFTEST INFO | Found unexpected crash dump file " + path +
-                     ".\n");
+            logger.info("Found unexpected crash dump file " + path);
             gUnexpectedCrashDumpFiles[path] = true;
         }
     }
 }
 
 function CleanUpCrashDumpFiles()
 {
     RemoveExpectedCrashDumpFiles();
     FindUnexpectedCrashDumpFiles();
     gExpectingProcessCrash = false;
 }
 
 function FinishTestItem()
 {
     // Replace document with BLANK_URL_FOR_CLEARING in case there are
     // assertions when unloading.
-    gDumpLog("REFTEST INFO | Loading a blank page\n");
+    logger.debug("Loading a blank page");
     // After clearing, content will notify us of the assertion count
     // and tests will continue.
     SendClear();
     gFailedNoPaint = false;
     gFailedOpaqueLayer = false;
     gFailedOpaqueLayerMessages = [];
     gFailedAssignedLayer = false;
     gFailedAssignedLayerMessages = [];
@@ -1870,36 +1830,35 @@ function DoAssertionCheck(numAsserts)
         var expectedAssertions = "expected " + minAsserts;
         if (minAsserts != maxAsserts) {
             expectedAssertions += " to " + maxAsserts;
         }
         expectedAssertions += " assertions";
 
         if (numAsserts < minAsserts) {
             ++gTestResults.AssertionUnexpectedFixed;
-            gDumpLog("REFTEST TEST-UNEXPECTED-PASS | " + gURLs[0].prettyPath +
-                 " | assertion count " + numAsserts + " is less than " +
-                 expectedAssertions + "\n");
+            gDumpFn("REFTEST TEST-UNEXPECTED-PASS | " + gURLs[0].prettyPath +
+                    " | assertion count" + numAsserts + " is less than " +
+                    expectedAssertions + "\n");
         } else if (numAsserts > maxAsserts) {
             ++gTestResults.AssertionUnexpected;
-            gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | " + gURLs[0].prettyPath +
-                 " | assertion count " + numAsserts + " is more than " +
-                 expectedAssertions + "\n");
+            gDumpFn("REFTEST TEST-UNEXPECTED-FAIL | " + gURLs[0].prettyPath +
+                    " | assertion count " + numAsserts + " is more than " +
+                    expectedAssertions + "\n");
         } else if (numAsserts != 0) {
             ++gTestResults.AssertionKnown;
-            gDumpLog("REFTEST TEST-KNOWN-FAIL | " + gURLs[0].prettyPath +
-                 " | assertion count " + numAsserts + " matches " +
-                 expectedAssertions + "\n");
+            gDumpFn("REFTEST TEST-KNOWN-FAIL | " + gURLs[0].prettyPath +
+                    "assertion count " + numAsserts + " matches " +
+                    expectedAssertions + "\n");
         }
     }
 
     if (gURLs[0].chaosMode) {
         gWindowUtils.leaveChaosMode();
     }
-    gDumpLog("REFTEST TEST-END | " + gURLs[0].prettyPath + "\n");
 
     // And start the next test.
     gURLs.shift();
     StartCurrentTest();
 }
 
 function ResetRenderingState()
 {
@@ -1918,17 +1877,17 @@ function RestoreChangedPreferences()
             if (ps.type == PREF_BOOLEAN) {
                 prefs.setBoolPref(ps.name, value);
             } else if (ps.type == PREF_STRING) {
                 prefs.setCharPref(ps.name, value);
                 value = '"' + value + '"';
             } else if (ps.type == PREF_INTEGER) {
                 prefs.setIntPref(ps.name, value);
             }
-            gDumpLog("RESTORE PREFERENCE pref(" + ps.name + "," + value + ")\n");
+            logger.info("RESTORE PREFERENCE pref(" + ps.name + "," + value + ")");
         });
         gPrefsToRestore = [];
     }
 }
 
 function RegisterMessageListenersAndLoadContentScript()
 {
     gBrowserMessageManager.addMessageListener(
@@ -1999,17 +1958,17 @@ function RecvAssertionCount(count)
 function RecvContentReady()
 {
     InitAndStartRefTests();
     return { remote: gBrowserIsRemote };
 }
 
 function RecvException(what)
 {
-    gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | " + gCurrentURL + " | " + what + "\n");
+    logger.error(gCurrentURL + " | " + what);
     ++gTestResults.Exception;
 }
 
 function RecvFailedLoad(why)
 {
     LoadFailed(why);
 }
 
@@ -2031,23 +1990,23 @@ function RecvFailedAssignedLayer(why) {
 function RecvInitCanvasWithSnapshot()
 {
     var painted = InitCurrentCanvasWithSnapshot();
     return { painted: painted };
 }
 
 function RecvLog(type, msg)
 {
-    msg = "[CONTENT] "+ msg;
+    msg = "[CONTENT] " + msg;
     if (type == "info") {
-        LogInfo(msg);
+        TestBuffer(msg);
     } else if (type == "warning") {
-        LogWarning(msg);
+        logger.warning(msg);
     } else {
-        gDumpLog("REFTEST TEST-UNEXPECTED-FAIL | " + gCurrentURL + " | unknown log type " + type + "\n");
+        logger.error("REFTEST TEST-UNEXPECTED-FAIL | " + gCurrentURL + " | unknown log type " + type + "\n");
         ++gTestResults.Exception;
     }
 }
 
 function RecvScriptResults(runtimeMs, error, results)
 {
     RecordResult(runtimeMs, error, results);
 }
--- a/layout/tools/reftest/reftestcommandline.py
+++ b/layout/tools/reftest/reftestcommandline.py
@@ -1,13 +1,16 @@
 import argparse
 import os
+import sys
 from collections import OrderedDict
 from urlparse import urlparse
 
+import mozlog
+
 here = os.path.abspath(os.path.dirname(__file__))
 
 
 class ReftestArgumentsParser(argparse.ArgumentParser):
     def __init__(self, **kwargs):
         super(ReftestArgumentsParser, self).__init__(**kwargs)
 
         # Try to import a MozbuildObject. Success indicates that we are
@@ -202,16 +205,18 @@ class ReftestArgumentsParser(argparse.Ar
                           default=None,
                           help=argparse.SUPPRESS)
 
         self.add_argument("tests",
                           metavar="TEST_PATH",
                           nargs="*",
                           help="Path to test file, manifest file, or directory containing tests")
 
+        mozlog.commandline.add_logging_group(self)
+
     def get_ip(self):
         import moznetwork
         if os.name != "nt":
             return moznetwork.get_ip()
         else:
             self.error(
                 "ERROR: you must specify a --remote-webserver=<ip address>\n")
 
@@ -230,18 +235,16 @@ class ReftestArgumentsParser(argparse.Ar
             for manifest_file, suite in manifests.iteritems():
                 if os.path.exists(os.path.join(test_path, manifest_file)):
                     options.suite = suite
                     return
 
         self.error("Failed to determine test suite; supply --suite to set this explicitly")
 
     def validate(self, options, reftest):
-        import sys
-
         if not options.tests:
             # Can't just set this in the argument parser because mach will set a default
             self.error("Must supply at least one path to a manifest file, test directory, or test file to run.")
 
         if options.suite is None:
             self.set_default_suite(options)
 
         if options.totalChunks is not None and options.thisChunk is None:
--- a/layout/tools/reftest/remotereftest.py
+++ b/layout/tools/reftest/remotereftest.py
@@ -3,29 +3,31 @@
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 import sys
 import os
 import time
 import tempfile
 import traceback
 
-# We need to know our current directory so that we can serve our test files from it.
-SCRIPT_DIRECTORY = os.path.abspath(os.path.realpath(os.path.dirname(__file__)))
-
-from runreftest import RefTest, ReftestResolver
-from automation import Automation
 import devicemanager
 import droid
 import mozinfo
 import moznetwork
+from automation import Automation
 from remoteautomation import RemoteAutomation, fennecLogcatFilters
 
+from output import OutputHandler
+from runreftest import RefTest, ReftestResolver
 import reftestcommandline
 
+# We need to know our current directory so that we can serve our test files from it.
+SCRIPT_DIRECTORY = os.path.abspath(os.path.realpath(os.path.dirname(__file__)))
+
+
 class RemoteReftestResolver(ReftestResolver):
     def absManifestPath(self, path):
         script_abs_path = os.path.join(SCRIPT_DIRECTORY, path)
         if os.path.exists(script_abs_path):
             rv = script_abs_path
         elif os.path.exists(os.path.abspath(path)):
             rv = os.path.abspath(path)
         else:
@@ -141,16 +143,23 @@ class RemoteReftest(RefTest):
         self.pidFile = options.pidFile
         if self.automation.IS_DEBUG_BUILD:
             self.SERVER_STARTUP_TIMEOUT = 180
         else:
             self.SERVER_STARTUP_TIMEOUT = 90
         self.automation.deleteANRs()
         self.automation.deleteTombstones()
 
+        self._populate_logger(options)
+        outputHandler = OutputHandler(self.log, options.utilityPath, options.symbolsPath)
+        # RemoteAutomation.py's 'messageLogger' is also used by mochitest. Mimic a mochitest
+        # MessageLogger object to re-use this code path.
+        outputHandler.write = outputHandler.__call__
+        self.automation._processArgs['messageLogger'] = outputHandler
+
     def findPath(self, paths, filename = None):
         for path in paths:
             p = path
             if filename:
                 p = os.path.join(p, filename)
             if os.path.exists(self.getFullPath(p)):
                 return path
         return None
@@ -440,9 +449,8 @@ def run(**kwargs):
 def main():
     parser = reftestcommandline.RemoteArgumentsParser()
     options = parser.parse_args()
     retVal = runTests(options, parser)
     return retVal
 
 if __name__ == "__main__":
     sys.exit(main())
-
--- a/layout/tools/reftest/runreftest.py
+++ b/layout/tools/reftest/runreftest.py
@@ -21,36 +21,33 @@ SCRIPT_DIRECTORY = os.path.abspath(
     os.path.realpath(os.path.dirname(__file__)))
 if SCRIPT_DIRECTORY not in sys.path:
     sys.path.insert(0, SCRIPT_DIRECTORY)
 
 import mozcrash
 import mozdebug
 import mozinfo
 import mozleak
+import mozlog
 import mozprocess
 import mozprofile
 import mozrunner
 from mozrunner.utils import get_stack_fixer_function, test_environment
 from mozscreenshot import printstatus, dump_screen
 
+from output import OutputHandler, ReftestFormatter
 import reftestcommandline
 
-# set up logging handler a la automation.py.in for compatability
-import logging
-log = logging.getLogger()
-
+here = os.path.abspath(os.path.dirname(__file__))
 
-def resetGlobalLog():
-    while log.handlers:
-        log.removeHandler(log.handlers[0])
-    handler = logging.StreamHandler(sys.stdout)
-    log.setLevel(logging.INFO)
-    log.addHandler(handler)
-resetGlobalLog()
+try:
+    from mozbuild.base import MozbuildObject
+    build_obj = MozbuildObject.from_environment(cwd=here)
+except ImportError:
+    build_obj = None
 
 
 def categoriesToRegex(categoryList):
     return "\\(" + ', '.join(["(?P<%s>\\d+) %s" % c for c in categoryList]) + "\\)"
 summaryLines = [('Successful', [('pass', 'pass'), ('loadOnly', 'load only')]),
                 ('Unexpected', [('fail', 'unexpected fail'),
                                 ('pass', 'unexpected pass'),
                                 ('asserts', 'unexpected asserts'),
@@ -198,16 +195,31 @@ class RefTest(object):
     oldcwd = os.getcwd()
     resolver_cls = ReftestResolver
 
     def __init__(self):
         self.update_mozinfo()
         self.lastTestSeen = 'reftest'
         self.haveDumpedScreen = False
         self.resolver = self.resolver_cls()
+        self.log = None
+
+    def _populate_logger(self, options):
+        if self.log:
+            return
+
+        mozlog.commandline.log_formatters["tbpl"] = (ReftestFormatter,
+                                                     "Reftest specific formatter for the"
+                                                     "benefit of legacy log parsers and"
+                                                     "tools such as the reftest analyzer")
+        fmt_options = {}
+        if not options.log_tbpl_level and os.environ.get('MOZ_REFTEST_VERBOSE'):
+            options.log_tbpl_level = fmt_options['level'] = 'debug'
+        self.log = mozlog.commandline.setup_logging(
+            "reftest harness", options, {"tbpl": sys.stdout}, fmt_options)
 
     def update_mozinfo(self):
         """walk up directories to find mozinfo.json update the info"""
         # TODO: This should go in a more generic place, e.g. mozinfo
 
         path = SCRIPT_DIRECTORY
         dirs = set()
         while path != os.path.expanduser('~'):
@@ -250,16 +262,17 @@ class RefTest(object):
             prefs['reftest.ignoreWindowSize'] = True
         if options.shuffle:
             prefs['reftest.shuffle'] = True
         if options.repeat:
             prefs['reftest.repeat'] = options.repeat
         if options.runUntilFailure:
             prefs['reftest.runUntilFailure'] = True
         prefs['reftest.focusFilterMode'] = options.focusFilterMode
+        prefs['reftest.logLevel'] = options.log_tbpl_level or 'info'
         prefs['reftest.manifests'] = json.dumps(manifests)
 
         # Ensure that telemetry is disabled, so we don't connect to the telemetry
         # server in the middle of the tests.
         prefs['toolkit.telemetry.enabled'] = False
         prefs['toolkit.telemetry.unified'] = False
         # Likewise for safebrowsing.
         prefs['browser.safebrowsing.enabled'] = False
@@ -327,17 +340,17 @@ class RefTest(object):
             profile = mozprofile.Profile.clone(profile_to_clone, **kwargs)
         else:
             profile = mozprofile.Profile(**kwargs)
 
         self.copyExtraFilesToProfile(options, profile)
         return profile
 
     def environment(self, **kwargs):
-        kwargs['log'] = log
+        kwargs['log'] = self.log
         return test_environment(**kwargs)
 
     def buildBrowserEnv(self, options, profileDir):
         browserEnv = self.environment(
             xrePath=options.xrePath, debugger=options.debugger)
         browserEnv["XPCOM_DEBUG_BREAK"] = "stack"
 
         if mozinfo.info["asan"]:
@@ -356,48 +369,50 @@ class RefTest(object):
 
         # Enable leaks detection to its own log file.
         self.leakLogFile = os.path.join(profileDir, "runreftest_leaks.log")
         browserEnv["XPCOM_MEM_BLOAT_LOG"] = self.leakLogFile
         return browserEnv
 
     def killNamedOrphans(self, pname):
         """ Kill orphan processes matching the given command name """
-        log.info("Checking for orphan %s processes..." % pname)
+        self.log.info("Checking for orphan %s processes..." % pname)
 
         def _psInfo(line):
             if pname in line:
-                log.info(line)
+                self.log.info(line)
         process = mozprocess.ProcessHandler(['ps', '-f'],
                                             processOutputLine=_psInfo)
         process.run()
         process.wait()
 
         def _psKill(line):
             parts = line.split()
             if len(parts) == 3 and parts[0].isdigit():
                 pid = int(parts[0])
                 if parts[2] == pname and parts[1] == '1':
-                    log.info("killing %s orphan with pid %d" % (pname, pid))
+                    self.log.info("killing %s orphan with pid %d" % (pname, pid))
                     try:
                         os.kill(
                             pid, getattr(signal, "SIGKILL", signal.SIGTERM))
                     except Exception as e:
-                        log.info("Failed to kill process %d: %s" %
-                                 (pid, str(e)))
+                        self.log.info("Failed to kill process %d: %s" %
+                                      (pid, str(e)))
         process = mozprocess.ProcessHandler(['ps', '-o', 'pid,ppid,comm'],
                                             processOutputLine=_psKill)
         process.run()
         process.wait()
 
     def cleanup(self, profileDir):
         if profileDir:
             shutil.rmtree(profileDir, True)
 
     def runTests(self, tests, options, cmdlineArgs=None):
+        self._populate_logger(options)
+
         # Despite our efforts to clean up servers started by this script, in practice
         # we still see infrequent cases where a process is orphaned and interferes
         # with future tests, typically because the old server is keeping the port in use.
         # Try to avoid those failures by checking for and killing orphan servers before
         # trying to start new ones.
         self.killNamedOrphans('ssltunnel')
         self.killNamedOrphans('xpcshell')
 
@@ -480,27 +495,26 @@ class RefTest(object):
             print 'REFTEST INFO | ' + text + ': ' + str(summaryObj['total']) + ' (' + details + ')'
 
         return int(any(t.retcode != 0 for t in threads))
 
     def handleTimeout(self, timeout, proc, utilityPath, debuggerInfo):
         """handle process output timeout"""
         # TODO: bug 913975 : _processOutput should call self.processOutputLine
         # one more time one timeout (I think)
-        log.error("TEST-UNEXPECTED-FAIL | %s | application timed out after %d seconds with no output" %
-                  (self.lastTestSeen, int(timeout)))
+        self.log.error("%s | application timed out after %d seconds with no output" % (self.lastTestSeen, int(timeout)))
         self.killAndGetStack(
             proc, utilityPath, debuggerInfo, dump_screen=not debuggerInfo)
 
     def dumpScreen(self, utilityPath):
         if self.haveDumpedScreen:
-            log.info("Not taking screenshot here: see the one that was previously logged")
+            self.log.info("Not taking screenshot here: see the one that was previously logged")
             return
         self.haveDumpedScreen = True
-        dump_screen(utilityPath, log)
+        dump_screen(utilityPath, self.log)
 
     def killAndGetStack(self, process, utilityPath, debuggerInfo, dump_screen=False):
         """
         Kill the process, preferrably in a way that gets us a stack trace.
         Also attempts to obtain a screenshot before killing the process
         if specified.
         """
 
@@ -518,104 +532,44 @@ class RefTest(object):
                     printstatus("crashinject", status)
                     if status == 0:
                         return
             else:
                 try:
                     process.kill(sig=signal.SIGABRT)
                 except OSError:
                     # https://bugzilla.mozilla.org/show_bug.cgi?id=921509
-                    log.info("Can't trigger Breakpad, process no longer exists")
+                    self.log.info("Can't trigger Breakpad, process no longer exists")
                 return
-        log.info("Can't trigger Breakpad, just killing process")
+        self.log.info("Can't trigger Breakpad, just killing process")
         process.kill()
 
-    # output processing
-
-    class OutputHandler(object):
-
-        """line output handler for mozrunner"""
-
-        def __init__(self, harness, utilityPath, symbolsPath=None, dump_screen_on_timeout=True):
-            """
-            harness -- harness instance
-            dump_screen_on_timeout -- whether to dump the screen on timeout
-            """
-            self.harness = harness
-            self.utilityPath = utilityPath
-            self.symbolsPath = symbolsPath
-            self.dump_screen_on_timeout = dump_screen_on_timeout
-            self.stack_fixer_function = self.stack_fixer()
-
-        def processOutputLine(self, line):
-            """per line handler of output for mozprocess"""
-            for handler in self.output_handlers():
-                line = handler(line)
-        __call__ = processOutputLine
-
-        def output_handlers(self):
-            """returns ordered list of output handlers"""
-            return [self.fix_stack,
-                    self.format,
-                    self.record_last_test,
-                    self.handle_timeout_and_dump_screen,
-                    self.log,
-                    ]
-
-        def stack_fixer(self):
-            """
-            return get_stack_fixer_function, if any, to use on the output lines
-            """
-            return get_stack_fixer_function(self.utilityPath, self.symbolsPath)
-
-        # output line handlers:
-        # these take a line and return a line
-        def fix_stack(self, line):
-            if self.stack_fixer_function:
-                return self.stack_fixer_function(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 handle_timeout_and_dump_screen(self, line):
-            if self.dump_screen_on_timeout and "TEST-UNEXPECTED-FAIL" in line and "Test timed out" in line:
-                self.harness.dumpScreen(self.utilityPath)
-            return line
-
-        def log(self, line):
-            log.info(line)
-            return line
-
     def runApp(self, profile, binary, cmdargs, env,
                timeout=None, debuggerInfo=None,
                symbolsPath=None, options=None,
                valgrindPath=None, valgrindArgs=None, valgrindSuppFiles=None):
 
         def timeoutHandler():
             self.handleTimeout(
                 timeout, proc, options.utilityPath, debuggerInfo)
 
         interactive = False
         debug_args = None
         if debuggerInfo:
             interactive = debuggerInfo.interactive
             debug_args = [debuggerInfo.path] + debuggerInfo.args
 
-        outputHandler = self.OutputHandler(harness=self,
-                                           utilityPath=options.utilityPath,
-                                           symbolsPath=symbolsPath,
-                                           dump_screen_on_timeout=not debuggerInfo)
+        def record_last_test(message):
+            """Records the last test seen by this harness for the benefit of crash logging."""
+            if message['action'] == 'test_start':
+                self.lastTestSeen = message['test']
+
+        self.log.add_handler(record_last_test)
+
+        outputHandler = OutputHandler(self.log, options.utilityPath, symbolsPath=symbolsPath)
 
         kp_kwargs = {
             'kill_on_timeout': False,
             'cwd': SCRIPT_DIRECTORY,
             'onTimeout': [timeoutHandler],
             'processOutputLine': [outputHandler],
         }
 
@@ -635,70 +589,64 @@ class RefTest(object):
                             process_class=mozprocess.ProcessHandlerMixin,
                             cmdargs=cmdargs,
                             env=env,
                             process_args=kp_kwargs)
         runner.start(debug_args=debug_args,
                      interactive=interactive,
                      outputTimeout=timeout)
         proc = runner.process_handler
+
         status = runner.wait()
         runner.process_handler = None
-        if timeout is None:
-            didTimeout = False
-        else:
-            didTimeout = proc.didTimeout
 
         if status:
-            log.info("TEST-UNEXPECTED-FAIL | %s | application terminated with exit code %s",
-                     self.lastTestSeen, status)
+            self.log.error("TEST-UNEXPECTED-FAIL | %s | application terminated with exit code %s" % (self.lastTestSeen, status))
         else:
             self.lastTestSeen = 'Main app process exited normally'
 
-        crashed = mozcrash.check_for_crashes(os.path.join(profile.profile, "minidumps"),
-                                             symbolsPath, test_name=self.lastTestSeen)
+        crashed = mozcrash.log_crashes(self.log, os.path.join(profile.profile, 'minidumps'),
+                                       symbolsPath, test=self.lastTestSeen)
+
         runner.cleanup()
         if not status and crashed:
             status = 1
         return status
 
     def runSerialTests(self, manifests, options, cmdlineArgs=None):
         debuggerInfo = None
         if options.debugger:
             debuggerInfo = mozdebug.get_debugger_info(options.debugger, options.debuggerArgs,
                                                       options.debuggerInteractive)
 
         profileDir = None
         try:
-            if cmdlineArgs == None:
+            if cmdlineArgs is None:
                 cmdlineArgs = []
             profile = self.createReftestProfile(options, manifests)
             profileDir = profile.profile  # name makes more sense
 
             # browser environment
             browserEnv = self.buildBrowserEnv(options, profileDir)
 
-            log.info("REFTEST INFO | runreftest.py | Running tests: start.\n")
             status = self.runApp(profile,
                                  binary=options.app,
                                  cmdargs=cmdlineArgs,
                                  # give the JS harness 30 seconds to deal with
                                  # its own timeouts
                                  env=browserEnv,
                                  timeout=options.timeout + 30.0,
                                  symbolsPath=options.symbolsPath,
                                  options=options,
                                  debuggerInfo=debuggerInfo)
             mozleak.process_leak_log(self.leakLogFile,
                                      leak_thresholds=options.leakThresholds,
-                                     log=log,
                                      stack_fixer=get_stack_fixer_function(options.utilityPath,
                                                                           options.symbolsPath),
             )
-            log.info("\nREFTEST INFO | runreftest.py | Running tests: end.")
         finally:
             self.cleanup(profileDir)
         return status
 
     def copyExtraFilesToProfile(self, options, profile):
         "Copy extra files or dirs specified on the command line to the testing profile."
         profileDir = profile.profile
         for f in options.extraProfileFiles:
@@ -708,36 +656,33 @@ class RefTest(object):
                     extra_prefs = mozprofile.Preferences.read_prefs(abspath)
                     profile.set_preferences(extra_prefs)
                 else:
                     shutil.copy2(abspath, profileDir)
             elif os.path.isdir(abspath):
                 dest = os.path.join(profileDir, os.path.basename(abspath))
                 shutil.copytree(abspath, dest)
             else:
-                log.warning(
-                    "WARNING | runreftest.py | Failed to copy %s to profile", abspath)
+                self.log.warning(
+                    "runreftest.py | Failed to copy %s to profile" % abspath)
                 continue
 
 
 def run(**kwargs):
+    parser = reftestcommandline.DesktopArgumentsParser()
+
     # Mach gives us kwargs; this is a way to turn them back into an
     # options object
-    parser = reftestcommandline.DesktopArgumentsParser()
+    parser.set_defaults(**kwargs)
+
+    if 'tests' in kwargs:
+        options = parser.parse_args(kwargs["tests"])
+    else:
+        options = parser.parse_args()
+
     reftest = RefTest()
-    parser.set_defaults(**kwargs)
-    options = parser.parse_args(kwargs["tests"])
     parser.validate(options, reftest)
+
     return reftest.runTests(options.tests, options)
 
 
-def main():
-    parser = reftestcommandline.DesktopArgumentsParser()
-    reftest = RefTest()
-
-    options = parser.parse_args()
-    parser.validate(options, reftest)
-
-    sys.exit(reftest.runTests(options.tests, options))
-
-
 if __name__ == "__main__":
-    main()
+    sys.exit(run())
--- a/layout/tools/reftest/runreftestb2g.py
+++ b/layout/tools/reftest/runreftestb2g.py
@@ -11,16 +11,17 @@ import traceback
 # We need to know our current directory so that we can serve our test files from it.
 here = os.path.abspath(os.path.dirname(__file__))
 if here not in sys.path:
     sys.path.insert(0, here)
 
 from automation import Automation
 from b2gautomation import B2GRemoteAutomation
 from runreftestmulet import run_test_harness as run_mulet_reftests
+from output import OutputHandler
 from remotereftest import RemoteReftestResolver, ReftestServer
 from runreftest import RefTest
 import reftestcommandline
 
 from mozdevice import DeviceManagerADB, DMError
 from marionette import Marionette
 
 class ProfileConfigParser(ConfigParser.RawConfigParser):
@@ -306,25 +307,28 @@ class B2GRemoteReftest(RefTest):
 
     def environment(self, **kwargs):
      return self.automation.environment(**kwargs)
 
     def runApp(self, profile, binary, cmdargs, env,
                timeout=None, debuggerInfo=None,
                symbolsPath=None, options=None,
                valgrindPath=None, valgrindArgs=None, valgrindSuppFiles=None):
+
+        outputHandler = OutputHandler(self.log, options.utilityPath, options.symbolsPath)
         status = self.automation.runApp(None, env,
                                         binary,
                                         profile.profile,
                                         cmdargs,
                                         utilityPath=options.utilityPath,
                                         xrePath=options.xrePath,
                                         debuggerInfo=debuggerInfo,
                                         symbolsPath=symbolsPath,
-                                        timeout=timeout)
+                                        timeout=timeout,
+                                        outputHandler=outputHandler)
         return status
 
 
 def run_remote_reftests(parser, options):
     auto = B2GRemoteAutomation(None, "fennec", context_chrome=True)
 
     # create our Marionette instance
     kwargs = {}
@@ -375,17 +379,16 @@ def run_remote_reftests(parser, options)
         height = int(parts[1].split(':')[1])
         if (width < 1366 or height < 1050):
             print "ERROR: Invalid screen resolution %sx%s, please adjust to 1366x1050 or higher" % (width, height)
             return 1
 
     auto.setProduct("b2g")
     auto.test_script = os.path.join(here, 'b2g_start_script.js')
     auto.test_script_args = [options.remoteWebServer, options.httpPort]
-    auto.logFinish = "REFTEST TEST-START | Shutdown"
 
     reftest = B2GRemoteReftest(auto, dm, options, here)
     parser.validate(options, reftest)
 
     logParent = os.path.dirname(options.remoteLogFile)
     dm.mkDir(logParent);
     auto.setRemoteLog(options.remoteLogFile)
     auto.setServerInfo(options.webServer, options.httpPort, options.sslPort)
--- a/layout/tools/reftest/runreftestmulet.py
+++ b/layout/tools/reftest/runreftestmulet.py
@@ -15,21 +15,20 @@ from marionette_driver.marionette import
 from marionette_driver.wait import Wait
 
 from mozprocess import ProcessHandler
 from mozrunner import FirefoxRunner
 import mozinfo
 import mozlog
 
 from runreftest import RefTest
+from output import OutputHandler
 import reftestcommandline
 
 
-log = mozlog.unstructured.getLogger('REFTEST')
-
 class MuletReftest(RefTest):
     build_type = "mulet"
     marionette = None
 
     def __init__(self, marionette_args):
         RefTest.__init__(self)
         self.last_test = os.path.basename(__file__)
         self.marionette_args = marionette_args
@@ -54,62 +53,66 @@ class MuletReftest(RefTest):
         self.marionette.execute_script(self.test_script)
 
     def run_tests(self, tests, options):
         manifests = self.resolver.resolveManifests(options, tests)
 
         self.profile = self.create_profile(options, manifests,
                                            profile_to_clone=options.profile)
         env = self.buildBrowserEnv(options, self.profile.profile)
-        kp_kwargs = { 'processOutputLine': [self._on_output],
+
+        self._populate_logger(options)
+        outputHandler = OutputHandler(self.log, options.utilityPath, symbolsPath=options.symbolsPath)
+
+        kp_kwargs = { 'processOutputLine': [outputHandler],
                       'onTimeout': [self._on_timeout],
                       'kill_on_timeout': False }
 
         if not options.debugger:
             if not options.timeout:
                 if mozinfo.info['debug']:
                     options.timeout = 420
                 else:
                     options.timeout = 300
             self.timeout = options.timeout + 30.0
 
-        log.info("%s | Running tests: start.", os.path.basename(__file__))
+        self.log.info("%s | Running tests: start." % os.path.basename(__file__))
         cmd, args = self.build_command_line(options.app,
                             ignore_window_size=options.ignoreWindowSize,
                             browser_arg=options.browser_arg)
         self.runner = FirefoxRunner(profile=self.profile,
                                     binary=cmd,
                                     cmdargs=args,
                                     env=env,
                                     process_class=ProcessHandler,
                                     process_args=kp_kwargs,
                                     symbols_path=options.symbolsPath)
 
         status = 0
         try:
             self.runner.start(outputTimeout=self.timeout)
-            log.info("%s | Application pid: %d",
+            self.log.info("%s | Application pid: %d" % (
                      os.path.basename(__file__),
-                     self.runner.process_handler.pid)
+                     self.runner.process_handler.pid))
 
             # kick starts the reftest harness
             self.run_marionette_script()
             status = self.runner.wait()
         finally:
             self.runner.check_for_crashes(test_name=self.last_test)
             self.runner.cleanup()
 
         if status > 0:
-            log.testFail("%s | application terminated with exit code %s",
-                         self.last_test, status)
+            self.log.testFail("%s | application terminated with exit code %s" % (
+                         self.last_test, status))
         elif status < 0:
-            log.info("%s | application killed with signal %s",
-                         self.last_test, -status)
+            self.log.info("%s | application killed with signal %s" % (
+                         self.last_test, -status))
 
-        log.info("%s | Running tests: end.", os.path.basename(__file__))
+        self.log.info("%s | Running tests: end." % os.path.basename(__file__))
         return status
 
     def create_profile(self, options, manifests, profile_to_clone=None):
         profile = RefTest.createReftestProfile(self, options, manifests,
                                                profile_to_clone=profile_to_clone)
 
         prefs = {}
         # Turn off the locale picker screen
@@ -154,44 +157,36 @@ class MuletReftest(RefTest):
 
         if not ignore_window_size:
             args.extend(['--screen', '800x1000'])
 
         if self.build_type == "mulet":
             args += ['-chrome', 'chrome://b2g/content/shell.html']
         return cmd, args
 
-    def _on_output(self, line):
-        sys.stdout.write("%s\n" % line)
-        sys.stdout.flush()
-
-        # TODO use structured logging
-        if "TEST-START" in line and "|" in line:
-            self.last_test = line.split("|")[1].strip()
-
     def _on_timeout(self):
         msg = "%s | application timed out after %s seconds with no output"
-        log.testFail(msg % (self.last_test, self.timeout))
+        self.log.testFail(msg % (self.last_test, self.timeout))
 
         # kill process to get a stack
         self.runner.stop(sig=signal.SIGABRT)
 
-
     def _unlockScreen(self):
         self.marionette.set_context(self.marionette.CONTEXT_CONTENT)
         self.marionette.import_script(os.path.abspath(
             os.path.join(__file__, os.path.pardir, "gaia_lock_screen.js")))
         self.marionette.switch_to_frame()
         self.marionette.execute_async_script('GaiaLockScreen.unlock()')
 
     def _wait_for_homescreen(self, timeout):
-        log.info("Waiting for home screen to load")
+        self.log.info("Waiting for home screen to load")
         Wait(self.marionette, timeout).until(expected.element_present(
             By.CSS_SELECTOR, '#homescreen[loading-state=false]'))
 
+
 def run_test_harness(parser, options):
     marionette_args = {}
     if options.marionette:
         host, port = options.marionette.split(':')
         marionette_args['host'] = host
         marionette_args['port'] = int(port)
 
     reftest = MuletReftest(marionette_args)
--- a/testing/modules/StructuredLog.jsm
+++ b/testing/modules/StructuredLog.jsm
@@ -82,27 +82,45 @@ StructuredLogger.prototype = {
     }
     if (extra !== null) {
       data.extra = extra;
     }
 
     this._logData("test_end", data);
   },
 
-  suiteStart: function (tests, runinfo=null) {
+  suiteStart: function (tests, runinfo=null, versioninfo=null, deviceinfo=null, extra=null) {
     var data = {tests: tests};
     if (runinfo !== null) {
       data.runinfo = runinfo;
     }
 
+    if (versioninfo !== null) {
+      data.versioninfo = versioninfo;
+    }
+
+    if (deviceinfo !== null) {
+      data.deviceinfo = deviceinfo;
+    }
+
+    if (extra !== null) {
+      data.extra = extra;
+    }
+
     this._logData("suite_start", data);
   },
 
-  suiteEnd: function () {
-    this._logData("suite_end");
+  suiteEnd: function (extra=null) {
+    var data = {};
+
+    if (extra !== null) {
+      data.extra = extra;
+    }
+
+    this._logData("suite_end", data);
   },
 
 
   /**
    * Unstructured logging functions. The "extra" parameter can always by used to
    * log suite specific data. If a "stack" field is provided it is logged at the
    * top level of the data object for the benefit of mozlog's formatters.
    */
@@ -137,16 +155,24 @@ StructuredLogger.prototype = {
   error: function (message, extra=null) {
     this.log("ERROR", message, extra);
   },
 
   critical: function (message, extra=null) {
     this.log("CRITICAL", message, extra);
   },
 
+  processOutput: function(thread, message) {
+    this._logData('process_output', {
+      message: message,
+      thread: thread,
+    });
+  },
+
+
   _logData: function (action, data={}) {
     var allData = {
       action: action,
       time: Date.now(),
       thread: null,
       pid: null,
       source: this.name
     };
--- a/testing/mozbase/mozleak/mozleak/leaklog.py
+++ b/testing/mozbase/mozleak/mozleak/leaklog.py
@@ -5,19 +5,25 @@
 
 import os
 import re
 import sys
 
 import mozinfo
 import mozrunner.utils
 
-def _raw_log():
-    import logging
-    return logging.getLogger(__name__)
+
+def _get_default_logger():
+    from mozlog import get_default_logger
+    log = get_default_logger(component='mozleak')
+
+    if not log:
+        import logging
+        log = logging.getLogger(__name__)
+    return log
 
 
 # Do not add anything to this list, unless one of the existing leaks below
 # has started to leak additional objects. This function returns a dict
 # mapping the names of objects as reported to the XPCOM leak checker to an
 # upper bound on the number of leaked objects of that kind that are allowed
 # to appear in a content process leak report.
 def expectedTabProcessLeakCounts():
@@ -125,17 +131,17 @@ def process_single_leak_file(leakLogFile
     # 833 |nsTimerImpl   |      60     120|     24726    2|
     # 930 |Foo<Bar, Bar> |      32       8|       100    1|
     lineRe = re.compile(r"^\s*\d+ \|"
                         r"(?P<name>[^|]+)\|"
                         r"\s*(?P<size>-?\d+)\s+(?P<bytesLeaked>-?\d+)\s*\|"
                         r"\s*-?\d+\s+(?P<numLeaked>-?\d+)")
     # The class name can contain spaces. We remove trailing whitespace later.
 
-    log = log or _raw_log()
+    log = log or _get_default_logger()
 
     processString = "%s process:" % processType
     expectedLeaks = expectedTabProcessLeakCounts() if processType == 'tab' else {}
     crashedOnPurpose = False
     totalBytesLeaked = None
     logAsWarning = False
     leakAnalysis = []
     leakedObjectAnalysis = []
@@ -271,17 +277,17 @@ def process_leak_log(leak_log_file, leak
     in bytes. If a process type is not present in the dict the threshold
     will be 0.
 
     ignore_missing_leaks should be a list of process types. If a process
     creates a leak log without a TOTAL, then we report an error if it isn't
     in the list ignore_missing_leaks.
     """
 
-    log = log or _raw_log()
+    log = log or _get_default_logger()
 
     leakLogFile = leak_log_file
     if not os.path.exists(leakLogFile):
         log.info(
             "WARNING | leakcheck | refcount logging is off, so leaks can't be detected!")
         return
 
     leakThresholds = leak_thresholds or {}
--- a/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
@@ -1,15 +1,16 @@
 # 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/.
 
 from .base import BaseFormatter
 from .process import strstatus
 
+
 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):
         self.suite_start_time = None
         self.test_start_times = {}
@@ -97,45 +98,47 @@ class TbplFormatter(BaseFormatter):
             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):
         test_id = self.test_id(data["test"])
-        time_msg = ""
+        duration_msg = ""
 
         if test_id in self.test_start_times:
             start_time = self.test_start_times.pop(test_id)
             time = data["time"] - start_time
-            time_msg = "took %ims" % time
+            duration_msg = "took %ims" % time
 
         if "expected" in data:
             message = data.get("message", "")
             if not message:
                 message = "expected %s" % data["expected"]
             if "stack" in data:
                 message += "\n%s" % data["stack"]
             if message and message[-1] == "\n":
                 message = message[:-1]
 
             failure_line = "TEST-UNEXPECTED-%s | %s | %s\n" % (
-                data["status"], test_id, message)
+                data["status"], self.id_str(test_id), message)
 
             if data["expected"] not in ("PASS", "OK"):
                 expected_msg = "expected %s | " % data["expected"]
             else:
                 expected_msg = ""
-            info_line = "TEST-INFO %s%s\n" % (expected_msg, time_msg)
+            info_line = "TEST-INFO %s%s\n" % (expected_msg, duration_msg)
 
             return failure_line + info_line
 
-        return "TEST-%s | %s | %s\n" % (
-            data["status"], test_id, time_msg)
+        sections = ["TEST-%s" % data['status'], self.id_str(test_id)]
+        if duration_msg:
+            sections.append(duration_msg)
+        return ' | '.join(sections) + '\n'
 
     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):
--- a/testing/mozbase/mozlog/mozlog/logtypes.py
+++ b/testing/mozbase/mozlog/mozlog/logtypes.py
@@ -127,19 +127,19 @@ class Unicode(DataType):
         if isinstance(data, str):
             return data.decode("utf8", "replace")
         return unicode(data)
 
 class TestId(DataType):
     def convert(self, data):
         if isinstance(data, unicode):
             return data
-        elif isinstance(data, str):
+        elif isinstance(data, bytes):
             return data.decode("utf-8", "replace")
-        elif isinstance(data, tuple):
+        elif isinstance(data, (tuple, list)):
             # This is really a bit of a hack; should really split out convertors from the
             # fields they operate on
             func = Unicode(None).convert
             return tuple(func(item) for item in data)
         else:
             raise ValueError
 
 class Status(DataType):
--- a/testing/mozbase/mozlog/mozlog/structuredlog.py
+++ b/testing/mozbase/mozlog/mozlog/structuredlog.py
@@ -233,31 +233,32 @@ class StructuredLogger(object):
                            "Logged with data: {}".format(json.dumps(data)))
                 return False
             self._state.suite_started = False
         return True
 
     @log_action(List("tests", Unicode),
                 Dict("run_info", default=None, optional=True),
                 Dict("version_info", default=None, optional=True),
-                Dict("device_info", default=None, optional=True))
+                Dict("device_info", default=None, optional=True),
+                Dict("extra", default=None, optional=True))
     def suite_start(self, data):
         """Log a suite_start message
 
         :param list tests: Test identifiers that will be run in the suite.
         :param dict run_info: Optional information typically provided by mozinfo.
         :param dict version_info: Optional target application version information provided by mozversion.
         :param dict device_info: Optional target device information provided by mozdevice.
         """
         if not self._ensure_suite_state('suite_start', data):
             return
 
         self._log_data("suite_start", data)
 
-    @log_action()
+    @log_action(Dict("extra", default=None, optional=True))
     def suite_end(self, data):
         """Log a suite_end message"""
         if not self._ensure_suite_state('suite_end', data):
             return
 
         self._log_data("suite_end")
 
     @log_action(TestId("test"),