Bug 1026710 - Make DeviceManagerADB use mozprocess to allow logging. r=wlach
authorArmen Zambrano Gasparnian <armenzg@mozilla.com>
Tue, 15 Jul 2014 08:59:48 -0400
changeset 194165 39f7ac6c97e3
parent 194164 beb19278a045
child 194166 43878d4b6d7f
push id27139
push userkwierso@gmail.com
push date2014-07-15 23:58 +0000
Treeherderresults
reviewerswlach
bugs1026710
milestone33.0a1
Bug 1026710 - Make DeviceManagerADB use mozprocess to allow logging. r=wlach

Up until now, mozdevice has been using subprocess. The switch gives us the
ability to log adb commands and its output. This will be mainly used
for the Firefox OS cert suite.
testing/mozbase/mozdevice/mozdevice/devicemanager.py
testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py
testing/mozbase/mozdevice/setup.py
testing/mozbase/mozlog/mozlog/__init__.py
testing/mozbase/mozprocess/mozprocess/processhandler.py
--- a/testing/mozbase/mozdevice/mozdevice/devicemanager.py
+++ b/testing/mozbase/mozdevice/mozdevice/devicemanager.py
@@ -42,23 +42,36 @@ class DeviceManager(object):
 
     Never instantiate this class directly! Instead, instantiate an
     implementation of it like DeviceManagerADB or DeviceManagerSUT.
     """
 
     _logcatNeedsRoot = True
 
     def __init__(self, logLevel=mozlog.ERROR, deviceRoot=None):
-        self._logger = mozlog.getLogger("DeviceManager")
+        try:
+            self._logger = mozlog.structured.structuredlog.get_default_logger(component="DeviceManager")
+            if not self._logger: # no global structured logger, fall back to reg logging
+                self._logger = mozlog.getLogger("DeviceManager")
+                self._logger.setLevel(logLevel)
+        except AttributeError:
+            # Structured logging doesn't work on Python 2.6
+            self._logger = None
         self._logLevel = logLevel
-        self._logger.setLevel(logLevel)
         self._remoteIsWin = None
         self._isDeviceRootSetup = False
         self._deviceRoot = deviceRoot
 
+    def _log(self, data):
+        """
+        This helper function is called by ProcessHandler to log
+        the output produced by processes
+        """
+        self._logger.debug(data)
+
     @property
     def remoteIsWin(self):
         if self._remoteIsWin is None:
             self._remoteIsWin = self.getInfo("os")["os"][0] == "windows"
         return self._remoteIsWin
 
     @property
     def logLevel(self):
--- a/testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py
+++ b/testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py
@@ -1,20 +1,20 @@
 # 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 subprocess
 import re
 import os
 import shutil
 import tempfile
 import time
 
-from devicemanager import DeviceManager, DMError, _pop_last_line
+from devicemanager import DeviceManager, DMError
+from mozprocess import ProcessHandler
 import mozfile
 import mozlog
 
 
 class DeviceManagerADB(DeviceManager):
     """
     Implementation of DeviceManager interface that uses the Android "adb"
     utility to communicate with the device. Normally used to communicate
@@ -116,47 +116,42 @@ class DeviceManagerADB(DeviceManager):
             cmdline = envstr + "; " + cmdline
 
         # all output should be in stdout
         args=[self._adbPath]
         if self._deviceSerial:
             args.extend(['-s', self._deviceSerial])
         args.extend(["shell", cmdline])
 
-        procOut = tempfile.SpooledTemporaryFile()
-        procErr = tempfile.SpooledTemporaryFile()
-        proc = subprocess.Popen(args, stdout=procOut, stderr=procErr)
+        def _raise():
+            raise DMError("Timeout exceeded for shell call")
+
+        self._logger.debug("shell - command: %s" % ' '.join(args))
+        proc = ProcessHandler(args, processOutputLine=self._log, onTimeout=_raise)
 
         if not timeout:
             # We are asserting that all commands will complete in this time unless otherwise specified
             timeout = self.default_timeout
 
         timeout = int(timeout)
