From e062120f9b4a74acac598b5b9b2178855d1835e4 Mon Sep 17 00:00:00 2001
From: Andrei Stepanov <astepano@redhat.com>
Date: Jun 26 2018 11:53:13 +0000
Subject: Rewrite standard-inventory-qcow2 with using logging module.


Signed-off-by: Andrei Stepanov <astepano@redhat.com>

---

diff --git a/inventory/standard-inventory-qcow2 b/inventory/standard-inventory-qcow2
index 289a4c4..6d095b2 100755
--- a/inventory/standard-inventory-qcow2
+++ b/inventory/standard-inventory-qcow2
@@ -8,6 +8,7 @@ import fmf
 import shutil
 import shlex
 import signal
+import logging
 import StringIO
 import random
 import socket
@@ -74,8 +75,42 @@ chpasswd:
   expire: False
 """.format(DEF_USER, DEF_PASSWD, AUTH_KEY)
 
-
 EMPTY_INVENTORY = {}
+LOG_FILE = "default_provisioners.log"
+
+
+def get_artifact_path(path=""):
+    """Return path to an artifact file in artifacts directory. If path == ""
+    than return path artifacts dir.  Create artifacts dir if necessary.
+    """
+    artifacts = os.environ.get("TEST_ARTIFACTS", os.path.join(os.getcwd(), "artifacts"))
+    try:
+        os.makedirs(artifacts)
+    except OSError as exc:
+        if exc.errno != errno.EEXIST or not os.path.isdir(artifacts):
+            raise
+    return os.path.join(artifacts, path)
+
+
+logger = logging.getLogger(__name__)
+logger.setLevel(logging.DEBUG)
+# stderr output
+conhandler = logging.StreamHandler()
+# Print to strerr by default messages with level >= warning, can be changed
+# with setting TEST_DEBUG=1.
+try:
+    diagnose = distutils.util.strtobool(os.getenv("TEST_DEBUG", "0"))
+except ValueError:
+    diagnose = 0
+conhandler.setLevel(logging.WARNING)
+if diagnose:
+    # Collect all messages with any log level to stderr.
+    conhandler.setLevel(logging.NOTSET)
+# Log format for stderr.
+log_format = "[%(levelname)-5.5s] {}: %(message)s".format(os.path.basename(__file__))
+formatter = logging.Formatter(log_format)
+conhandler.setFormatter(formatter)
+logger.addHandler(conhandler)
 
 
 def main(argv):
@@ -84,19 +119,23 @@ def main(argv):
     parser.add_argument('--host', help="Get host variables")
     parser.add_argument("subjects", nargs="*", default=shlex.split(os.environ.get("TEST_SUBJECTS", "")))
     opts = parser.parse_args()
-
-    try:
-        if opts.host:
-            data = inv_host(opts.host)
-        else:
-            data = inv_list(opts.subjects)
-        sys.stdout.write(json.dumps(data, indent=4, separators=(',', ': ')))
-    except RuntimeError as ex:
-        sys.stderr.write("{0}: {1}\n".format(os.path.basename(sys.argv[0]), str(ex)))
-        sys.stdout.write(json.dumps(EMPTY_INVENTORY, indent=4, separators=(',', ': ')))
-        return 1
-
-    return 0
+    # Send logs to common logfile for all default provisioners.
+    log_file = get_artifact_path(LOG_FILE)
+    fhandler = logging.FileHandler(log_file)
+    # Collect all messages with any log level to log file.
+    fhandler.setLevel(logging.NOTSET)
+    log_format = ("%(asctime)s [{}/%(threadName)-12.12s] [%(levelname)-5.5s]:"
+                  "%(message)s").format(os.path.basename(__file__))
+    logFormatter = logging.Formatter(log_format)
+    fhandler.setFormatter(logFormatter)
+    logger.addHandler(fhandler)
+    logger.info("Start provisioner.")
+    if opts.host:
+        data = inv_host(opts.host)
+    else:
+        data = inv_list(opts.subjects)
+    # Dump Ansible inventory.
+    sys.stdout.write(json.dumps(data, indent=4, separators=(',', ': ')))
 
 
 def inv_list(subjects):
@@ -196,7 +235,7 @@ def fmf_get(path, default=None):
     return value
 
 
-def start_qemu(image, cloudinit, artifacts, portrange=(2222, 5555)):
+def start_qemu(image, cloudinit, portrange=(2222, 5555)):
     for _ in range(10):
         port = random.randint(*portrange)
         sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
@@ -212,12 +251,9 @@ def start_qemu(image, cloudinit, artifacts, portrange=(2222, 5555)):
     else:
         raise RuntimeError("unable to find free local port to map SSH to")
 
-    try:
-        diagnose = distutils.util.strtobool(os.getenv("TEST_DEBUG", "0"))
-    except ValueError:
-        diagnose = 0
     # Log all traffic received from the guest to a file.
-    log_guest = os.path.join(artifacts, "{0}.guest.log".format(os.path.basename(image)))
+    log_file = "{0}.guest.log".format(os.path.basename(image))
+    log_guest = get_artifact_path(log_file)
     # Log from qemu itself.
     log_qemu = log_guest.replace(".guest.log", ".qemu.log")
     # Parameters from FMF:
@@ -239,14 +275,15 @@ def start_qemu(image, cloudinit, artifacts, portrange=(2222, 5555)):
     qemu_proc = subprocess.Popen(qemu_cmd, stdout=open(log_qemu, 'a'), stderr=subprocess.STDOUT)
 
     if qemu_proc and diagnose:
-        sys.stderr.write("DIAGNOSE: qemu-kvm is running with VNC server. PID: {}\n".format(qemu_proc.pid))
-        sys.stderr.write("DIAGNOSE: netstat -ltpn4 | grep {0} # to find VNC server port\n".format(qemu_proc.pid))
+        logger.info("qemu-kvm is running with VNC server. PID: {}".format(qemu_proc.pid))
+        logger.info("netstat -ltpn4 | grep {0} # to find VNC server port".format(qemu_proc.pid))
 
     return qemu_proc, port
 
 
 def inv_host(image):
     if not image.endswith((".qcow2", ".qcow2c")):
+        logger.info("Return empty inventory for image: %s.", image)
         return EMPTY_INVENTORY
 
     null = open(os.devnull, 'w')
@@ -276,27 +313,15 @@ def inv_host(image):
                            "-volid", "cidata", "-joliet", "-rock", "-quiet",
                            "-output", cloudinit, userdata, metadata], stdout=null)
 
-    # Determine if virtual machine should be kept available for diagnosis after completion
-    try:
-        diagnose = distutils.util.strtobool(os.getenv("TEST_DEBUG", "0"))
-    except ValueError:
-        diagnose = 0
-
-    sys.stderr.write("Launching virtual machine for {0}\n".format(image))
+    logger.info("Launching virtual machine for {0}".format(image))
 
     # And launch the actual VM
-    artifacts = os.environ.get("TEST_ARTIFACTS", os.path.join(os.getcwd(), "artifacts"))
-    try:
-        os.makedirs(artifacts)
-    except OSError as exc:
-        if exc.errno != errno.EEXIST or not os.path.isdir(artifacts):
-            raise
 
     proc = None  # for failure detection
     cpe = None  # for exception scoping
     for _ in range(0, 5):
         try:
-            proc, port = start_qemu(image, cloudinit, artifacts)
+            proc, port = start_qemu(image, cloudinit)
             break
         except subprocess.CalledProcessError as cpe:
             time.sleep(1)
@@ -373,7 +398,7 @@ def inv_host(image):
             except subprocess.CalledProcessError:
                 pass
         else:
-            sys.stderr.write("ERROR: Could not set ansible_python_interpreter")
+            logger.error("Could not set ansible_python_interpreter.")
             return None
         variables["ansible_python_interpreter"] = ansible_python_interpreter
         # Update inventory file
@@ -395,12 +420,19 @@ def inv_host(image):
 
     # alternatively, lock on a file
     lock_file = os.environ.get("LOCK_ON_FILE", None)
+    ssh_cmd = ("ssh -p {port} -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -i {identity} {user}@{host}"
+               ).format(port=port, identity=identity, user=DEF_USER, host=DEF_HOST)
+    logger.info(ssh_cmd)
+    logger.info("Password is: {}".format(DEF_PASSWD))
+    logger.info("Cloudinit init location: {}".format(directory))
+    logger.info("export ANSIBLE_INVENTORY={0}".format(inventory))
+    logger.info("Wait until parent for provision-script (ansible-playbook) dies or qemu.")
     while True:
         time.sleep(3)
 
         if lock_file:
             if not os.path.exists(lock_file):
-                sys.stderr.write("Lock file is gone.")
+                logger.error("Lock file is gone.")
                 break
         else:
             # Now wait for the parent process to go away, then kill the VM
@@ -408,36 +440,29 @@ def inv_host(image):
                 os.kill(ppid, 0)
                 os.kill(proc.pid, 0)
             except OSError:
-                sys.stderr.write("Either parent process or VM process is gone.")
-                break  # Either of the processes no longer exist
-
+                logger.info("Either parent process or VM process is gone.")
+                break
     if diagnose:
-        sys.stderr.write("\n")
-        sys.stderr.write("DIAGNOSE: ssh -p {port} -o StrictHostKeyChecking=no "
-                         "-o UserKnownHostsFile=/dev/null -i {identity} "
-                         "{user}@{host}\n".format(port=port, identity=identity,
-                                                  user=DEF_USER, host=DEF_HOST
-                                                  )
-                         )
-        sys.stderr.write("DIAGNOSE: Passwort is: {}".format(DEF_PASSWD))
-        sys.stderr.write("DIAGNOSE: export ANSIBLE_INVENTORY={0}\n".format(inventory))
-        sys.stderr.write("DIAGNOSE: kill {0} # when finished\n".format(os.getpid()))
-
         def _signal_handler(*args):
-            sys.stderr.write("\nDIAGNOSE ending...\n")
-
+            logger.info("Diagnose ending.")
         signal.signal(signal.SIGTERM, _signal_handler)
+        logger.info("kill {0} # when finished to debug VM.".format(os.getpid()))
         signal.pause()
-
     # Kill the qemu process
     try:
         os.kill(proc.pid, signal.SIGTERM)
     except OSError:
         pass
-
     shutil.rmtree(directory)
     sys.exit(0)
 
 
 if __name__ == '__main__':
-    sys.exit(main(sys.argv))
+    ret = -1
+    try:
+        main(sys.argv)
+        ret = 0
+    except Exception:
+        # Backtrace stack goes to log file. If TEST_DEBUG == 1, it goes to stderr too.
+        logger.info("Fatal error in provision script.", exc_info=True)
+    sys.exit(ret)

