Bug 956739 - Move marionette tests to structured logging.;r=mdas

testing/marionette/client/marionette/marionette_test.py

@@ -15,7 +15,7 @@ import weakref
 import warnings
 
 from errors import (
-        ErrorCodes, MarionetteException, InstallGeckoError, TimeoutException, InvalidResponseException, 
+        ErrorCodes, MarionetteException, InstallGeckoError, TimeoutException, InvalidResponseException,
         JavascriptException, NoSuchElementException, XPathLookupException, NoSuchWindowException,
         StaleElementException, ScriptTimeoutException, ElementNotVisibleException,
         NoSuchFrameException, InvalidElementStateException, NoAlertPresentException,
@@ -23,6 +23,7 @@ from errors import (
         MoveTargetOutOfBoundsException, FrameSendNotInitializedError, FrameSendFailureError
         )
 from marionette import Marionette
+from mozlog.structured.structuredlog import get_default_logger
 
 class SkipTest(Exception):
     """
@@ -244,6 +245,13 @@ class CommonTestCase(unittest.TestCase):
                                     self.__class__.__name__,
                                     self._testMethodName)
 
+    def id(self):
+        # TBPL starring requires that the "test name" field of a failure message
+        # not differ over time. The test name to be used is passed to
+        # mozlog.structured via the test id, so this is overriden to maintain
+        # consistency.
+        return self.test_name
+
     def set_up_test_page(self, emulator, url="test.html", permissions=None):
         emulator.set_context("content")
         url = emulator.absolute_url(url)
@@ -503,14 +511,14 @@ setReq.onerror = function() {
                 self.assertTrue(results['failed'] > 0,
                                 "expected test failures didn't occur")
             else:
-                fails = []
+                logger = get_default_logger()
                 for failure in results['failures']:
-                    diag = "" if failure.get('diag') is None else "| %s " % failure['diag']
+                    diag = "" if failure.get('diag') is None else failure['diag']
                     name = "got false, expected true" if failure.get('name') is None else failure['name']
-                    fails.append('TEST-UNEXPECTED-FAIL | %s %s| %s' %
+                    logger.test_status(self.test_name, name, 'FAIL',
-                                 (os.path.basename(self.jsFile), diag, name))
+                                       message=diag)
                 self.assertEqual(0, results['failed'],
-                                 '%d tests failed:\n%s' % (results['failed'], '\n'.join(fails)))
+                                 '%d tests failed' % (results['failed']))
 
             self.assertTrue(results['passed'] + results['failed'] > 0,
                             'no tests run')

testing/marionette/client/marionette/runner/base.py

@@ -2,27 +2,27 @@
 # 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 optparse import OptionParser
 from datetime import datetime
-import logging
+from optparse import OptionParser
+
+import json
+import mozinfo
+import moznetwork
 import os
-import unittest
+import random
 import socket
 import sys
 import time
 import traceback
-import random
+import unittest
-import re
-import mozinfo
-import moznetwork
 import xml.dom.minidom as dom
 
 from manifestparser import TestManifest
-from mozhttpd import MozHttpd
 from marionette import Marionette
-from moztest.results import TestResultCollection, TestResult, relevant_line
 from mixins.b2g import B2GTestResultMixin, get_b2g_pid, get_dm
-
+from mozhttpd import MozHttpd
+from moztest.adapters.unit import StructuredTestRunner, StructuredTestResult
+from moztest.results import TestResultCollection, TestResult, relevant_line
 
 class MarionetteTest(TestResult):
 
@@ -35,8 +35,7 @@ class MarionetteTest(TestResult):
         else:
             return self.name
 
-
+class MarionetteTestResult(StructuredTestResult, TestResultCollection):
-class MarionetteTestResult(unittest._TextTestResult, TestResultCollection):
 
     resultClass = MarionetteTest
 
@@ -53,7 +52,7 @@ class MarionetteTestResult(unittest._TextTestResult, TestResultCollection):
                 bases.append(B2GTestResultMixin)
                 self.__class__.__bases__ = tuple(bases)
             B2GTestResultMixin.__init__(self, b2g_pid=pid)
-        unittest._TextTestResult.__init__(self, *args, **kwargs)
+        StructuredTestResult.__init__(self, *args, **kwargs)
 
     @property
     def skipped(self):
@@ -131,57 +130,31 @@ class MarionetteTestResult(unittest._TextTestResult, TestResultCollection):
 
     def addError(self, test, err):
         self.add_test_result(test, output=self._exc_info_to_string(err, test), result_actual='ERROR')
-        self._mirrorOutput = True
+        super(MarionetteTestResult, self).addError(test, err)
-        if self.showAll:
-            self.stream.writeln("ERROR")
-        elif self.dots:
-            self.stream.write('E')
-            self.stream.flush()
 
     def addFailure(self, test, err):
         self.add_test_result(test, output=self._exc_info_to_string(err, test), result_actual='UNEXPECTED-FAIL')
-        self._mirrorOutput = True
+        super(MarionetteTestResult, self).addFailure(test, err)
-        if self.showAll:
-            self.stream.writeln("FAIL")
-        elif self.dots:
-            self.stream.write('F')
-            self.stream.flush()
 
     def addSuccess(self, test):
         self.passed += 1
         self.add_test_result(test, result_actual='PASS')
-        if self.showAll:
+        super(MarionetteTestResult, self).addSuccess(test)
-            self.stream.writeln("ok")
-        elif self.dots:
-            self.stream.write('.')
-            self.stream.flush()
 
     def addExpectedFailure(self, test, err):
         """Called when an expected failure/error occured."""
         self.add_test_result(test, output=self._exc_info_to_string(err, test),
-                        result_actual='KNOWN-FAIL')
+                             result_actual='KNOWN-FAIL')
-        if self.showAll:
+        super(MarionetteTestResult, self).addExpectedFailure(test, err)
-            self.stream.writeln("expected failure")
-        elif self.dots:
-            self.stream.write("x")
-            self.stream.flush()
 
     def addUnexpectedSuccess(self, test):
         """Called when a test was expected to fail, but succeed."""
         self.add_test_result(test, result_actual='UNEXPECTED-PASS')
-        if self.showAll:
+        super(MarionetteTestResult, self).addUnexpectedSuccess(test)
-            self.stream.writeln("unexpected success")
-        elif self.dots:
-            self.stream.write("u")
-            self.stream.flush()
 
     def addSkip(self, test, reason):
         self.add_test_result(test, output=reason, result_actual='SKIPPED')
-        if self.showAll:
+        super(MarionetteTestResult, self).addSkip(test, reason)
-            self.stream.writeln("skipped {0!r}".format(reason))
-        elif self.dots:
-            self.stream.write("s")
-            self.stream.flush()
 
     def getInfo(self, test):
         return test.test_name
@@ -209,37 +182,10 @@ class MarionetteTestResult(unittest._TextTestResult, TestResultCollection):
                         break
                 if skip_log:
                     return
-                self.stream.writeln('\nSTART LOG:')
+                self.logger.info('START LOG:')
                 for line in testcase.loglines:
-                    self.stream.writeln(' '.join(line).encode('ascii', 'replace'))
+                    self.logger.info(' '.join(line).encode('ascii', 'replace'))
-                self.stream.writeln('END LOG:')
+                self.logger.info('END LOG:')
-
-    def printErrorList(self, flavour, errors):
-        TIMEOUT_MESSAGE = "ScriptTimeoutException: ScriptTimeoutException: timed out"
-        for error in errors:
-            err = error.output
-            self.stream.writeln(self.separator1)
-            self.stream.writeln("%s: %s" % (flavour, error.description))
-            self.stream.writeln(self.separator2)
-            lastline = None
-            fail_present = None
-            test_name = self.getInfo(error)
-            for line in err:
-                if not line.startswith('\t') and line != '':
-                    lastline = line
-                if 'TEST-UNEXPECTED-FAIL' in line:
-                    fail_present = True
-            for line in err:
-                if line != lastline or fail_present:
-                    if re.match('.*\.js', test_name):
-                        if error.reason != TIMEOUT_MESSAGE:
-                            self.stream.writeln("%s" % line)
-                    else:
-                        self.stream.writeln("%s" % line)
-
-                else:
-                    self.stream.writeln("TEST-UNEXPECTED-FAIL | %s | %s" %
-                                        (test_name, error.reason))
 
     def stopTest(self, *args, **kwargs):
         unittest._TextTestResult.stopTest(self, *args, **kwargs)
@@ -248,16 +194,15 @@ class MarionetteTestResult(unittest._TextTestResult, TestResultCollection):
             self.shouldStop = True
 
 
-class MarionetteTextTestRunner(unittest.TextTestRunner):
+class MarionetteTextTestRunner(StructuredTestRunner):
 
     resultclass = MarionetteTestResult
 
     def __init__(self, **kwargs):
-        self.marionette = kwargs['marionette']
+        self.marionette = kwargs.pop('marionette')
         self.capabilities = kwargs.pop('capabilities')
         self.pre_run_functions = []
         self.b2g_pid = None
-        del kwargs['marionette']
 
         if self.capabilities["device"] != "desktop" and self.capabilities["browserName"] == "B2G":
             def b2g_pre_run():
@@ -266,76 +211,24 @@ class MarionetteTextTestRunner(unittest.TextTestRunner):
                     self.b2g_pid = get_b2g_pid(get_dm(self.marionette))
             self.pre_run_functions.append(b2g_pre_run)
 
-        unittest.TextTestRunner.__init__(self, **kwargs)
+        StructuredTestRunner.__init__(self, **kwargs)
+
 
     def _makeResult(self):
         return self.resultclass(self.stream,
                                 self.descriptions,
                                 self.verbosity,
                                 marionette=self.marionette,
-                                b2g_pid=self.b2g_pid)
+                                b2g_pid=self.b2g_pid,
+                                logger=self.logger)
 
     def run(self, test):
         "Run the given test case or test suite."
         for pre_run_func in self.pre_run_functions:
             pre_run_func()
-        result = self._makeResult()
+
-        if hasattr(self, 'failfast'):
+        result = super(MarionetteTextTestRunner, self).run(test)
-            result.failfast = self.failfast
-        if hasattr(self, 'buffer'):
-            result.buffer = self.buffer
-        startTime = time.time()
-        startTestRun = getattr(result, 'startTestRun', None)
-        if startTestRun is not None:
-            startTestRun()
-        try:
-            test(result)
-        finally:
-            stopTestRun = getattr(result, 'stopTestRun', None)
-            if stopTestRun is not None:
-                stopTestRun()
-        stopTime = time.time()
-        if hasattr(result, 'time_taken'):
-            result.time_taken = stopTime - startTime
         result.printLogs(test)
-        result.printErrors()
-        if hasattr(result, 'separator2'):
-            self.stream.writeln(result.separator2)
-        run = result.testsRun
-        self.stream.writeln("Ran %d test%s in %.3fs" %
-                            (run, run != 1 and "s" or "", result.time_taken))
-        self.stream.writeln()
-
-        expectedFails = unexpectedSuccesses = skipped = 0
-        try:
-            results = map(len, (result.expectedFailures,
-                                result.unexpectedSuccesses,
-                                result.skipped))
-        except AttributeError:
-            pass
-        else:
-            expectedFails, unexpectedSuccesses, skipped = results
-
-        infos = []
-        if not result.wasSuccessful():
-            self.stream.write("FAILED")
-            failed, errored = map(len, (result.failures, result.errors))
-            if failed:
-                infos.append("failures=%d" % failed)
-            if errored:
-                infos.append("errors=%d" % errored)
-        else:
-            self.stream.write("OK")
-        if skipped:
-            infos.append("skipped=%d" % skipped)
-        if expectedFails:
-            infos.append("expected failures=%d" % expectedFails)
-        if unexpectedSuccesses:
-            infos.append("unexpected successes=%d" % unexpectedSuccesses)
-        if infos:
-            self.stream.writeln(" (%s)" % (", ".join(infos),))
-        else:
-            self.stream.write("\n")
         return result
 
 
@@ -423,7 +316,7 @@ class BaseMarionetteOptions(OptionParser):
                         default=[],
                         help='specify a command line argument to be passed onto the application')
         self.add_option('--binary',
-                        dest='bin',
+                        dest='binary',
                         action='store',
                         help='gecko executable to launch before running the test')
         self.add_option('--profile',
@@ -458,10 +351,6 @@ class BaseMarionetteOptions(OptionParser):
                         dest='timeout',
                         type=int,
                         help='if a --timeout value is given, it will set the default page load timeout, search timeout and script timeout to the given value. If not passed in, it will use the default values of 30000ms for page load, 0ms for search timeout and 10000ms for script timeout')
-        self.add_option('--es-server',
-                        dest='es_servers',
-                        action='append',
-                        help='the ElasticSearch server to use for autolog submission')
         self.add_option('--shuffle',
                         action='store_true',
                         dest='shuffle',
@@ -495,6 +384,12 @@ class BaseMarionetteOptions(OptionParser):
                              " a directory, the real log file will be created"
                              " given the format gecko-(timestamp).log. If it is"
                              " a file, if will be used directly. Default: 'gecko.log'")
+        self.add_option('--logger-name',
+                        dest='logger_name',
+                        action='store',
+                        default='Marionette-based Tests',
+                        help='Define the name to associate with the logger used')
+
 
     def parse_args(self, args=None, values=None):
         options, tests = OptionParser.parse_args(self, args, values)
@@ -508,18 +403,14 @@ class BaseMarionetteOptions(OptionParser):
             print 'must specify one or more test files, manifests, or directories'
             sys.exit(1)
 
-        if not options.emulator and not options.address and not options.bin:
+        if not options.emulator and not options.address and not options.binary:
             print 'must specify --binary, --emulator or --address'
             sys.exit(1)
 
-        if options.emulator and options.bin:
+        if options.emulator and options.binary:
             print 'can\'t specify both --emulator and --binary'
             sys.exit(1)
 
-        if not options.es_servers:
-            options.es_servers = ['elasticsearch-zlb.dev.vlan81.phx.mozilla.com:9200',
-                                  'elasticsearch-zlb.webapp.scl3.mozilla.com:9200']
-
         # default to storing logcat output for emulator runs
         if options.emulator and not options.logdir:
             options.logdir = 'logcat'
@@ -560,11 +451,11 @@ class BaseMarionetteTestRunner(object):
 
     def __init__(self, address=None, emulator=None, emulator_binary=None,
                  emulator_img=None, emulator_res='480x800', homedir=None,
-                 app=None, app_args=None, bin=None, profile=None, autolog=False,
+                 app=None, app_args=None, binary=None, profile=None, autolog=False,
                  revision=None, logger=None, testgroup="marionette", no_window=False,
                  logdir=None, xml_output=None, repeat=0,
                  testvars=None, tree=None, type=None, device_serial=None,
-                 symbols_path=None, timeout=None, es_servers=None, shuffle=False,
+                 symbols_path=None, timeout=None, shuffle=False,
                  shuffle_seed=random.randint(0, sys.maxint), sdcard=None,
                  this_chunk=1, total_chunks=1, sources=None, server_root=None,
                  gecko_log=None,
@@ -577,7 +468,7 @@ class BaseMarionetteTestRunner(object):
         self.homedir = homedir
         self.app = app
         self.app_args = app_args or []
-        self.bin = bin
+        self.bin = binary
         self.profile = profile
         self.autolog = autolog
         self.testgroup = testgroup
@@ -599,7 +490,6 @@ class BaseMarionetteTestRunner(object):
         self._device = None
         self._capabilities = None
         self._appName = None
-        self.es_servers = es_servers
         self.shuffle = shuffle
         self.shuffle_seed = shuffle_seed
         self.sdcard = sdcard
@@ -616,7 +506,6 @@ class BaseMarionetteTestRunner(object):
             if not os.path.exists(testvars):
                 raise IOError('--testvars file does not exist')
 
-            import json
             try:
                 with open(testvars) as f:
                     self.testvars = json.loads(f.read())
@@ -630,11 +519,6 @@ class BaseMarionetteTestRunner(object):
 
         self.reset_test_stats()
 
-        if self.logger is None:
-            self.logger = logging.getLogger('Marionette')
-            self.logger.setLevel(logging.INFO)
-            self.logger.addHandler(logging.StreamHandler())
-
         if self.logdir:
             if not os.access(self.logdir, os.F_OK):
                 os.mkdir(self.logdir)
@@ -746,50 +630,6 @@ class BaseMarionetteTestRunner(object):
     def start_marionette(self):
         self.marionette = Marionette(**self._build_kwargs())
 
-    def post_to_autolog(self, elapsedtime):
-        self.logger.info('posting results to autolog')
-
-        logfile = None
-        if self.emulator:
-            filename = os.path.join(os.path.abspath(self.logdir),
-                                    "emulator-%d.log" % self.marionette.emulator.port)
-            if os.access(filename, os.F_OK):
-                logfile = filename
-
-        for es_server in self.es_servers:
-
-            # This is all autolog stuff.
-            # See: https://wiki.mozilla.org/Auto-tools/Projects/Autolog
-            from mozautolog import RESTfulAutologTestGroup
-            testgroup = RESTfulAutologTestGroup(
-                testgroup=self.testgroup,
-                os='android',
-                platform='emulator',
-                harness='marionette',
-                server=es_server,
-                restserver=None,
-                machine=socket.gethostname(),
-                logfile=logfile)
-
-            testgroup.set_primary_product(
-                tree=self.tree,
-                buildtype='opt',
-                revision=self.revision)
-
-            testgroup.add_test_suite(
-                testsuite='b2g emulator testsuite',
-                elapsedtime=elapsedtime.seconds,
-                cmdline='',
-                passed=self.passed,
-                failed=self.failed,
-                todo=self.todo)
-
-            # Add in the test failures.
-            for f in self.failures:
-                testgroup.add_test_failure(test=f[0], text=f[1], status=f[2])
-
-            testgroup.submit()
-
     def run_tests(self, tests):
         self.reset_test_stats()
         starttime = datetime.utcnow()
@@ -808,12 +648,14 @@ class BaseMarionetteTestRunner(object):
                 need_external_ip = False
 
         if not self.httpd:
-            print "starting httpd"
+            self.logger.info("starting httpd")
             self.start_httpd(need_external_ip)
 
         for test in tests:
             self.add_test(test)
 
+        self.logger.suite_start(self.tests)
+
         counter = self.repeat
         while counter >=0:
             round = self.repeat - counter
@@ -821,16 +663,17 @@ class BaseMarionetteTestRunner(object):
                 self.logger.info('\nREPEAT %d\n-------' % round)
             self.run_test_sets()
             counter -= 1
+
         self.logger.info('\nSUMMARY\n-------')
         self.logger.info('passed: %d' % self.passed)
         if self.unexpected_successes == 0:
             self.logger.info('failed: %d' % self.failed)
         else:
-            self.logger.info('failed: %d (unexpected sucesses: %d)', self.failed, self.unexpected_successes)
+            self.logger.info('failed: %d (unexpected sucesses: %d)' % (self.failed, self.unexpected_successes))
         if self.skipped == 0:
-            self.logger.info('todo: %d', self.todo)
+            self.logger.info('todo: %d' % self.todo)
         else:
-            self.logger.info('todo: %d (skipped: %d)', self.todo, self.skipped)
+            self.logger.info('todo: %d (skipped: %d)' % (self.todo, self.skipped))
 
         if self.failed > 0:
             self.logger.info('\nFAILED TESTS\n-------')
@@ -843,8 +686,6 @@ class BaseMarionetteTestRunner(object):
             traceback.print_exc()
 
         self.elapsedtime = datetime.utcnow() - starttime
-        if self.autolog:
-            self.post_to_autolog(self.elapsedtime)
 
         if self.xml_output:
             xml_dir = os.path.dirname(os.path.abspath(self.xml_output))
@@ -864,6 +705,8 @@ class BaseMarionetteTestRunner(object):
         if self.shuffle:
             self.logger.info("Using seed where seed is:%d" % self.shuffle_seed)
 
+        self.logger.suite_end()
+
     def add_test(self, test, expected='pass', oop=None):
         filepath = os.path.abspath(test)
 
@@ -972,7 +815,6 @@ class BaseMarionetteTestRunner(object):
         self.tests.append({'filepath': filepath, 'expected': expected, 'oop': oop})
 
     def run_test(self, filepath, expected, oop):
-        self.logger.info('TEST-START %s' % os.path.basename(filepath))
 
         testloader = unittest.TestLoader()
         suite = unittest.TestSuite()
@@ -991,7 +833,7 @@ class BaseMarionetteTestRunner(object):
                 break
 
         if suite.countTestCases():
-            runner = self.textrunnerclass(verbosity=3,
+            runner = self.textrunnerclass(logger=self.logger,
                                           marionette=self.marionette,
                                           capabilities=self.capabilities)
             results = runner.run(suite)
@@ -1008,7 +850,7 @@ class BaseMarionetteTestRunner(object):
                 self.failed += len(results.unexpectedSuccesses)
                 self.unexpected_successes += len(results.unexpectedSuccesses)
                 for failure in results.unexpectedSuccesses:
-                    self.failures.append((results.getInfo(failure), 'TEST-UNEXPECTED-PASS'))
+                    self.failures.append((results.getInfo(failure), failure.output, 'TEST-UNEXPECTED-PASS'))
             if hasattr(results, 'expectedFailures'):
                 self.todo += len(results.expectedFailures)
 
@@ -1132,4 +974,3 @@ class BaseMarionetteTestRunner(object):
 
         doc.appendChild(testsuite)
         return doc.toprettyxml(encoding='utf-8')
-

testing/marionette/client/marionette/runner/mixins/b2g.py

@@ -56,48 +56,53 @@ class B2GTestResultMixin(object):
         self.result_modifiers.append(self.b2g_output_modifier)
         self.b2g_pid = kwargs.pop('b2g_pid')
 
-    def b2g_output_modifier(self, test, result_expected, result_actual, output, context):
+    def _diagnose_socket(self):
         # This function will check if b2g is running and report any recent errors. This is
         # used in automation since a plain timeout error doesn't tell you
         # much information about what actually is going on
-        def diagnose_socket(output):
-            dm_type = os.environ.get('DM_TRANS', 'adb')
-            if dm_type == 'adb':
-                device_manager = get_dm(self.marionette)
-                pid = get_b2g_pid(device_manager)
-                if pid:
-                    # find recent errors
-                    message = ""
-                    error_re = re.compile(r"""[\s\S]*(exception|error)[\s\S]*""", flags=re.IGNORECASE)
-                    logcat = device_manager.getLogcat()
-                    latest = []
-                    iters = len(logcat) - 1
-                    # reading from the latest line
-                    while len(latest) < 5 and iters >= 0:
-                        line = logcat[iters]
-                        error_log_line = error_re.match(line)
-                        if error_log_line is not None:
-                            latest.append(line)
-                        iters -= 1
-                    message += "\nMost recent errors/exceptions are:\n"
-                    for line in reversed(latest):
-                        message += "%s" % line
-                    b2g_status = ""
-                    if pid != self.b2g_pid:
-                        b2g_status = "The B2G process has restarted after crashing during the tests so "
-                    else:
-                        b2g_status = "B2G is still running but "
-                    output += "%s\n%sMarionette can't respond due to either a Gecko, Gaia or Marionette error. " \
-                              "Above, the 5 most recent errors are " \
-                              "listed. Check logcat for all errors if these errors are not the cause " \
-                              "of the failure." % (message, b2g_status)
-                else:
-                    output += "B2G process has died"
-            return output
-        # output is the actual string output from the test, so we have to do string comparison
-        if "Broken pipe" in output:
-            output = diagnose_socket(output)
-        elif "Connection timed out" in output:
-            output = diagnose_socket(output)
-        return result_expected, result_actual, output, context
 
+        extra_output = None
+        dm_type = os.environ.get('DM_TRANS', 'adb')
+        if dm_type == 'adb':
+            device_manager = get_dm(self.marionette)
+            pid = get_b2g_pid(device_manager)
+            if pid:
+                # find recent errors
+                message = ""
+                error_re = re.compile(r"""[\s\S]*(exception|error)[\s\S]*""",
+                                      flags=re.IGNORECASE)
+                logcat = device_manager.getLogcat()
+                latest = []
+                iters = len(logcat) - 1
+                # reading from the latest line
+                while len(latest) < 5 and iters >= 0:
+                    line = logcat[iters]
+                    error_log_line = error_re.match(line)
+                    if error_log_line is not None:
+                        latest.append(line)
+                    iters -= 1
+                message += "\nMost recent errors/exceptions are:\n"
+                for line in reversed(latest):
+                    message += "%s" % line
+                b2g_status = ""
+                if pid != self.b2g_pid:
+                    b2g_status = "The B2G process has restarted after crashing during  the tests so "
+                else:
+                    b2g_status = "B2G is still running but "
+                extra_output = ("%s\n%sMarionette can't respond due to either a Gecko, Gaia or Marionette error. "
+                                "Above, the 5 most recent errors are listed. "
+                                "Check logcat for all errors if these errors are not the cause "
+                                "of the failure." % (message, b2g_status))
+            else:
+                extra_output = "B2G process has died"
+        return extra_output
+
+    def b2g_output_modifier(self, test, result_expected, result_actual, output, context):
+        # output is the actual string output from the test, so we have to do string comparison
+        if "Broken pipe" in output or "Connection timed out" in output:
+            extra_output = self._diagnose_socket()
+            if extra_output:
+                self.logger.error(extra_output)
+                output += extra_output
+
+        return result_expected, result_actual, output, context

testing/marionette/client/marionette/runtests.py

@@ -5,30 +5,64 @@
 import sys
 
 from marionette_test import MarionetteTestCase, MarionetteJSTestCase
+from mozlog import structured
 from runner import BaseMarionetteTestRunner, BaseMarionetteOptions
 
+class MarionetteTbplFormatter(structured.formatters.TbplFormatter):
+    """Formatter that logs failures in a format that agrees with legacy
+    log data used by tbpl."""
+
+    def test_end(self, data):
+        # TBPL ui expects relevant info about an exception to appear in the first
+        # line of the log message, however tracebacks provided by marionette
+        # put this information on the last line.
+        if "message" in data:
+            message_lines = [line for line in data["message"].splitlines() if line != ""]
+            if "Traceback" in message_lines[0]:
+                exc_msg_index = None
+                for index, line in enumerate(message_lines):
+                    if "Error: " in line or "Exception: " in line:
+                        exc_msg_index = index
+                        break
+                if exc_msg_index:
+                    message_lines = (message_lines[exc_msg_index:] +
+                                     message_lines[:exc_msg_index])
+            data["message"] = "\n".join(message_lines)
+        return super(MarionetteTbplFormatter, self).test_end(data)
 
 class MarionetteTestRunner(BaseMarionetteTestRunner):
     def __init__(self, **kwargs):
         BaseMarionetteTestRunner.__init__(self, **kwargs)
         self.test_handlers = [MarionetteTestCase, MarionetteJSTestCase]
 
-
 def startTestRunner(runner_class, options, tests):
+
     runner = runner_class(**vars(options))
     runner.run_tests(tests)
     return runner
 
-
 def cli(runner_class=MarionetteTestRunner, parser_class=BaseMarionetteOptions):
     parser = parser_class(usage='%prog [options] test_file_or_dir <test_file_or_dir> ...')
+    structured.commandline.add_logging_group(parser)
     options, tests = parser.parse_args()
     parser.verify_usage(options, tests)
 
+    logger = structured.commandline.setup_logging(options.logger_name,
+                                                  options,
+                                                  {})
+
+    # Only add the tbpl logger if a handler isn't already logging to stdout
+    has_stdout_logger = any([h.stream == sys.stdout for h in logger.handlers])
+    if not has_stdout_logger:
+        formatter = MarionetteTbplFormatter()
+        handler = structured.handlers.StreamHandler(sys.stdout, formatter)
+        logger.add_handler(handler)
+
+    options.logger = logger
+
     runner = startTestRunner(runner_class, options, tests)
     if runner.failed > 0:
         sys.exit(10)
 
 if __name__ == "__main__":
     cli()
-

testing/marionette/client/requirements.txt

@@ -5,6 +5,7 @@ mozinfo >= 0.7
 mozprocess >= 0.9
 mozrunner >= 6.0
 mozdevice >= 0.37
+mozlog >= 2.0
 moznetwork >= 0.21
 mozcrash >= 0.5
 mozprofile >= 0.7

testing/marionette/client/setup.py

@@ -2,7 +2,7 @@ import os
 from setuptools import setup, find_packages
 import sys
 
-version = '0.7.11'
+version = '0.8'
 
 # dependencies
 with open('requirements.txt') as f:

testing/marionette/mach_commands.py

@@ -3,7 +3,11 @@
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 from __future__ import unicode_literals
+
 import os
+import sys
+
+from mozlog import structured
 
 from mozbuild.base import (
     MachCommandBase,
@@ -26,7 +30,7 @@ VARIANT=eng ./build.sh
 '''
 
 def run_marionette(tests, b2g_path=None, emulator=None, testtype=None,
-    address=None, bin=None, topsrcdir=None):
+    address=None, binary=None, topsrcdir=None):
     from marionette.runtests import (
         MarionetteTestRunner,
         BaseMarionetteOptions,
@@ -46,13 +50,17 @@ def run_marionette(tests, b2g_path=None, emulator=None, testtype=None,
         if emulator:
             options.emulator = emulator
     else:
-        options.bin = bin
+        options.binary = binary
-        path, exe = os.path.split(options.bin)
+        path, exe = os.path.split(options.binary)
 
     options.address = address
 
     parser.verify_usage(options, tests)
 
+    options.logger = structured.commandline.setup_logging("Marionette Unit Tests",
+                                                          options,
+                                                          {"mach": sys.stdout})
+
     runner = startTestRunner(MarionetteTestRunner, options, tests)
     if runner.failed > 0:
         return 1
@@ -103,6 +111,6 @@ class MachCommands(MachCommandBase):
     @CommandArgument('tests', nargs='*', metavar='TESTS',
         help='Path to test(s) to run.')
     def run_marionette_test(self, tests, address=None, testtype=None):
-        bin = self.get_binary_path('app')
+        binary = self.get_binary_path('app')
-        return run_marionette(tests, bin=bin, testtype=testtype,
+        return run_marionette(tests, binary=binary, testtype=testtype,
             topsrcdir=self.topsrcdir, address=address)