-        start_time = time.time()
-        ret_code = proc.poll()
-        while ((time.time() - start_time) <= timeout) and ret_code == None:
-            time.sleep(self._pollingInterval)
-            ret_code = proc.poll()
-        if ret_code == None:
-            proc.kill()
-            raise DMError("Timeout exceeded for shell call")
+        proc.run(timeout)
+        proc.wait()
+        output = proc.output
 
-        procOut.seek(0)
-        outputfile.write(procOut.read().rstrip('\n'))
-        procOut.close()
-        procErr.close()
-
-        lastline = _pop_last_line(outputfile)
-        if lastline:
-            m = re.search('([0-9]+)', lastline)
-            if m:
-                return_code = m.group(1)
-                outputfile.seek(-2, 2)
-                outputfile.truncate() # truncate off the return code
-                return int(return_code)
+        if output:
+            lastline = output[-1]
+            if lastline:
+                m = re.search('([0-9]+)', lastline)
+                if m:
+                    return_code = m.group(1)
+                    for line in output:
+                        outputfile.write(line + '\n')
+                    outputfile.seek(-2, 2)
+                    outputfile.truncate() # truncate off the return code
+                    return int(return_code)
 
         return None
 
     def forward(self, local, remote):
         """
         Forward socket connections.
 
         Forward specs are one of:
@@ -171,19 +166,19 @@ class DeviceManagerADB(DeviceManager):
 
     def remount(self):
         "Remounts the /system partition on the device read-write."
         return self._checkCmd(['remount'])
 
     def devices(self):
         "Return a list of connected devices as (serial, status) tuples."
         proc = self._runCmd(['devices'])
-        proc.stdout.readline() # ignore first line of output
+        proc.output.pop(0) # ignore first line of output
         devices = []
-        for line in iter(proc.stdout.readline, ''):
+        for line in proc.output:
             result = re.match('(.*?)\t(.*)', line)
             if result:
                 devices.append((result.group(1), result.group(2)))
         return devices
 
     def _connectRemoteADB(self):
         self._checkCmd(["connect", self.host + ":" + str(self.port)])
 
@@ -201,38 +196,38 @@ class DeviceManagerADB(DeviceManager):
                           (localname, destname))
         if not os.access(localname, os.F_OK):
             raise DMError("File not found: %s" % localname)
 
         self._checkCmd(["push", os.path.realpath(localname), destname],
                        retryLimit=retryLimit)
 
     def mkDir(self, name):
-        result = self._runCmd(["shell", "mkdir", name]).stdout.read()
+        result = str(self._runCmd(["shell", "mkdir", name]).output)
         if 'read-only file system' in result.lower():
             raise DMError("Error creating directory: read only file system")
 
     def pushDir(self, localDir, remoteDir, retryLimit=None, timeout=None):
         # adb "push" accepts a directory as an argument, but if the directory
         # contains symbolic links, the links are pushed, rather than the linked
         # files; we either zip/unzip or re-copy the directory into a temporary
         # one to get around this limitation
         retryLimit = retryLimit or self.retryLimit
         if not self.dirExists(remoteDir):
             self.mkDirs(remoteDir+"/x")
         if self._useZip:
             try:
                 localZip = tempfile.mktemp() + ".zip"
                 remoteZip = remoteDir + "/adbdmtmp.zip"
-                subprocess.Popen(["zip", "-r", localZip, '.'], cwd=localDir,
-                                 stdout=subprocess.PIPE, stderr=subprocess.PIPE).communicate()
+                ProcessHandler(["zip", "-r", localZip, '.'], cwd=localDir,
+                        processOutputLine=self._log).run().wait()
                 self.pushFile(localZip, remoteZip, retryLimit=retryLimit, createDir=False)
                 mozfile.remove(localZip)
                 data = self._runCmd(["shell", "unzip", "-o", remoteZip,
-                                     "-d", remoteDir]).stdout.read()
+                                     "-d", remoteDir]).output
                 self._checkCmd(["shell", "rm", remoteZip],
                                retryLimit=retryLimit, timeout=timeout)
                 if re.search("unzip: exiting", data) or re.search("Operation not permitted", data):
                     raise Exception("unzip failed, or permissions error")
             except:
                 self._logger.info("zip/unzip failure: falling back to normal push")
                 self._useZip = False
                 self.pushDir(localDir, remoteDir, retryLimit=retryLimit)
@@ -240,28 +235,26 @@ class DeviceManagerADB(DeviceManager):
             tmpDir = tempfile.mkdtemp()
             # copytree's target dir must not already exist, so create a subdir
             tmpDirTarget = os.path.join(tmpDir, "tmp")
             shutil.copytree(localDir, tmpDirTarget)
             self._checkCmd(["push", tmpDirTarget, remoteDir], retryLimit=retryLimit)
             mozfile.remove(tmpDir)
 
     def dirExists(self, remotePath):
-        p = self._runCmd(["shell", "ls", "-a", remotePath + '/'])
+        data = self._runCmd(["shell", "ls", "-a", remotePath + '/']).output
 
-        data = p.stdout.readlines()
         if len(data) == 1:
             res = data[0]
             if "Not a directory" in res or "No such file or directory" in res:
                 return False
         return True
 
     def fileExists(self, filepath):
-        p = self._runCmd(["shell", "ls", "-a", filepath])
-        data = p.stdout.readlines()
+        data = self._runCmd(["shell", "ls", "-a", filepath]).output
         if len(data) == 1:
             foundpath = data[0].decode('utf-8').rstrip()
             if foundpath == filepath:
                 return True
         return False
 
     def removeFile(self, filename):
         if self.fileExists(filename):
@@ -275,46 +268,44 @@ class DeviceManagerADB(DeviceManager):
 
     def moveTree(self, source, destination):
         self._checkCmd(["shell", "mv", source, destination])
 
     def copyTree(self, source, destination):
         self._checkCmd(["shell", "dd", "if=%s" % source, "of=%s" % destination])
 
     def listFiles(self, rootdir):
-        p = self._runCmd(["shell", "ls", "-a", rootdir])
-        data = p.stdout.readlines()
+        data = self._runCmd(["shell", "ls", "-a", rootdir]).output
         data[:] = [item.rstrip('\r\n') for item in data]
         if (len(data) == 1):
             if (data[0] == rootdir):
                 return []
             if (data[0].find("No such file or directory") != -1):
                 return []
             if (data[0].find("Not a directory") != -1):
                 return []
             if (data[0].find("Permission denied") != -1):
                 return []
             if (data[0].find("opendir failed") != -1):
                 return []
         return data
 
     def getProcessList(self):
         p = self._runCmd(["shell", "ps"])
-            # first line is the headers
-        p.stdout.readline()
-        proc = p.stdout.readline()
+        # first line is the headers
+        p.output.pop(0)
         ret = []
-        while (proc):
+        for proc in p.output:
             els = proc.split()
-            # we need to figure out if this is "user pid name" or "pid user vsz stat command"
+            # We need to figure out if this is "user pid name" or
+            # "pid user vsz stat command"
             if els[1].isdigit():
                 ret.append(list([int(els[1]), els[len(els) - 1], els[0]]))
             else:
                 ret.append(list([int(els[0]), els[len(els) - 1], els[1]]))
-            proc =  p.stdout.readline()
         return ret
 
     def fireProcess(self, appname, failIfRunning=False):
         """
         Starts a process
 
         returns: pid
 
