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