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