@@ -377,27 +368,26 @@ class DeviceManagerADB(DeviceManager):
         procs = self.getProcessList()
         for (pid, name, user) in procs:
             if name == appname:
                 args = ["shell", "kill"]
                 if sig:
                     args.append("-%d" % sig)
                 args.append(str(pid))
                 p = self._runCmd(args)
-                p.communicate()
                 if p.returncode != 0:
                     raise DMError("Error killing process "
-                                  "'%s': %s" % (appname, p.stdout.read()))
+                                  "'%s': %s" % (appname, p.output))
 
     def _runPull(self, remoteFile, localFile):
         """
         Pulls remoteFile from device to host
         """
         try:
-            self._runCmd(["pull",  remoteFile, localFile]).communicate()
+            self._runCmd(["pull",  remoteFile, localFile])
         except (OSError, ValueError):
             raise DMError("Error pulling remote file '%s' to '%s'" % (remoteFile, localFile))
 
     def pullFile(self, remoteFile, offset=None, length=None):
         # TODO: add debug flags and allow for printing stdout
         localFile = tempfile.mkstemp()[1]
         self._runPull(remoteFile, localFile)
 
@@ -480,104 +470,107 @@ class DeviceManagerADB(DeviceManager):
         return self._tempDir
 
     def reboot(self, wait = False, **kwargs):
         self._checkCmd(["reboot"])
         if wait:
             self._checkCmd(["wait-for-device", "shell", "ls", "/sbin"])
 
     def updateApp(self, appBundlePath, **kwargs):
