Bug 959520 - Make socket.timeout error messages more useful, r=jgriffin
authorMalini Das <mdas@mozilla.com>
Mon, 10 Feb 2014 10:10:45 -0500
changeset 167901 083e26c547507deb4ffe84604109bf10a64cad54
parent 167900 64b3f71d79a8812433414b77d70438fb2fa3e219
child 167902 6fda903b457151acc2b2edefccbe481eb7174229
push id26191
push userryanvm@gmail.com
push dateMon, 10 Feb 2014 20:42:58 +0000
treeherdermozilla-central@d812f80a0f1d [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjgriffin
bugs959520
milestone30.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 959520 - Make socket.timeout error messages more useful, r=jgriffin
testing/marionette/client/marionette/client.py
testing/marionette/client/marionette/runner/base.py
testing/marionette/client/marionette/runner/mixins/b2g.py
testing/marionette/client/marionette/runner/mixins/reporting.py
--- a/testing/marionette/client/marionette/client.py
+++ b/testing/marionette/client/marionette/client.py
@@ -1,12 +1,13 @@
 # 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 errno
 import json
 import socket
 
 from errors import InvalidResponseException, ErrorCodes
 
 
 class MarionetteClient(object):
     """ The Marionette socket client.  This speaks the same protocol
@@ -47,19 +48,18 @@ class MarionetteClient(object):
         response = self.sock.recv(10)
         sep = response.find(':')
         length = response[0:sep]
         if length != '':
             response = response[sep + 1:]
             response += self._recv_n_bytes(int(length) + 1 + len(length) - 10)
             return json.loads(response)
         else:
-            raise InvalidResponseException("Could not successfully complete "
-                                           "transport of message to Gecko, "
-                                           "socket closed?",
+            raise InvalidResponseException("Could not communicate with Marionette server. "
+                                           "Is the Gecko process still running?",
                                            status=ErrorCodes.INVALID_RESPONSE)
 
     def connect(self, timeout=360.0):
         """ Connect to the server and process the hello message we expect
             to receive in response.
         """
         self.sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
         self.sock.settimeout(timeout)
@@ -85,17 +85,23 @@ class MarionetteClient(object):
             self.connect()
         if 'to' not in msg:
             msg['to'] = self.actor
         data = json.dumps(msg)
         data = '%s:%s' % (len(data), data)
 
         for packet in [data[i:i + self.max_packet_length] for i in
                        range(0, len(data), self.max_packet_length)]:
-            self.sock.send(packet)
+            try: 
+                self.sock.send(packet)
+            except IOError as e:
+                if e.errno == errno.EPIPE:
+                    raise IOError("%s: Connection to Marionette server is lost. Check gecko.log (desktop firefox) or logcat (b2g) for errors." % str(e))
+                else:
+                    raise e
 
         response = self.receive()
         return response
 
     def close(self):
         """ Close the socket.
         """
         self.sock.close()
--- a/testing/marionette/client/marionette/runner/base.py
+++ b/testing/marionette/client/marionette/runner/base.py
@@ -15,16 +15,17 @@ import random
 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
 
 
 class MarionetteTest(TestResult):
 
     @property
     def test_name(self):
         if self.test_class is not None:
             return '%s.py %s.%s' % (self.test_class.split('.')[0],
@@ -108,17 +109,17 @@ class MarionetteTestResult(unittest._Tex
             name = os.path.basename(test.jsFile)
             test_class = None
 
         t = self.resultClass(name=name, test_class=test_class,
                        time_start=test.start_time, result_expected=result_expected,
                        context=context, **kwargs)
         # call any registered result modifiers
         for modifier in self.result_modifiers:
-            modifier(t, result_expected, result_actual, output, context)
+            result_expected, result_actual, output, context = modifier(t, result_expected, result_actual, output, context)
         t.finish(result_actual,
                  time_end=time.time() if test.start_time else 0,
                  reason=relevant_line(output),
                  output=output)
         self.append(t)
 
     def addError(self, test, err):
         self.add_test_result(test, output=self._exc_info_to_string(err, test), result_actual='ERROR')
@@ -233,16 +234,17 @@ class MarionetteTestResult(unittest._Tex
 
 
 class MarionetteTextTestRunner(unittest.TextTestRunner):
 
     resultclass = MarionetteTestResult
 
     def __init__(self, **kwargs):
         self.marionette = kwargs['marionette']
+        self.capabilities = kwargs.pop('capabilities')
         del kwargs['marionette']
         unittest.TextTestRunner.__init__(self, **kwargs)
 
     def _makeResult(self):
         return self.resultclass(self.stream,
                                 self.descriptions,
                                 self.verbosity,
                                 marionette=self.marionette)
@@ -304,16 +306,50 @@ class MarionetteTextTestRunner(unittest.
             infos.append("unexpected successes=%d" % unexpectedSuccesses)
         if infos:
             self.stream.writeln(" (%s)" % (", ".join(infos),))
         else:
             self.stream.write("\n")
         return result
 
 
+class B2GMarionetteTestResult(MarionetteTestResult, B2GTestResultMixin):
+
+    def __init__(self, *args, **kwargs):
+        # stupid hack because _TextTestRunner doesn't accept **kwargs
+        b2g_pid = kwargs.pop('b2g_pid')
+        MarionetteTestResult.__init__(self, *args, **kwargs)
+        kwargs['b2g_pid'] = b2g_pid
+        B2GTestResultMixin.__init__(self, *args, **kwargs)
+ 
+
+class B2GMarionetteTextTestRunner(MarionetteTextTestRunner):
+
+    resultclass = B2GMarionetteTestResult
+
+    def __init__(self, **kwargs):
+        MarionetteTextTestRunner.__init__(self, **kwargs)
+        if self.capabilities['device'] != 'desktop':
+            self.resultclass = B2GMarionetteTestResult
+        self.b2g_pid = None
+
+    def _makeResult(self):
+        return self.resultclass(self.stream,
+                                self.descriptions,
+                                self.verbosity,
+                                marionette=self.marionette,
+                                b2g_pid=self.b2g_pid)
+
+    def run(self, test):
+        dm_type = os.environ.get('DM_TRANS', 'adb')
+        if dm_type == 'adb':
+            self.b2g_pid = get_b2g_pid(get_dm(self.marionette))
+        return super(B2GMarionetteTextTestRunner, self).run(test)
+
+
 class BaseMarionetteOptions(OptionParser):
     def __init__(self, **kwargs):
         OptionParser.__init__(self, **kwargs)
         self.parse_args_handlers = [] # Used by mixins
         self.verify_usage_handlers = [] # Used by mixins
         self.add_option('--autolog',
                         action='store_true',
                         dest='autolog',
@@ -763,16 +799,22 @@ class BaseMarionetteTestRunner(object):
         if not self.httpd:
             print "starting httpd"
             self.start_httpd()
 
         if not self.marionette:
             self.start_marionette()
             if self.emulator:
                 self.marionette.emulator.wait_for_homescreen(self.marionette)
+            # Retrieve capabilities for later use
+            if not self._capabilities:
+                self.capabilities
+
+        if self.capabilities['device'] != 'desktop':
+            self.textrunnerclass = B2GMarionetteTextTestRunner
 
         testargs = {}
         if self.type is not None:
             testtypes = self.type.replace('+', ' +').replace('-', ' -').split()
             for atype in testtypes:
                 if atype.startswith('+'):
                     testargs.update({ atype[1:]: 'true' })
                 elif atype.startswith('-'):
@@ -853,17 +895,18 @@ class BaseMarionetteTestRunner(object):
                                            testloader,
                                            self.marionette,
                                            self.testvars,
                                            **self.test_kwargs)
                 break
 
         if suite.countTestCases():
             runner = self.textrunnerclass(verbosity=3,
-                                          marionette=self.marionette)
+                                          marionette=self.marionette,
+                                          capabilities=self.capabilities)
             results = runner.run(suite)
             self.results.append(results)
 
             self.failed += len(results.failures) + len(results.errors)
             if hasattr(results, 'skipped'):
                 self.todo += len(results.skipped)
             self.passed += results.passed
             for failure in results.failures + results.errors:
--- a/testing/marionette/client/marionette/runner/mixins/b2g.py
+++ b/testing/marionette/client/marionette/runner/mixins/b2g.py
@@ -1,31 +1,102 @@
 # 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 mozdevice
 import os
+import re
+
+
+def get_dm(marionette=None,**kwargs):
+    if marionette and marionette.emulator:
+        adb_path = marionette.emulator.b2g.adb_path
+        return mozdevice.DeviceManagerADB(adbPath=adb_path,
+                                          deviceSerial='emulator-%d' % marionette.emulator.port,
+                                          **kwargs)
+    else:
+        dm_type = os.environ.get('DM_TRANS', 'adb')
+        if dm_type == 'adb':
+            return mozdevice.DeviceManagerADB(**kwargs)
+        elif dm_type == 'sut':
+            host = os.environ.get('TEST_DEVICE')
+            if not host:
+                raise Exception('Must specify host with SUT!')
+            return mozdevice.DeviceManagerSUT(host=host)
+        else:
+            raise Exception('Unknown device manager type: %s' % dm_type)
+
+
+def get_b2g_pid(dm):
+    b2g_output = dm.shellCheckOutput(['b2g-ps'])
+    pid_re = re.compile(r"""[\s\S]*root[\s]*([\d]+)[\s]*(?:[\w]*[\s]*){6}/system/b2g/b2g""")
+    if '/system/b2g/b2g' in b2g_output:
+        pid = pid_re.match(b2g_output)
+        return pid.group(1)
 
 
 class B2GTestCaseMixin(object):
 
     # TODO: add methods like 'restart b2g'
     def __init__(self, *args, **kwargs):
         self._device_manager = None
 
     def get_device_manager(self, *args, **kwargs):
         if not self._device_manager:
-            dm_type = os.environ.get('DM_TRANS', 'adb')
-            if dm_type == 'adb':
-                self._device_manager = mozdevice.DeviceManagerADB(**kwargs)
-            elif dm_type == 'sut':
-                host = os.environ.get('TEST_DEVICE')
-                if not host:
-                    raise Exception('Must specify host with SUT!')
-                self._device_manager = mozdevice.DeviceManagerSUT(host=host)
-            else:
-                raise Exception('Unknown device manager type: %s' % dm_type)
+            self._device_manager = get_dm(self.marionette, **kwargs)
         return self._device_manager
 
     @property
     def device_manager(self):
         return self.get_device_manager()
+
+class B2GTestResultMixin(object):
+
+    def __init__(self, *args, **kwargs):
+        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):
+        # 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
+
--- a/testing/marionette/client/marionette/runner/mixins/reporting.py
+++ b/testing/marionette/client/marionette/runner/mixins/reporting.py
@@ -188,16 +188,17 @@ class HTMLReportingTestResultMixin(objec
 
     def __init__(self, *args, **kwargs):
         self.result_modifiers.append(self.html_modifier)
 
     def html_modifier(self, test, result_expected, result_actual, output, context):
         test.debug = None
         if result_actual is not 'PASS':
             test.debug = self.gather_debug()
+        return result_expected, result_actual, output, context
 
     def gather_debug(self):
         debug = {}
         try:
             # TODO make screenshot consistant size by using full viewport
             # Bug 883294 - Add ability to take full viewport screenshots
             debug['screenshot'] = self.marionette.screenshot()
             debug['source'] = self.marionette.page_source