From e062120f9b4a74acac598b5b9b2178855d1835e4 Mon Sep 17 00:00:00 2001 From: Andrei Stepanov Date: Jun 26 2018 11:53:13 +0000 Subject: Rewrite standard-inventory-qcow2 with using logging module. Signed-off-by: Andrei Stepanov --- 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)