-        return self._runCmd(["install", "-r", appBundlePath]).stdout.read()
+        return self._runCmd(["install", "-r", appBundlePath]).output
 
     def getCurrentTime(self):
-        timestr = self._runCmd(["shell", "date", "+%s"]).stdout.read().strip()
+        timestr = str(self._runCmd(["shell", "date", "+%s"]).output[0])
         if (not timestr or not timestr.isdigit()):
             raise DMError("Unable to get current time using date (got: '%s')" % timestr)
         return int(timestr)*1000
 
     def getInfo(self, directive=None):
         ret = {}
         if (directive == "id" or directive == "all"):
-            ret["id"] = self._runCmd(["get-serialno"]).stdout.read()
+            ret["id"] = self._runCmd(["get-serialno"]).output
         if (directive == "os" or directive == "all"):
-            ret["os"] = self._runCmd(["shell", "getprop", "ro.build.display.id"]).stdout.read()
+            ret["os"] = self._runCmd(["shell", "getprop", "ro.build.display.id"]).output
         if (directive == "uptime" or directive == "all"):
-            utime = self._runCmd(["shell", "uptime"]).stdout.read()
+            utime = self._runCmd(["shell", "uptime"]).output[0]
             if (not utime):
                 raise DMError("error getting uptime")
             utime = utime[9:]
             hours = utime[0:utime.find(":")]
             utime = utime[utime[1:].find(":") + 2:]
             minutes = utime[0:utime.find(":")]
             utime = utime[utime[1:].find(":") +  2:]
             seconds = utime[0:utime.find(",")]
             ret["uptime"] = ["0 days " + hours + " hours " + minutes + " minutes " + seconds + " seconds"]
         if (directive == "process" or directive == "all"):
-            ret["process"] = self._runCmd(["shell", "ps"]).stdout.read()
+            ret["process"] = self._runCmd(["shell", "ps"]).output
         if (directive == "systime" or directive == "all"):
-            ret["systime"] = self._runCmd(["shell", "date"]).stdout.read()
+            ret["systime"] = self._runCmd(["shell", "date"]).output
         self._logger.info(ret)
         return ret
 
     def uninstallApp(self, appName, installPath=None):
-        data = self._runCmd(["uninstall", appName]).stdout.read().strip()
+        data = self._runCmd(["uninstall", appName]).output.strip()
         status = data.split('\n')[0].strip()
         if status != 'Success':
             raise DMError("uninstall failed for %s. Got: %s" % (appName, status))
 
     def uninstallAppAndReboot(self, appName, installPath=None):
         self.uninstallApp(appName)
         self.reboot()
 
     def _runCmd(self, args):
         """
         Runs a command using adb
 
-        returns: returncode from subprocess.Popen
+        returns: instance of ProcessHandler
         """
         finalArgs = [self._adbPath]
         if self._deviceSerial:
             finalArgs.extend(['-s', self._deviceSerial])
         finalArgs.extend(args)
-        return subprocess.Popen(finalArgs, stdout=subprocess.PIPE,
-                                stderr=subprocess.STDOUT)
+        self._logger.debug("_runCmd - command: %s" % ' '.join(finalArgs))
+        proc = ProcessHandler(finalArgs, storeOutput=True,
+                processOutputLine=self._log)
+        proc.run()
+        proc.returncode = proc.wait()
+        return proc
 
     # timeout is specified in seconds, and if no timeout is given,
     # we will run until we hit the default_timeout specified in the __init__
     def _checkCmd(self, args, timeout=None, retryLimit=None):
         """
         Runs a command using adb and waits for the command to finish.
         If timeout is specified, the process is killed after <timeout> seconds.
 
-        returns: returncode from subprocess.Popen
+        returns: returncode from process
         """
         retryLimit = retryLimit or self.retryLimit
         finalArgs = [self._adbPath]
         if self._deviceSerial:
             finalArgs.extend(['-s', self._deviceSerial])
         finalArgs.extend(args)
