![Jouni Malinen](/assets/img/avatar_default.png)
It was possible for the scr.addstr() operations to fail and terminate parallel-vm.py if the number of failed test cases increased beyond what fits on the screen. Signed-off-by: Jouni Malinen <j@w1.fi>
440 lines
15 KiB
Python
Executable file
440 lines
15 KiB
Python
Executable file
#!/usr/bin/env python2
|
|
#
|
|
# Parallel VM test case executor
|
|
# Copyright (c) 2014, Jouni Malinen <j@w1.fi>
|
|
#
|
|
# This software may be distributed under the terms of the BSD license.
|
|
# See README for more details.
|
|
|
|
import curses
|
|
import fcntl
|
|
import logging
|
|
import os
|
|
import subprocess
|
|
import sys
|
|
import time
|
|
|
|
logger = logging.getLogger()
|
|
|
|
def get_failed(vm):
|
|
failed = []
|
|
for i in range(num_servers):
|
|
failed += vm[i]['failed']
|
|
return failed
|
|
|
|
def vm_read_stdout(vm, i):
|
|
global total_started, total_passed, total_failed, total_skipped
|
|
|
|
ready = False
|
|
try:
|
|
out = vm['proc'].stdout.read()
|
|
except:
|
|
return False
|
|
logger.debug("VM[%d] stdout.read[%s]" % (i, out))
|
|
pending = vm['pending'] + out
|
|
lines = []
|
|
while True:
|
|
pos = pending.find('\n')
|
|
if pos < 0:
|
|
break
|
|
line = pending[0:pos].rstrip()
|
|
pending = pending[(pos + 1):]
|
|
logger.debug("VM[%d] stdout full line[%s]" % (i, line))
|
|
if line.startswith("READY"):
|
|
ready = True
|
|
elif line.startswith("PASS"):
|
|
ready = True
|
|
total_passed += 1
|
|
elif line.startswith("FAIL"):
|
|
ready = True
|
|
total_failed += 1
|
|
name = line.split(' ')[1]
|
|
logger.debug("VM[%d] test case failed: %s" % (i, name))
|
|
vm['failed'].append(name)
|
|
elif line.startswith("NOT-FOUND"):
|
|
ready = True
|
|
total_failed += 1
|
|
logger.info("VM[%d] test case not found" % i)
|
|
elif line.startswith("SKIP"):
|
|
ready = True
|
|
total_skipped += 1
|
|
elif line.startswith("START"):
|
|
total_started += 1
|
|
vm['out'] += line + '\n'
|
|
lines.append(line)
|
|
vm['pending'] = pending
|
|
return ready
|
|
|
|
def show_progress(scr):
|
|
global num_servers
|
|
global vm
|
|
global dir
|
|
global timestamp
|
|
global tests
|
|
global first_run_failures
|
|
global total_started, total_passed, total_failed, total_skipped
|
|
|
|
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)
|
|
for i in range(0, num_servers):
|
|
scr.addstr(i + 1, 0, "VM %d:" % (i + 1), curses.A_BOLD)
|
|
scr.addstr(i + 1, 10, "starting VM")
|
|
scr.addstr(num_servers + 1, 0, "Total:", curses.A_BOLD)
|
|
scr.addstr(num_servers + 1, 20, "TOTAL={} STARTED=0 PASS=0 FAIL=0 SKIP=0".format(total_tests))
|
|
scr.refresh()
|
|
|
|
completed_first_pass = False
|
|
rerun_tests = []
|
|
|
|
while True:
|
|
running = False
|
|
first_running = False
|
|
updated = False
|
|
|
|
for i in range(0, num_servers):
|
|
if completed_first_pass:
|
|
continue
|
|
if vm[i]['first_run_done']:
|
|
continue
|
|
if not vm[i]['proc']:
|
|
continue
|
|
if vm[i]['proc'].poll() is not None:
|
|
vm[i]['proc'] = None
|
|
scr.move(i + 1, 10)
|
|
scr.clrtoeol()
|
|
log = '{}/{}.srv.{}/console'.format(dir, timestamp, i + 1)
|
|
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
|
|
|
|
running = True
|
|
first_running = True
|
|
try:
|
|
err = vm[i]['proc'].stderr.read()
|
|
vm[i]['err'] += err
|
|
logger.debug("VM[%d] stderr.read[%s]" % (i, err))
|
|
except:
|
|
pass
|
|
|
|
if vm_read_stdout(vm[i], i):
|
|
scr.move(i + 1, 10)
|
|
scr.clrtoeol()
|
|
updated = True
|
|
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))
|
|
|
|
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
|
|
for name in get_failed(vm):
|
|
rerun_tests.append(name)
|
|
first_run_failures.append(name)
|
|
|
|
for i in range(num_servers):
|
|
if not completed_first_pass:
|
|
continue
|
|
if not vm[i]['proc']:
|
|
continue
|
|
if vm[i]['proc'].poll() is not None:
|
|
vm[i]['proc'] = None
|
|
scr.move(i + 1, 10)
|
|
scr.clrtoeol()
|
|
log = '{}/{}.srv.{}/console'.format(dir, timestamp, i + 1)
|
|
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
|
|
|
|
running = True
|
|
try:
|
|
err = vm[i]['proc'].stderr.read()
|
|
vm[i]['err'] += err
|
|
logger.debug("VM[%d] stderr.read[%s]" % (i, err))
|
|
except:
|
|
pass
|
|
|
|
ready = False
|
|
if vm[i]['first_run_done']:
|
|
vm[i]['first_run_done'] = False
|
|
ready = True
|
|
else:
|
|
ready = vm_read_stdout(vm[i], i)
|
|
if ready:
|
|
scr.move(i + 1, 10)
|
|
scr.clrtoeol()
|
|
updated = True
|
|
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))
|
|
|
|
if not running:
|
|
break
|
|
|
|
if updated:
|
|
scr.move(num_servers + 1, 10)
|
|
scr.clrtoeol()
|
|
scr.addstr("{} %".format(int(100.0 * (total_passed + total_failed + total_skipped) / total_tests)))
|
|
scr.addstr(num_servers + 1, 20, "TOTAL={} STARTED={} PASS={} FAIL={} SKIP={}".format(total_tests, total_started, total_passed, total_failed, total_skipped))
|
|
failed = get_failed(vm)
|
|
if len(failed) > 0:
|
|
scr.move(num_servers + 2, 0)
|
|
scr.clrtoeol()
|
|
scr.addstr("Failed test cases: ")
|
|
count = 0
|
|
for f in failed:
|
|
count += 1
|
|
if count > 30:
|
|
scr.addstr('...')
|
|
scr.clrtoeol()
|
|
break
|
|
scr.addstr(f)
|
|
scr.addstr(' ')
|
|
|
|
scr.move(0, 35)
|
|
scr.clrtoeol()
|
|
if rerun_tests:
|
|
scr.addstr("(RETRY FAILED %d)" % len(rerun_tests))
|
|
elif first_run_failures:
|
|
scr.addstr("(RETRY FAILED)")
|
|
|
|
scr.refresh()
|
|
|
|
time.sleep(0.25)
|
|
|
|
scr.refresh()
|
|
time.sleep(0.3)
|
|
|
|
def main():
|
|
global num_servers
|
|
global vm
|
|
global dir
|
|
global timestamp
|
|
global tests
|
|
global first_run_failures
|
|
global total_started, total_passed, total_failed, total_skipped
|
|
|
|
total_started = 0
|
|
total_passed = 0
|
|
total_failed = 0
|
|
total_skipped = 0
|
|
|
|
debug_level = logging.INFO
|
|
|
|
if len(sys.argv) < 2:
|
|
sys.exit("Usage: %s <number of VMs> [--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())
|
|
|
|
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)
|
|
subprocess.check_call(['./build-codecov.sh', logdir])
|
|
codecov_args = ['--codecov_dir', logdir]
|
|
codecov = True
|
|
else:
|
|
codecov_args = []
|
|
codecov = False
|
|
|
|
first_run_failures = []
|
|
tests = []
|
|
cmd = [ '../run-tests.py', '-L' ] + sys.argv[idx:]
|
|
lst = subprocess.Popen(cmd, stdout=subprocess.PIPE)
|
|
for l in lst.stdout.readlines():
|
|
name = l.split(' ')[0]
|
|
tests.append(name)
|
|
if len(tests) == 0:
|
|
sys.exit("No test cases selected")
|
|
if '-f' in sys.argv[idx:]:
|
|
extra_args = sys.argv[idx:]
|
|
else:
|
|
extra_args = [x for x in sys.argv[idx:] if x not in tests]
|
|
|
|
dir = '/tmp/hwsim-test-logs'
|
|
try:
|
|
os.mkdir(dir)
|
|
except:
|
|
pass
|
|
|
|
if num_servers > 2 and len(tests) > 100:
|
|
# Move test cases with long duration to the beginning as an
|
|
# optimization to avoid last part of the test execution running a long
|
|
# duration test case on a single VM while all other VMs have already
|
|
# completed their work.
|
|
long = [ "ap_roam_open",
|
|
"ap_hs20_fetch_osu_stop",
|
|
"ap_roam_wpa2_psk",
|
|
"ibss_wpa_none_ccmp",
|
|
"nfc_wps_er_handover_pk_hash_mismatch_sta",
|
|
"go_neg_peers_force_diff_freq",
|
|
"p2p_cli_invite",
|
|
"sta_ap_scan_2b",
|
|
"ap_pmf_sta_unprot_deauth_burst",
|
|
"ap_bss_add_remove_during_ht_scan",
|
|
"wext_scan_hidden",
|
|
"autoscan_exponential",
|
|
"nfc_p2p_client",
|
|
"wnm_bss_keep_alive",
|
|
"ap_inactivity_disconnect",
|
|
"scan_bss_expiration_age",
|
|
"autoscan_periodic",
|
|
"discovery_group_client",
|
|
"concurrent_p2pcli",
|
|
"ap_bss_add_remove",
|
|
"wpas_ap_wps",
|
|
"wext_pmksa_cache",
|
|
"ibss_wpa_none",
|
|
"ap_ht_40mhz_intolerant_ap",
|
|
"ibss_rsn",
|
|
"discovery_pd_retries",
|
|
"ap_wps_setup_locked_timeout",
|
|
"ap_vht160",
|
|
"dfs_radar",
|
|
"dfs",
|
|
"grpform_cred_ready_timeout",
|
|
"ap_wps_pbc_timeout" ]
|
|
for l in long:
|
|
if l in tests:
|
|
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
|
|
vm[i] = {}
|
|
vm[i]['first_run_done'] = False
|
|
vm[i]['proc'] = subprocess.Popen(cmd,
|
|
stdin=subprocess.PIPE,
|
|
stdout=subprocess.PIPE,
|
|
stderr=subprocess.PIPE)
|
|
vm[i]['out'] = ""
|
|
vm[i]['pending'] = ""
|
|
vm[i]['err'] = ""
|
|
vm[i]['failed'] = []
|
|
for stream in [ vm[i]['proc'].stdout, vm[i]['proc'].stderr ]:
|
|
fd = stream.fileno()
|
|
fl = fcntl.fcntl(fd, fcntl.F_GETFL)
|
|
fcntl.fcntl(fd, fcntl.F_SETFL, fl | os.O_NONBLOCK)
|
|
print
|
|
|
|
curses.wrapper(show_progress)
|
|
|
|
with open('{}/{}-parallel.log'.format(dir, timestamp), 'w') as f:
|
|
for i in range(0, num_servers):
|
|
f.write('VM {}\n{}\n{}\n'.format(i, vm[i]['out'], vm[i]['err']))
|
|
|
|
failed = get_failed(vm)
|
|
|
|
if first_run_failures:
|
|
print "Failed test cases:"
|
|
for f in first_run_failures:
|
|
print f,
|
|
logger.info("Failed: " + f)
|
|
print
|
|
double_failed = []
|
|
for name in failed:
|
|
double_failed.append(name)
|
|
for test in first_run_failures:
|
|
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
|
|
res = "TOTAL={} PASS={} FAIL={} SKIP={}".format(total_started,
|
|
total_passed,
|
|
total_failed,
|
|
total_skipped)
|
|
print(res)
|
|
logger.info(res)
|
|
print "Logs: " + dir + '/' + str(timestamp)
|
|
logger.info("Logs: " + dir + '/' + str(timestamp))
|
|
|
|
for i in range(0, num_servers):
|
|
if len(vm[i]['pending']) > 0:
|
|
logger.info("Unprocessed stdout from VM[%d]: '%s'" %
|
|
(i, vm[i]['pending']))
|
|
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"
|
|
for i in range(num_servers):
|
|
subprocess.check_call(['./process-codecov.sh',
|
|
logdir + ".srv.%d" % (i + 1),
|
|
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__":
|
|
main()
|