tests/hwsim/run-tests.py

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