+        self._logger.debug("_checkCmd - command: %s" % ' '.join(finalArgs))
         if not timeout:
-            # We are asserting that all commands will complete in this time unless otherwise specified
+            # We are asserting that all commands will complete in this
+            # time unless otherwise specified
             timeout = self.default_timeout
 
         timeout = int(timeout)
         retries = 0
-        with tempfile.SpooledTemporaryFile() as procOut:
-            while retries < retryLimit:
-                proc = subprocess.Popen(finalArgs, stdout=procOut, stderr=subprocess.STDOUT)
-                start_time = time.time()
-                ret_code = proc.poll()
-                while ((time.time() - start_time) <= timeout) and ret_code == None:
-                    time.sleep(self._pollingInterval)
-                    ret_code = proc.poll()
-                if ret_code == None:
-                    proc.kill()
-                    retries += 1
-                    continue
+        while retries < retryLimit:
+            proc = ProcessHandler(finalArgs, processOutputLine=self._log)
+            proc.run(timeout=timeout)
+            ret_code = proc.wait()
+            if ret_code == None:
+                proc.kill()
+                retries += 1
+            else:
                 return ret_code
+
         raise DMError("Timeout exceeded for _checkCmd call after %d retries." % retries)
 
     def chmodDir(self, remoteDir, mask="777"):
         if (self.dirExists(remoteDir)):
             files = self.listFiles(remoteDir.strip())
             for f in files:
                 remoteEntry = remoteDir.strip() + "/" + f.strip()
                 if (self.dirExists(remoteEntry)):
@@ -598,51 +591,40 @@ class DeviceManagerADB(DeviceManager):
         if self._adbPath != 'adb':
             if not os.access(self._adbPath, os.X_OK):
                 raise DMError("invalid adb path, or adb not executable: %s" % self._adbPath)
 
         try:
             self._checkCmd(["version"])
         except os.error, err:
             raise DMError("unable to execute ADB (%s): ensure Android SDK is installed and adb is in your $PATH" % err)
-        except subprocess.CalledProcessError:
-            raise DMError("unable to execute ADB: ensure Android SDK is installed and adb is in your $PATH")
 
     def _verifyDevice(self):
         # If there is a device serial number, see if adb is connected to it
         if self._deviceSerial:
             deviceStatus = None
-            proc = subprocess.Popen([self._adbPath, "devices"],
-                                    stdout=subprocess.PIPE,
-                                    stderr=subprocess.STDOUT)
-            for line in proc.stdout:
+            for line in self._runCmd(["devices"]).output:
                 m = re.match('(.+)?\s+(.+)$', line)
                 if m:
                     if self._deviceSerial == m.group(1):
                         deviceStatus = m.group(2)
             if deviceStatus == None:
                 raise DMError("device not found: %s" % self._deviceSerial)
             elif deviceStatus != "device":
                 raise DMError("bad status for device %s: %s" % (self._deviceSerial, deviceStatus))
 
         # Check to see if we can connect to device and run a simple command
-        ret = None
-        try:
-            ret = self._checkCmd(["shell", "echo"])
-        except subprocess.CalledProcessError:
-            raise DMError("unable to connect to device: is it plugged in?")
-        if ret:
+        if self._checkCmd(["shell", "echo"]) is None:
             raise DMError("unable to connect to device")
 
     def _checkForRoot(self):
         # Check whether we _are_ root by default (some development boards work
         # this way, this is also the result of some relatively rare rooting
         # techniques)
-        proc = self._runCmd(["shell", "id"])
-        data = proc.stdout.read()
+        data = self._runCmd(["shell", "id"]).output[0]
         if data.find('uid=0(root)') >= 0:
             self._haveRootShell = True
             # if this returns true, we don't care about su
             return
 
         # if root shell is not available, check if 'su' can be used to gain
         # root
         proc = self._runCmd(["shell", "su", "-c", "id"])
