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