tests/hwsim/run-tests.py

   1 #!/usr/bin/python
   2 #
   3 # AP tests
   4 # Copyright (c) 2013, 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
  17 import logging
  18 logger = logging.getLogger()
  19
  20 sys.path.append('../../wpaspy')
  21
  22 from wpasupplicant import WpaSupplicant
  23 from hostapd import HostapdGlobal
  24 from check_kernel import check_kernel
  25 from wlantest import Wlantest
  26
  27 def reset_devs(dev, apdev):
  28     ok = True
  29     for d in dev:
  30         try:
  31             d.reset()
  32         except Exception, e:
  33             logger.info("Failed to reset device " + d.ifname)
  34             print str(e)
  35             ok = False
  36
  37     try:
  38         wpas = WpaSupplicant(global_iface='/tmp/wpas-wlan5')
  39         wpas.interface_remove("wlan5")
  40     except Exception, e:
  41         pass
  42
  43     try:
  44         hapd = HostapdGlobal()
  45         hapd.remove('wlan3-3')
  46         hapd.remove('wlan3-2')
  47         for ap in apdev:
  48             hapd.remove(ap['ifname'])
  49     except Exception, e:
  50         logger.info("Failed to remove hostapd interface")
  51         print str(e)
  52         ok = False
  53     return ok
  54
  55 def report(conn, prefill, build, commit, run, test, result, duration):
  56     if conn:
  57         if not build:
  58             build = ''
  59         if not commit:
  60             commit = ''
  61         if prefill:
  62             conn.execute('DELETE FROM results WHERE test=? AND run=? AND result=?', (test, run, 'NOTRUN'))
  63         sql = "INSERT INTO results(test,result,run,time,duration,build,commitid) VALUES(?, ?, ?, ?, ?, ?, ?)"
  64         params = (test, result, run, time.time(), duration, build, commit)
  65         try:
  66             conn.execute(sql, params)
  67             conn.commit()
  68         except Exception, e:
  69             print "sqlite: " + str(e)
  70             print "sql: %r" % (params, )
  71
  72 class DataCollector(object):
  73     def __init__(self, logdir, testname, tracing, dmesg):
  74         self._logdir = logdir
  75         self._testname = testname
  76         self._tracing = tracing
  77         self._dmesg = dmesg
  78     def __enter__(self):
  79         if self._tracing:
  80             output = os.path.join(self._logdir, '%s.dat' % (self._testname, ))
  81             self._trace_cmd = subprocess.Popen(['sudo', 'trace-cmd', 'record', '-o', output, '-e', 'mac80211', '-e', 'cfg80211', 'sh', '-c', 'echo STARTED ; read l'],
  82                                                stdin=subprocess.PIPE,
  83                                                stdout=subprocess.PIPE,
  84                                                stderr=open('/dev/null', 'w'),
  85                                                cwd=self._logdir)
  86             l = self._trace_cmd.stdout.read(7)
  87             while not 'STARTED' in l:
  88                 l += self._trace_cmd.stdout.read(1)
  89     def __exit__(self, type, value, traceback):
  90         if self._tracing:
  91             self._trace_cmd.stdin.write('DONE\n')
  92             self._trace_cmd.wait()
  93         if self._dmesg:
  94             output = os.path.join(self._logdir, '%s.dmesg' % (self._testname, ))
  95             subprocess.call(['sudo', 'dmesg', '-c'], stdout=open(output, 'w'))
  96
  97 def rename_log(logdir, basename, testname, dev):
  98     try:
  99         import getpass
 100         srcname = os.path.join(logdir, basename)
 101         dstname = os.path.join(logdir, testname + '.' + basename)
 102         num = 0
 103         while os.path.exists(dstname):
 104             dstname = os.path.join(logdir,
 105                                    testname + '.' + basename + '-' + str(num))
 106             num = num + 1
 107         os.rename(srcname, dstname)
 108         if dev:
 109             dev.relog()
 110             subprocess.call(['sudo', 'chown', '-f', getpass.getuser(), srcname])
 111     except Exception, e:
 112         logger.info("Failed to rename log files")
 113         logger.info(e)
 114
 115 def main():
 116     tests = []
 117     test_modules = []
 118     for t in os.listdir("."):
 119         m = re.match(r'(test_.*)\.py$', t)
 120         if m:
 121             logger.debug("Import test cases from " + t)
 122             mod = __import__(m.group(1))
 123             test_modules.append(mod.__name__.replace('test_', '', 1))
 124             for s in dir(mod):
 125                 if s.startswith("test_"):
 126                     func = mod.__dict__.get(s)
 127                     tests.append(func)
 128     test_names = list(set([t.__name__.replace('test_', '', 1) for t in tests]))
 129
 130     run = None
 131
 132     parser = argparse.ArgumentParser(description='hwsim test runner')
 133     parser.add_argument('--logdir', metavar='<directory>',
 134                         help='log output directory for all other options, ' +
 135                              'must be given if other log options are used')
 136     group = parser.add_mutually_exclusive_group()
 137     group.add_argument('-d', const=logging.DEBUG, action='store_const',
 138                        dest='loglevel', default=logging.INFO,
 139                        help="verbose debug output")
 140     group.add_argument('-q', const=logging.WARNING, action='store_const',
 141                        dest='loglevel', help="be quiet")
 142
 143     parser.add_argument('-S', metavar='<sqlite3 db>', dest='database',
 144                         help='database to write results to')
 145     parser.add_argument('--prefill-tests', action='store_true', dest='prefill',
 146                         help='prefill test database with NOTRUN before all tests')
 147     parser.add_argument('--commit', metavar='<commit id>',
 148                         help='commit ID, only for database')
 149     parser.add_argument('-b', metavar='<build>', dest='build', help='build ID')
 150     parser.add_argument('-L', action='store_true', dest='update_tests_db',
 151                         help='List tests (and update descriptions in DB)')
 152     parser.add_argument('-T', action='store_true', dest='tracing',
 153                         help='collect tracing per test case (in log directory)')
 154     parser.add_argument('-D', action='store_true', dest='dmesg',
 155                         help='collect dmesg per test case (in log directory)')
 156     parser.add_argument('--shuffle-tests', action='store_true',
 157                         dest='shuffle_tests',
 158                         help='Shuffle test cases to randomize order')
 159     parser.add_argument('--no-reset', action='store_true', dest='no_reset',
 160                         help='Do not reset devices at the end of the test')
 161     parser.add_argument('-f', dest='testmodules', metavar='<test module>',
 162                         help='execute only tests from these test modules',
 163                         type=str, choices=[[]] + test_modules, nargs='+')
 164     parser.add_argument('tests', metavar='<test>', nargs='*', type=str,
 165                         help='tests to run (only valid without -f)',
 166                         choices=[[]] + test_names)
 167
 168     args = parser.parse_args()
 169
 170     if args.tests and args.testmodules:
 171         print 'Invalid arguments - both test module and tests given'
 172         sys.exit(2)
 173
 174     if not args.logdir:
 175         if os.path.exists('logs/current'):
 176             args.logdir = 'logs/current'
 177         else:
 178             args.logdir = 'logs'
 179
 180     # Write debug level log to a file and configurable verbosity to stdout
 181     logger.setLevel(logging.DEBUG)
 182
 183     stdout_handler = logging.StreamHandler()
 184     stdout_handler.setLevel(args.loglevel)
 185     logger.addHandler(stdout_handler)
 186
 187     file_name = os.path.join(args.logdir, 'run-tests.log')
 188     log_handler = logging.FileHandler(file_name)
 189     log_handler.setLevel(logging.DEBUG)
 190     fmt = "%(asctime)s %(levelname)s %(message)s"
 191     log_formatter = logging.Formatter(fmt)
 192     log_handler.setFormatter(log_formatter)
 193     logger.addHandler(log_handler)
 194
 195     if args.database:
 196         import sqlite3
 197         conn = sqlite3.connect(args.database)
 198         conn.execute('CREATE TABLE IF NOT EXISTS results (test,result,run,time,duration,build,commitid)')
 199         conn.execute('CREATE TABLE IF NOT EXISTS tests (test,description)')
 200     else:
 201         conn = None
 202
 203     if conn:
 204         run = int(time.time())
 205
 206     if args.update_tests_db:
 207         for t in tests:
 208             name = t.__name__.replace('test_', '', 1)
 209             print name + " - " + t.__doc__
 210             if conn:
 211                 sql = 'INSERT OR REPLACE INTO tests(test,description) VALUES (?, ?)'
 212                 params = (name, t.__doc__)
 213                 try:
 214                     conn.execute(sql, params)
 215                 except Exception, e:
 216                     print "sqlite: " + str(e)
 217                     print "sql: %r" % (params,)
 218         if conn:
 219             conn.commit()
 220             conn.close()
 221         sys.exit(0)
 222
 223
 224     dev0 = WpaSupplicant('wlan0', '/tmp/wpas-wlan0')
 225     dev1 = WpaSupplicant('wlan1', '/tmp/wpas-wlan1')
 226     dev2 = WpaSupplicant('wlan2', '/tmp/wpas-wlan2')
 227     dev = [ dev0, dev1, dev2 ]
 228     apdev = [ ]
 229     apdev.append({"ifname": 'wlan3', "bssid": "02:00:00:00:03:00"})
 230     apdev.append({"ifname": 'wlan4', "bssid": "02:00:00:00:04:00"})
 231
 232     for d in dev:
 233         if not d.ping():
 234             logger.info(d.ifname + ": No response from wpa_supplicant")
 235             return
 236         logger.info("DEV: " + d.ifname + ": " + d.p2p_dev_addr())
 237     for ap in apdev:
 238         logger.info("APDEV: " + ap['ifname'])
 239
 240     passed = []
 241     skipped = []
 242     failed = []
 243
 244     # make sure nothing is left over from previous runs
 245     # (if there were any other manual runs or we crashed)
 246     if not reset_devs(dev, apdev):
 247         if conn:
 248             conn.close()
 249             conn = None
 250         sys.exit(1)
 251
 252     if args.dmesg:
 253         subprocess.call(['sudo', 'dmesg', '-c'], stdout=open('/dev/null', 'w'))
 254
 255     tests_to_run = []
 256     for t in tests:
 257         name = t.__name__.replace('test_', '', 1)
 258         if args.tests:
 259             if not name in args.tests:
 260                 continue
 261         if args.testmodules:
 262             if not t.__module__.replace('test_', '', 1) in args.testmodules:
 263                 continue
 264         tests_to_run.append(t)
 265
 266     if conn and args.prefill:
 267         for t in tests_to_run:
 268             name = t.__name__.replace('test_', '', 1)
 269             report(conn, False, args.build, args.commit, run, name, 'NOTRUN', 0)
 270
 271     if args.shuffle_tests:
 272         from random import shuffle
 273         shuffle(tests_to_run)
 274
 275     count = 0
 276     for t in tests_to_run:
 277         name = t.__name__.replace('test_', '', 1)
 278         if log_handler:
 279             log_handler.stream.close()
 280             logger.removeHandler(log_handler)
 281             file_name = os.path.join(args.logdir, name + '.log')
 282             log_handler = logging.FileHandler(file_name)
 283             log_handler.setLevel(logging.DEBUG)
 284             log_handler.setFormatter(log_formatter)
 285             logger.addHandler(log_handler)
 286
 287         reset_ok = True
 288         with DataCollector(args.logdir, name, args.tracing, args.dmesg):
 289             count = count + 1
 290             msg = "START {} {}/{}".format(name, count, len(tests_to_run))
 291             logger.info(msg)
 292             if args.loglevel == logging.WARNING:
 293                 print msg
 294                 sys.stdout.flush()
 295             if t.__doc__:
 296                 logger.info("Test: " + t.__doc__)
 297             start = datetime.now()
 298             for d in dev:
 299                 try:
 300                     d.request("NOTE TEST-START " + name)
 301                 except Exception, e:
 302                     logger.info("Failed to issue TEST-START before " + name + " for " + d.ifname)
 303                     logger.info(e)
 304                     print "FAIL " + name + " - could not start test"
 305                     if conn:
 306                         conn.close()
 307                         conn = None
 308                     sys.exit(1)
 309             try:
 310                 if t.func_code.co_argcount > 1:
 311                     res = t(dev, apdev)
 312                 else:
 313                     res = t(dev)
 314                 if res == "skip":
 315                     result = "SKIP"
 316                 else:
 317                     result = "PASS"
 318             except Exception, e:
 319                 logger.info(e)
 320                 result = "FAIL"
 321             for d in dev:
 322                 try:
 323                     d.request("NOTE TEST-STOP " + name)
 324                 except Exception, e:
 325                     logger.info("Failed to issue TEST-STOP after {} for {}".format(name, d.ifname))
 326                     logger.info(e)
 327                     result = "FAIL"
 328             try:
 329                 wpas = WpaSupplicant("wlan5", "/tmp/wpas-wlan5")
 330                 rename_log(args.logdir, 'log5', name, wpas)
 331                 if not args.no_reset:
 332                     wpas.remove_ifname()
 333             except Exception, e:
 334                 pass
 335             if args.no_reset:
 336                 print "Leaving devices in current state"
 337             else:
 338                 reset_ok = reset_devs(dev, apdev)
 339
 340             for i in range(0, 3):
 341                 rename_log(args.logdir, 'log' + str(i), name, dev[i])
 342             try:
 343                 hapd = HostapdGlobal()
 344             except Exception, e:
 345                 print "Failed to connect to hostapd interface"
 346                 print str(e)
 347                 reset_ok = False
 348                 result = "FAIL"
 349                 hapd = None
 350             rename_log(args.logdir, 'hostapd', name, hapd)
 351
 352             wt = Wlantest()
 353             rename_log(args.logdir, 'hwsim0.pcapng', name, wt)
 354             rename_log(args.logdir, 'hwsim0', name, wt)
 355
 356         end = datetime.now()
 357         diff = end - start
 358
 359         if result == 'PASS' and args.dmesg:
 360             if not check_kernel(os.path.join(args.logdir, name + '.dmesg')):
 361                 logger.info("Kernel issue found in dmesg - mark test failed")
 362                 result = 'FAIL'
 363
 364         if result == 'PASS':
 365             passed.append(name)
 366         elif result == 'SKIP':
 367             skipped.append(name)
 368         else:
 369             failed.append(name)
 370
 371         report(conn, args.prefill, args.build, args.commit, run, name, result, diff.total_seconds())
 372         result = "{} {} {} {}".format(result, name, diff.total_seconds(), end)
 373         logger.info(result)
 374         if args.loglevel == logging.WARNING:
 375             print result
 376             sys.stdout.flush()
 377
 378         if not reset_ok:
 379             print "Terminating early due to device reset failure"
 380             break
 381
 382     if log_handler:
 383         log_handler.stream.close()
 384         logger.removeHandler(log_handler)
 385         file_name = os.path.join(args.logdir, 'run-tests.log')
 386         log_handler = logging.FileHandler(file_name)
 387         log_handler.setLevel(logging.DEBUG)
 388         log_handler.setFormatter(log_formatter)
 389         logger.addHandler(log_handler)
 390
 391     if conn:
 392         conn.close()
 393
 394     if len(failed):
 395         logger.info("passed {} test case(s)".format(len(passed)))
 396         logger.info("skipped {} test case(s)".format(len(skipped)))
 397         logger.info("failed tests: " + ' '.join(failed))
 398         if args.loglevel == logging.WARNING:
 399             print "failed tests: " + ' '.join(failed)
 400         sys.exit(1)
 401     logger.info("passed all {} test case(s)".format(len(passed)))
 402     if len(skipped):
 403         logger.info("skipped {} test case(s)".format(len(skipped)))
 404     if args.loglevel == logging.WARNING:
 405         print "passed all {} test case(s)".format(len(passed))
 406         if len(skipped):
 407             print "skipped {} test case(s)".format(len(skipped))
 408
 409 if __name__ == "__main__":
 410     main()