Merge lp:~matsubara/curtin/jenkins into lp:~curtin-dev/curtin/trunk

[Diogo Matsubara]

Add a logger to save logs to file and print output to console.

Hi, this branch adds a logger to the vmtests so test run logs as well the serial.log files generated by different kvm invocations will be kept for a post mortem analysis. This is specially useful for tests run under the jenkins instance I'm setting up for curtin CI. It also keeps the functionality of print()ing the output of tests to the console and it sets a pattern to be used for future test additions to the vmtests.

[Ryan Harper (raharper)]

Looks fine, please do add something so subsequent and/or parallel runs of vmtest don't write to the same file.

The rest is fine.

review: Needs Fixing

[Diogo Matsubara (matsubara)]

> Looks fine, please do add something so subsequent and/or parallel runs of
> vmtest don't write to the same file.
>
> The rest is fine.

Hi Ryan,

I initially used the FileHandler mode='a' so the log would always be appended but then the log file was growing too much (and my initial intention was to have it collected by each jenkins job after the run). I like the idea of putting a date in the name so it'll be kept separate. Fixed.

Thanks for the review!

[Ryan Harper (raharper)]

review: Approve

[Scott Moser (smoser)]

review: Approve

[lp:~matsubara/curtin/jenkins]

270. By Ryan Harper on 2015-09-14

Add a logger to save logs to file and print output to console.

Use logger to capture vmtest logs, serial.log files generated during test runs.
Tests will continue to produce output to stderr for capture under test
harnesses like Jenkins

=== modified file 'tests/vmtests/__init__.py'
--- tests/vmtests/__init__.py	2015-08-31 20:58:03 +0000
+++ tests/vmtests/__init__.py	2015-09-10 13:04:01 +0000
@@ -1,5 +1,7 @@
 import ast
+import datetime
 import hashlib
+import logging
 import os
 import re
 import shutil
@@ -12,6 +14,26 @@
 DEVNULL = open(os.devnull, 'w')
 
 
