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