Merge lp:~javier.collado/utah/bug1089884 into lp:utah

[Javier Collado]

This branch updates the ISO validation script to generate a yaml file report
that can be parsed by the QA dashboard.

Aside from this, the script output has been modified to:
- Include all debug logs
- Print backtraces and skipped test cases

Backtraces were already in the script, but was lost when switiching to running
the test suite manually to process results to generate the yaml report.

[Javier Collado (javier.collado)]

The changes in this branch should be enough to make the ISO validation script
friendlier. However, I still need to look at the setup-jobs.py script to
update the job so that the yaml file is archived as an artifact in jenkins.

Please let me know if some other thing is missing. Thanks.

[Max Brustkern (nuclearbob)]

There are a few things I'd like to see changed here, but I'm not sure they're necessary to deployment.

First, I ran this on a raring ISO from last week, and it passed. I know we've discussed changing the tests to support validating old ISOs, but the current default behavior is to fail on an old ISO, which I think is appropriate for daily smoke testing, where we always want to be testing the latest ISO.

Second, and less important, I don't like that the default behavior of this script is to write a file to my current working directory. In my view, the only time that's useful is when we're running under jenkins, and if we are running under jenkins, there are several ways we can handle that. We can write the yaml to standard out by default (and redirect it to a file in the jenkins job.) We can default to writing a file to a logs directory, and either add a parameter to write that file to a specific location (such as the current working directory) or provide clear and consistent output regarding where that file is written so that the output can be parsed and the file picked up. If I'm testing the scripts, or manually validating an ISO for some reason, I'm going to end up with extra files in my branch that need to be cleaned up.

[lp:~javier.collado/utah/bug1089884]

800. By Javier Collado on 2012-12-13

Added log directory default (relative path not used anymore)

801. By Javier Collado on 2012-12-13

Fixed error/failure counters

Bad subclassing of `unittest.TestResult` was the problem. Using `super` to call
the default implementation, brings the counters correct value back.

[Javier Collado (javier.collado)]

Fixed both issues in previous comment.

review: Needs Resubmitting

[lp:~javier.collado/utah/bug1089884]

802. By Javier Collado on 2012-12-13

Fixed log filename printed to stdout

803. By Javier Collado on 2012-12-13

Fixed unknown `uname` should be an empty array

[Javier Collado (javier.collado)]

Log file name is now printed to stdout (and prefixed with a tab) and `uname` is
set to an empty array.

review: Needs Resubmitting

[lp:~javier.collado/utah/bug1089884]

804. By Javier Collado on 2012-12-13

Fixed timestamp format

[Javier Collado (javier.collado)]

Generated report example:

---
arch: i386
build_number: '20121108.2'
commands: []
errors: 5
failures: 0
fetch_errors: 0
install_type: desktop
media-info: Ubuntu 13.04 "Raring Ringtail" - Alpha i386 (20121108.2)
passes: 5
ran_at: 2012-12-13_15-06-22
release: raring
runlist: iso_static_validation
uname: []

[lp:~javier.collado/utah/bug1089884]

805. By Javier Collado on 2012-12-13

Fixed use different timestamp format in the report and in the filename

806. By Javier Collado on 2012-12-13

Added name field to the report

807. By Javier Collado on 2012-12-13

Expanded comment about `name` and `runlist` fields

[Javier Collado (javier.collado)]

New format after the fixes above:

---
arch: i386
build_number: '20121108.2'
commands: []
errors: 5
failures: 0
fetch_errors: 0
install_type: desktop
media-info: Ubuntu 13.04 "Raring Ringtail" - Alpha i386 (20121108.2)
name: iso_static_validation
passes: 5
ran_at: '2012-12-13 16:18:35'
release: raring
runlist: iso_static_validation
uname: []

review: Needs Resubmitting

[lp:~javier.collado/utah/bug1089884]

808. By Javier Collado on 2012-12-13

Moved logging message outside of loop to get it just once

[Joe Talbott (joetalbott)]

Looks good to me.

review: Approve

=== modified file 'utah/isotest/iso_static_validation.py'
--- utah/isotest/iso_static_validation.py	2012-12-07 18:04:00 +0000
+++ utah/isotest/iso_static_validation.py	2012-12-13 17:31:21 +0000
@@ -20,7 +20,7 @@
 #
 # This file is part of utah.
 #
-# iso_satatic_validation is free software: you can redistribute it
+# iso_static_validation 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.
@@ -37,6 +37,13 @@
 
 # TODO: support for non-daily images
 