@@ -651,30 +633,30 @@ class DeviceManagerADB(DeviceManager):
         # password or triggers the Android SuperUser prompt
         start_time = time.time()
         retcode = None
         while (time.time() - start_time) <= 15 and retcode is None:
             retcode = proc.poll()
         if retcode is None: # still not terminated, kill
             proc.kill()
 
-        data = proc.stdout.read()
+        data = proc.output
         if data.find('uid=0(root)') >= 0:
             self._haveSu = True
 
     def _isUnzipAvailable(self):
-        data = self._runCmd(["shell", "unzip"]).stdout.read()
-        if (re.search('Usage', data)):
-            return True
-        else:
-            return False
+        data = self._runCmd(["shell", "unzip"]).output
+        for line in data:
+            if (re.search('Usage', line)):
+                return True
+        return False
 
     def _isLocalZipAvailable(self):
         try:
-            subprocess.check_call(["zip", "-?"], stdout=subprocess.PIPE, stderr=subprocess.PIPE)
+            self._checkCmd(["zip", "-?"])
         except:
             return False
         return True
 
     def _verifyZip(self):
         # If "zip" can be run locally, and "unzip" can be run remotely, then pushDir
         # can use these to push just one file per directory -- a significant
         # optimization for large directories.
--- a/testing/mozbase/mozdevice/setup.py
+++ b/testing/mozbase/mozdevice/setup.py
@@ -4,17 +4,18 @@
 
 from setuptools import setup
 
 PACKAGE_NAME = 'mozdevice'
 PACKAGE_VERSION = '0.37'
 
 deps = ['mozfile >= 1.0',
         'mozlog',
-        'moznetwork >= 0.24'
+        'moznetwork >= 0.24',
+        'mozprocess >= 0.19',
        ]
 
 setup(name=PACKAGE_NAME,
       version=PACKAGE_VERSION,
       description="Mozilla-authored device management",
       long_description="see http://mozbase.readthedocs.org/",
       classifiers=[], # Get strings from http://pypi.python.org/pypi?%3Aaction=list_classifiers
       keywords='',
--- a/testing/mozbase/mozlog/mozlog/__init__.py
+++ b/testing/mozbase/mozlog/mozlog/__init__.py
@@ -15,10 +15,12 @@ from logger import *
 from loglistener import LogMessageServer
 from loggingmixin import LoggingMixin
 
 try:
     import structured
 except ImportError:
     # Structured logging doesn't work on python 2.6 which is still used on some
     # legacy test machines; https://bugzilla.mozilla.org/show_bug.cgi?id=864866
+    # Once we move away from Python 2.6, please cleanup devicemanager.py's
+    # exception block
     pass
 
--- a/testing/mozbase/mozprocess/mozprocess/processhandler.py
+++ b/testing/mozbase/mozprocess/mozprocess/processhandler.py
@@ -816,17 +816,18 @@ falling back to not using job objects fo
             # wake up once a second in case a keyboard interrupt is sent
             count = 0
             while self.outThread.isAlive():
                 self.outThread.join(timeout=1)
                 count += 1
                 if timeout and count > timeout:
                     return None
 
-        return self.proc.wait()
+        self.returncode = self.proc.wait()
+        return self.returncode
 
     # TODO Remove this method when consumers have been fixed
     def waitForFinish(self, timeout=None):
         print >> sys.stderr, "MOZPROCESS WARNING: ProcessHandler.waitForFinish() is deprecated, " \
                              "use ProcessHandler.wait() instead"
         return self.wait(timeout=timeout)
 
 
@@ -946,17 +947,17 @@ class ProcessHandler(ProcessHandlerMixin
 
     If storeOutput==True, the output produced by the process will be saved
     as self.output.
 
     If logfile is not None, the output produced by the process will be
     appended to the given file.
     """
 
-    def __init__(self, cmd, logfile=None, stream=None,  storeOutput=True, **kwargs):
+    def __init__(self, cmd, logfile=None, stream=None, storeOutput=True, **kwargs):
         kwargs.setdefault('processOutputLine', [])
         if callable(kwargs['processOutputLine']):
             kwargs['processOutputLine'] = [kwargs['processOutputLine']]
 
         if logfile:
             logoutput = LogOutput(logfile)
             kwargs['processOutputLine'].append(logoutput)