From 9a307c2c55fffd72832eafc237a4e89c84a25edd Mon Sep 17 00:00:00 2001
From: Jeff Lane <jeffrey.lane@canonical.com>
Date: Tue, 20 Jun 2017 18:45:06 -0400
Subject: bin/virtualization: quiet urllib3 info log messages; script now
 properly polls VM output for success message LP: #1628264

---
 bin/virtualization | 57 +++++++++++++++++++++++++++++++++---------------------
 1 file changed, 35 insertions(+), 22 deletions(-)

(limited to 'bin')

diff --git a/bin/virtualization b/bin/virtualization
index 46cf13e..df04470 100755
--- a/bin/virtualization
+++ b/bin/virtualization
@@ -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
 
@@ -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:
-- 
cgit v1.2.3