Merge ~bladernr/plainbox-provider-checkbox:1628264-virt-timeout into plainbox-provider-checkbox:master

[Jeff Lane ]

KVM test now properly polls console output for status message (before, regardless of successful boot, it would just sleep the full TIMEOUT before checking).
Also, quiet urllib3 built in logger to squash unnecessary INFO level messages.

[Rod Smith (rodsmith)]

The Good
--------

I've run the modified script on a couple of systems, one of which supports virtualization and the other of which does not, and I got expected results both times:

* https://certification.canonical.com/hardware/201701-25363/submission/120327/test/380/result/8905819/
* https://certification.canonical.com/hardware/201409-15506/submission/120330/test/380/result/8906798/

I have not tested every possible failure mode, though.

The Bad
-------

Both "pylint" and "flake8" produce large numbers of errors and warnings on this script. Most of these are for existing code, so it's unfair to ask you to fix them on this submission; however, there were a few complaints about code submitted here. From the pylint output:

C:443, 0: Exactly one space required after comma
    def log_check(self,stream):
                      ^ (bad-whitespace)
C:499, 0: Exactly one space required around assignment
                self.elapsed_time=0
                                 ^ (bad-whitespace)
W:529,30: Use % formatting in logging functions and pass the % parameters as arguments (logging-format-interpolation)
W:499,16: Attribute 'elapsed_time' defined outside __init__ (attribute-defined-outside-init)

If you prefer to file a bug report about the large number of complaints by these tools and leave these as-is, I'm willing to let this slide, since they seem to be trivial things that don't affect the program's ability to work, and they're a drop in the bucket amidst the many similar complaints by pylint and flake8.

The Question:
-------------

Finally, concerning the while/else clause on lines 501-524: It seems that a lot of code is duplicated from the main while loop in the else clause. The main difference seems to be that, in the else clause, the output of debug_file.read() is saved to the variable stream so that it can be logged if there's an error. Wouldn't it make more sense to simply store output in the stream variable in the main while loop and then log it only if there's an error? If there's some reason this doesn't work, then I'll pass it as-is; but if I'm not overlooking something, it appears that the code could be made cleaner by revising this logic.

review: Needs Information

[Jeff Lane  (bladernr)]

On Wed, Jun 21, 2017 at 12:29 PM, Rod Smith <email address hidden> wrote:
> The Bad
> -------
>
> Both "pylint" and "flake8" produce large numbers of errors and warnings on this script. Most of these are for existing code, so it's unfair to ask you to fix them on this submission; however, there were a few complaints about code
> submitted here. From the pylint output:

There's a reason I don't use pylint and flake8. Pylint, for example,
also tells me this:

C:742, 0: Unnecessary parens after 'print' keyword (superfluous-parens)
C:745, 0: Unnecessary parens after 'print' keyword (superfluous-parens)

which is incorrect, python3 treats print as a function and the parens
are passing arguments to that function... they're both a bit crazy
and require a good bit of configuration and work to produce useful
output, IMO. IN any case, I always check to the level of pep8, (apt
install pep8) which catches most of the PEP8 violations (the important
ones at least).

> C:443, 0: Exactly one space required after comma
> def log_check(self,stream):
> ^ (bad-whitespace)
> C:499, 0: Exactly one space required around assignment
> self.elapsed_time=0
> ^ (bad-whitespace)
> W:529,30: Use % formatting in logging functions and pass the % parameters as arguments (logging-format-interpolation)
> W:499,16: Attribute 'elapsed_time' defined outside __init__ (attribute-defined-outside-init)
>
> If you prefer to file a bug report about the large number of complaints by these tools and leave these as-is, I'm willing to let this slide, since they seem to be trivial things that don't affect the program's ability to work, and they're a drop in the bucket amidst the many similar complaints by pylint and flake8.

I did a few, just to see how bit a task it would be, and it would be
huge. If it really bugs you, we can revisit it later to pylint/flake8
it, but once you go down that road, it'll need to be done for every
python script in there ;) pep8 was the recommended tool way back
when, and afaik, still is, and most, or all, the scripts at this point
will pass a pep8 check.

