From d3fb9c140379ae553172f1761595caf0ff6ce0ae Mon Sep 17 00:00:00 2001 From: Jouni Malinen Date: Wed, 24 Dec 2014 11:40:03 +0200 Subject: [PATCH] tests: Add debug logging for parallel-vm.py parallel-vm.log is now written with details of test execution steps and results. This makes it easier to debug if something goes wrong in VM monitoring. The --debug option can be used to enable verbose debugging. Signed-off-by: Jouni Malinen --- tests/hwsim/vm/parallel-vm.py | 55 +++++++++++++++++++++++++++++++---- 1 file changed, 50 insertions(+), 5 deletions(-) diff --git a/tests/hwsim/vm/parallel-vm.py b/tests/hwsim/vm/parallel-vm.py index 97fb2c2ff..88015bcc0 100755 --- a/tests/hwsim/vm/parallel-vm.py +++ b/tests/hwsim/vm/parallel-vm.py @@ -8,11 +8,14 @@ import curses import fcntl +import logging import os import subprocess import sys import time +logger = logging.getLogger() + def get_results(): global vm started = [] @@ -36,6 +39,7 @@ def show_progress(scr): global first_run_failures total_tests = len(tests) + logger.info("Total tests: %d" % total_tests) scr.leaveok(1) scr.addstr(0, 0, "Parallel test execution status", curses.A_BOLD) @@ -69,8 +73,10 @@ def show_progress(scr): with open(log, 'r') as f: if "Kernel panic" in f.read(): scr.addstr("kernel panic") + logger.info("VM[%d] kernel panic" % i) else: scr.addstr("unexpected exit") + logger.info("VM[%d] unexpected exit" % i) updated = True continue @@ -79,12 +85,14 @@ def show_progress(scr): try: err = vm[i]['proc'].stderr.read() vm[i]['err'] += err + logger.debug("VM[%d] stderr.read[%s]" % (i, err)) except: pass try: out = vm[i]['proc'].stdout.read() vm[i]['out'] += out + logger.debug("VM[%d] stdout.read[%s]" % (i, out)) if "READY" in out or "PASS" in out or "FAIL" in out or "SKIP" in out: scr.move(i + 1, 10) scr.clrtoeol() @@ -92,16 +100,20 @@ def show_progress(scr): if not tests: vm[i]['first_run_done'] = True scr.addstr("completed first round") + logger.info("VM[%d] completed first round" % i) continue else: name = tests.pop(0) vm[i]['proc'].stdin.write(name + '\n') scr.addstr(name) + logger.debug("VM[%d] start test %s" % (i, name)) except: pass if not first_running and not completed_first_pass: + logger.info("First round of testing completed") if tests: + logger.info("Unexpected test cases remaining from first round: " + str(tests)) raise Exception("Unexpected test cases remaining from first round") completed_first_pass = True (started, passed, failed, skipped) = get_results() @@ -123,8 +135,10 @@ def show_progress(scr): with open(log, 'r') as f: if "Kernel panic" in f.read(): scr.addstr("kernel panic") + logger.info("VM[%d] kernel panic" % i) else: scr.addstr("completed run") + logger.info("VM[%d] completed run" % i) updated = True continue @@ -132,6 +146,7 @@ def show_progress(scr): try: err = vm[i]['proc'].stderr.read() vm[i]['err'] += err + logger.debug("VM[%d] stderr.read[%s]" % (i, err)) except: pass @@ -143,6 +158,7 @@ def show_progress(scr): else: out = vm[i]['proc'].stdout.read() vm[i]['out'] += out + logger.debug("VM[%d] stdout.read[%s]" % (i, out)) if "READY" in out or "PASS" in out or "FAIL" in out or "SKIP" in out: ready = True if ready: @@ -152,10 +168,12 @@ def show_progress(scr): if not rerun_tests: vm[i]['proc'].stdin.write('\n') scr.addstr("shutting down") + logger.info("VM[%d] shutting down" % i) else: name = rerun_tests.pop(0) vm[i]['proc'].stdin.write(name + '\n') scr.addstr(name + "(*)") + logger.debug("VM[%d] start test %s (*)" % (i, name)) except: pass @@ -198,16 +216,24 @@ def main(): global tests global first_run_failures + debug_level = logging.INFO + if len(sys.argv) < 2: - sys.exit("Usage: %s [--codecov] [params..]" % sys.argv[0]) + sys.exit("Usage: %s [--debug] [--codecov] [params..]" % sys.argv[0]) num_servers = int(sys.argv[1]) if num_servers < 1: sys.exit("Too small number of VMs") timestamp = int(time.time()) - if len(sys.argv) > 2 and sys.argv[2] == "--codecov": - idx = 3 + idx = 2 + + if len(sys.argv) > idx and sys.argv[idx] == "--debug": + idx += 1 + debug_level = logging.DEBUG + + if len(sys.argv) > idx and sys.argv[idx] == "--codecov": + idx += 1 print "Code coverage - build separate binaries" logdir = "/tmp/hwsim-test-logs/" + str(timestamp) os.makedirs(logdir) @@ -215,7 +241,6 @@ def main(): codecov_args = ['--codecov_dir', logdir] codecov = True else: - idx = 2 codecov_args = [] codecov = False @@ -281,9 +306,18 @@ def main(): tests.remove(l) tests.insert(0, l) + logger.setLevel(debug_level) + log_handler = logging.FileHandler('parallel-vm.log') + log_handler.setLevel(debug_level) + fmt = "%(asctime)s %(levelname)s %(message)s" + log_formatter = logging.Formatter(fmt) + log_handler.setFormatter(log_formatter) + logger.addHandler(log_handler) + vm = {} for i in range(0, num_servers): print("\rStarting virtual machine {}/{}".format(i + 1, num_servers)), + logger.info("Starting virtual machine {}/{}".format(i + 1, num_servers)) cmd = ['./vm-run.sh', '--delay', str(i), '--timestamp', str(timestamp), '--ext', 'srv.%d' % (i + 1), '-i'] + codecov_args + extra_args @@ -313,6 +347,7 @@ def main(): print "Failed test cases:" for f in first_run_failures: print f, + logger.info("Failed: " + f) print double_failed = [] for f in failed: @@ -322,19 +357,25 @@ def main(): double_failed.remove(test) if failed and not double_failed: print "All failed cases passed on retry" + logger.info("All failed cases passed on retry") elif double_failed: print "Failed even on retry:" for f in double_failed: print f, + logger.info("Failed on retry: " + f) print - print("TOTAL={} PASS={} FAIL={} SKIP={}".format(len(started), len(passed), len(failed), len(skipped))) + res = "TOTAL={} PASS={} FAIL={} SKIP={}".format(len(started), len(passed), len(failed), len(skipped)) + print(res) + logger.info(res) print "Logs: " + dir + '/' + str(timestamp) + logger.info("Logs: " + dir + '/' + str(timestamp)) for i in range(0, num_servers): log = '{}/{}.srv.{}/console'.format(dir, timestamp, i + 1) with open(log, 'r') as f: if "Kernel panic" in f.read(): print "Kernel panic in " + log + logger.info("Kernel panic in " + log) if codecov: print "Code coverage - preparing report" @@ -344,11 +385,15 @@ def main(): str(i)]) subprocess.check_call(['./combine-codecov.sh', logdir]) print "file://%s/index.html" % logdir + logger.info("Code coverage report: file://%s/index.html" % logdir) if double_failed: + logger.info("Test run complete - failures found") sys.exit(2) if failed: + logger.info("Test run complete - failures found on first run; passed on retry") sys.exit(1) + logger.info("Test run complete - no failures") sys.exit(0) if __name__ == "__main__":