~heber013/ubuntu-server-iso-testing/fixing-default-distro-error

#!/usr/bin/python
# 
# Copyright (C) 2010, Canonical Ltd (http://www.canonical.com/)
#
# This file is part of ubuntu-iso-testing.
# 
# ubuntu-iso-testing is free software: you can redistribute it 
# and/or modify it under the terms of the GNU General Public License 
# as published by the Free Software Foundation, either version 3 of 
# the License, or (at your option) any later version.
# 
# ubuntu-iso-testing is distributed in the hope that it will 
# be useful, but WITHOUT ANY WARRANTY; without even the implied warranty 
# of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.
# 
# You should have received a copy of the GNU General Public License
# along with ubuntu-iso-testing.  If not, see 
# <http://www.gnu.org/licenses/>.
# 

import datetime
import logging
import optparse
import os
import pipes
import random
import shutil
import string
import subprocess
import sys
import tempfile
import uuid
import time
import couchdb
import jinja2
import re
import ConfigParser
import glob

logging.basicConfig(level=logging.DEBUG)


def set_config(variant='server', arch='i386'):
    """ Set parameters specific to a variant """
    global DEFAULT_TMPL_DIR, DEFAULT_TEST_TIMEOUT, DISK_SIZE, COMPRESS_CMD,\
            UNCOMPRESS_CMD, KERNEL_DIR, INITRD, KERNEL, PRESEED

    variant = variant.lower()
    if variant == 'desktop':
        DEFAULT_TMPL_DIR = "/usr/share/ubuntu-iso-testing/templates.desktop"
        DEFAULT_TEST_TIMEOUT = 3600
        DISK_SIZE = "6G"
        COMPRESS_CMD = "lzma "
        UNCOMPRESS_CMD = "lzcat -S lz "
        KERNEL_DIR = "casper"
        INITRD = "initrd.lz"
        if arch == 'amd64':
            KERNEL = "vmlinuz.efi"
    elif variant in ('alternate', 'netboot'):
        DEFAULT_TMPL_DIR = "/usr/share/ubuntu-iso-testing/templates.alternate"
        DEFAULT_TEST_TIMEOUT = 3600
        DISK_SIZE = "6G"

        # Use initrd preseeding
        PRESEED='preseed.cfg'
        # Netboot has specific kernel location and name
        if variant == 'netboot':
            KERNEL_DIR = "."
            KERNEL = "linux"

def load_test_config(test_dir, config_file = "config"):
    """Load test configuration from config file in test directory"""
    config_path = os.path.join(test_dir, config_file)
    logging.debug("Loading test configuration file: '%s'", config_path)
    config = ConfigParser.SafeConfigParser()

    config.read(config_path)

    return config

def get_config_value(config, section, option, default=''):
    """Return the value for a section/option in a preloaded config file"""
    logging.debug("Loading configuration option: '%s/%s'", section, option)
    try:
        value = config.get(section, option)
        return value
    except ConfigParser.NoSectionError:
        logging.info("Section doesn't exists: '%s'", section)
        return default
    except ConfigParser.NoOptionError:
        logging.info("Option doesn't exists: '%s/%s'", section, option)
        return default

def add_media_info(isopath, destdb, doc):
    """Extract .disk/info from iso and add it as attachment to couchdb"""
    logging.debug('Extracting media info from ISO')

    cmd = ['bsdtar', '-xf', isopath, '-O', '.disk/info' ]
    logging.debug("Cmd: %s", (cmd))
    media_info = ''
    try:
        media_info = subprocess.check_output(cmd)
        logging.debug('Media Info: %s', media_info)
        destdb.put_attachment(doc, media_info, "media_info")
    except:
        return False

    return True

def update_inittab(tmpdir):
    """Add an entry to inittab for logging
    @param tmp_dir: Temp directory where initrd has been unpacked
    """
    # Add entry to inittab for logging
    inittab = os.path.join(tmpdir, 'etc', 'inittab')
    if os.path.isfile(inittab):
        logging.debug('Updating inittab')
        with open(inittab, 'a') as f:
            ttyS = "\n\
# logging to serial\n\
ttyS0::respawn:/usr/bin/tail -n 1200 -f /var/log/syslog \n"
            f.write(ttyS)
    else:
        logging.info('inittab not found')

