tests/hwsim/run-tests.py

   1 #!/usr/bin/env python2
   2 #
   3 # Test case executor
   4 # Copyright (c) 2013-2015, Jouni Malinen <j@w1.fi>
   5 #
   6 # This software may be distributed under the terms of the BSD license.
   7 # See README for more details.
   8
   9 import os
  10 import re
  11 import sys
  12 import time
  13 from datetime import datetime
  14 import argparse
  15 import subprocess
  16 import termios
  17
  18 import logging
  19 logger = logging.getLogger()
  20
  21 if os.path.exists('../../wpaspy'):
  22     sys.path.append('../../wpaspy')
  23 else:
  24     sys.path.append('../../../wpaspy')
  25
  26 from wpasupplicant import WpaSupplicant
  27 from hostapd import HostapdGlobal
  28 from check_kernel import check_kernel
  29 from wlantest import Wlantest
  30 from utils import HwsimSkip
  31
  32 def set_term_echo(fd, enabled):
  33     [iflag, oflag, cflag, lflag, ispeed, ospeed, cc] = termios.tcgetattr(fd)
  34     if enabled:
  35         lflag |= termios.ECHO
  36     else:
  37         lflag &= ~termios.ECHO
  38     termios.tcsetattr(fd, termios.TCSANOW,
  39                       [iflag, oflag, cflag, lflag, ispeed, ospeed, cc])
  40
  41 def reset_devs(dev, apdev):
  42     ok = True
  43     for d in dev:
  44         try:
  45             d.reset()
  46         except Exception, e:
  47             logger.info("Failed to reset device " + d.ifname)
  48             print str(e)
  49             ok = False
  50
  51     try:
  52         wpas = WpaSupplicant(global_iface='/tmp/wpas-wlan5')
  53         ifaces = wpas.global_request("INTERFACES").splitlines()
  54         for iface in ifaces:
  55             if iface.startswith("wlan"):
  56                 wpas.interface_remove(iface)
  57     except Exception, e:
  58         pass
  59
  60     try:
  61         hapd = HostapdGlobal()
  62         hapd.flush()
  63         hapd.remove('wlan3-3')
  64         hapd.remove('wlan3-2')
  65         for ap in apdev:
  66             hapd.remove(ap['ifname'])
  67     except Exception, e:
  68         logger.info("Failed to remove hostapd interface")
  69         print str(e)
  70         ok = False
  71     return ok
  72
  73 def add_log_file(conn, test, run, type, path):
  74     if not os.path.exists(path):
  75         return
  76     contents = None
  77     with open(path, 'r') as f:
  78         contents = f.read()
  79     if contents is None:
  80         return
  81     sql = "INSERT INTO logs(test,run,type,contents) VALUES(?, ?, ?, ?)"
  82     params = (test, run, type, contents)
  83     try:
  84         conn.execute(sql, params)
  85         conn.commit()
  86     except Exception, e:
  87         print "sqlite: " + str(e)
  88         print "sql: %r" % (params, )
  89
  90 def report(conn, prefill, build, commit, run, test, result, duration, logdir,
  91            sql_commit=True):
  92     if conn:
  93         if not build:
  94             build = ''
  95         if not commit:
  96             commit = ''
  97         if prefill:
  98             conn.execute('DELETE FROM results WHERE test=? AND run=? AND result=?', (test, run, 'NOTRUN'))
  99         sql = "INSERT INTO results(test,result,run,time,duration,build,commitid) VALUES(?, ?, ?, ?, ?, ?, ?)"
 100         params = (test, result, run, time.time(), duration, build, commit)
 101         try:
 102             conn.execute(sql, params)
 103             if sql_commit:
 104                 conn.commit()
 105         except Exception, e:
 106             print "sqlite: " + str(e)
 107             print "sql: %r" % (params, )
 108
 109         if result == "FAIL":
 110             for log in [ "log", "log0", "log1", "log2", "log3", "log5",
 111                          "hostapd", "dmesg", "hwsim0", "hwsim0.pcapng" ]:
 112                 add_log_file(conn, test, run, log,
 113                              logdir + "/" + test + "." + log)
 114
 115 class DataCollector(object):
 116     def __init__(self, logdir, testname, tracing, dmesg):
 117         self._logdir = logdir
 118         self._testname = testname
 119         self._tracing = tracing
 120         self._dmesg = dmesg
 121     def __enter__(self):
 122         if self._tracing:
 123             output = os.path.abspath(os.path.join(self._logdir, '%s.dat' % (self._testname, )))
 124             self._trace_cmd = subprocess.Popen(['sudo', 'trace-cmd', 'record', '-o', output, '-e', 'mac80211', '-e', 'cfg80211', 'sh', '-c', 'echo STARTED ; read l'],
 125                                                stdin=subprocess.PIPE,
 126                                                stdout=subprocess.PIPE,
 127                                                stderr=open('/dev/null', 'w'),
 128                                                cwd=self._logdir)
 129             l = self._trace_cmd.stdout.read(7)
 130             while self._trace_cmd.poll() is None and not 'STARTED' in l:
 131                 l += self._trace_cmd.stdout.read(1)
 132             res = self._trace_cmd.returncode
 133             if res:
 134                 print "Failed calling trace-cmd: returned exit status %d" % res
 135                 sys.exit(1)
 136     def __exit__(self, type, value, traceback):
 137         if self._tracing:
 138             self._trace_cmd.stdin.write('DONE\n')
 139             self._trace_cmd.wait()
 140         if self._dmesg:
 141             output = os.path.join(self._logdir, '%s.dmesg' % (self._testname, ))
 142             subprocess.call(['sudo', 'dmesg', '-c'], stdout=open(output, 'w'))
 143
 144 def rename_log(logdir, basename, testname, dev):
 145     try:
 146         import getpass
 147         srcname = os.path.join(logdir, basename)
 148         dstname = os.path.join(logdir, testname + '.' + basename)
 149         num = 0
 150         while os.path.exists(dstname):
 151             dstname = os.path.join(logdir,
 152                                    testname + '.' + basename + '-' + str(num))
 153             num = num + 1
 154         os.rename(srcname, dstname)
 155         if dev:
 156             dev.relog()
 157             subprocess.call(['sudo', 'chown', '-f', getpass.getuser(), srcname])
 158     except Exception, e:
 159         logger.info("Failed to rename log files")
 160         logger.info(e)
 161
 162 def main():
 163     tests = []
 164     test_modules = []
 165     if os.path.exists('run-tests.py'):
 166         files = os.listdir(".")
 167     else:
 168         files = os.listdir("..")
 169     for t in files:
 170         m = re.match(r'(test_.*)\.py$', t)
 171         if m:
 172             logger.debug("Import test cases from " + t)
 173             mod = __import__(m.group(1))
 174             test_modules.append(mod.__name__.replace('test_', '', 1))
 175             for key,val in mod.__dict__.iteritems():
 176                 if key.startswith("test_"):
 177                     tests.append(val)
 178     test_names = list(set([t.__name__.replace('test_', '', 1) for t in tests]))
 179
 180     run = None
 181
 182     parser = argparse.ArgumentParser(description='hwsim test runner')
 183     parser.add_argument('--logdir', metavar='<directory>',
 184                         help='log output directory for all other options, ' +
 185                              'must be given if other log options are used')
 186     group = parser.add_mutually_exclusive_group()
 187     group.add_argument('-d', const=logging.DEBUG, action='store_const',
 188                        dest='loglevel', default=logging.INFO,
 189                        help="verbose debug output")
 190     group.add_argument('-q', const=logging.WARNING, action='store_const',
 191                        dest='loglevel', help="be quiet")
 192
 193     parser.add_argument('-S', metavar='<sqlite3 db>', dest='database',
 194                         help='database to write results to')
 195     parser.add_argument('--prefill-tests', action='store_true', dest='prefill',
 196                         help='prefill test database with NOTRUN before all tests')
 197     parser.add_argument('--commit', metavar='<commit id>',
 198                         help='commit ID, only for database')
 199     parser.add_argument('-b', metavar='<build>', dest='build', help='build ID')
 200     parser.add_argument('-L', action='store_true', dest='update_tests_db',
 201                         help='List tests (and update descriptions in DB)')
 202     parser.add_argument('-T', action='store_true', dest='tracing',
 203                         help='collect tracing per test case (in log directory)')
 204     parser.add_argument('-D', action='store_true', dest='dmesg',
 205                         help='collect dmesg per test case (in log directory)')
 206     parser.add_argument('--shuffle-tests', action='store_true',
 207                         dest='shuffle_tests',
 208                         help='Shuffle test cases to randomize order')
 209     parser.add_argument('--split', help='split tests for parallel execution (<server number>/<total servers>)')
 210     parser.add_argument('--no-reset', action='store_true', dest='no_reset',
 211                         help='Do not reset devices at the end of the test')
 212     parser.add_argument('--long', action='store_true',
 213                         help='Include test cases that take long time')
 214     parser.add_argument('-f', dest='testmodules', metavar='<test module>',
 215                         help='execute only tests from these test modules',
 216                         type=str, choices=[[]] + test_modules, nargs='+')
 217     parser.add_argument('-l', metavar='<modules file>', dest='mfile',
 218                         help='test modules file name')
 219     parser.add_argument('-i', action='store_true', dest='stdin_ctrl',
 220                         help='stdin-controlled test case execution')
 221     parser.add_argument('tests', metavar='<test>', nargs='*', type=str,
 222                         help='tests to run (only valid without -f)',
 223                         choices=[[]] + test_names)
 224
 225     args = parser.parse_args()
 226
 227     if (args.tests and args.testmodules) or (args.tests and args.mfile) or (args.testmodules and args.mfile):
 228         print 'Invalid arguments - only one of (test, test modules, modules file) can be given.'
 229         sys.exit(2)
 230
 231     if args.database:
 232         import sqlite3
 233         conn = sqlite3.connect(args.database)
 234         conn.execute('CREATE TABLE IF NOT EXISTS results (test,result,run,time,duration,build,commitid)')
 235         conn.execute('CREATE TABLE IF NOT EXISTS tests (test,description)')
 236         conn.execute('CREATE TABLE IF NOT EXISTS logs (test,run,type,contents)')
 237     else:
 238         conn = None
 239
 240     if conn:
 241         run = int(time.time())
 242
 243     # read the modules from the modules file
 244     if args.mfile:
 245         args.testmodules = []
 246         with open(args.mfile) as f:
 247             for line in f.readlines():
 248                 line = line.strip()
 249                 if not line or line.startswith('#'):
 250                     continue
 251                 args.testmodules.append(line)
 252
 253     tests_to_run = []
 254     if args.tests:
 255         for selected in args.tests:
 256             for t in tests:
 257                 name = t.__name__.replace('test_', '', 1)
 258                 if name == selected:
 259                     tests_to_run.append(t)
 260     else:
 261         for t in tests:
 262             name = t.__name__.replace('test_', '', 1)
 263             if args.testmodules:
 264                 if not t.__module__.replace('test_', '', 1) in args.testmodules:
 265                     continue
 266             tests_to_run.append(t)
 267
 268     if args.update_tests_db:
 269         for t in tests_to_run:
 270             name = t.__name__.replace('test_', '', 1)
 271             if t.__doc__ is None:
 272                 print name + " - MISSING DESCRIPTION"
 273             else:
 274                 print name + " - " + t.__doc__
 275             if conn:
 276                 sql = 'INSERT OR REPLACE INTO tests(test,description) VALUES (?, ?)'
 277                 params = (name, t.__doc__)
 278                 try:
 279                     conn.execute(sql, params)
 280                 except Exception, e:
 281                     print "sqlite: " + str(e)
 282                     print "sql: %r" % (params,)
 283         if conn:
 284             conn.commit()
 285             conn.close()
 286         sys.exit(0)
 287
 288     if not args.logdir:
 289         if os.path.exists('logs/current'):
 290             args.logdir = 'logs/current'
 291         else:
 292             args.logdir = 'logs'
 293
 294     # Write debug level log to a file and configurable verbosity to stdout
 295     logger.setLevel(logging.DEBUG)
 296
 297     stdout_handler = logging.StreamHandler()
 298     stdout_handler.setLevel(args.loglevel)
 299     logger.addHandler(stdout_handler)
 300
 301     file_name = os.path.join(args.logdir, 'run-tests.log')
 302     log_handler = logging.FileHandler(file_name)
 303     log_handler.setLevel(logging.DEBUG)
 304     fmt = "%(asctime)s %(levelname)s %(message)s"
 305     log_formatter = logging.Formatter(fmt)
 306     log_handler.setFormatter(log_formatter)
 307     logger.addHandler(log_handler)
 308
 309     dev0 = WpaSupplicant('wlan0', '/tmp/wpas-wlan0')
 310     dev1 = WpaSupplicant('wlan1', '/tmp/wpas-wlan1')
 311     dev2 = WpaSupplicant('wlan2', '/tmp/wpas-wlan2')
 312     dev = [ dev0, dev1, dev2 ]
 313     apdev = [ ]
 314     apdev.append({"ifname": 'wlan3', "bssid": "02:00:00:00:03:00"})
 315     apdev.append({"ifname": 'wlan4', "bssid": "02:00:00:00:04:00"})
 316
 317     for d in dev:
 318         if not d.ping():
 319             logger.info(d.ifname + ": No response from wpa_supplicant")
 320             return
 321         logger.info("DEV: " + d.ifname + ": " + d.p2p_dev_addr())
 322     for ap in apdev:
 323         logger.info("APDEV: " + ap['ifname'])
 324
 325     passed = []
 326     skipped = []
 327     failed = []
 328
 329     # make sure nothing is left over from previous runs
 330     # (if there were any other manual runs or we crashed)
 331     if not reset_devs(dev, apdev):
 332         if conn:
 333             conn.close()
 334             conn = None
 335         sys.exit(1)
 336
 337     if args.dmesg:
 338         subprocess.call(['sudo', 'dmesg', '-c'], stdout=open('/dev/null', 'w'))
 339
 340     if conn and args.prefill:
 341         for t in tests_to_run:
 342             name = t.__name__.replace('test_', '', 1)
 343             report(conn, False, args.build, args.commit, run, name, 'NOTRUN', 0,
 344                    args.logdir, sql_commit=False)
 345         conn.commit()
 346
 347     if args.split:
 348         vals = args.split.split('/')
 349         split_server = int(vals[0])
 350         split_total = int(vals[1])
 351         logger.info("Parallel execution - %d/%d" % (split_server, split_total))
 352         split_server -= 1
 353         tests_to_run.sort(key=lambda t: t.__name__)
 354         tests_to_run = [x for i,x in enumerate(tests_to_run) if i % split_total == split_server]
 355
 356     if args.shuffle_tests:
 357         from random import shuffle
 358         shuffle(tests_to_run)
 359
 360     count = 0
 361     if args.stdin_ctrl:
 362         print "READY"
 363         sys.stdout.flush()
 364         num_tests = 0
 365     else:
 366         num_tests = len(tests_to_run)
 367     if args.stdin_ctrl:
 368         set_term_echo(sys.stdin.fileno(), False)
 369     while True:
 370         if args.stdin_ctrl:
 371             test = sys.stdin.readline()
 372             if not test:
 373                 break
 374             test = test.splitlines()[0]
 375             if test == '':
 376                 break
 377             t = None
 378             for tt in tests:
 379                 name = tt.__name__.replace('test_', '', 1)
 380                 if name == test:
 381                     t = tt
 382                     break
 383             if not t:
 384                 print "NOT-FOUND"
 385                 sys.stdout.flush()
 386                 continue
 387         else:
 388             if len(tests_to_run) == 0:
 389                 break
 390             t = tests_to_run.pop(0)
 391
 392         name = t.__name__.replace('test_', '', 1)
 393         if log_handler:
 394             log_handler.stream.close()
 395             logger.removeHandler(log_handler)
 396             file_name = os.path.join(args.logdir, name + '.log')
 397             log_handler = logging.FileHandler(file_name)
 398             log_handler.setLevel(logging.DEBUG)
 399             log_handler.setFormatter(log_formatter)
 400             logger.addHandler(log_handler)
 401
 402         reset_ok = True
 403         with DataCollector(args.logdir, name, args.tracing, args.dmesg):
 404             count = count + 1
 405             msg = "START {} {}/{}".format(name, count, num_tests)
 406             logger.info(msg)
 407             if args.loglevel == logging.WARNING:
 408                 print msg
 409                 sys.stdout.flush()
 410             if t.__doc__:
 411                 logger.info("Test: " + t.__doc__)
 412             start = datetime.now()
 413             for d in dev:
 414                 try:
 415                     d.dump_monitor()
 416                     if not d.ping():
 417                         raise Exception("PING failed for {}".format(d.ifname))
 418                     if not d.global_ping():
 419                         raise Exception("Global PING failed for {}".format(d.ifname))
 420                     d.request("NOTE TEST-START " + name)
 421                 except Exception, e:
 422                     logger.info("Failed to issue TEST-START before " + name + " for " + d.ifname)
 423                     logger.info(e)
 424                     print "FAIL " + name + " - could not start test"
 425                     if conn:
 426                         conn.close()
 427                         conn = None
 428                     if args.stdin_ctrl:
 429                         set_term_echo(sys.stdin.fileno(), True)
 430                     sys.exit(1)
 431             try:
 432                 if t.func_code.co_argcount > 2:
 433                     params = {}
 434                     params['logdir'] = args.logdir
 435                     params['long'] = args.long
 436                     t(dev, apdev, params)
 437                 elif t.func_code.co_argcount > 1:
 438                     t(dev, apdev)
 439                 else:
 440                     t(dev)
 441                 result = "PASS"
 442             except HwsimSkip, e:
 443                 logger.info("Skip test case: %s" % e)
 444                 result = "SKIP"
 445             except Exception, e:
 446                 logger.info(e)
 447                 if args.loglevel == logging.WARNING:
 448                     print "Exception: " + str(e)
 449                 result = "FAIL"
 450             for d in dev:
 451                 try:
 452                     d.dump_monitor()
 453                     d.request("NOTE TEST-STOP " + name)
 454                 except Exception, e:
 455                     logger.info("Failed to issue TEST-STOP after {} for {}".format(name, d.ifname))
 456                     logger.info(e)
 457                     result = "FAIL"
 458             try:
 459                 wpas = WpaSupplicant("/tmp/wpas-wlan5")
 460                 d.dump_monitor()
 461                 rename_log(args.logdir, 'log5', name, wpas)
 462                 if not args.no_reset:
 463                     wpas.remove_ifname()
 464             except Exception, e:
 465                 pass
 466             if args.no_reset:
 467                 print "Leaving devices in current state"
 468             else:
 469                 reset_ok = reset_devs(dev, apdev)
 470
 471             for i in range(0, 3):
 472                 rename_log(args.logdir, 'log' + str(i), name, dev[i])
 473             try:
 474                 hapd = HostapdGlobal()
 475             except Exception, e:
 476                 print "Failed to connect to hostapd interface"
 477                 print str(e)
 478                 reset_ok = False
 479                 result = "FAIL"
 480                 hapd = None
 481             rename_log(args.logdir, 'hostapd', name, hapd)
 482
 483             wt = Wlantest()
 484             rename_log(args.logdir, 'hwsim0.pcapng', name, wt)
 485             rename_log(args.logdir, 'hwsim0', name, wt)
 486
 487         end = datetime.now()
 488         diff = end - start
 489
 490         if result == 'PASS' and args.dmesg:
 491             if not check_kernel(os.path.join(args.logdir, name + '.dmesg')):
 492                 logger.info("Kernel issue found in dmesg - mark test failed")
 493                 result = 'FAIL'
 494
 495         if result == 'PASS':
 496             passed.append(name)
 497         elif result == 'SKIP':
 498             skipped.append(name)
 499         else:
 500             failed.append(name)
 501
 502         report(conn, args.prefill, args.build, args.commit, run, name, result,
 503                diff.total_seconds(), args.logdir)
 504         result = "{} {} {} {}".format(result, name, diff.total_seconds(), end)
 505         logger.info(result)
 506         if args.loglevel == logging.WARNING:
 507             print result
 508             sys.stdout.flush()
 509
 510         if not reset_ok:
 511             print "Terminating early due to device reset failure"
 512             break
 513     if args.stdin_ctrl:
 514         set_term_echo(sys.stdin.fileno(), True)
 515
 516     if log_handler:
 517         log_handler.stream.close()
 518         logger.removeHandler(log_handler)
 519         file_name = os.path.join(args.logdir, 'run-tests.log')
 520         log_handler = logging.FileHandler(file_name)
 521         log_handler.setLevel(logging.DEBUG)
 522         log_handler.setFormatter(log_formatter)
 523         logger.addHandler(log_handler)
 524
 525     if conn:
 526         conn.close()
 527
 528     if len(failed):
 529         logger.info("passed {} test case(s)".format(len(passed)))
 530         logger.info("skipped {} test case(s)".format(len(skipped)))
 531         logger.info("failed tests: " + ' '.join(failed))
 532         if args.loglevel == logging.WARNING:
 533             print "failed tests: " + ' '.join(failed)
 534         sys.exit(1)
 535     logger.info("passed all {} test case(s)".format(len(passed)))
 536     if len(skipped):
 537         logger.info("skipped {} test case(s)".format(len(skipped)))
 538     if args.loglevel == logging.WARNING:
 539         print "passed all {} test case(s)".format(len(passed))
 540         if len(skipped):
 541             print "skipped {} test case(s)".format(len(skipped))
 542
 543 if __name__ == "__main__":
 544     main()