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                     res = t(dev, apdev, params)
 437                 elif t.func_code.co_argcount > 1:
 438                     res = t(dev, apdev)
 439                 else:
 440                     res = t(dev)
 441                 if res == "skip":
 442                     result = "SKIP"
 443                 else:
 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             try:
 462                 wpas = WpaSupplicant("/tmp/wpas-wlan5")
 463                 d.dump_monitor()
 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 args.no_reset:
 470                 print "Leaving devices in current state"
 471             else:
 472                 reset_ok = reset_devs(dev, apdev)
 473
 474             for i in range(0, 3):
 475                 rename_log(args.logdir, 'log' + str(i), name, dev[i])
 476             try:
 477                 hapd = HostapdGlobal()
 478             except Exception, e:
 479                 print "Failed to connect to hostapd interface"
 480                 print str(e)
 481                 reset_ok = False
 482                 result = "FAIL"
 483                 hapd = None
 484             rename_log(args.logdir, 'hostapd', name, hapd)
 485
 486             wt = Wlantest()
 487             rename_log(args.logdir, 'hwsim0.pcapng', name, wt)
 488             rename_log(args.logdir, 'hwsim0', name, wt)
 489
 490         end = datetime.now()
 491         diff = end - start
 492
 493         if result == 'PASS' and args.dmesg:
 494             if not check_kernel(os.path.join(args.logdir, name + '.dmesg')):
 495                 logger.info("Kernel issue found in dmesg - mark test failed")
 496                 result = 'FAIL'
 497
 498         if result == 'PASS':
 499             passed.append(name)
 500         elif result == 'SKIP':
 501             skipped.append(name)
 502         else:
 503             failed.append(name)
 504
 505         report(conn, args.prefill, args.build, args.commit, run, name, result,
 506                diff.total_seconds(), args.logdir)
 507         result = "{} {} {} {}".format(result, name, diff.total_seconds(), end)
 508         logger.info(result)
 509         if args.loglevel == logging.WARNING:
 510             print result
 511             sys.stdout.flush()
 512
 513         if not reset_ok:
 514             print "Terminating early due to device reset failure"
 515             break
 516     if args.stdin_ctrl:
 517         set_term_echo(sys.stdin.fileno(), True)
 518
 519     if log_handler:
 520         log_handler.stream.close()
 521         logger.removeHandler(log_handler)
 522         file_name = os.path.join(args.logdir, 'run-tests.log')
 523         log_handler = logging.FileHandler(file_name)
 524         log_handler.setLevel(logging.DEBUG)
 525         log_handler.setFormatter(log_formatter)
 526         logger.addHandler(log_handler)
 527
 528     if conn:
 529         conn.close()
 530
 531     if len(failed):
 532         logger.info("passed {} test case(s)".format(len(passed)))
 533         logger.info("skipped {} test case(s)".format(len(skipped)))
 534         logger.info("failed tests: " + ' '.join(failed))
 535         if args.loglevel == logging.WARNING:
 536             print "failed tests: " + ' '.join(failed)
 537         sys.exit(1)
 538     logger.info("passed all {} test case(s)".format(len(passed)))
 539     if len(skipped):
 540         logger.info("skipped {} test case(s)".format(len(skipped)))
 541     if args.loglevel == logging.WARNING:
 542         print "passed all {} test case(s)".format(len(passed))
 543         if len(skipped):
 544             print "skipped {} test case(s)".format(len(skipped))
 545
 546 if __name__ == "__main__":
 547     main()