# Defaults
DEFAULT_VARIANT = 'server'
DEFAULT_RELEASE = 'oneiric'
DEFAULT_ARCH = 'i386'
DEFAULT_FLAVOR = 'ubuntu-server'
DEFAULT_ISOROOT = os.path.expanduser('~/isos')
DEFAULT_TMPL_DIR = "/usr/share/ubuntu-iso-testing/templates"
DEFAULT_TEST_TIMEOUT = 1200

DISK_FORMAT = "qcow2"
DISK_BUS = "virtio"
DISK_SIZE = "2G"
DISK_NUMBER = 1

COMPRESS_CMD = "gzip "
UNCOMPRESS_CMD = "zcat "
KERNEL_DIR = "install"
INITRD = "initrd.gz"
KERNEL = "vmlinuz"
PRESEED = "preseed"

usage = "usage: %prog [options] preseed1"
parser = optparse.OptionParser(usage=usage)
parser.add_option("-d", "--debug", dest="debug", action="store_true",  default=False,
                  help="enable debugging")
parser.add_option("-r", "--release",  dest="release", default=DEFAULT_RELEASE, 
                  help="release of Ubuntu to download (default=%s)" % DEFAULT_RELEASE)
parser.add_option("-v", "--variant",  dest="variant", default=DEFAULT_VARIANT, 
                  help="variant of Ubuntu to download (default=%s)" % DEFAULT_VARIANT)
parser.add_option("-a", "--arch",  dest="arch", default=DEFAULT_ARCH, 
                  help="arch of Ubuntu to download (default=%s)" % DEFAULT_ARCH)
parser.add_option("-i", "--isoroot",  dest="isoroot", default=DEFAULT_ISOROOT, 
                  help="location to store iso images (default=%s)" % DEFAULT_ISOROOT)
parser.add_option("-f", "--flavor",  dest="flavor", default=DEFAULT_FLAVOR, 
                  help="flavor of Ubuntu to download (default=%s)" % DEFAULT_FLAVOR)
parser.add_option("-n", "--isoname",  dest="isoname", default=False,
                  help="specify name of a local iso file")  
parser.add_option("-t", "--tests" , dest="test_dir", 
                  help="Location of test templates to use")

(options, args) = parser.parse_args()
if options.debug:
    logging.basicConfig(level=logging.DEBUG)
else:
    logging.basicConfig(level=logging.INFO)

logging.debug("Options: %s" % (options))
logging.debug("Arguments: %s" % (args))

if len(args) == 0:
    logging.error("Need test preseed as a parameter")
    parser.print_help()
    sys.exit(1)

START_DELAY = random.randint(0, 60)
logging.info('Sleeping for %d seconds (LP: #961217)', START_DELAY)
time.sleep(START_DELAY)

set_config(options.variant, options.arch)
# Get all environment variable for general test configuration
global TMPL_DIR
if options.test_dir:
    TMPL_DIR = os.path.abspath(options.test_dir)
else:
    TMPL_DIR = DEFAULT_TMPL_DIR

RUN_TEST = os.path.join(TMPL_DIR, 'run_test')
BOOTTESTS = os.path.join(TMPL_DIR, 'boottests.py')
TEST_CASE_DIR = os.path.join(TMPL_DIR, 'test_cases')
POST_REBOOT_TEST_CASE_DIR = os.path.join(TMPL_DIR, 'post_reboot_test_cases')
PRESEED_TMPL_DIR = [os.path.join(TMPL_DIR, 'preseeds-common'), TEST_CASE_DIR]
TEST_DIR = os.environ.get("TEST_DIR",
                          os.path.expanduser('~/tests'))
TEST_TRACKER = os.environ.get("TEST_TRACKER", "http://192.168.123.1:5984")
TFTP_HOST = os.environ.get("TFTP_HOST", "192.168.123.1")
TFTP_DIR = os.environ.get("TFTP_DIR",
                          os.path.expanduser('~/tftp'))
TEST_DATABASE = os.environ.get("TEST_DATABASE", "tests")
TEST_RESULTS = os.environ.get("TEST_RESULTS","test-results")
APT_PROXY = os.environ.get("APT_PROXY","http://192.168.123.1:3142")

# URL of Hudson CI Server
HUDSON_URL = os.environ.get("HUDSON_URL", "")
BUILD_NUMBER = os.environ.get("BUILD_NUMBER", "")
ATTACHEMENT_EXCLUSIONS = ['pxe/kernel', 'pxe/initrd']

