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         open('/dev/kmsg', 'w').write('running hwsim test case %s\n' % name)
 404         if log_handler:
 405             log_handler.stream.close()
 406             logger.removeHandler(log_handler)
 407             file_name = os.path.join(args.logdir, name + '.log')
 408             log_handler = logging.FileHandler(file_name)
 409             log_handler.setLevel(logging.DEBUG)
 410             log_handler.setFormatter(log_formatter)
 411             logger.addHandler(log_handler)
 412
 413         reset_ok = True
 414         with DataCollector(args.logdir, name, args.tracing, args.dmesg):
 415             count = count + 1
 416             msg = "START {} {}/{}".format(name, count, num_tests)
 417             logger.info(msg)
 418             if args.loglevel == logging.WARNING:
 419                 print msg
 420                 sys.stdout.flush()
 421             if t.__doc__:
 422                 logger.info("Test: " + t.__doc__)
 423             start = datetime.now()
 424             for d in dev:
 425                 try:
 426                     d.dump_monitor()
 427                     if not d.ping():
 428                         raise Exception("PING failed for {}".format(d.ifname))
 429                     if not d.global_ping():
 430                         raise Exception("Global PING failed for {}".format(d.ifname))
 431                     d.request("NOTE TEST-START " + name)
 432                 except Exception, e:
 433                     logger.info("Failed to issue TEST-START before " + name + " for " + d.ifname)
 434                     logger.info(e)
 435                     print "FAIL " + name + " - could not start test"
 436                     if conn:
 437                         conn.close()
 438                         conn = None
 439                     if args.stdin_ctrl:
 440                         set_term_echo(sys.stdin.fileno(), True)
 441                     sys.exit(1)
 442             try:
 443                 if t.func_code.co_argcount > 2:
 444                     params = {}
 445                     params['logdir'] = args.logdir
 446                     params['long'] = args.long
 447                     t(dev, apdev, params)
 448                 elif t.func_code.co_argcount > 1:
 449                     t(dev, apdev)
 450                 else:
 451                     t(dev)
 452                 result = "PASS"
 453             except HwsimSkip, e:
 454                 logger.info("Skip test case: %s" % e)
 455                 result = "SKIP"
 456             except NameError, e:
 457                 import traceback
 458                 logger.info(e)
 459                 traceback.print_exc()
 460                 result = "FAIL"
 461             except Exception, e:
 462                 import traceback
 463                 logger.info(e)
 464                 traceback.print_exc()
 465                 if args.loglevel == logging.WARNING:
 466                     print "Exception: " + str(e)
 467                 result = "FAIL"
 468             for d in dev:
 469                 try:
 470                     d.dump_monitor()
 471                     d.request("NOTE TEST-STOP " + name)
 472                 except Exception, e:
 473                     logger.info("Failed to issue TEST-STOP after {} for {}".format(name, d.ifname))
 474                     logger.info(e)
 475                     result = "FAIL"
 476             if args.no_reset:
 477                 print "Leaving devices in current state"
 478             else:
 479                 reset_ok = reset_devs(dev, apdev)
 480             wpas = None
 481             try:
 482                 wpas = WpaSupplicant(global_iface="/tmp/wpas-wlan5")
 483                 rename_log(args.logdir, 'log5', name, wpas)
 484                 if not args.no_reset:
 485                     wpas.remove_ifname()
 486             except Exception, e:
 487                 pass
 488             if wpas:
 489                 wpas.close_ctrl()
 490
 491             for i in range(0, 3):
 492                 rename_log(args.logdir, 'log' + str(i), name, dev[i])
 493             try:
 494                 hapd = HostapdGlobal()
 495             except Exception, e:
 496                 print "Failed to connect to hostapd interface"
 497                 print str(e)
 498                 reset_ok = False
 499                 result = "FAIL"
 500                 hapd = None
 501             rename_log(args.logdir, 'hostapd', name, hapd)
 502             if hapd:
 503                 del hapd
 504                 hapd = None
 505
 506             # Use None here since this instance of Wlantest() will never be
 507             # used for remote host hwsim tests on real hardware.
 508             Wlantest.setup(None)
 509             wt = Wlantest()
 510             rename_log(args.logdir, 'hwsim0.pcapng', name, wt)
 511             rename_log(args.logdir, 'hwsim0', name, wt)
 512             if os.path.exists(os.path.join(args.logdir, 'fst-wpa_supplicant')):
 513                 rename_log(args.logdir, 'fst-wpa_supplicant', name, None)
 514             if os.path.exists(os.path.join(args.logdir, 'fst-hostapd')):
 515                 rename_log(args.logdir, 'fst-hostapd', name, None)
 516
 517         end = datetime.now()
 518         diff = end - start
 519
 520         if result == 'PASS' and args.dmesg:
 521             if not check_kernel(os.path.join(args.logdir, name + '.dmesg')):
 522                 logger.info("Kernel issue found in dmesg - mark test failed")
 523                 result = 'FAIL'
 524
 525         if result == 'PASS':
 526             passed.append(name)
 527         elif result == 'SKIP':
 528             skipped.append(name)
 529         else:
 530             failed.append(name)
 531
 532         report(conn, args.prefill, args.build, args.commit, run, name, result,
 533                diff.total_seconds(), args.logdir)
 534         result = "{} {} {} {}".format(result, name, diff.total_seconds(), end)
 535         logger.info(result)
 536         if args.loglevel == logging.WARNING:
 537             print result
 538             sys.stdout.flush()
 539
 540         if not reset_ok:
 541             print "Terminating early due to device reset failure"
 542             break
 543     if args.stdin_ctrl:
 544         set_term_echo(sys.stdin.fileno(), True)
 545
 546     if log_handler:
 547         log_handler.stream.close()
 548         logger.removeHandler(log_handler)
 549         file_name = os.path.join(args.logdir, 'run-tests.log')
 550         log_handler = logging.FileHandler(file_name)
 551         log_handler.setLevel(logging.DEBUG)
 552         log_handler.setFormatter(log_formatter)
 553         logger.addHandler(log_handler)
 554
 555     if conn:
 556         conn.close()
 557
 558     if len(failed):
 559         logger.info("passed {} test case(s)".format(len(passed)))
 560         logger.info("skipped {} test case(s)".format(len(skipped)))
 561         logger.info("failed tests: " + ' '.join(failed))
 562         if args.loglevel == logging.WARNING:
 563             print "failed tests: " + ' '.join(failed)
 564         sys.exit(1)
 565     logger.info("passed all {} test case(s)".format(len(passed)))
 566     if len(skipped):
 567         logger.info("skipped {} test case(s)".format(len(skipped)))
 568     if args.loglevel == logging.WARNING:
 569         print "passed all {} test case(s)".format(len(passed))
 570         if len(skipped):
 571             print "skipped {} test case(s)".format(len(skipped))
 572
 573 if __name__ == "__main__":
 574     main()