> The Question:
> -------------
>
> Finally, concerning the while/else clause on lines 501-524: It seems that a lot of code is duplicated from the main while loop in the else clause. The main difference seems to be that, in the else clause, the output of debug_file.read() is
> saved to the variable stream so that it can be logged if there's an error. Wouldn't it make more sense to simply store output in the stream variable in the main while loop and then log it only if there's an error? If there's some reason this
> doesn't work, then I'll pass it as-is; but if I'm not overlooking something, it appears that the code could be made cleaner by revising this logic.

That's a good question, and I did spend a fair bit of time wrestling
with how to do what I wanted to do. In the end, this was the least
complicated... The file reads have to happen within the while loop,
since we read the contents and close the filehandle on each pass. I
didn't want to open a second filehandle (since KVM is already writing
to that file) that was cont...

[Rod Smith (rodsmith)]

OK. I see you've fixed the couple of pep8 complaints. (I agree that these Python code-checking tools are overly-anal, but I wanted you to be aware of the fact that they ARE complaining a lot when fed this script.) Your explanation for why duplicating code in the "while" loop's "else" clause is necessary makes sense. Thus, I'm accepting this version.

review: Approve

diff --git a/bin/virtualization b/bin/virtualization
index 46cf13e..b67a5fa 100755
--- a/bin/virtualization
+++ b/bin/virtualization
@@ -229,14 +229,14 @@ class KVMTest(object):
         def _construct_filename(alt_pattern=None, initial_url=None):
             if self.qemu_config['cloudimg_type'] == CLOUD_IMAGE_TYPE_TAR:
                 cloud_iso = "%s-server-cloudimg-%s.tar.gz" % (
-                            self.release, self.qemu_config['cloudimg_arch'])
+                    self.release, self.qemu_config['cloudimg_arch'])
             elif alt_pattern is "modern":
                 # LP 1635345 - yakkety and beyond have a new naming scheme
                 cloud_iso = "%s-server-cloudimg-%s.img" % (
-                            self.release, self.qemu_config['cloudimg_arch'])
+                    self.release, self.qemu_config['cloudimg_arch'])
             elif self.qemu_config['cloudimg_type'] == CLOUD_IMAGE_TYPE_DISK:
                 cloud_iso = "%s-server-cloudimg-%s-disk1.img" % (
-                            self.release, self.qemu_config['cloudimg_arch'])
+                    self.release, self.qemu_config['cloudimg_arch'])
             elif initial_url:
                 # LP 1662580 - if we pass a full URL, assume the last piece is
                 # the filname and return that.
@@ -388,7 +388,7 @@ class KVMTest(object):
         logging.debug("Using params:{}".format(" ".join(params)))
 
         logging.info("Storing VM console output in {}".format(
-                     os.path.realpath(self.debug_file)))
+            os.path.realpath(self.debug_file)))
         # Open VM STDERR/STDOUT log file for writing
         try:
             file = open(self.debug_file, 'w')
@@ -440,6 +440,12 @@ final_message: CERTIFICATION BOOT COMPLETE
         except CalledProcessError as exception:
             logging.exception("Cloud data disk creation failed")
 
+    def log_check(self, stream):
+        if "CERTIFICATION BOOT COMPLETE" in stream:
+            return 0
+        else:
+            return 1
+
     def start(self):
         if self.arch == 'arm64':
             # lp:1548539 - For arm64, we need to make sure we're using qemu
@@ -485,36 +491,42 @@ final_message: CERTIFICATION BOOT COMPLETE
                 # Boot Virtual Machine
                 instance = self.boot_image(self.image)
 
-                time.sleep(self.timeout)
                 # If running in console, reset console window to regain
                 # control from VM Serial I/0
                 if sys.stdout.isatty():
                     call('reset')
                 # Check to be sure VM boot was successful