+logger = logging.getLogger(__name__)
+logger.setLevel(logging.DEBUG)
+formatter = logging.Formatter(
+    '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
+# Configure logging module to save output to disk and present it on
+# sys.stderr
+now = datetime.datetime.now().isoformat()
+fh = logging.FileHandler(
+    '/tmp/{}-vmtest.log'.format(now), mode='w', encoding='utf-8')
+fh.setLevel(logging.DEBUG)
+fh.setFormatter(formatter)
+
+ch = logging.StreamHandler()
+ch.setLevel(logging.DEBUG)
+ch.setFormatter(formatter)
+
+logger.addHandler(fh)
+logger.addHandler(ch)
+
+
 class ImageStore:
     def __init__(self, base_dir):
         self.base_dir = base_dir
@@ -20,19 +42,19 @@
 
     def get_image(self, repo, release, arch):
         # query sstream for root image
-        print('Query simplestreams for root image: '
-              'release={release} arch={arch}'.format(release=release,
-                                                     arch=arch))
+        logger.debug(
+            'Query simplestreams for root image: '
+            'release={release} arch={arch}'.format(release=release, arch=arch))
         cmd = ["tools/usquery", "--max=1", repo, "release=%s" % release,
                "krel=%s" % release, "arch=%s" % arch,
                "item_name=root-image.gz"]
-        print(" ".join(cmd))
+        logger.debug(" ".join(cmd))
         out = subprocess.check_output(cmd)
-        print(out)
+        logger.debug(out)
         sstream_data = ast.literal_eval(bytes.decode(out))
 
         # Check if we already have the image
-        print('Checking cache for image')
+        logger.debug('Checking cache for image')
         checksum = ""
         release_dir = os.path.join(self.base_dir, repo, release, arch,
                                    sstream_data['version_name'])
@@ -50,13 +72,13 @@
                 not os.path.exists(p("root-image-kernel")) or \
                 not os.path.exists(p("root-image-initrd")):
             # clear dir, download, and extract image
-            print('Image not found, downloading...')
+            logger.debug('Image not found, downloading...')
             shutil.rmtree(release_dir, ignore_errors=True)
             os.makedirs(release_dir)
             subprocess.check_call(
                 ["wget", "-c", sstream_data['item_url'], "-O",
                  p("root-image.gz")])
-            print('Converting image format')
+            logger.debug('Converting image format')
             subprocess.check_call(["tools/maas2roottar", p("root-image.gz")])
         return (p("root-image"), p("root-image-kernel"),
                 p("root-image-initrd"))
@@ -80,21 +102,21 @@
         os.mkdir(self.mnt)
 
         # create target disk
-        print('Creating target disk')
+        logger.debug('Creating target disk')
         self.target_disk = os.path.join(self.tmpdir, "install_disk.img")
         subprocess.check_call(["qemu-img", "create", "-f", "qcow2",
                               self.target_disk, "10G"],
                               stdout=DEVNULL, stderr=subprocess.STDOUT)
 
         # create seed.img for installed system's cloud init
-        print('Creating seed disk')
+        logger.debug('Creating seed disk')
         self.seed_disk = os.path.join(self.tmpdir, "seed.img")
         subprocess.check_call(["cloud-localds", self.seed_disk,
                               user_data_file, meta_data_file],
                               stdout=DEVNULL, stderr=subprocess.STDOUT)
 
         # create output disk, mount ro
-        print('Creating output disk')
+        logger.debug('Creating output disk')
         self.output_disk = os.path.join(self.tmpdir, "output_disk.img")
         subprocess.check_call(["qemu-img", "create", "-f", "raw",
                               self.output_disk, "10M"],
@@ -103,7 +125,7 @@
                               stdout=DEVNULL, stderr=subprocess.STDOUT)
 
     def mount_output_disk(self):
-        print('Mounting output disk')
+        logger.debug('Mounting output disk')
         subprocess.check_call(["fuseext2", "-o", "rw+", self.output_disk,
                               self.mnt],
                               stdout=DEVNULL, stderr=subprocess.STDOUT)
@@ -116,14 +138,14 @@
 class VMBaseClass:
     @classmethod
     def setUpClass(self):
-        print('Acquiring boot image')
+        logger.debug('Acquiring boot image')
         # get boot img
         image_store = ImageStore(IMAGE_DIR)
         (boot_img, boot_kernel, boot_initrd) = image_store.get_image(
             self.repo, self.release, self.arch)
 
         # set up tempdir
-        print('Setting up tempdir')
+        logger.debug('Setting up tempdir')
         self.td = TempDir(self.user_data)
 
         # create launch cmd
@@ -133,7 +155,7 @@
 
         # check for network configuration
         self.network_state = curtin_net.parse_net_config(self.conf_file)
-        print(self.network_state)
+        logger.debug("Network state: {}".format(self.network_state))
 
         # build -n arg list with macaddrs from net_config physical config
         macs = []
@@ -141,7 +163,7 @@
         if self.network_state:
             interfaces = self.network_state.get('interfaces')
         for ifname in interfaces:
-            print(ifname)
+            logger.debug("Interface name: {}".format(ifname))
             iface = interfaces.get(ifname)
             hwaddr = iface.get('mac_address')
             if hwaddr:
@@ -166,31 +188,32 @@
 
         # run vm with installer
         try:
-            print('Running curtin installer')
-            print('{}'.format(" ".join(cmd)))
+            logger.debug('Running curtin installer')
+            logger.debug('{}'.format(" ".join(cmd)))
             subprocess.check_call(cmd, timeout=self.install_timeout,
                                   stdout=DEVNULL, stderr=subprocess.STDOUT)
         except subprocess.TimeoutExpired:
-            print('Curting installer failed')
+            logger.debug('Curtin installer failed')
             raise
         finally:
             if os.path.exists('serial.log'):
-                with open('serial.log', 'r') as l:
-                    print('Serial console output:\n{}'.format(l.read()))
+                with open('serial.log', 'r', encoding='utf-8') as l:
+                    logger.debug(
+                        u'Serial console output:\n{}'.format(l.read()))
 
-        print('')
-        print('Checking curtin install output for errors')
+        logger.debug('')
+        logger.debug('Checking curtin install output for errors')
         with open('serial.log') as l:
             install_log = l.read()
             errors = re.findall('\[.*\]\ cloud-init.*:.*Installation\ failed',
                                 install_log)
             if len(errors) > 0:
                 for e in errors:
-                    print(e)
-                print('Errors during curtin installer')
+                    logger.debug(e)
+                logger.debug('Errors during curtin installer')
                 raise Exception('Errors during curtin installer')
             else:
-                print('Install OK')
+                logger.debug('Install OK')
 
         # drop the size parameter if present in extra_disks
         extra_disks = [x if ":" not in x else x.split(':')[0]
@@ -207,26 +230,27 @@
 
         # run vm with installed system, fail if timeout expires
         try:
-            print('Booting target image')
-            print('{}'.format(" ".join(cmd)))
+            logger.debug('Booting target image')
+            logger.debug('{}'.format(" ".join(cmd)))
             subprocess.check_call(cmd, timeout=self.boot_timeout,
                                   stdout=DEVNULL, stderr=subprocess.STDOUT)
         except subprocess.TimeoutExpired:
-            print('Booting after install failed')
+            logger.debug('Booting after install failed')
             raise
         finally:
             serial_log = os.path.join(self.td.tmpdir, 'serial.log')
             if os.path.exists(serial_log):
-                with open(serial_log, 'r') as l:
-                    print('Serial console output:\n{}'.format(l.read()))
+                with open(serial_log, 'r', encoding='utf-8') as l:
+                    logger.debug(
+                        u'Serial console output:\n{}'.format(l.read()))
 
         # mount output disk
         self.td.mount_output_disk()
-        print('Ready for testcases')
+        logger.debug('Ready for testcases')
 
     @classmethod
     def tearDownClass(self):
-        print('Removing launch logfile')
+        logger.debug('Removing launch logfile')
         subprocess.call(["fusermount", "-u", self.td.mnt])
         # remove launch logfile
         if os.path.exists("./serial.log"):

=== modified file 'tests/vmtests/test_bonding.py'
--- tests/vmtests/test_bonding.py	2015-09-04 18:44:08 +0000
+++ tests/vmtests/test_bonding.py	2015-09-10 13:04:01 +0000
@@ -1,4 +1,4 @@
-from . import VMBaseClass
+from . import VMBaseClass, logger
 from unittest import TestCase
 
 import ipaddress
@@ -84,13 +84,13 @@
     def test_ifenslave_installed(self):
         with open(os.path.join(self.td.mnt, "ifenslave_installed")) as fp:
             status = fp.read().strip()
-            print('ifenslave installed: {}'.format(status))
+            logger.debug('ifenslave installed: {}'.format(status))
             self.assertEqual('install ok installed', status)
 
     def test_etc_network_interfaces(self):
         with open(os.path.join(self.td.mnt, "interfaces")) as fp:
             eni = fp.read()
-            print('etc/network/interfaces:\n{}'.format(eni))
+            logger.debug('etc/network/interfaces:\n{}'.format(eni))
 
         expected_eni = self.get_expected_etc_network_interfaces()
         eni_lines = eni.split('\n')
@@ -100,20 +100,20 @@
     def test_ifconfig_output(self):
         '''check ifconfig output with test input'''
         network_state = self.get_network_state()
-        print('expected_network_state:\n{}'.format(
+        logger.debug('expected_network_state:\n{}'.format(
             yaml.dump(network_state, default_flow_style=False, indent=4)))
 
         with open(os.path.join(self.td.mnt, "ifconfig_a")) as fp:
             ifconfig_a = fp.read()
-            print('ifconfig -a:\n{}'.format(ifconfig_a))
+            logger.debug('ifconfig -a:\n{}'.format(ifconfig_a))
 
         ifconfig_dict = ifconfig_to_dict(ifconfig_a)
-        print('parsed ifcfg dict:\n{}'.format(
+        logger.debug('parsed ifcfg dict:\n{}'.format(
             yaml.dump(ifconfig_dict, default_flow_style=False, indent=4)))
 
         with open(os.path.join(self.td.mnt, "ip_route_show")) as fp:
             ip_route_show = fp.read()
-            print("ip route show:\n{}".format(ip_route_show))
+            logger.debug("ip route show:\n{}".format(ip_route_show))
             for line in [line for line in ip_route_show.split('\n')
                          if 'src' in line]:
                 m = re.search(r'^(?P<network>\S+)\sdev\s' +
@@ -122,11 +122,11 @@
                               r'\s+src\s(?P<src_ip>\S+)',
                               line)
                 route_info = m.groupdict('')
-                print(route_info)
+                logger.debug(route_info)
 
         with open(os.path.join(self.td.mnt, "route_n")) as fp:
             route_n = fp.read()
-            print("route -n:\n{}".format(route_n))
+            logger.debug("route -n:\n{}".format(route_n))
 
         interfaces = network_state.get('interfaces')
         for iface in interfaces.values():
@@ -149,8 +149,8 @@
                                      route_n)
 
     def check_interface(self, iface, ifconfig, route_n):
-        print('testing iface:\n{}\n\nifconfig:\n{}'.format(
-              iface, ifconfig))
+        logger.debug(
+            'testing iface:\n{}\n\nifconfig:\n{}'.format(iface, ifconfig))
         subnets = iface.get('subnets', {})
         if subnets and iface['index'] != 0:
             ifname = "{name}:{index}".format(**iface)
@@ -158,8 +158,8 @@
             ifname = "{name}".format(**iface)
 
         # initial check, do we have the correct iface ?
-        print('ifname={}'.format(ifname))
-        print("ifconfig['interface']={}".format(ifconfig['interface']))
+        logger.debug('ifname={}'.format(ifname))
+        logger.debug("ifconfig['interface']={}".format(ifconfig['interface']))
         self.assertEqual(ifname, ifconfig['interface'])
 
         # check physical interface attributes
@@ -205,12 +205,12 @@
                 gw_ip = subnet['gateway']
                 gateways = [line for line in route_n.split('\n')
                             if 'UG' in line and gw_ip in line]
-                print('matching gateways:\n{}'.format(gateways))
+                logger.debug('matching gateways:\n{}'.format(gateways))
                 self.assertEqual(len(gateways), 1)
                 [gateways] = gateways
                 (dest, gw, genmask, flags, metric, ref, use, iface) = \
                     gateways.split()
-                print('expected gw:{} found gw:{}'.format(gw_ip, gw))
+                logger.debug('expected gw:{} found gw:{}'.format(gw_ip, gw))
                 self.assertEqual(gw_ip, gw)
 
 

=== modified file 'tests/vmtests/test_network.py'
--- tests/vmtests/test_network.py	2015-08-27 21:46:55 +0000
+++ tests/vmtests/test_network.py	2015-09-10 13:04:01 +0000
@@ -1,4 +1,4 @@
-from . import VMBaseClass
+from . import VMBaseClass, logger
 from unittest import TestCase
 
 import ipaddress
@@ -81,7 +81,7 @@
     def test_etc_network_interfaces(self):
         with open(os.path.join(self.td.mnt, "interfaces")) as fp:
             eni = fp.read()
-            print('etc/network/interfaces:\n{}'.format(eni))
+            logger.debug('etc/network/interfaces:\n{}'.format(eni))
 
         expected_eni = self.get_expected_etc_network_interfaces()
         eni_lines = eni.split('\n')
@@ -91,20 +91,20 @@
     def test_ifconfig_output(self):
         '''check ifconfig output with test input'''
         network_state = self.get_network_state()
-        print('expected_network_state:\n{}'.format(
+        logger.debug('expected_network_state:\n{}'.format(
             yaml.dump(network_state, default_flow_style=False, indent=4)))
 
         with open(os.path.join(self.td.mnt, "ifconfig_a")) as fp:
             ifconfig_a = fp.read()
-            print('ifconfig -a:\n{}'.format(ifconfig_a))
+            logger.debug('ifconfig -a:\n{}'.format(ifconfig_a))
 
         ifconfig_dict = ifconfig_to_dict(ifconfig_a)
-        print('parsed ifcfg dict:\n{}'.format(
+        logger.debug('parsed ifcfg dict:\n{}'.format(
             yaml.dump(ifconfig_dict, default_flow_style=False, indent=4)))
 
         with open(os.path.join(self.td.mnt, "ip_route_show")) as fp:
             ip_route_show = fp.read()
-            print("ip route show:\n{}".format(ip_route_show))
+            logger.debug("ip route show:\n{}".format(ip_route_show))
             for line in [line for line in ip_route_show.split('\n')
                          if 'src' in line]:
                 m = re.search(r'^(?P<network>\S+)\sdev\s' +
@@ -113,11 +113,11 @@
                               r'\s+src\s(?P<src_ip>\S+)',
                               line)
                 route_info = m.groupdict('')
-                print(route_info)
+                logger.debug(route_info)
 
         with open(os.path.join(self.td.mnt, "route_n")) as fp:
             route_n = fp.read()
-            print("route -n:\n{}".format(route_n))
+            logger.debug("route -n:\n{}".format(route_n))
 
         interfaces = network_state.get('interfaces')
         for iface in interfaces.values():
@@ -140,8 +140,8 @@
                                      route_n)
 
     def check_interface(self, iface, ifconfig, route_n):
-        print('testing iface:\n{}\n\nifconfig:\n{}'.format(
-              iface, ifconfig))
+        logger.debug(
+            'testing iface:\n{}\n\nifconfig:\n{}'.format(iface, ifconfig))
         subnets = iface.get('subnets', {})
         if subnets and iface['index'] != 0:
             ifname = "{name}:{index}".format(**iface)
@@ -149,8 +149,8 @@
             ifname = "{name}".format(**iface)
 
         # initial check, do we have the correct iface ?
-        print('ifname={}'.format(ifname))
-        print("ifconfig['interface']={}".format(ifconfig['interface']))
+        logger.debug('ifname={}'.format(ifname))
+        logger.debug("ifconfig['interface']={}".format(ifconfig['interface']))
         self.assertEqual(ifname, ifconfig['interface'])
 
         # check physical interface attributes
@@ -194,12 +194,12 @@
                 gw_ip = subnet['gateway']
                 gateways = [line for line in route_n.split('\n')
                             if 'UG' in line and gw_ip in line]
-                print('matching gateways:\n{}'.format(gateways))
+                logger.debug('matching gateways:\n{}'.format(gateways))
                 self.assertEqual(len(gateways), 1)
                 [gateways] = gateways
                 (dest, gw, genmask, flags, metric, ref, use, iface) = \
                     gateways.split()
-                print('expected gw:{} found gw:{}'.format(gw_ip, gw))
+                logger.debug('expected gw:{} found gw:{}'.format(gw_ip, gw))
                 self.assertEqual(gw_ip, gw)