diff mbox

[Branch,~linaro-validation/lava-dispatcher/trunk] Rev 568: Fix gathering of logs for storage.

Message ID 20130327214614.29062.33250.launchpad@ackee.canonical.com
State Accepted
Headers show

Commit Message

Antonio Terceiro March 27, 2013, 9:46 p.m. UTC
Merge authors:
  Antonio Terceiro (terceiro)
  Michael Hudson-Doyle (mwhudson)
  Nicholas Schutt (nick-schutt)
Related merge proposals:
  https://code.launchpad.net/~nick-schutt/lava-dispatcher/nick-1130814/+merge/152326
  proposed by: Nicholas Schutt (nick-schutt)
  https://code.launchpad.net/~mwhudson/lava-dispatcher/subprocess-output/+merge/148975
  proposed by: Michael Hudson-Doyle (mwhudson)
  review: Approve - Antonio Terceiro (terceiro)
------------------------------------------------------------
revno: 568 [merge]
fixes bug: https://launchpad.net/bugs/1127288
committer: Antonio Terceiro <antonio.terceiro@linaro.org>
branch nick: trunk
timestamp: Wed 2013-03-27 18:40:22 -0300
message:
  Fix gathering of logs for storage.
  
  This required a rewrite of how we handle running and spawning subprocesses. All
  of that is now concentrated in the LavaContext class by means of methods
  spawn() and run_command(). Those methods will make sure that any subprocesses
  get their output writtten to both stdout and the log file.
modified:
  lava_dispatcher/actions/lava_android_test.py
  lava_dispatcher/client/lmc_utils.py
  lava_dispatcher/client/targetdevice.py
  lava_dispatcher/context.py
  lava_dispatcher/device/fastmodel.py
  lava_dispatcher/device/master.py
  lava_dispatcher/device/nexus.py
  lava_dispatcher/device/qemu.py
  lava_dispatcher/device/sdmux.py
  lava_dispatcher/utils.py


--
lp:lava-dispatcher
https://code.launchpad.net/~linaro-validation/lava-dispatcher/trunk

You are subscribed to branch lp:lava-dispatcher.
To unsubscribe from this branch go to https://code.launchpad.net/~linaro-validation/lava-dispatcher/trunk/+edit-subscription
diff mbox

Patch

=== modified file 'lava_dispatcher/actions/lava_android_test.py'
--- lava_dispatcher/actions/lava_android_test.py	2012-11-22 02:14:51 +0000
+++ lava_dispatcher/actions/lava_android_test.py	2013-02-18 04:01:02 +0000
@@ -20,7 +20,6 @@ 
 # along with this program; if not, see <http://www.gnu.org/licenses>.
 
 import os
-import subprocess
 import logging
 from lava_dispatcher.actions import BaseAction
 from lava_dispatcher.errors import OperationFailed, TimeoutError
@@ -69,7 +68,7 @@ 
             t = DrainConsoleOutput(proc=session._connection, timeout=timeout)
             t.start()
             logging.info("Execute command on host: %s" % (' '.join(cmds)))