# Default time to sleep for monitoring VM execution
# configurable using environment variable.
SLEEP_TIME = 30
try:
    TEST_TIMEOUT = int(os.environ.get("TEST_TIMEOUT", DEFAULT_TEST_TIMEOUT))
except ValueError:
    TEST_TIMEOUT = DEFAULT_TEST_TIMEOUT

logging.info("Preseed: %s" % (args[0]))
preseed = os.path.join(TEST_CASE_DIR,args[0])

# See http://kennethreitz.com/blog/generate-a-random-mac-address-in-python/
def random_mac_address():
    """Returns a completely random Mac Address"""
    mac = [0x52, 0x54, 0x00, random.randint(0x00, 0xff),
                             random.randint(0x00, 0xff),
                             random.randint(0x00, 0xff)]
    return ':'.join(map(lambda x: "%02x" % x, mac))

# Load the templates
templates = jinja2.Environment(loader = jinja2.FileSystemLoader(TMPL_DIR))

# Load the preseed templates
preseed_templates = \
        jinja2.Environment(loader = jinja2.FileSystemLoader(PRESEED_TMPL_DIR))

if not os.path.exists(TEST_DIR):
    os.makedirs(TEST_DIR)

server = couchdb.client.Server(TEST_TRACKER)
# Create database if it does not exist.
if TEST_DATABASE not in server:
  server.create(TEST_DATABASE)

db = server[TEST_DATABASE]

# Check and Download ISO if need be.

# Create useful handles to ISO location
if options.isoname:
    iso_name = options.isoname
else: 
    iso_name = options.release + '-' + options.variant + '-' + options.arch + '.iso'

iso_dir = options.flavor
iso_location = os.path.join(options.isoroot, iso_dir, iso_name)

# Extract kernel and initrd from ISO to build new initrd including
# required preseed
logging.info("Extracting kernel and initrd from %s" % (iso_location))
iso_tmp_dir = tempfile.mkdtemp(prefix="%s-" % (os.path.basename(iso_location)))
kernel = os.path.join(iso_tmp_dir, KERNEL_DIR, KERNEL)
initrd = os.path.join(iso_tmp_dir, KERNEL_DIR, INITRD)
cmd = ['unbsdtar-safelink', '-xf', iso_location, '-C', iso_tmp_dir,
       KERNEL_DIR + "/" + KERNEL, KERNEL_DIR + "/" + INITRD]
logging.debug("Cmd: %s" % (cmd))
subprocess.check_call(cmd)

t_preseed = os.path.basename(os.path.normpath(preseed))
logging.info("Generating %s configuration" % (t_preseed))
test_config = load_test_config(os.path.join(preseed))

old_wd = os.getcwd()
mac_address = random_mac_address()
test_uuid = str(uuid.uuid4())
logging.debug("Couch Document UUID: '%s'", test_uuid)
db[test_uuid] = { "test_case": t_preseed,
                  "states": {
                      'creating': datetime.datetime.utcnow().isoformat()
                  }
                }
test_tmp_dir = tempfile.mkdtemp(prefix="%s-" % (t_preseed),
                                dir=iso_tmp_dir)
initrd_tmp_dir = tempfile.mkdtemp(prefix='initrd-', dir=test_tmp_dir)
t_initrd = os.path.join(test_tmp_dir, INITRD)

logging.debug("Generate preseed file")
tmpl = preseed_templates.get_template("%s/preseed" % (t_preseed))
ctxt = { 'hostname': test_uuid,
         'test_case_url': "%s/%s/%s" % (TEST_TRACKER, TEST_DATABASE,
                                        test_uuid),
         'proxyurl': APT_PROXY }
preseed_file = os.path.join(test_tmp_dir, 'preseed')
logging.debug("will preseed %s" % preseed_file)
tmpl.stream(ctxt).dump(preseed_file)

logging.info("Uncompressing initrd")
logging.debug("Initrd file: %s" % (initrd))
os.chdir(initrd_tmp_dir)
t = pipes.Template()
t.prepend(UNCOMPRESS_CMD + " $IN", "f-")
t.append("cpio -ivd 2>/dev/null", "-.")
t.copy(initrd, '/dev/null')

logging.debug("Copying preseed to initrd and test case document")
shutil.copy(preseed_file, os.path.join(initrd_tmp_dir, PRESEED))
test_case_doc = db[test_uuid]
db.put_attachment(test_case_doc, open(preseed_file), PRESEED)

# Adding media info
add_media_info( iso_location, db, test_case_doc)