-                with open(self.debug_file, 'r') as debug_file:
-                    file_contents = debug_file.read()
-                    if "CERTIFICATION BOOT COMPLETE" in file_contents:
-                        if "END SSH HOST KEY KEYS" in file_contents:
-                            print("Booted successfully", file=sys.stderr)
+                self.elapsed_time = 0
+                status = 1
+                while self.elapsed_time <= self.timeout:
+                    # Check log every 30 seconds to see if the VM boots
+                    with open(self.debug_file, 'r') as debug_file:
+                        status = self.log_check(debug_file.read())
+                        if status == 0:
+                            logging.info("Booted successfully.")
+                            break
                         else:
-                            print("Booted successfully (Previously "
-                                  "initalized VM)", file=sys.stderr)
-                        status = 0
-                    else:
-                        print("E: KVM instance failed to boot",
-                              file=sys.stderr)
-                        print("Console output".center(72, "="),
-                              file=sys.stderr)
-                        with open(self.debug_file, 'r') as console_log:
-                            print(console_log.read(), file=sys.stderr)
-                        print("E: KVM instance failed to boot",
-                              file=sys.stderr)
+                            # Sleep 30 seconds and log check again
+                            time.sleep(30)
+                            self.elapsed_time += 30
+                else:
+                    # Finally, if we didn't get the Success message by now try
+                    # one more time and return 1 if we still haven't booted
+                    if status != 0:
+                        with open(self.debug_file, 'r') as debug_file:
+                            stream = debug_file.read()
+                            status = self.log_check(stream)
+                            if status == 0:
+                                logging.info("Booted successfully.")
+                            else:
+                                logging.error("KVM instance failed to boot.")
+                                logging.error("Console output".center(72, "="))
+                                logging.error(stream)
                 self.process.terminate()
             elif not self.image:
-                print("Could not find downloaded image")
+                logging.error("Could not find downloaded image")
             else:
-                print("Could not find: {}".format(self.image),
-                      file=sys.stderr)
+                logging.error("Could not find: {}".format(self.image))
 
         return status
 
@@ -560,7 +572,7 @@ class LXDTest(object):
         task = RunCommand(cmd)
         if task.returncode != 0:
             logging.error('Command {} returnd a code of {}'.format(
-                          task.cmd, task.returncode))
+                task.cmd, task.returncode))
             logging.error(' STDOUT: {}'.format(task.stdout))
             logging.error(' STDERR: {}'.format(task.stderr))
             return False
@@ -611,7 +623,7 @@ class LXDTest(object):
                                                            filename)
                 if not self.rootfs_tarball:
                     logging.error("Unable to download {} from{}".format(
-                              self.rootfs_tarball, self.rootfs_url))
+                        self.rootfs_tarball, self.rootfs_url))
                     logging.error("Aborting")
                     result = False
             else:
@@ -620,11 +632,11 @@ class LXDTest(object):
                 self.rootfs_tarball = filename
 
         # Insert images
-        if self.template_url is not None and  self.rootfs_url is not None:
+        if self.template_url is not None and self.rootfs_url is not None:
             logging.debug("Importing images into LXD")
             cmd = 'lxc image import {} rootfs {} --alias {}'.format(
-                        self.template_tarball, self.rootfs_tarball,
-                        self.image_alias)
+                self.template_tarball, self.rootfs_tarball,
+                self.image_alias)
             if not self.run_command(cmd):
                 logging.error('Error encountered while attempting to '
                               'import images into LXD')
@@ -633,7 +645,7 @@ class LXDTest(object):
             logging.debug("No local image available, attempting to "
                           "import from default remote.")
             cmd = 'lxc image copy {}{} local: --alias {}'.format(
-                        self.default_remote, self.os_version, self.image_alias)
+                self.default_remote, self.os_version, self.image_alias)
             if not self.run_command(cmd):
                 logging.error('Error encountered while attempting to '
                               'import images from default remote.')
@@ -735,7 +747,7 @@ def test_lxd(args):
 
 
 def test_kvm(args):
-    print("Executing KVM Test", file=sys.stderr)
+    logging.debug("Executing KVM Test")
 
     image = ""
     timeout = ""
@@ -809,6 +821,7 @@ def main():
 
     # silence normal output from requests module
     logging.getLogger("requests").setLevel(logging.WARNING)
+    logging.getLogger("urllib3").setLevel(logging.WARNING)
 
     # Verify args
     try: