test/test/autotest_runner.py

   1 # SPDX-License-Identifier: BSD-3-Clause
   2 # Copyright(c) 2010-2014 Intel Corporation
   3
   4 # The main logic behind running autotests in parallel
   5
   6 import StringIO
   7 import csv
   8 import multiprocessing
   9 import pexpect
  10 import re
  11 import subprocess
  12 import sys
  13 import time
  14
  15 # wait for prompt
  16
  17
  18 def wait_prompt(child):
  19     try:
  20         child.sendline()
  21         result = child.expect(["RTE>>", pexpect.TIMEOUT, pexpect.EOF],
  22                               timeout=120)
  23     except:
  24         return False
  25     if result == 0:
  26         return True
  27     else:
  28         return False
  29
  30 # run a test group
  31 # each result tuple in results list consists of:
  32 #   result value (0 or -1)
  33 #   result string
  34 #   test name
  35 #   total test run time (double)
  36 #   raw test log
  37 #   test report (if not available, should be None)
  38 #
  39 # this function needs to be outside AutotestRunner class
  40 # because otherwise Pool won't work (or rather it will require
  41 # quite a bit of effort to make it work).
  42
  43
  44 def run_test_group(cmdline, target, test_group):
  45     results = []
  46     child = None
  47     start_time = time.time()
  48     startuplog = None
  49
  50     # run test app
  51     try:
  52         # prepare logging of init
  53         startuplog = StringIO.StringIO()
  54
  55         print >>startuplog, "\n%s %s\n" % ("=" * 20, test_group["Prefix"])
  56         print >>startuplog, "\ncmdline=%s" % cmdline
  57
  58         child = pexpect.spawn(cmdline, logfile=startuplog)
  59
  60         # wait for target to boot
  61         if not wait_prompt(child):
  62             child.close()
  63
  64             results.append((-1,
  65                             "Fail [No prompt]",
  66                             "Start %s" % test_group["Prefix"],
  67                             time.time() - start_time,
  68                             startuplog.getvalue(),
  69                             None))
  70
  71             # mark all tests as failed
  72             for test in test_group["Tests"]:
  73                 results.append((-1, "Fail [No prompt]", test["Name"],
  74                                 time.time() - start_time, "", None))
  75             # exit test
  76             return results
  77
  78     except:
  79         results.append((-1,
  80                         "Fail [Can't run]",
  81                         "Start %s" % test_group["Prefix"],
  82                         time.time() - start_time,
  83                         startuplog.getvalue(),
  84                         None))
  85
  86         # mark all tests as failed
  87         for t in test_group["Tests"]:
  88             results.append((-1, "Fail [Can't run]", t["Name"],
  89                             time.time() - start_time, "", None))
  90         # exit test
  91         return results
  92
  93     # startup was successful
  94     results.append((0, "Success", "Start %s" % test_group["Prefix"],
  95                     time.time() - start_time, startuplog.getvalue(), None))
  96
  97     # parse the binary for available test commands
  98     binary = cmdline.split()[0]
  99     stripped = 'not stripped' not in subprocess.check_output(['file', binary])
 100     if not stripped:
 101         symbols = subprocess.check_output(['nm', binary]).decode('utf-8')
 102         avail_cmds = re.findall('test_register_(\w+)', symbols)
 103
 104     # run all tests in test group
 105     for test in test_group["Tests"]:
 106
 107         # create log buffer for each test
 108         # in multiprocessing environment, the logging would be
 109         # interleaved and will create a mess, hence the buffering
 110         logfile = StringIO.StringIO()
 111         child.logfile = logfile
 112
 113         result = ()
 114
 115         # make a note when the test started
 116         start_time = time.time()
 117
 118         try:
 119             # print test name to log buffer
 120             print >>logfile, "\n%s %s\n" % ("-" * 20, test["Name"])
 121
 122             # run test function associated with the test
 123             if stripped or test["Command"] in avail_cmds:
 124                 result = test["Func"](child, test["Command"])
 125             else:
 126                 result = (0, "Skipped [Not Available]")
 127
 128             # make a note when the test was finished
 129             end_time = time.time()
 130
 131             log = logfile.getvalue()
 132
 133             # append test data to the result tuple
 134             result += (test["Name"], end_time - start_time, log)
 135
 136             # call report function, if any defined, and supply it with
 137             # target and complete log for test run
 138             if test["Report"]:
 139                 report = test["Report"](target, log)
 140
 141                 # append report to results tuple
 142                 result += (report,)
 143             else:
 144                 # report is None
 145                 result += (None,)
 146         except:
 147             # make a note when the test crashed
 148             end_time = time.time()
 149
 150             # mark test as failed
 151             result = (-1, "Fail [Crash]", test["Name"],
 152                       end_time - start_time, logfile.getvalue(), None)
 153         finally:
 154             # append the results to the results list
 155             results.append(result)
 156
 157     # regardless of whether test has crashed, try quitting it
 158     try:
 159         child.sendline("quit")
 160         child.close()
 161     # if the test crashed, just do nothing instead
 162     except:
 163         # nop
 164         pass
 165
 166     # return test results
 167     return results
 168
 169
 170 # class representing an instance of autotests run
 171 class AutotestRunner:
 172     cmdline = ""
 173     parallel_test_groups = []
 174     non_parallel_test_groups = []
 175     logfile = None
 176     csvwriter = None
 177     target = ""
 178     start = None
 179     n_tests = 0
 180     fails = 0
 181     log_buffers = []
 182     blacklist = []
 183     whitelist = []
 184
 185     def __init__(self, cmdline, target, blacklist, whitelist):
 186         self.cmdline = cmdline
 187         self.target = target
 188         self.blacklist = blacklist
 189         self.whitelist = whitelist
 190
 191         # log file filename
 192         logfile = "%s.log" % target
 193         csvfile = "%s.csv" % target
 194
 195         self.logfile = open(logfile, "w")
 196         csvfile = open(csvfile, "w")
 197         self.csvwriter = csv.writer(csvfile)
 198
 199         # prepare results table
 200         self.csvwriter.writerow(["test_name", "test_result", "result_str"])
 201
 202     # set up cmdline string
 203     def __get_cmdline(self, test):
 204         cmdline = self.cmdline
 205
 206         # append memory limitations for each test
 207         # otherwise tests won't run in parallel
 208         if "i686" not in self.target:
 209             cmdline += " --socket-mem=%s" % test["Memory"]
 210         else:
 211             # affinitize startup so that tests don't fail on i686
 212             cmdline = "taskset 1 " + cmdline
 213             cmdline += " -m " + str(sum(map(int, test["Memory"].split(","))))
 214
 215         # set group prefix for autotest group
 216         # otherwise they won't run in parallel
 217         cmdline += " --file-prefix=%s" % test["Prefix"]
 218
 219         return cmdline
 220
 221     def add_parallel_test_group(self, test_group):
 222         self.parallel_test_groups.append(test_group)
 223
 224     def add_non_parallel_test_group(self, test_group):
 225         self.non_parallel_test_groups.append(test_group)
 226
 227     def __process_results(self, results):
 228         # this iterates over individual test results
 229         for i, result in enumerate(results):
 230
 231             # increase total number of tests that were run
 232             # do not include "start" test
 233             if i > 0:
 234                 self.n_tests += 1
 235
 236             # unpack result tuple
 237             test_result, result_str, test_name, \
 238                 test_time, log, report = result
 239
 240             # get total run time
 241             cur_time = time.time()
 242             total_time = int(cur_time - self.start)
 243
 244             # print results, test run time and total time since start
 245             result = ("%s:" % test_name).ljust(30)
 246             result += result_str.ljust(29)
 247             result += "[%02dm %02ds]" % (test_time / 60, test_time % 60)
 248
 249             # don't print out total time every line, it's the same anyway
 250             if i == len(results) - 1:
 251                 print(result +
 252                       "[%02dm %02ds]" % (total_time / 60, total_time % 60))
 253             else:
 254                 print(result)
 255
 256             # if test failed and it wasn't a "start" test
 257             if test_result < 0 and not i == 0:
 258                 self.fails += 1
 259
 260             # collect logs
 261             self.log_buffers.append(log)
 262
 263             # create report if it exists
 264             if report:
 265                 try:
 266                     f = open("%s_%s_report.rst" %
 267                              (self.target, test_name), "w")
 268                 except IOError:
 269                     print("Report for %s could not be created!" % test_name)
 270                 else:
 271                     with f:
 272                         f.write(report)
 273
 274             # write test result to CSV file
 275             if i != 0:
 276                 self.csvwriter.writerow([test_name, test_result, result_str])
 277
 278     # this function iterates over test groups and removes each
 279     # test that is not in whitelist/blacklist
 280     def __filter_groups(self, test_groups):
 281         groups_to_remove = []
 282
 283         # filter out tests from parallel test groups
 284         for i, test_group in enumerate(test_groups):
 285
 286             # iterate over a copy so that we could safely delete individual
 287             # tests
 288             for test in test_group["Tests"][:]:
 289                 test_id = test["Command"]
 290
 291                 # dump tests are specified in full e.g. "Dump_mempool"
 292                 if "_autotest" in test_id:
 293                     test_id = test_id[:-len("_autotest")]
 294
 295                 # filter out blacklisted/whitelisted tests
 296                 if self.blacklist and test_id in self.blacklist:
 297                     test_group["Tests"].remove(test)
 298                     continue
 299                 if self.whitelist and test_id not in self.whitelist:
 300                     test_group["Tests"].remove(test)
 301                     continue
 302
 303             # modify or remove original group
 304             if len(test_group["Tests"]) > 0:
 305                 test_groups[i] = test_group
 306             else:
 307                 # remember which groups should be deleted
 308                 # put the numbers backwards so that we start
 309                 # deleting from the end, not from the beginning
 310                 groups_to_remove.insert(0, i)
 311
 312         # remove test groups that need to be removed
 313         for i in groups_to_remove:
 314             del test_groups[i]
 315
 316         return test_groups
 317
 318     # iterate over test groups and run tests associated with them
 319     def run_all_tests(self):
 320         # filter groups
 321         self.parallel_test_groups = \
 322             self.__filter_groups(self.parallel_test_groups)
 323         self.non_parallel_test_groups = \
 324             self.__filter_groups(self.non_parallel_test_groups)
 325
 326         # create a pool of worker threads
 327         pool = multiprocessing.Pool(processes=1)
 328
 329         results = []
 330
 331         # whatever happens, try to save as much logs as possible
 332         try:
 333
 334             # create table header
 335             print("")
 336             print("Test name".ljust(30) + "Test result".ljust(29) +
 337                   "Test".center(9) + "Total".center(9))
 338             print("=" * 80)
 339
 340             # make a note of tests start time
 341             self.start = time.time()
 342
 343             # assign worker threads to run test groups
 344             for test_group in self.parallel_test_groups:
 345                 result = pool.apply_async(run_test_group,
 346                                           [self.__get_cmdline(test_group),
 347                                            self.target,
 348                                            test_group])
 349                 results.append(result)
 350
 351             # iterate while we have group execution results to get
 352             while len(results) > 0:
 353
 354                 # iterate over a copy to be able to safely delete results
 355                 # this iterates over a list of group results
 356                 for group_result in results[:]:
 357
 358                     # if the thread hasn't finished yet, continue
 359                     if not group_result.ready():
 360                         continue
 361
 362                     res = group_result.get()
 363
 364                     self.__process_results(res)
 365
 366                     # remove result from results list once we're done with it
 367                     results.remove(group_result)
 368
 369             # run non_parallel tests. they are run one by one, synchronously
 370             for test_group in self.non_parallel_test_groups:
 371                 group_result = run_test_group(
 372                     self.__get_cmdline(test_group), self.target, test_group)
 373
 374                 self.__process_results(group_result)
 375
 376             # get total run time
 377             cur_time = time.time()
 378             total_time = int(cur_time - self.start)
 379
 380             # print out summary
 381             print("=" * 80)
 382             print("Total run time: %02dm %02ds" % (total_time / 60,
 383                                                    total_time % 60))
 384             if self.fails != 0:
 385                 print("Number of failed tests: %s" % str(self.fails))
 386
 387             # write summary to logfile
 388             self.logfile.write("Summary\n")
 389             self.logfile.write("Target: ".ljust(15) + "%s\n" % self.target)
 390             self.logfile.write("Tests: ".ljust(15) + "%i\n" % self.n_tests)
 391             self.logfile.write("Failed tests: ".ljust(
 392                 15) + "%i\n" % self.fails)
 393         except:
 394             print("Exception occurred")
 395             print(sys.exc_info())
 396             self.fails = 1
 397
 398         # drop logs from all executions to a logfile
 399         for buf in self.log_buffers:
 400             self.logfile.write(buf.replace("\r", ""))
 401
 402         return self.fails