# Create location for TFTP setup 
# test_tftp_dir = os.path.join(TFTP_DIR,test_uuid)
# os.makedirs(test_tftp_dir)

logging.debug("Copying preseed to tftp root")
shutil.copy(preseed_file, os.path.join(TFTP_DIR, 'preseed.%s' % test_uuid))

logging.info("Copying %s -> %s", RUN_TEST, initrd_tmp_dir)
# Put run_test in the initrd so that the installer can copy it
# into the target system at late_command time
shutil.copy(RUN_TEST, os.path.join(initrd_tmp_dir, 'run_test'))

if os.path.isfile(BOOTTESTS):
    logging.info("Copying %s -> %s", BOOTTESTS, initrd_tmp_dir)
    # Put boottests.py in the initrd so that the installer can copy it
    # into the target system at late_command time
    shutil.copy(BOOTTESTS, os.path.join(initrd_tmp_dir, 'boottests.py'))

# Keep a copy in test case doc
test_case_doc = db[test_uuid]
db.put_attachment(test_case_doc, open(RUN_TEST), "run_test")

update_inittab(initrd_tmp_dir)

if options.variant == 'desktop':
    # Specific bits for Desktop
    # Put run_test wrapper in the initrd too
    logging.info("Copying custom-installation hooks")
    datadir = initrd_tmp_dir
    src_custom_dir = os.path.join(TMPL_DIR, 'custom-installation')
    dst_custom_dir = os.path.join(datadir, 'custom-installation')
    test_custom_dir = os.path.join(preseed, 'custom-installation')

    shutil.copytree(src_custom_dir, dst_custom_dir)

    # Overwrite with custom-installation from testdir if any
    if os.path.exists(test_custom_dir) and os.path.isdir(dst_custom_dir):
        logging.debug('Test custom-installation directory found. Copying...')
        cmd = ['cp', '-rf']
        cmd.extend(glob.glob(test_custom_dir + '/*'))
        cmd.append(dst_custom_dir)
        subprocess.call(cmd)

    # Write test_uuid on custom-installation for later use
    with open(os.path.join(initrd_tmp_dir, 'test.id'), 'w') as ftest:
              ftest.write('TEST_TRACKER="%s"\n' % TEST_TRACKER)
              ftest.write('TEST_DATABASE="%s"\n' % TEST_DATABASE)
              ftest.write('TEST_UUID="%s"\n' % test_uuid)

    # TODO: Do not preseed a LDTP installation
    shutil.copy(preseed_file, os.path.join(datadir, 'preseed.cfg'))
    RUN_TEST_WRAPPER = os.path.join(TMPL_DIR, 'run_test.wrapper')
    shutil.copy(RUN_TEST_WRAPPER, os.path.join(initrd_tmp_dir,
                                               'run_test.wrapper'))
    # Keep a copy in test case doc
    test_case_doc = db[test_uuid]
    db.put_attachment(test_case_doc, open(RUN_TEST_WRAPPER), "run_test.wrapper")

logging.info("Compressing initrd")
os.chdir(initrd_tmp_dir)
t = pipes.Template()
t.prepend("find .", ".-")
t.append("cpio --quiet -o -H newc", '--')
t.append(COMPRESS_CMD + ' -9fc ', '--')
t.copy("/dev/null", t_initrd)

# Done with the initrd - chdir to old working dir
os.chdir(old_wd)

logging.debug("Attaching initrd")
test_case_doc = db[test_uuid]
db.put_attachment(test_case_doc,
                  open(t_initrd),
                  'pxe/initrd')

logging.debug("Copying initrd to tftp root")
shutil.copy(t_initrd,os.path.join(TFTP_DIR,'initrd.%s' % test_uuid))

logging.debug("Attaching kernel")
test_case_doc = db[test_uuid]
db.put_attachment(test_case_doc,
                  open(kernel),
                  'pxe/kernel')

logging.debug("Copying kernel to tftp root")
shutil.copy(kernel,os.path.join(TFTP_DIR,'kernel.%s' % test_uuid))

# All tests now use flat structure - use one pxelinux.0
#logging.debug("Attaching pxelinux.0")
#test_case_doc = db[test_uuid]
#db.put_attachment(test_case_doc,
#                  open(os.path.join(TMPL_DIR, 'pxelinux.0')),
#                  'pxe/pxelinux.0')
#
#logging.debug("Copying pxelinux.0 to tftp root")
#shutil.copy(os.path.join(TMPL_DIR, 'pxelinux.0'),test_tftp_dir)
# Generate pxelinux configuration file for test cashe

