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