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