logging.debug("Copying pxelinux config to tftp root")
kernel_boot_args = get_config_value(test_config, 'pxelinux', 'kernel_boot_args')
tmpl = templates.get_template('pxelinuxcfg.install')
ctxt = { 'mac': mac_address,
         'uuid': test_uuid,
         'kernel_boot_args': kernel_boot_args
       }
logging.debug("Context: %s" % (ctxt))
pxelinux_cfg_file = os.path.join(TFTP_DIR,'pxelinux.cfg',
                                 '01-%s' % mac_address.replace(':','-'))
tmpl.stream(ctxt).dump(pxelinux_cfg_file)

logging.debug("Attaching pxelinux config")
test_case_doc = db[test_uuid]
db.put_attachment(test_case_doc,
                  open(pxelinux_cfg_file),
                  "pxe/pxelinux.cfg/%s" % mac_address)

#logging.debug("Copying pxelinux config to tftp root")
#pxelinux_cfg = os.path.join(test_tftp_dir,'pxelinux.cfg')
#os.makedirs(pxelinux_cfg)
# Template PXE configuration 
#shutil.copy(os.path.join(TMPL_DIR, 'pxelinuxcfg.install'),
#            os.path.join(pxelinux_cfg,mac_address))

logging.debug("Adding test script to test case document")
t_script = os.path.join(TEST_CASE_DIR, t_preseed, 'test')
logging.debug("Test script: %s" % (t_script))
test_case_doc = db[test_uuid]
db.put_attachment(test_case_doc, open(t_script),
                  filename="tests/%s" % (t_preseed))

post_reboot_test = os.path.join(POST_REBOOT_TEST_CASE_DIR, t_preseed, 'test')
if os.path.exists(post_reboot_test):
    logging.debug("Adding post-reboot tests")
    test_case_doc = db[test_uuid]
    logging.debug("Test script: %s" % (post_reboot_test))
    db.put_attachment(test_case_doc, open(post_reboot_test),
                      filename="post-reboot-tests/%s" % (t_preseed))

# Allow tests to override the default disk size
DISK_SIZE = get_config_value(test_config, 'vm', 'disk_size', DISK_SIZE)
DISK_NUMBER = int(get_config_value(test_config, 'vm', 'disk_number', DISK_NUMBER))

logging.debug("Generating libvirt information for %s" % (preseed))
logging.debug("Generating disk information")
disks = []
for d_i in range(1, DISK_NUMBER+1):
    disks.append({ 'target': "vd%s" % (string.ascii_lowercase[d_i-1]),
                   'bus': DISK_BUS,
                   'format': DISK_FORMAT,
                   'size': DISK_SIZE,
                 })

test_case_doc = db[test_uuid]
test_case_doc['disks'] = disks
test_case_doc['mac'] = mac_address
test_case_doc['iso_url'] = "%s" % (iso_location)
db[test_uuid] = test_case_doc

logging.debug("Setting state to created")
test_case_doc = db[test_uuid]
test_case_doc['states']['created'] = datetime.datetime.utcnow()\
                                                         .isoformat()
db[test_uuid] = test_case_doc

shutil.rmtree(test_tmp_dir)    
shutil.rmtree(iso_tmp_dir)

# Test Setup - Now Execute
if not os.path.exists(TEST_DIR):
    os.makedirs(TEST_DIR)

logging.debug("Loading test case to run")
test = db[test_uuid]
logging.info("Configuring test case: %s" % (test['_id']))
test_dir = os.path.join(TEST_DIR, test['_id'])
os.mkdir(test_dir)

logging.debug("Retrieving iso file")
iso_file = test["iso_url"]

logging.debug("Generating disks")
disks = test['disks']
for disk in disks:
    root_disk = os.path.join(test_dir, "disk%s.%s" % (disks.index(disk)+1,
                                                      disk['format']))
    cmd = [ 'qemu-img', 'create', '-f', disk['format'], root_disk,
            disk['size'] ]
    logging.debug("Cmd: %s" % (cmd))
    subprocess.check_call(cmd)
    shutil.copy(root_disk, root_disk + ".orig")
    disk['source'] = root_disk

logging.debug("Generating libvirt configuration")
ctxt = { 'name': test['_id'],
         'uuid': test['_id'],
         'disks': disks,
         'iso_file': iso_file,
         'mac': test['mac'],
       }