+"""ISO static validation.
+
+The test cases in this scripts are used to make sure that an ISO image isn't
+broken and can be used for smoke testing.
+
+"""
+
 import os
 import argparse
 import sys
@@ -48,6 +55,11 @@
 import re
 import tempfile
 import shutil
+import time
+import platform
+from traceback import format_exception
+
+import yaml
 
 lib_path = os.path.abspath('../')
 sys.path.append(lib_path)
@@ -57,6 +69,7 @@
 # Defaults
 DEFAULT_ISOROOT = os.path.expanduser('~/Downloads')
 DEFAULT_URL = 'http://cdimage.ubuntu.com/'
+DEFAULT_LOG_DIR = '/var/log/utah/'
 
 #constants
 ONE_MB_BLOCK = 2 ** 20
@@ -66,7 +79,26 @@
 parser.add_argument('--name')
 args = parser.parse_args()
 
-logging.basicConfig(level=logging.INFO)
+
+def configure_logging(log_level=logging.DEBUG):
+    """Configure logging to stderr using the passed log_level.
+
+    :param log_level: Log level to be used
+    :type log_level: int
+
+    """
+    logger = logging.getLogger()
+    logger.setLevel(logging.DEBUG)
+    formatter = logging.Formatter('%(levelname)s: %(message)s')
+
+    log_handler = logging.StreamHandler()
+    log_handler.setFormatter(formatter)
+    log_handler.setLevel(log_level)
+
+    logger.addHandler(log_handler)
+
+
+configure_logging()
 
 if args.name is None or '.iso' not in args.name:
     print 'The usage:', sys.argv[0],  '--name release-variant-arch.iso'
@@ -101,10 +133,12 @@
         try:
             cls.temp_dir = tempfile.mkdtemp()
         except OSError:
-            logging.error("Creating temp dirrectory failed")
+            logging.error("Creating temp directory failed")
             unittest.fail("Setup error")
 
     def setUp(self):
+        logging.info('\n{separator}\n{id}\n{separator}'
+                     .format(separator='-' * 80, id=self.id()))
         self.block_size = ONE_MB_BLOCK
         self.iso_location = iso_location
         logging.debug('Using iso at: ' + self.iso_location)
@@ -198,8 +232,8 @@
         logging.debug('Checking for error in extracting the file list')
         self.assertEqual(stderr, '')
 
+        logging.debug('Checking that each list entry is in the iso')
         for list_entry in list_repository:
-            logging.debug('Checking that each list entry is in the iso')
             self.assertIn(list_entry[1:].rstrip(), stdout)
 
     # Test if the manfest is the same as that is given in the server
@@ -221,8 +255,8 @@
         manifest_path = self.iso.extract('casper/filesystem.manifest',
                                          self.temp_dir)
         manifest_local = open(manifest_path)
+        logging.debug('Checking manifest are the same in iso and repo')
         for manifest_entry in manifest:
-            logging.debug('Checking manifest are the same in iso and repo')
             self.assertIn(manifest_entry, manifest_local)
 
     # Test if the buildid present in the download server is
@@ -278,8 +312,8 @@
             # wubi is not shipped in raring
             exclude_files.append('autorun.inf')
             exclude_files.append('wubi.exe')
+        logging.debug('Check if relevant files are present in the iso')
         for list_server in files_list:
-            logging.debug('Check if relevant files are present in the iso')
             path = list_server.rstrip()
             if path in exclude_files:
                 logging.debug(path + ' excluded based on release')
@@ -359,12 +393,17 @@
         self.assertIn("Squashfs filesystem", stdout)
 
         #unsquashfs extracts only in pwd
-        os.chdir(self.temp_dir)
-
-        cmd = ["unsquashfs", "-f",  squashfs_path, "-l", "vmlinuz"]
-        output = subprocess.Popen(cmd, stdout=subprocess.PIPE,
-                                  stderr=subprocess.PIPE)
-        (stdout, stderr) = output.communicate()
+        cwd = os.getcwd()
+        try:
+            os.chdir(self.temp_dir)
+
+            cmd = ["unsquashfs", "-f",  squashfs_path, "-l", "vmlinuz"]
+            output = subprocess.Popen(cmd, stdout=subprocess.PIPE,
+                                      stderr=subprocess.PIPE)
+            (stdout, stderr) = output.communicate()
+        finally:
+            os.chdir(cwd)
+
         logging.debug('Check that vmlinuz could be extracted')
         self.assertEqual(stderr, '')
         self.assertIn("created 1 directories", stdout)
@@ -378,6 +417,80 @@
             logging.error("Removing the temp directory failed")
             unittest.fail("Cleanup error")
 