-            rc = subprocess.call(cmds)
+            rc = self.context.run_command(cmds)
             t.join()
             if rc == 124:
                 raise TimeoutError(
@@ -132,7 +131,7 @@ 
                     cmds.insert(0, 'timeout')
                     cmds.insert(1, '%ss' % timeout)
                 logging.info("Execute command on host: %s" % (' '.join(cmds)))
-                rc = subprocess.call(cmds)
+                rc = self.context.run_command(cmds)
                 if rc == 124:
                     raise TimeoutError(
                                "The test (%s) on device(%s) times out." % (
@@ -180,7 +179,7 @@ 
                 cmds.insert(1, '%ss' % timeout)
 
             logging.info("Execute command on host: %s" % (' '.join(cmds)))
-            rc = subprocess.call(cmds)
+            rc = self.context.run_command(cmds)
             if rc == 124:
                 raise TimeoutError(
                        "Failed to run monkeyrunner test url[%s] "
@@ -219,7 +218,7 @@ 
                     cmds.insert(0, 'timeout')
                     cmds.insert(1, '%ss' % timeout)
                 logging.info("Execute command on host: %s" % (' '.join(cmds)))
-                rc = subprocess.call(cmds)
+                rc = self.context.run_commands(cmds)
                 if rc == 124:
                     raise OperationFailed(
                         "The installation of test case(%s)"

=== modified file 'lava_dispatcher/client/lmc_utils.py'
--- lava_dispatcher/client/lmc_utils.py	2012-11-20 13:34:19 +0000
+++ lava_dispatcher/client/lmc_utils.py	2013-02-18 03:19:14 +0000
@@ -50,24 +50,24 @@ 
     logging.info("Executing the linaro-media-create command")
     logging.info(cmd)
 
-    _run_linaro_media_create(cmd)
+    _run_linaro_media_create(client.context, cmd)
     return image_file
 
-def generate_fastmodel_image(hwpack, rootfs, odir, bootloader='u_boot', size="2000M"):
+def generate_fastmodel_image(context, hwpack, rootfs, odir, bootloader='u_boot', size="2000M"):
     cmd = ("flock /var/lock/lava-lmc.lck sudo linaro-media-create "
            "--dev fastmodel --output-directory %s --image-size %s "
            "--hwpack %s --binary %s --hwpack-force-yes --bootloader %s" %
             (odir, size, hwpack, rootfs, bootloader) )
     logging.info("Generating fastmodel image with: %s" % cmd)
-    _run_linaro_media_create(cmd)
+    _run_linaro_media_create(context, cmd)
 
-def generate_android_image(device, boot, data, system, ofile, size="2000M"):
+def generate_android_image(context, device, boot, data, system, ofile, size="2000M"):
     cmd = ("flock /var/lock/lava-lmc.lck linaro-android-media-create "
            "--dev %s --image_file %s --image_size %s "
            "--boot %s --userdata %s --system %s" %
             (device, ofile, size, boot, data, system) )
     logging.info("Generating android image with: %s" % cmd)
-    _run_linaro_media_create(cmd)
+    _run_linaro_media_create(context, cmd)
 
 def get_partition_offset(image, partno):
     cmd = 'parted %s -m -s unit b print' % image
@@ -97,10 +97,10 @@ 
         logging_system('sudo umount ' + mntdir)
         logging_system('rm -rf ' + mntdir)
 
-def _run_linaro_media_create(cmd):
+def _run_linaro_media_create(context, cmd):
     """Run linaro-media-create and accept licenses thrown up in the process.
     """
-    proc = pexpect.spawn(cmd, logfile=sys.stdout)
+    proc = context.spawn(cmd)
 
     # This code is a bit out of control.  It describes a state machine.  Each
     # state has a name, a mapping patterns to wait for -> state to move to, a

=== modified file 'lava_dispatcher/client/targetdevice.py'
--- lava_dispatcher/client/targetdevice.py	2013-01-22 23:50:06 +0000
+++ lava_dispatcher/client/targetdevice.py	2013-03-25 20:29:23 +0000
@@ -33,7 +33,6 @@ 
 )
 from lava_dispatcher.utils import (
     mk_targz,
-    logging_system,
 )
 
 
@@ -75,7 +74,7 @@ 
         """Booting android or ubuntu style images don't differ much"""
 
         logging.info('ensuring ADB port is ready')
-        while logging_system("sh -c 'netstat -an | grep 5555.*TIME_WAIT'") == 0:
+        while self.context.run_command("sh -c 'netstat -an | grep 5555.*TIME_WAIT'") == 0:
             logging.info("waiting for TIME_WAIT 5555 socket to finish")
             time.sleep(3)
 

=== modified file 'lava_dispatcher/context.py'
--- lava_dispatcher/context.py	2013-01-23 23:10:37 +0000
+++ lava_dispatcher/context.py	2013-03-27 21:06:23 +0000
@@ -21,61 +21,65 @@ 
 import atexit
 import logging
 import os
+import subprocess
 import sys
 import tempfile
 
 from lava_dispatcher.config import get_device_config
 from lava_dispatcher.client.targetdevice import TargetBasedClient
 from lava_dispatcher.test_data import LavaTestData
-from lava_dispatcher.utils import rmtree
-
-
-def _write_and_flush(fobj, data):
-    fobj.write(data)
-    fobj.flush()
-
-
-class _Forwarder(object):
-    """A file-like object that just forwards data written to it to a callable.
-    """
-
-    def __init__(self, callback):
-        self.callback = callback
+from lava_dispatcher.utils import (
+    logging_spawn,
+    rmtree,
+    )
+
+
+class Flusher(object):
+    """
+    A Decorator for stream objects that makes all writes flush immediately
+    """
+    def __init__(self, stream):
+        self.stream = stream
 
     def write(self, data):
-        self.callback(data)
-
-    def flush(self):
-        pass
-
+        self.stream.write(data)
+        self.stream.flush()
+
+    def __getattr__(self, name):
+        return getattr(self.stream, name)
 
 class Outputter(object):
+    """
+    Handles the problem of where to send the output. Always sends to stdout,
+    and if you pass an output directory it will also store the log in a file
+    called output.txt inside that directory.
+
+    During initialization, also sets up the logging subsystem to use the same
+    output.
+    """
 
     def __init__(self, output_dir):
-        self.output_dir = output_dir
+
+        self._output_dir = output_dir
         if output_dir:
-            self.output_txt = open(os.path.join(output_dir, 'output.txt'), 'w')
+            output_txt = os.path.join(output_dir, 'output.txt')
+            output_pipe = subprocess.Popen(['tee', output_txt], stdin=subprocess.PIPE)
+            self.logfile_read = Flusher(output_pipe.stdin)
         else:
-            self.output_txt = None
-
-        self.logfile_read = _Forwarder(self.serial_output)
-
-        self._log_handler = logging.StreamHandler(_Forwarder(self.log_output))
+            self.logfile_read = Flusher(sys.stdout)
+
+        log_handler = logging.StreamHandler(self.logfile_read)
         FORMAT = '<LAVA_DISPATCHER>%(asctime)s %(levelname)s: %(message)s'
         DATEFMT = '%Y-%m-%d %I:%M:%S %p'
-        self._log_handler.setFormatter(
+        log_handler.setFormatter(
             logging.Formatter(fmt=FORMAT, datefmt=DATEFMT))
         del logging.root.handlers[:]
         del logging.root.filters[:]
-        logging.root.addHandler(self._log_handler)
-
-    def serial_output(self, data):
-        _write_and_flush(sys.stdout, data)
-        if self.output_txt is not None:
-            _write_and_flush(self.output_txt, data)
-
-    # Currently all output is treated the same way.
-    log_output = serial_output
+        logging.root.addHandler(log_handler)
+
+    @property
+    def output_dir(self):
+        return self._output_dir
 
     def write_named_data(self, name, data):
         if self.output_dir is None:
@@ -116,3 +120,24 @@ 
 
     def get_device_version(self):
         return self.client.target_device.get_device_version()
+
+    def spawn(self, command, timeout=30):
+        proc = logging_spawn(command, timeout)
+        proc.logfile_read = self.logfile_read
+        return proc
+
+    def run_command(self, command, failok=True):
+        """run command 'command' with output going to output-dir if specified"""
+        if isinstance(command, (str, unicode)):
+            command = ['sh', '-c', command]
+        logging.debug("Executing on host : '%r'" % command)
+        output_args = {
+            'stdout': self.logfile_read,
+            'stderr': subprocess.STDOUT,
+        }
+        if failok:
+            rc = subprocess.call(command, **output_args)
+        else:
+            rc = subprocess.check_call(command, **output_args)
+        return rc
+

=== modified file 'lava_dispatcher/device/fastmodel.py'
--- lava_dispatcher/device/fastmodel.py	2013-02-18 02:11:39 +0000
+++ lava_dispatcher/device/fastmodel.py	2013-03-25 20:23:35 +0000
@@ -25,8 +25,6 @@ 
 import os
 import shutil
 import stat
-import threading
-import re
 import subprocess
 
 import lava_dispatcher.device.boot_options as boot_options
@@ -48,8 +46,6 @@ 
 from lava_dispatcher.utils import (
     ensure_directory,
     extract_targz,
-    logging_spawn,
-    logging_system,
     DrainConsoleOutput,
     )
 
@@ -70,7 +66,7 @@ 
         with image_partition_mounted(self._sd_image, self.DATA_PARTITION) as d:
             wallpaper = '%s/%s' % (d, self.ANDROID_WALLPAPER)
             # delete the android active wallpaper as slows things down
-            logging_system('sudo rm -f %s' % wallpaper)
+            self.context.run_command('sudo rm -f %s' % wallpaper)
 
         with image_partition_mounted(self._sd_image, self.SYS_PARTITION) as d:
             with open('%s/etc/mkshrc' % d, 'a') as f:
@@ -107,7 +103,7 @@ 
         self._sd_image = '%s/android.img' % os.path.dirname(self._system)
 
         generate_android_image(
-            'vexpress-a9', self._boot, self._data, self._system, self._sd_image
+            self.context, 'vexpress-a9', self._boot, self._data, self._system, self._sd_image
             )
 
         self._copy_axf(self.config.boot_part, '')
@@ -119,7 +115,7 @@ 
         rootfs = download_image(rootfs, self.context, decompress=False)
         odir = os.path.dirname(rootfs)
 
-        generate_fastmodel_image(hwpack, rootfs, odir, bootloader)
+        generate_fastmodel_image(self.context, hwpack, rootfs, odir, bootloader)
         self._sd_image = '%s/sd.img' % odir
         self._axf = None
         for f in self.config.simulator_axf_files:
@@ -203,10 +199,7 @@ 
         # the simulator proc only has stdout/stderr about the simulator
         # we hook up into a telnet port which emulates a serial console
         logging.info('launching fastmodel with command %r' % sim_cmd)
-        self._sim_proc = logging_spawn(
-            sim_cmd,
-            logfile=self.context.logfile_read,
-            timeout=1200)
+        self._sim_proc = self.context.spawn(sim_cmd, timeout=1200)
         self._sim_proc.expect(self.PORT_PATTERN, timeout=300)
         self._serial_port = self._sim_proc.match.groups()[0]
         logging.info('serial console port on: %s' % self._serial_port)
@@ -219,11 +212,11 @@ 
         self._drain_sim_proc()
 
         logging.info('simulator is started connecting to serial port')
-        self.proc = logging_spawn(
+        self.proc = self.context.spawn(
             'telnet localhost %s' % self._serial_port,
-            logfile=self._create_rtsm_ostream(
-                self.context.logfile_read),
             timeout=1200)
+        self.proc.logfile_read = self._create_rtsm_ostream(
+            self.proc.logfile_read)
         return self.proc
 
     def get_test_data_attachments(self):

=== modified file 'lava_dispatcher/device/master.py'
--- lava_dispatcher/device/master.py	2013-01-30 18:45:16 +0000
+++ lava_dispatcher/device/master.py	2013-03-25 20:23:35 +0000
@@ -46,7 +46,6 @@ 
 )
 from lava_dispatcher.utils import (
     connect_to_serial,
-    logging_system,
     mk_targz,
     string_to_list,
     rmtree,
@@ -82,9 +81,9 @@ 
         self.device_version = None
 
         if config.pre_connect_command:
-            logging_system(config.pre_connect_command)
+            self.context.run_command(config.pre_connect_command)
 
-        self.proc = connect_to_serial(config, self.context.logfile_read)
+        self.proc = connect_to_serial(self.context)
 
     def get_device_version(self):
         return self.device_version
@@ -278,7 +277,7 @@ 
                 tfdir = os.path.join(self.scratch_dir, str(time.time()))
                 try:
                     os.mkdir(tfdir)
-                    logging_system('tar -C %s -xzf %s' % (tfdir, tf))
+                    self.context.run_command('tar -C %s -xzf %s' % (tfdir, tf))
                     yield os.path.join(tfdir, target_name)
 
                 finally:
@@ -397,7 +396,7 @@ 
         logging.info("Perform hard reset on the system")
         self.master_ip = None
         if self.config.hard_reset_command != "":
-            logging_system(self.config.hard_reset_command)
+            self.context.run_command(self.config.hard_reset_command)
         else:
             self.proc.send("~$")
             self.proc.sendline("hardreset")

=== modified file 'lava_dispatcher/device/nexus.py'
--- lava_dispatcher/device/nexus.py	2013-02-04 13:31:34 +0000
+++ lava_dispatcher/device/nexus.py	2013-03-26 01:02:10 +0000
@@ -19,7 +19,6 @@ 
 # with this program; if not, see <http://www.gnu.org/licenses>.
 
 import subprocess
-import pexpect
 from time import sleep
 import logging
 import contextlib
@@ -31,8 +30,6 @@ 
     download_image
 )
 from lava_dispatcher.utils import (
-    logging_system,
-    logging_spawn,
     mkdtemp
 )
 from lava_dispatcher.errors import (
@@ -40,24 +37,21 @@ 
 )
 
 
-def _call(cmd, ignore_failure, timeout):
+def _call(context, cmd, ignore_failure, timeout):
     cmd = 'timeout ' + str(timeout) + 's ' + cmd
-    logging.debug("Running on the host: %s", cmd)
-    if ignore_failure:
-        subprocess.call(cmd, shell=True)
-    else:
-        subprocess.check_call(cmd, shell=True)
+    context.run_command(cmd, failok=ignore_failure)
 
 
 class FastBoot(object):
 
     def __init__(self, device):
         self.device = device
+        self.context = device.context
 
     def __call__(self, args, ignore_failure=False, timeout=600):
         command = self.device.config.fastboot_command + ' ' + args
         command = "flock /var/lock/lava-fastboot.lck " + command
-        _call(command, ignore_failure, timeout)
+        _call(self.context, command, ignore_failure, timeout)
 
     def enter(self):
         if self.on():
@@ -71,7 +65,7 @@ 
             # probably hung.
             if self.device.config.hard_reset_command:
                 logging.debug("Will hard reset the device")
-                logging_system(self.device.config.hard_reset_command)
+                self.context.run_command(self.device.config.hard_reset_command)
             else:
                 logging.critical(
                     "Hard reset command not configured. "
@@ -187,9 +181,9 @@ 
     def _adb(self, args, ignore_failure=False, spawn=False, timeout=600):
         cmd = self.config.adb_command + ' ' + args
         if spawn:
-            return logging_spawn(cmd, timeout=60)
+            return self.context.spawn(cmd, timeout=60)
         else:
-            _call(cmd, ignore_failure, timeout)
+            _call(self.context, cmd, ignore_failure, timeout)
 
     def _get_image(self, url):
         sdir = self.working_dir

=== modified file 'lava_dispatcher/device/qemu.py'
--- lava_dispatcher/device/qemu.py	2013-01-16 23:27:28 +0000
+++ lava_dispatcher/device/qemu.py	2013-02-18 03:06:06 +0000
@@ -36,7 +36,6 @@ 
 from lava_dispatcher.utils import (
     ensure_directory,
     extract_targz,
-    logging_spawn,
     )
 
 
@@ -79,10 +78,7 @@ 
             self.config.qemu_drive_interface,
             self._sd_image)
         logging.info('launching qemu with command %r' % qemu_cmd)
-        proc = logging_spawn(
-            qemu_cmd,
-            logfile=self.context.logfile_read,
-            timeout=1200)
+        proc = self.context.spawn(qemu_cmd, timeout=1200)
         return proc
 
     def get_device_version(self):

=== modified file 'lava_dispatcher/device/sdmux.py'
--- lava_dispatcher/device/sdmux.py	2013-01-28 23:59:47 +0000
+++ lava_dispatcher/device/sdmux.py	2013-02-18 04:01:02 +0000
@@ -42,7 +42,6 @@ 
     connect_to_serial,
     ensure_directory,
     extract_targz,
-    logging_system,
 )
 
 
@@ -87,7 +86,7 @@ 
             raise CriticalError('Device config requires "power_off_cmd"')
 
         if config.pre_connect_command:
-            logging_system(config.pre_connect_command)
+            self.context.run_command(config.pre_connect_command)
 
     def deploy_linaro(self, hwpack=None, rootfs=None):
         img = generate_image(self, hwpack, rootfs, self.scratch_dir)
@@ -115,7 +114,7 @@ 
 
         img = os.path.join(scratch, 'android.img')
         device_type = self.config.lmc_dev_arg
-        generate_android_image(device_type, boot, data, system, img)
+        generate_android_image(self.context, device_type, boot, data, system, img)
         self._customize_android(img)
         self._write_image(img)
 
@@ -170,7 +169,7 @@ 
             raise CriticalError('Unable to access sdmux device')
         finally:
             logging.info('powering off sdmux')
-            subprocess.check_call([muxscript, '-d', muxid, 'off'])
+            self.context.run_command([muxscript, '-d', muxid, 'off'], failok=False)
 
     @contextlib.contextmanager
     def file_system(self, partition, directory):
@@ -185,7 +184,7 @@ 
         with self.mux_device() as device:
             device = '%s%s' % (device, partition)
             try:
-                subprocess.check_call(['mount', device, mntdir])
+                self.context.run_command(['mount', device, mntdir], failok=False)
                 if directory[0] == '/':
                     directory = directory[1:]
                 path = os.path.join(mntdir, directory)
@@ -203,11 +202,11 @@ 
                 logging.info('unmounting sdmux')
                 try:
                     _flush_files(mntdir)
-                    subprocess.check_call(['umount', device])
+                    self.context.run_command(['umount', device], failok=False)
                 except subprocess.CalledProcessError:
                     logging.exception('umount failed, re-try in 10 seconds')
                     time.sleep(10)
-                    if subprocess.call(['umount', device]) != 0:
+                    if self.context.run_command(['umount', device]) != 0:
                         logging.error(
                             'Unable to unmount sdmux device %s', device)
 
@@ -219,14 +218,13 @@ 
 
     def power_off(self, proc):
         super(SDMuxTarget, self).power_off(proc)
-        logging_system(self.config.power_off_cmd)
+        self.context.run_command(self.config.power_off_cmd)
 
     def power_on(self):
-        self.proc = connect_to_serial(
-            self.config, self.context.logfile_read)
+        self.proc = connect_to_serial(self.context)
 
         logging.info('powering on')
-        logging_system(self.config.power_on_cmd)
+        self.context.run_command(self.config.power_on_cmd)
 
         return self.proc
 

=== modified file 'lava_dispatcher/utils.py'
--- lava_dispatcher/utils.py	2013-01-16 23:27:28 +0000
+++ lava_dispatcher/utils.py	2013-02-18 03:34:31 +0000
@@ -169,9 +169,9 @@ 
 
 class logging_spawn(pexpect.spawn):
 
-    def __init__(self, command, timeout=30, logfile=None):
+    def __init__(self, command, timeout=30):
         pexpect.spawn.__init__(
-            self, command, timeout=timeout, logfile=logfile)
+            self, command, timeout=timeout)
 
         # serial can be slow, races do funny things, so increase delay
         self.delaybeforesend = 0.05
@@ -214,7 +214,7 @@ 
                 timeout=1, lava_no_logging=1)
 
 
-def connect_to_serial(device_config, logfile_read):
+def connect_to_serial(context):
     """
     Attempts to connect to a serial console server like conmux or cyclades
     """
@@ -237,8 +237,9 @@ 
         results.append(result)
 
     while retry_count < retry_limit:
-        proc = logging_spawn(device_config.connection_command, timeout=1200)
-        proc.logfile_read = logfile_read
+        proc = context.spawn(
+            context.client.config.connection_command,
+            timeout=1200)
         logging.info('Attempting to connect to device')
         match = proc.expect(patterns, timeout=10)
         result = results[match]
@@ -252,9 +253,9 @@ 
             atexit.register(proc.close, True)
             return proc
         elif result == 'reset-port':
-            reset_cmd = device_config.reset_port_command
+            reset_cmd = context.client.config.reset_port_command
             if reset_cmd:
-                logging_system(reset_cmd)
+                context.run_command(reset_cmd)
             else:
                 raise CriticalError('no reset_port command configured')
             proc.close(True)