logging.debug("Context: %s" % (ctxt))
libvirt_file = os.path.join(test_dir, 'libvirt.xml')
tmpl = templates.get_template('libvirt.xml')
tmpl.stream(ctxt).dump(libvirt_file)
cmd = [ "virsh", "define", libvirt_file]
l_testStarted = time.localtime()
logging.debug("Cmd: %s" % (cmd))
subprocess.check_call(cmd)
test_case_doc = db[test['_id']]
db.put_attachment(test_case_doc, open(libvirt_file), "libvirt.xml")

#logging.debug("Updating dnsmasq configuration for %s" % (test['_id']))
#tmpl = templates.get_template('dnsmasq.conf')
#ctxt = { 'mac': test['mac'],
#         'test_tracker': TEST_TRACKER,
#         'test_db': TEST_DATABASE,
#         'tftp_host' : TFTP_HOST,
#         'uuid': test['_id'],
#       }
#logging.debug("Context: %s" % (ctxt))
#dnsmasq_conf_file = os.path.join(DNSMASQ_DIR, "%s.conf" % (test['_id']))
#tmpl.stream(ctxt).dump(dnsmasq_conf_file)
#cmd = [ "sudo", "/usr/bin/pkill", "-HUP", "dnsmasq"]
#logging.debug("Cmd: %s" % (cmd))
#subprocess.check_call(cmd)
#test_case_doc = db[test['_id']]
#db.put_attachment(test_case_doc, open(dnsmasq_conf_file), "dnsmasq.conf")

test = db[test['_id']]
test['states']['configured'] = datetime.datetime.utcnow().isoformat()
db[test['_id']] = test

logging.debug("Starting test case %s" % (test['_id']))
cmd = [ "virsh", "start", test['_id']]
logging.debug("Cmd: %s" % (cmd))
subprocess.check_call(cmd)

test = db[test['_id']]
test['states']['started'] = datetime.datetime.utcnow().isoformat()
db[test['_id']] = test


# Monitor the state of the virtual machine to determine
# completion of execution of test scripts
l_macAddress = None
l_ipAddress = None

# OK, I agree that the 'def's below look weird here, but ah well

