From b6dcadeae74455563996193bc54fac118fa44663 Mon Sep 17 00:00:00 2001
From: Andrei Stepanov <astepano@redhat.com>
Date: Jun 27 2018 10:55:54 +0000
Subject: Rewrite rpm/docker/local provisioners with using logging module.


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

---

diff --git a/inventory/standard-inventory-docker b/inventory/standard-inventory-docker
index a35ca99..e834050 100755
--- a/inventory/standard-inventory-docker
+++ b/inventory/standard-inventory-docker
@@ -35,8 +35,45 @@ import sys
 import tempfile
 import time
 import distutils.util
+import logging
+
 
 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):
@@ -47,19 +84,22 @@ def main(argv):
                         default=os.environ.get("TEST_DOCKER_EXTRA_ARGS", ""))
     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, opts.docker_extra_args)
-        else:
-            data = inv_list(opts.subjects, opts.docker_extra_args)
-        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, opts.docker_extra_args)
+    else:
+        data = inv_list(opts.subjects, opts.docker_extra_args)
+    sys.stdout.write(json.dumps(data, indent=4, separators=(',', ': ')))
 
 
 def inv_list(subjects, docker_extra_args):
@@ -93,20 +133,13 @@ def inv_host(subject, docker_extra_args):
 
     directory = tempfile.mkdtemp(prefix="inventory-docker")
     cidfile = os.path.join(directory, "cid")
-
-    # Determine if container should be kept available for diagnosis after completion
-    try:
-        diagnose = distutils.util.strtobool(os.getenv("TEST_DEBUG", "0"))
-    except ValueError:
-        diagnose = 0
-
     # Check for any additional arguments to include when starting docker container
     try:
         extra_arg_list = shlex.split(docker_extra_args)
     except ValueError:
         raise RuntimeError("Could not parse DOCKER_EXTRA_ARGS")
 
-    sys.stderr.write("Launching Docker container for {0}\n".format(image))
+    logger.info("Launching Docker container for {0}".format(image))
 
     # Make sure the docker service is running
     cmd = [
@@ -150,7 +183,7 @@ def inv_host(subject, docker_extra_args):
         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
 
     # Directory to place artifacts
@@ -183,6 +216,7 @@ def inv_host(subject, docker_extra_args):
     os.dup2(tty, 2)
 
     # Now wait for the parent process to go away, then kill the VM
+    logger.info("docker exec -it {0} /bin/bash".format(name))
     while True:
         time.sleep(3)
 
@@ -192,13 +226,9 @@ def inv_host(subject, docker_extra_args):
             break  # Either of the processes no longer exist
 
     if diagnose:
-        sys.stderr.write("\n")
-        sys.stderr.write("DIAGNOSE: docker exec -it {0} /bin/bash\n".format(name))
-        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.")
+        logger.info("kill {0} # when finished".format(os.getpid()))
         signal.signal(signal.SIGTERM, _signal_handler)
         signal.pause()
 
@@ -220,4 +250,11 @@ def inv_host(subject, docker_extra_args):
 
 
 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)
diff --git a/inventory/standard-inventory-local b/inventory/standard-inventory-local
index 162b315..3376a5b 100755
--- a/inventory/standard-inventory-local
+++ b/inventory/standard-inventory-local
@@ -27,8 +27,47 @@ import argparse
 import json
 import os
 import sys
+import logging
+import errno
+import distutils.util
 
 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):
@@ -36,19 +75,22 @@ def main(argv):
     parser.add_argument("--list", action="store_true", help="Verbose output")
     parser.add_argument('--host', help="Get host variables")
     opts = parser.parse_args()
-
-    try:
-        if opts.host:
-            data = inv_host(opts.host)
-        else:
-            data = inv_list()
-        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()
+    sys.stdout.write(json.dumps(data, indent=4, separators=(',', ': ')))
 
 
 def inv_list():
@@ -73,4 +115,11 @@ def inv_host(host):
 
 
 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)
diff --git a/inventory/standard-inventory-rpm b/inventory/standard-inventory-rpm
index 739179a..e8bfbc2 100755
--- a/inventory/standard-inventory-rpm
+++ b/inventory/standard-inventory-rpm
@@ -30,8 +30,47 @@ import os
 import shlex
 import subprocess
 import sys
+import logging
+import errno
+import distutils.util
 
 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):
@@ -40,19 +79,22 @@ def main(argv):
     parser.add_argument('--host', help="Get host variables")
     parser.add_argument("subjects", nargs="*", default=os.environ.get("TEST_SUBJECTS", ""))
     opts = parser.parse_args()
-
-    try:
-        if opts.host:
-            data = gethost(opts.host)
-        else:
-            data = getlist(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 = gethost(opts.host)
+    else:
+        data = getlist(opts.subjects)
+    sys.stdout.write(json.dumps(data, indent=4, separators=(',', ': ')))
 
 
 def getlist(subjects):
@@ -120,4 +162,11 @@ def isrepo(subject):
 
 
 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)