+
+def get_report_data(runlist, results):
+    errors = len(results.errors)
+    failures = len(results.failures)
+    skipped = len(results.skipped)
+    passes = results.testsRun - skipped - errors - failures
+    report_timestamp = time.strftime('%Y-%m-%d %H:%M:%S', time.gmtime())
+
+    # Note: Ideally 'name' is the runlist name and 'runlist' the path to the
+    # runlist file. Given that there isn't a real runlist file here, the name
+    # is being used for both fields.
+    report_data = {
+        'name': runlist,
+        'runlist': runlist,
+        'media-info': iso.media_info,
+        'build_number': iso.buildnumber,
+        'release': iso.series,
+        'ran_at': report_timestamp,
+        'install_type': iso.installtype,
+        'arch': iso.arch,
+        'commands': [],
+        'fetch_errors': 0,
+        'errors': errors,
+        'failures': failures,
+        'passes': passes,
+        'uname': [],
+    }
+
+    return report_data
+
+
+class ISOResult(unittest.TestResult):
+    def _print_error(self, test, error):
+        logging.error(test)
+        logging.error(''.join(format_exception(*error)))
+
+    def addError(self, test, error):
+        super(ISOResult, self).addError(test, error)
+        self._print_error(test, error)
+
+    def addFailure(self, test, error):
+        super(ISOResult, self).addError(test, error)
+        self._print_error(test, error)
+
+    def addSkip(self, test, reason):
+        logging.info('\n{separator}\n{id}\n{separator}'
+                     .format(separator='-' * 80, id=test.id()))
+        logging.info('Skipped: {}'.format(reason))
+
+
+def main():
+    """Run test cases and write qa dashboard friendly report."""
+    suite = unittest.TestLoader().loadTestsFromTestCase(TestValidateISO)
+    results = ISOResult()
+    results.buffer = True
+    suite.run(results)
+
+    fake_runlist = 'iso_static_validation'
+    report_data = get_report_data(fake_runlist, results)
+    report = yaml.dump(report_data,
+                       explicit_start='---',
+                       default_flow_style=False)
+    filename_timestamp = time.strftime('%Y-%m-%d_%H-%M-%S', time.gmtime())
+    log_filename = ('{machine}_{runlist}_{timestamp}.{suffix}'
+                    .format(machine=platform.node(),
+                            runlist=fake_runlist,
+                            timestamp=filename_timestamp,
+                            suffix='yaml'))
+    absolute_log_filename = os.path.join(DEFAULT_LOG_DIR, log_filename)
+    with open(absolute_log_filename, 'w') as f:
+        f.write(report)
+    print('Test log copied to\n\t{}'.format(absolute_log_filename))
+
+    return 0 if results.wasSuccessful() else 1
+
 if __name__ == '__main__':
-    from test import test_support
-    test_support.run_unittest(TestValidateISO)
+    sys.exit(main())

=== modified file 'utah/run.py'
--- utah/run.py	2012-12-06 16:30:34 +0000
+++ utah/run.py	2012-12-13 17:31:21 +0000
@@ -59,16 +59,16 @@
         report will be generated.
 
         """
-        timestamp = time.strftime('%Y-%m-%d_%H-%m-%S', time.gmtime())
-
+        gmtime = time.gmtime()
         if report is None:
             # Generate default report with empty results to fake client output
+            report_timestamp = time.strftime('%Y-%m-%d %H:%M:%S', gmtime)
             default_report = {
                 'runlist': runlist,
                 'media-info': machine.image.media_info,
                 'build_number': machine.image.buildnumber,
                 'release': machine.image.series,
-                'ran_at': timestamp,
+                'ran_at': report_timestamp,
                 'install_type': machine.installtype,
                 'arch': machine.arch,
                 'commands': [],
@@ -76,7 +76,7 @@
                 'errors': 0,
                 'failures': 0,
                 'passes': 0,
-                'uname': '',
+                'uname': [],
 
 
             }
@@ -91,10 +91,11 @@
                                  .format(report_type))
 
         listname = os.path.basename(runlist)
+        filename_timestamp = time.strftime('%Y-%m-%d %H:%M:%S', gmtime)
         log_filename = ('{machine}_{runlist}_{timestamp}.{suffix}'
                         .format(machine=machine.name,
                                 runlist=listname,
-                                timestamp=timestamp,
+                                timestamp=filename_timestamp,
                                 suffix=report_type))
         locallog = os.path.join(config.logpath, log_filename)
         locallog = os.path.normpath(locallog)