def get_ipAddress(domain, macAddress):
    '''
    Note we can get a variable number of lines as output here:
    0   -> the domain has not yet sent a DHCP request
    1   -> the domain _did_ send a DHCP request, and dnsmasq ack-ed it
    >1  -> we have a series of runs for this domain... we have to get the 
           last line of output (the most recent request

    There is a potential problem window here: this domain has run sometimes
    already (so there is at least one previous DHCPREQ for this macAddress)
    but *this* run has not yet gotten to send a DHCPREQ. Right now I just
    hope it does not happen ;-)
    It does, worked around it :-(
    '''
    #logging.debug("Looking for the IP address on test case %s" % domain)
    cmd = ["grep", "-E", "dnsmasq.+DHCPREQUEST.+" + macAddress,
       "/var/log/syslog" ]
    #logging.debug("Cmd=%s" % cmd)
    proc = subprocess.Popen(cmd, bufsize=2048, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
    retcode = proc.wait()
    output = proc.communicate()[0]
    #logging.debug("RC=%s, output=%s" % (retcode, output))
    if retcode != 0:
        return None
    # last line returned could have it
    output = output.splitlines().pop()
    # we are looking for a line like:
    # Jan 18 03:20:39 localhost dnsmasq-dhcp[14312]: DHCPREQUEST(virbr0) 192.168.123.213 52:54:00:7b:69:82 
    # first off, we check if the line's timestamp is *after* the start of the test
    logTS = None
    try:
        # yet another hack: rsyslog messages do not print year by default. Sigh.
        tStamp = output[0:15] + " %s" % l_testStarted.tm_year
        logTS = time.strptime(tStamp, "%b %d %H:%M:%S %Y")
    except ValueError:
            logging.error("strptime error on '%s'" % output[0:15])
            return None
    logging.debug("test start: %s, %s" % (time.strftime("%b %d %Y %H:%M:%S", l_testStarted), output))
    if time.strftime("%Y%m%d%H%M%S", logTS) < time.strftime("%Y%m%d%H%M%S", l_testStarted):
        # this log entry is from before the start of the test, disregard
        return None
    ipAddress = output.split()[6]
    logging.debug("Got IP address of %s for %s" % (ipAddress, domain))
    if ipAddress is not None:
        return ipAddress
    else:
        return None

def get_diSyslog(domain, ipAddress):
    '''
    the Debian-installer syslog is always immediately saved with
    overwrite, so that the last version of it will always be available
    to be uploaded to Hudson as part of the test artifact.
    Return:
        None: we got a bad RC from wget
        String: with up to 10 lines of d-i syslog

        The latest d-i syslog is kept at d-i-syslog.log.
    '''
    logging.debug("Capturing current d-i syslog for test case %s" % domain)
    syslog_path = os.path.join('/tmp', '%s.syslog.log' % domain)
    cmd = [ 'tail', syslog_path]
    proc = subprocess.Popen(cmd, bufsize=204800, stdout=subprocess.PIPE)
    retcode = proc.wait()
    output = proc.communicate()[0].strip()
    return output

def check_for_errors(di_syslog):
    if di_syslog is None:
        # nothing to check on
        return False
    if "question will be asked" in di_syslog:
        return True

def end_VM(VM_id):
    logging.debug("Terminating test case %s" % (VM_id))
    cmd = [ "virsh", "destroy", VM_id]
    logging.debug("Cmd: %s" % (cmd))
    subprocess.check_call(cmd)

start_time = time.time()
## support for cancelling runs where the debian-installer syslog is not
## seen in 200 seconds (wait_di_syslog * SLEEP_TIME)
seen_di_syslog = False
iter_wait_di_syslog = 0
wait_di_syslog = 20

# libvirt thinks it owns everything!
syslog_path = os.path.join('/tmp/', '%s.syslog.log' % test['_id'])
cmd = [ "sudo", "chown", os.getenv('USER'), syslog_path]
logging.debug("Cmd: %s" % (cmd))
subprocess.check_call(cmd)

while True:
    if l_ipAddress is None:
        l_ipAddress = get_ipAddress(test['_id'], mac_address)

    if l_ipAddress is not None:
        l_output = get_diSyslog(test['_id'], l_ipAddress)
        logging.debug(l_output)
        if l_output is None and options.variant != 'desktop':
            if not seen_di_syslog:
                iter_wait_di_syslog += 1
                if iter_wait_di_syslog == wait_di_syslog:
                    logging.info("Test %s: no debian-installer log seen \
in %s seconds, cancelling run", test['_id'], iter_wait_di_syslog*SLEEP_TIME)
                    end_VM(test['_id'])
        else:
            seen_di_syslog = True

        if check_for_errors(l_output):
            logging.info("Test %s: debian-installer reports error", test['_id'])
            end_VM(test['_id'])
            break

    logging.debug("Checking VM state for test case %s" % test['_id'])
    cmd = [ "virsh", "domstate", test['_id']]
    logging.debug("Cmd: %s", (cmd))
    # Execute Process, capturing return code and output
    l_proc = subprocess.Popen(cmd, bufsize=2048, stdout=subprocess.PIPE)
    l_retcode = l_proc.wait()
    l_output = l_proc.communicate()[0].strip()
    logging.debug(l_output)

    if l_retcode == 0 and l_output  == "shut off":
        logging.debug("VM powered off for test case %s" % test['_id'])
        break
    elif start_time + TEST_TIMEOUT < time.time():
        logging.debug("Test %s failed to execute within %d minutes" % (test['_id'], TEST_TIMEOUT / 60))
        end_VM(test['_id'])
        break
    else:
        # Have another look in SLEEP_TIME seconds
        time.sleep(SLEEP_TIME)

# Retrieve latest copy of data
test = db[test['_id']]
for i in test:
    logging.debug("test[%s]=%s" % (i, test[i]))
# Flag to indicate if tests successfully executed
test_completed = False

testresultsdir = os.path.join(BUILD_NUMBER, TEST_RESULTS)
# Create the output directory to store results
if not os.path.exists(testresultsdir):
    os.makedirs(testresultsdir)

if test['states'].has_key('tested') and test.has_key('results'):
    # Testing appears to have completed - VM ran and run_tests
    # execute and wrote to CouchDB
    # Retrieve log output an place in hudson workspace
    logging.debug("Tests completed for test case %s" % test['_id'])
    # Iterate over all test results as tests completed OK
    test_results = test['results']
    for test_result in test_results:
        logging.debug("Storing results for test %s", test_result)
        test_results_file = os.path.join(testresultsdir,  "%s.stderr" % test_result)
        f = open (test_results_file, 'w')
        f.write(test['results'][test_result]['script_stderr'])
        f.close()
        test_results_file = os.path.join(testresultsdir,  "TEST-%s.xml" % test_result)
        f = open (test_results_file, 'w')
        f.write(test['results'][test_result]['script_stdout'])
        f.close()
    test_completed = True
else:
    logging.error("VM for test case %s powered off but tests not completed" % test['_id'])

if test['states'].has_key('rebooted') and test.has_key('post-reboot-results'):
    logging.debug("Reboot tests completed for test case %s" % test['_id'])
    post_reboot_results = test['post-reboot-results']
    for test_result in post_reboot_results:
        logging.debug("Storing results for test %s", test_result)
        test_results_file = os.path.join(testresultsdir,  "post-reboot-%s.stderr" % test_result)
        f = open (test_results_file, 'w')
        f.write(test['post-reboot-results'][test_result]['script_stderr'])
        f.close()
        test_results_file = os.path.join(testresultsdir,  "TEST-POST-REBOOT-%s.xml" % test_result)
        f = open (test_results_file, 'w')
        f.write(test['post-reboot-results'][test_result]['script_stdout'])
        f.close()
elif test['states'].has_key('rebooted') and not test.has_key('post-reboot-results'):
    logging.error("VM for test case %s rebooted but reboot tests not completed", test['_id'])

# save D-I logs no matter what (if they exist, of course)
if os.path.isfile(syslog_path):
    # we do have a debian-installer syslog
    try:
        shutil.move(syslog_path, os.path.join(testresultsdir, 'd-i-syslog.log'))
    except IOError, e:
        # This only happens if users run these tests instead of root
        logging.warn("Could not move syslog (%s)" % e)
    
# Undefine and delete the Virtual Machine
logging.debug("Undefine VM for  test case %s" % (test['_id']))
cmd = [ "virsh", "undefine", test['_id']]
logging.debug("Cmd: %s" % (cmd))
subprocess.check_call(cmd)
# Remove VM config and disks - no longer required
shutil.rmtree(os.path.join(TEST_DIR,  test['_id']))

# Remove TFTP files - no longer required
#shutil.rmtree(test_tftp_dir)
# TODO remove pxelinux configuration from TFTP_DIR
os.remove(os.path.join(TFTP_DIR, 'kernel.%s' % test_uuid))
os.remove(os.path.join(TFTP_DIR, 'initrd.%s' % test_uuid))
os.remove(os.path.join(TFTP_DIR, 'preseed.%s' % test_uuid))
os.remove(os.path.join(TFTP_DIR, 'pxelinux.cfg',
                       '01-%s' % mac_address.replace(':', '-')))
    
# Remove dnsmasq configuration and restart dnsmasq
#logging.debug("Removing dnsmasq configuration for %s" % (test['_id']))
#os.remove(dnsmasq_conf_file )
#cmd = [ "sudo", "/usr/bin/pkill", "-HUP", "dnsmasq"]
#logging.debug("Cmd: %s" % (cmd))
#subprocess.check_call(cmd)

# Running under Hudson?
if HUDSON_URL:
    logging.debug("Collating output for test case %s" % (test['_id']))
    # Test output is located in a directory associated with the 
    # Hudson build number
    #testoutputdir= os.path.join(os.getcwd(), BUILD_NUMBER)
    #if not os.path.exists(testoutputdir):
    #        os.makedirs(testoutputdir)
    #l_cwd = os.getcwd()
    # Change to testoutput directory
    #os.chdir(testoutputdir)
    # Collate attachements into workspace
    for a in test['_attachments']:
        # Filter out stuff not interested in
        if a not in ATTACHEMENT_EXCLUSIONS:
            # Retrieve attachement to CWD
            content = db.get_attachment(test, a)
            # Check to see if directory needs to be created
            DIR = os.path.dirname(a)
            if DIR and not os.path.exists(DIR):
                os.makedirs(DIR)
            # Write out the attachment
            tgt = open(a, 'w')
            try:
                tgt.write(content.read())
            except TypeError:
                logging.error("got TypeError on the content of '%s'" % a)
            tgt.close()
    # Write out a copy of the CouchDB document for reference
    tgt = open('%s-couch.txt' % (test['_id']), 'w')
    tgt.write(str(test))
    tgt.close()
    # Move back to old working directory
    #os.chdir(l_cwd)
    
# Delete the test case from the Couch Database
db.delete(test)

# Determine if testing failed and return exit status 1 if not executed
if not test_completed:
    sys.exit(1)