test/framework.py

   1 #!/usr/bin/env python
   2
   3 from __future__ import print_function
   4 import gc
   5 import sys
   6 import os
   7 import select
   8 import unittest
   9 import tempfile
  10 import time
  11 import faulthandler
  12 import random
  13 import copy
  14 import psutil
  15 import platform
  16 from collections import deque
  17 from threading import Thread, Event
  18 from inspect import getdoc, isclass
  19 from traceback import format_exception
  20 from logging import FileHandler, DEBUG, Formatter
  21
  22 import scapy.compat
  23 from scapy.packet import Raw
  24 from hook import StepHook, PollHook, VppDiedError
  25 from vpp_pg_interface import VppPGInterface
  26 from vpp_sub_interface import VppSubInterface
  27 from vpp_lo_interface import VppLoInterface
  28 from vpp_bvi_interface import VppBviInterface
  29 from vpp_papi_provider import VppPapiProvider
  30 from vpp_papi.vpp_stats import VPPStats
  31 from log import RED, GREEN, YELLOW, double_line_delim, single_line_delim, \
  32     get_logger, colorize
  33 from vpp_object import VppObjectRegistry
  34 from util import ppp, is_core_present
  35 from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
  36 from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
  37 from scapy.layers.inet6 import ICMPv6EchoReply
  38
  39 if os.name == 'posix' and sys.version_info[0] < 3:
  40     # using subprocess32 is recommended by python official documentation
  41     # @ https://docs.python.org/2/library/subprocess.html
  42     import subprocess32 as subprocess
  43 else:
  44     import subprocess
  45
  46 #  Python2/3 compatible
  47 try:
  48     input = raw_input
  49 except NameError:
  50     pass
  51
  52 PASS = 0
  53 FAIL = 1
  54 ERROR = 2
  55 SKIP = 3
  56 TEST_RUN = 4
  57
  58 debug_framework = False
  59 if os.getenv('TEST_DEBUG', "0") == "1":
  60     debug_framework = True
  61     import debug_internal
  62
  63 """
  64   Test framework module.
  65
  66   The module provides a set of tools for constructing and running tests and
  67   representing the results.
  68 """
  69
  70
  71 class _PacketInfo(object):
  72     """Private class to create packet info object.
  73
  74     Help process information about the next packet.
  75     Set variables to default values.
  76     """
  77     #: Store the index of the packet.
  78     index = -1
  79     #: Store the index of the source packet generator interface of the packet.
  80     src = -1
  81     #: Store the index of the destination packet generator interface
  82     #: of the packet.
  83     dst = -1
  84     #: Store expected ip version
  85     ip = -1
  86     #: Store expected upper protocol
  87     proto = -1
  88     #: Store the copy of the former packet.
  89     data = None
  90
  91     def __eq__(self, other):
  92         index = self.index == other.index
  93         src = self.src == other.src
  94         dst = self.dst == other.dst
  95         data = self.data == other.data
  96         return index and src and dst and data
  97
  98
  99 def pump_output(testclass):
 100     """ pump output from vpp stdout/stderr to proper queues """
 101     stdout_fragment = ""
 102     stderr_fragment = ""
 103     while not testclass.pump_thread_stop_flag.is_set():
 104         readable = select.select([testclass.vpp.stdout.fileno(),
 105                                   testclass.vpp.stderr.fileno(),
 106                                   testclass.pump_thread_wakeup_pipe[0]],
 107                                  [], [])[0]
 108         if testclass.vpp.stdout.fileno() in readable:
 109             read = os.read(testclass.vpp.stdout.fileno(), 102400)
 110             if len(read) > 0:
 111                 split = read.splitlines(True)
 112                 if len(stdout_fragment) > 0:
 113                     split[0] = "%s%s" % (stdout_fragment, split[0])
 114                 if len(split) > 0 and split[-1].endswith("\n"):
 115                     limit = None
 116                 else:
 117                     limit = -1
 118                     stdout_fragment = split[-1]
 119                 testclass.vpp_stdout_deque.extend(split[:limit])
 120                 if not testclass.cache_vpp_output:
 121                     for line in split[:limit]:
 122                         testclass.logger.debug(
 123                             "VPP STDOUT: %s" % line.rstrip("\n"))
 124         if testclass.vpp.stderr.fileno() in readable:
 125             read = os.read(testclass.vpp.stderr.fileno(), 102400)
 126             if len(read) > 0:
 127                 split = read.splitlines(True)
 128                 if len(stderr_fragment) > 0:
 129                     split[0] = "%s%s" % (stderr_fragment, split[0])
 130                 if len(split) > 0 and split[-1].endswith(b"\n"):
 131                     limit = None
 132                 else:
 133                     limit = -1
 134                     stderr_fragment = split[-1]
 135                 testclass.vpp_stderr_deque.extend(split[:limit])
 136                 if not testclass.cache_vpp_output:
 137                     for line in split[:limit]:
 138                         testclass.logger.debug(
 139                             "VPP STDERR: %s" % line.rstrip("\n"))
 140                         # ignoring the dummy pipe here intentionally - the
 141                         # flag will take care of properly terminating the loop
 142
 143
 144 def _is_skip_aarch64_set():
 145     return os.getenv('SKIP_AARCH64', 'n').lower() in ('yes', 'y', '1')
 146
 147 is_skip_aarch64_set = _is_skip_aarch64_set()
 148
 149
 150 def _is_platform_aarch64():
 151     return platform.machine() == 'aarch64'
 152
 153 is_platform_aarch64 = _is_platform_aarch64()
 154
 155
 156 def _running_extended_tests():
 157     s = os.getenv("EXTENDED_TESTS", "n")
 158     return True if s.lower() in ("y", "yes", "1") else False
 159
 160 running_extended_tests = _running_extended_tests()
 161
 162
 163 def _running_on_centos():
 164     os_id = os.getenv("OS_ID", "")
 165     return True if "centos" in os_id.lower() else False
 166
 167 running_on_centos = _running_on_centos
 168
 169
 170 class KeepAliveReporter(object):
 171     """
 172     Singleton object which reports test start to parent process
 173     """
 174     _shared_state = {}
 175
 176     def __init__(self):
 177         self.__dict__ = self._shared_state
 178         self._pipe = None
 179
 180     @property
 181     def pipe(self):
 182         return self._pipe
 183
 184     @pipe.setter
 185     def pipe(self, pipe):
 186         if self._pipe is not None:
 187             raise Exception("Internal error - pipe should only be set once.")
 188         self._pipe = pipe
 189
 190     def send_keep_alive(self, test, desc=None):
 191         """
 192         Write current test tmpdir & desc to keep-alive pipe to signal liveness
 193         """
 194         if self.pipe is None:
 195             # if not running forked..
 196             return
 197
 198         if isclass(test):
 199             desc = '%s (%s)' % (desc, unittest.util.strclass(test))
 200         else:
 201             desc = test.id()
 202
 203         self.pipe.send((desc, test.vpp_bin, test.tempdir, test.vpp.pid))
 204
 205
 206 class VppTestCase(unittest.TestCase):
 207     """This subclass is a base class for VPP test cases that are implemented as
 208     classes. It provides methods to create and run test case.
 209     """
 210
 211     extra_vpp_punt_config = []
 212     extra_vpp_plugin_config = []
 213
 214     @property
 215     def packet_infos(self):
 216         """List of packet infos"""
 217         return self._packet_infos
 218
 219     @classmethod
 220     def get_packet_count_for_if_idx(cls, dst_if_index):
 221         """Get the number of packet info for specified destination if index"""
 222         if dst_if_index in cls._packet_count_for_dst_if_idx:
 223             return cls._packet_count_for_dst_if_idx[dst_if_index]
 224         else:
 225             return 0
 226
 227     @classmethod
 228     def instance(cls):
 229         """Return the instance of this testcase"""
 230         return cls.test_instance
 231
 232     @classmethod
 233     def set_debug_flags(cls, d):
 234         cls.debug_core = False
 235         cls.debug_gdb = False
 236         cls.debug_gdbserver = False
 237         if d is None:
 238             return
 239         dl = d.lower()
 240         if dl == "core":
 241             cls.debug_core = True
 242         elif dl == "gdb":
 243             cls.debug_gdb = True
 244         elif dl == "gdbserver":
 245             cls.debug_gdbserver = True
 246         else:
 247             raise Exception("Unrecognized DEBUG option: '%s'" % d)
 248
 249     @staticmethod
 250     def get_least_used_cpu():
 251         cpu_usage_list = [set(range(psutil.cpu_count()))]
 252         vpp_processes = [p for p in psutil.process_iter(attrs=['pid', 'name'])
 253                          if 'vpp_main' == p.info['name']]
 254         for vpp_process in vpp_processes:
 255             for cpu_usage_set in cpu_usage_list:
 256                 try:
 257                     cpu_num = vpp_process.cpu_num()
 258                     if cpu_num in cpu_usage_set:
 259                         cpu_usage_set_index = cpu_usage_list.index(
 260                             cpu_usage_set)
 261                         if cpu_usage_set_index == len(cpu_usage_list) - 1:
 262                             cpu_usage_list.append({cpu_num})
 263                         else:
 264                             cpu_usage_list[cpu_usage_set_index + 1].add(
 265                                 cpu_num)
 266                         cpu_usage_set.remove(cpu_num)
 267                         break
 268                 except psutil.NoSuchProcess:
 269                     pass
 270
 271         for cpu_usage_set in cpu_usage_list:
 272             if len(cpu_usage_set) > 0:
 273                 min_usage_set = cpu_usage_set
 274                 break
 275
 276         return random.choice(tuple(min_usage_set))
 277
 278     @classmethod
 279     def setUpConstants(cls):
 280         """ Set-up the test case class based on environment variables """
 281         s = os.getenv("STEP", "n")
 282         cls.step = True if s.lower() in ("y", "yes", "1") else False
 283         d = os.getenv("DEBUG", None)
 284         c = os.getenv("CACHE_OUTPUT", "1")
 285         cls.cache_vpp_output = False if c.lower() in ("n", "no", "0") else True
 286         cls.set_debug_flags(d)
 287         cls.vpp_bin = os.getenv('VPP_BIN', "vpp")
 288         cls.plugin_path = os.getenv('VPP_PLUGIN_PATH')
 289         cls.test_plugin_path = os.getenv('VPP_TEST_PLUGIN_PATH')
 290         cls.extern_plugin_path = os.getenv('EXTERN_PLUGINS')
 291         plugin_path = None
 292         if cls.plugin_path is not None:
 293             if cls.extern_plugin_path is not None:
 294                 plugin_path = "%s:%s" % (
 295                     cls.plugin_path, cls.extern_plugin_path)
 296             else:
 297                 plugin_path = cls.plugin_path
 298         elif cls.extern_plugin_path is not None:
 299             plugin_path = cls.extern_plugin_path
 300         debug_cli = ""
 301         if cls.step or cls.debug_gdb or cls.debug_gdbserver:
 302             debug_cli = "cli-listen localhost:5002"
 303         coredump_size = None
 304         size = os.getenv("COREDUMP_SIZE")
 305         if size is not None:
 306             coredump_size = "coredump-size %s" % size
 307         if coredump_size is None:
 308             coredump_size = "coredump-size unlimited"
 309
 310         cpu_core_number = cls.get_least_used_cpu()
 311
 312         cls.vpp_cmdline = [cls.vpp_bin, "unix",
 313                            "{", "nodaemon", debug_cli, "full-coredump",
 314                            coredump_size, "runtime-dir", cls.tempdir, "}",
 315                            "api-trace", "{", "on", "}", "api-segment", "{",
 316                            "prefix", cls.shm_prefix, "}", "cpu", "{",
 317                            "main-core", str(cpu_core_number), "}",
 318                            "statseg", "{", "socket-name", cls.stats_sock, "}",
 319                            "socksvr", "{", "socket-name", cls.api_sock, "}",
 320                            "plugins",
 321                            "{", "plugin", "dpdk_plugin.so", "{", "disable",
 322                            "}", "plugin", "rdma_plugin.so", "{", "disable",
 323                            "}", "plugin", "unittest_plugin.so", "{", "enable",
 324                            "}"] + cls.extra_vpp_plugin_config + ["}", ]
 325         if cls.extra_vpp_punt_config is not None:
 326             cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
 327         if plugin_path is not None:
 328             cls.vpp_cmdline.extend(["plugin_path", plugin_path])
 329         if cls.test_plugin_path is not None:
 330             cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
 331
 332         cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
 333         cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
 334
 335     @classmethod
 336     def wait_for_enter(cls):
 337         if cls.debug_gdbserver:
 338             print(double_line_delim)
 339             print("Spawned GDB server with PID: %d" % cls.vpp.pid)
 340         elif cls.debug_gdb:
 341             print(double_line_delim)
 342             print("Spawned VPP with PID: %d" % cls.vpp.pid)
 343         else:
 344             cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
 345             return
 346         print(single_line_delim)
 347         print("You can debug the VPP using e.g.:")
 348         if cls.debug_gdbserver:
 349             print("gdb " + cls.vpp_bin + " -ex 'target remote localhost:7777'")
 350             print("Now is the time to attach a gdb by running the above "
 351                   "command, set up breakpoints etc. and then resume VPP from "
 352                   "within gdb by issuing the 'continue' command")
 353         elif cls.debug_gdb:
 354             print("gdb " + cls.vpp_bin + " -ex 'attach %s'" % cls.vpp.pid)
 355             print("Now is the time to attach a gdb by running the above "
 356                   "command and set up breakpoints etc.")
 357         print(single_line_delim)
 358         input("Press ENTER to continue running the testcase...")
 359
 360     @classmethod
 361     def run_vpp(cls):
 362         cmdline = cls.vpp_cmdline
 363
 364         if cls.debug_gdbserver:
 365             gdbserver = '/usr/bin/gdbserver'
 366             if not os.path.isfile(gdbserver) or \
 367                     not os.access(gdbserver, os.X_OK):
 368                 raise Exception("gdbserver binary '%s' does not exist or is "
 369                                 "not executable" % gdbserver)
 370
 371             cmdline = [gdbserver, 'localhost:7777'] + cls.vpp_cmdline
 372             cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
 373
 374         try:
 375             cls.vpp = subprocess.Popen(cmdline,
 376                                        stdout=subprocess.PIPE,
 377                                        stderr=subprocess.PIPE,
 378                                        bufsize=1)
 379         except subprocess.CalledProcessError as e:
 380             cls.logger.critical("Subprocess returned with non-0 return code: ("
 381                                 "%s)", e.returncode)
 382             raise
 383         except OSError as e:
 384             cls.logger.critical("Subprocess returned with OS error: "
 385                                 "(%s) %s", e.errno, e.strerror)
 386             raise
 387         except Exception as e:
 388             cls.logger.exception("Subprocess returned unexpected from "
 389                                  "%s:", cmdline)
 390             raise
 391
 392         cls.wait_for_enter()
 393
 394     @classmethod
 395     def wait_for_stats_socket(cls):
 396         deadline = time.time() + 3
 397         ok = False
 398         while time.time() < deadline or \
 399                 cls.debug_gdb or cls.debug_gdbserver:
 400             if os.path.exists(cls.stats_sock):
 401                 ok = True
 402                 break
 403             cls.sleep(0.8)
 404         if not ok:
 405             cls.logger.critical("Couldn't stat : {}".format(cls.stats_sock))
 406
 407     @classmethod
 408     def wait_for_coredump(cls):
 409         corefile = cls.tempdir + "/core"
 410         if os.path.isfile(corefile):
 411             cls.logger.error("Waiting for coredump to complete: %s", corefile)
 412             curr_size = os.path.getsize(corefile)
 413             deadline = time.time() + 60
 414             ok = False
 415             while time.time() < deadline:
 416                 cls.sleep(1)
 417                 size = curr_size
 418                 curr_size = os.path.getsize(corefile)
 419                 if size == curr_size:
 420                     ok = True
 421                     break
 422             if not ok:
 423                 cls.logger.error("Timed out waiting for coredump to complete:"
 424                                  " %s", corefile)
 425             else:
 426                 cls.logger.error("Coredump complete: %s, size %d",
 427                                  corefile, curr_size)
 428
 429     @classmethod
 430     def setUpClass(cls):
 431         """
 432         Perform class setup before running the testcase
 433         Remove shared memory files, start vpp and connect the vpp-api
 434         """
 435         super(VppTestCase, cls).setUpClass()
 436         gc.collect()  # run garbage collection first
 437         random.seed()
 438         cls.logger = get_logger(cls.__name__)
 439         if hasattr(cls, 'parallel_handler'):
 440             cls.logger.addHandler(cls.parallel_handler)
 441             cls.logger.propagate = False
 442
 443         cls.tempdir = tempfile.mkdtemp(
 444             prefix='vpp-unittest-%s-' % cls.__name__)
 445         cls.stats_sock = "%s/stats.sock" % cls.tempdir
 446         cls.api_sock = "%s/api.sock" % cls.tempdir
 447         cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
 448         cls.file_handler.setFormatter(
 449             Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
 450                       datefmt="%H:%M:%S"))
 451         cls.file_handler.setLevel(DEBUG)
 452         cls.logger.addHandler(cls.file_handler)
 453         cls.logger.debug("--- setUpClass() for %s called ---" %
 454                          cls.__name__)
 455         cls.shm_prefix = os.path.basename(cls.tempdir)
 456         os.chdir(cls.tempdir)
 457         cls.logger.info("Temporary dir is %s, shm prefix is %s",
 458                         cls.tempdir, cls.shm_prefix)
 459         cls.setUpConstants()
 460         cls.reset_packet_infos()
 461         cls._captures = []
 462         cls._zombie_captures = []
 463         cls.verbose = 0
 464         cls.vpp_dead = False
 465         cls.registry = VppObjectRegistry()
 466         cls.vpp_startup_failed = False
 467         cls.reporter = KeepAliveReporter()
 468         # need to catch exceptions here because if we raise, then the cleanup
 469         # doesn't get called and we might end with a zombie vpp
 470         try:
 471             cls.run_vpp()
 472             cls.reporter.send_keep_alive(cls, 'setUpClass')
 473             VppTestResult.current_test_case_info = TestCaseInfo(
 474                 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
 475             cls.vpp_stdout_deque = deque()
 476             cls.vpp_stderr_deque = deque()
 477             cls.pump_thread_stop_flag = Event()
 478             cls.pump_thread_wakeup_pipe = os.pipe()
 479             cls.pump_thread = Thread(target=pump_output, args=(cls,))
 480             cls.pump_thread.daemon = True
 481             cls.pump_thread.start()
 482             if cls.debug_gdb or cls.debug_gdbserver:
 483                 read_timeout = 0
 484             else:
 485                 read_timeout = 5
 486             cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
 487                                        read_timeout)
 488             if cls.step:
 489                 hook = StepHook(cls)
 490             else:
 491                 hook = PollHook(cls)
 492             cls.vapi.register_hook(hook)
 493             cls.wait_for_stats_socket()
 494             cls.statistics = VPPStats(socketname=cls.stats_sock)
 495             try:
 496                 hook.poll_vpp()
 497             except VppDiedError:
 498                 cls.vpp_startup_failed = True
 499                 cls.logger.critical(
 500                     "VPP died shortly after startup, check the"
 501                     " output to standard error for possible cause")
 502                 raise
 503             try:
 504                 cls.vapi.connect()
 505             except Exception:
 506                 try:
 507                     cls.vapi.disconnect()
 508                 except Exception:
 509                     pass
 510                 if cls.debug_gdbserver:
 511                     print(colorize("You're running VPP inside gdbserver but "
 512                                    "VPP-API connection failed, did you forget "
 513                                    "to 'continue' VPP from within gdb?", RED))
 514                 raise
 515         except Exception:
 516             try:
 517                 cls.quit()
 518             except Exception:
 519                 pass
 520             raise
 521
 522     @classmethod
 523     def quit(cls):
 524         """
 525         Disconnect vpp-api, kill vpp and cleanup shared memory files
 526         """
 527         if (cls.debug_gdbserver or cls.debug_gdb) and hasattr(cls, 'vpp'):
 528             cls.vpp.poll()
 529             if cls.vpp.returncode is None:
 530                 print(double_line_delim)
 531                 print("VPP or GDB server is still running")
 532                 print(single_line_delim)
 533                 input("When done debugging, press ENTER to kill the "
 534                       "process and finish running the testcase...")
 535
 536         # first signal that we want to stop the pump thread, then wake it up
 537         if hasattr(cls, 'pump_thread_stop_flag'):
 538             cls.pump_thread_stop_flag.set()
 539         if hasattr(cls, 'pump_thread_wakeup_pipe'):
 540             os.write(cls.pump_thread_wakeup_pipe[1], b'ding dong wake up')
 541         if hasattr(cls, 'pump_thread'):
 542             cls.logger.debug("Waiting for pump thread to stop")
 543             cls.pump_thread.join()
 544         if hasattr(cls, 'vpp_stderr_reader_thread'):
 545             cls.logger.debug("Waiting for stdderr pump to stop")
 546             cls.vpp_stderr_reader_thread.join()
 547
 548         if hasattr(cls, 'vpp'):
 549             if hasattr(cls, 'vapi'):
 550                 cls.logger.debug("Disconnecting class vapi client on %s",
 551                                  cls.__name__)
 552                 cls.vapi.disconnect()
 553                 cls.logger.debug("Deleting class vapi attribute on %s",
 554                                  cls.__name__)
 555                 del cls.vapi
 556             cls.vpp.poll()
 557             if cls.vpp.returncode is None:
 558                 cls.wait_for_coredump()
 559                 cls.logger.debug("Sending TERM to vpp")
 560                 cls.vpp.terminate()
 561                 cls.logger.debug("Waiting for vpp to die")
 562                 cls.vpp.communicate()
 563             cls.logger.debug("Deleting class vpp attribute on %s",
 564                              cls.__name__)
 565             del cls.vpp
 566
 567         if cls.vpp_startup_failed:
 568             stdout_log = cls.logger.info
 569             stderr_log = cls.logger.critical
 570         else:
 571             stdout_log = cls.logger.info
 572             stderr_log = cls.logger.info
 573
 574         if hasattr(cls, 'vpp_stdout_deque'):
 575             stdout_log(single_line_delim)
 576             stdout_log('VPP output to stdout while running %s:', cls.__name__)
 577             stdout_log(single_line_delim)
 578             vpp_output = "".join(cls.vpp_stdout_deque)
 579             with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
 580                 f.write(vpp_output)
 581             stdout_log('\n%s', vpp_output)
 582             stdout_log(single_line_delim)
 583
 584         if hasattr(cls, 'vpp_stderr_deque'):
 585             stderr_log(single_line_delim)
 586             stderr_log('VPP output to stderr while running %s:', cls.__name__)
 587             stderr_log(single_line_delim)
 588             vpp_output = "".join(cls.vpp_stderr_deque)
 589             with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
 590                 f.write(vpp_output)
 591             stderr_log('\n%s', vpp_output)
 592             stderr_log(single_line_delim)
 593
 594     @classmethod
 595     def tearDownClass(cls):
 596         """ Perform final cleanup after running all tests in this test-case """
 597         cls.logger.debug("--- tearDownClass() for %s called ---" %
 598                          cls.__name__)
 599         cls.reporter.send_keep_alive(cls, 'tearDownClass')
 600         cls.quit()
 601         cls.file_handler.close()
 602         cls.reset_packet_infos()
 603         if debug_framework:
 604             debug_internal.on_tear_down_class(cls)
 605
 606     def show_commands_at_teardown(self):
 607         """ Allow subclass specific teardown logging additions."""
 608         self.logger.info("--- No test specific show commands provided. ---")
 609
 610     def tearDown(self):
 611         """ Show various debug prints after each test """
 612         self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
 613                           (self.__class__.__name__, self._testMethodName,
 614                            self._testMethodDoc))
 615         if not self.vpp_dead:
 616             self.logger.info(
 617                 "--- Logging show commands common to all testcases. ---")
 618             self.logger.debug(self.vapi.cli("show trace max 1000"))
 619             self.logger.info(self.vapi.ppcli("show interface"))
 620             self.logger.info(self.vapi.ppcli("show hardware"))
 621             self.logger.info(self.statistics.set_errors_str())
 622             self.logger.info(self.vapi.ppcli("show run"))
 623             self.logger.info(self.vapi.ppcli("show log"))
 624             self.logger.info("Logging testcase specific show commands.")
 625             self.show_commands_at_teardown()
 626             self.registry.remove_vpp_config(self.logger)
 627             # Save/Dump VPP api trace log
 628             api_trace = "vpp_api_trace.%s.log" % self._testMethodName
 629             tmp_api_trace = "/tmp/%s" % api_trace
 630             vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
 631             self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
 632             self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
 633                                                     vpp_api_trace_log))
 634             os.rename(tmp_api_trace, vpp_api_trace_log)
 635             self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
 636                                              vpp_api_trace_log))
 637         else:
 638             self.registry.unregister_all(self.logger)
 639
 640     def setUp(self):
 641         """ Clear trace before running each test"""
 642         super(VppTestCase, self).setUp()
 643         self.reporter.send_keep_alive(self)
 644         if self.vpp_dead:
 645             raise Exception("VPP is dead when setting up the test")
 646         self.sleep(.1, "during setUp")
 647         self.vpp_stdout_deque.append(
 648             "--- test setUp() for %s.%s(%s) starts here ---\n" %
 649             (self.__class__.__name__, self._testMethodName,
 650              self._testMethodDoc))
 651         self.vpp_stderr_deque.append(
 652             "--- test setUp() for %s.%s(%s) starts here ---\n" %
 653             (self.__class__.__name__, self._testMethodName,
 654              self._testMethodDoc))
 655         self.vapi.cli("clear trace")
 656         # store the test instance inside the test class - so that objects
 657         # holding the class can access instance methods (like assertEqual)
 658         type(self).test_instance = self
 659
 660     @classmethod
 661     def pg_enable_capture(cls, interfaces=None):
 662         """
 663         Enable capture on packet-generator interfaces
 664
 665         :param interfaces: iterable interface indexes (if None,
 666                            use self.pg_interfaces)
 667
 668         """
 669         if interfaces is None:
 670             interfaces = cls.pg_interfaces
 671         for i in interfaces:
 672             i.enable_capture()
 673
 674     @classmethod
 675     def register_capture(cls, cap_name):
 676         """ Register a capture in the testclass """
 677         # add to the list of captures with current timestamp
 678         cls._captures.append((time.time(), cap_name))
 679         # filter out from zombies
 680         cls._zombie_captures = [(stamp, name)
 681                                 for (stamp, name) in cls._zombie_captures
 682                                 if name != cap_name]
 683
 684     @classmethod
 685     def pg_start(cls):
 686         """ Remove any zombie captures and enable the packet generator """
 687         # how long before capture is allowed to be deleted - otherwise vpp
 688         # crashes - 100ms seems enough (this shouldn't be needed at all)
 689         capture_ttl = 0.1
 690         now = time.time()
 691         for stamp, cap_name in cls._zombie_captures:
 692             wait = stamp + capture_ttl - now
 693             if wait > 0:
 694                 cls.sleep(wait, "before deleting capture %s" % cap_name)
 695                 now = time.time()
 696             cls.logger.debug("Removing zombie capture %s" % cap_name)
 697             cls.vapi.cli('packet-generator delete %s' % cap_name)
 698
 699         cls.vapi.cli("trace add pg-input 1000")
 700         cls.vapi.cli('packet-generator enable')
 701         cls._zombie_captures = cls._captures
 702         cls._captures = []
 703
 704     @classmethod
 705     def create_pg_interfaces(cls, interfaces):
 706         """
 707         Create packet-generator interfaces.
 708
 709         :param interfaces: iterable indexes of the interfaces.
 710         :returns: List of created interfaces.
 711
 712         """
 713         result = []
 714         for i in interfaces:
 715             intf = VppPGInterface(cls, i)
 716             setattr(cls, intf.name, intf)
 717             result.append(intf)
 718         cls.pg_interfaces = result
 719         return result
 720
 721     @classmethod
 722     def create_loopback_interfaces(cls, count):
 723         """
 724         Create loopback interfaces.
 725
 726         :param count: number of interfaces created.
 727         :returns: List of created interfaces.
 728         """
 729         result = [VppLoInterface(cls) for i in range(count)]
 730         for intf in result:
 731             setattr(cls, intf.name, intf)
 732         cls.lo_interfaces = result
 733         return result
 734
 735     @classmethod
 736     def create_bvi_interfaces(cls, count):
 737         """
 738         Create BVI interfaces.
 739
 740         :param count: number of interfaces created.
 741         :returns: List of created interfaces.
 742         """
 743         result = [VppBviInterface(cls) for i in range(count)]
 744         for intf in result:
 745             setattr(cls, intf.name, intf)
 746         cls.bvi_interfaces = result
 747         return result
 748
 749     @staticmethod
 750     def extend_packet(packet, size, padding=' '):
 751         """
 752         Extend packet to given size by padding with spaces or custom padding
 753         NOTE: Currently works only when Raw layer is present.
 754
 755         :param packet: packet
 756         :param size: target size
 757         :param padding: padding used to extend the payload
 758
 759         """
 760         packet_len = len(packet) + 4
 761         extend = size - packet_len
 762         if extend > 0:
 763             num = (extend // len(padding)) + 1
 764             packet[Raw].load += (padding * num)[:extend].encode("ascii")
 765
 766     @classmethod
 767     def reset_packet_infos(cls):
 768         """ Reset the list of packet info objects and packet counts to zero """
 769         cls._packet_infos = {}
 770         cls._packet_count_for_dst_if_idx = {}
 771
 772     @classmethod
 773     def create_packet_info(cls, src_if, dst_if):
 774         """
 775         Create packet info object containing the source and destination indexes
 776         and add it to the testcase's packet info list
 777
 778         :param VppInterface src_if: source interface
 779         :param VppInterface dst_if: destination interface
 780
 781         :returns: _PacketInfo object
 782
 783         """
 784         info = _PacketInfo()
 785         info.index = len(cls._packet_infos)
 786         info.src = src_if.sw_if_index
 787         info.dst = dst_if.sw_if_index
 788         if isinstance(dst_if, VppSubInterface):
 789             dst_idx = dst_if.parent.sw_if_index
 790         else:
 791             dst_idx = dst_if.sw_if_index
 792         if dst_idx in cls._packet_count_for_dst_if_idx:
 793             cls._packet_count_for_dst_if_idx[dst_idx] += 1
 794         else:
 795             cls._packet_count_for_dst_if_idx[dst_idx] = 1
 796         cls._packet_infos[info.index] = info
 797         return info
 798
 799     @staticmethod
 800     def info_to_payload(info):
 801         """
 802         Convert _PacketInfo object to packet payload
 803
 804         :param info: _PacketInfo object
 805
 806         :returns: string containing serialized data from packet info
 807         """
 808         return "%d %d %d %d %d" % (info.index, info.src, info.dst,
 809                                    info.ip, info.proto)
 810
 811     @staticmethod
 812     def payload_to_info(payload, payload_field='load'):
 813         """
 814         Convert packet payload to _PacketInfo object
 815
 816         :param payload: packet payload
 817         :type payload:  <class 'scapy.packet.Raw'>
 818         :param payload_field: packet fieldname of payload "load" for
 819                 <class 'scapy.packet.Raw'>
 820         :type payload_field: str
 821         :returns: _PacketInfo object containing de-serialized data from payload
 822
 823         """
 824         numbers = getattr(payload, payload_field).split()
 825         info = _PacketInfo()
 826         info.index = int(numbers[0])
 827         info.src = int(numbers[1])
 828         info.dst = int(numbers[2])
 829         info.ip = int(numbers[3])
 830         info.proto = int(numbers[4])
 831         return info
 832
 833     def get_next_packet_info(self, info):
 834         """
 835         Iterate over the packet info list stored in the testcase
 836         Start iteration with first element if info is None
 837         Continue based on index in info if info is specified
 838
 839         :param info: info or None
 840         :returns: next info in list or None if no more infos
 841         """
 842         if info is None:
 843             next_index = 0
 844         else:
 845             next_index = info.index + 1
 846         if next_index == len(self._packet_infos):
 847             return None
 848         else:
 849             return self._packet_infos[next_index]
 850
 851     def get_next_packet_info_for_interface(self, src_index, info):
 852         """
 853         Search the packet info list for the next packet info with same source
 854         interface index
 855
 856         :param src_index: source interface index to search for
 857         :param info: packet info - where to start the search
 858         :returns: packet info or None
 859
 860         """
 861         while True:
 862             info = self.get_next_packet_info(info)
 863             if info is None:
 864                 return None
 865             if info.src == src_index:
 866                 return info
 867
 868     def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
 869         """
 870         Search the packet info list for the next packet info with same source
 871         and destination interface indexes
 872
 873         :param src_index: source interface index to search for
 874         :param dst_index: destination interface index to search for
 875         :param info: packet info - where to start the search
 876         :returns: packet info or None
 877
 878         """
 879         while True:
 880             info = self.get_next_packet_info_for_interface(src_index, info)
 881             if info is None:
 882                 return None
 883             if info.dst == dst_index:
 884                 return info
 885
 886     def assert_equal(self, real_value, expected_value, name_or_class=None):
 887         if name_or_class is None:
 888             self.assertEqual(real_value, expected_value)
 889             return
 890         try:
 891             msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
 892             msg = msg % (getdoc(name_or_class).strip(),
 893                          real_value, str(name_or_class(real_value)),
 894                          expected_value, str(name_or_class(expected_value)))
 895         except Exception:
 896             msg = "Invalid %s: %s does not match expected value %s" % (
 897                 name_or_class, real_value, expected_value)
 898
 899         self.assertEqual(real_value, expected_value, msg)
 900
 901     def assert_in_range(self,
 902                         real_value,
 903                         expected_min,
 904                         expected_max,
 905                         name=None):
 906         if name is None:
 907             msg = None
 908         else:
 909             msg = "Invalid %s: %s out of range <%s,%s>" % (
 910                 name, real_value, expected_min, expected_max)
 911         self.assertTrue(expected_min <= real_value <= expected_max, msg)
 912
 913     def assert_packet_checksums_valid(self, packet,
 914                                       ignore_zero_udp_checksums=True):
 915         received = packet.__class__(scapy.compat.raw(packet))
 916         self.logger.debug(
 917             ppp("Verifying packet checksums for packet:", received))
 918         udp_layers = ['UDP', 'UDPerror']
 919         checksum_fields = ['cksum', 'chksum']
 920         checksums = []
 921         counter = 0
 922         temp = received.__class__(scapy.compat.raw(received))
 923         while True:
 924             layer = temp.getlayer(counter)
 925             if layer:
 926                 for cf in checksum_fields:
 927                     if hasattr(layer, cf):
 928                         if ignore_zero_udp_checksums and \
 929                                         0 == getattr(layer, cf) and \
 930                                         layer.name in udp_layers:
 931                             continue
 932                         delattr(layer, cf)
 933                         checksums.append((counter, cf))
 934             else:
 935                 break
 936             counter = counter + 1
 937         if 0 == len(checksums):
 938             return
 939         temp = temp.__class__(scapy.compat.raw(temp))
 940         for layer, cf in checksums:
 941             calc_sum = getattr(temp[layer], cf)
 942             self.assert_equal(
 943                 getattr(received[layer], cf), calc_sum,
 944                 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
 945             self.logger.debug(
 946                 "Checksum field `%s` on `%s` layer has correct value `%s`" %
 947                 (cf, temp[layer].name, calc_sum))
 948
 949     def assert_checksum_valid(self, received_packet, layer,
 950                               field_name='chksum',
 951                               ignore_zero_checksum=False):
 952         """ Check checksum of received packet on given layer """
 953         received_packet_checksum = getattr(received_packet[layer], field_name)
 954         if ignore_zero_checksum and 0 == received_packet_checksum:
 955             return
 956         recalculated = received_packet.__class__(
 957             scapy.compat.raw(received_packet))
 958         delattr(recalculated[layer], field_name)
 959         recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
 960         self.assert_equal(received_packet_checksum,
 961                           getattr(recalculated[layer], field_name),
 962                           "packet checksum on layer: %s" % layer)
 963
 964     def assert_ip_checksum_valid(self, received_packet,
 965                                  ignore_zero_checksum=False):
 966         self.assert_checksum_valid(received_packet, 'IP',
 967                                    ignore_zero_checksum=ignore_zero_checksum)
 968
 969     def assert_tcp_checksum_valid(self, received_packet,
 970                                   ignore_zero_checksum=False):
 971         self.assert_checksum_valid(received_packet, 'TCP',
 972                                    ignore_zero_checksum=ignore_zero_checksum)
 973
 974     def assert_udp_checksum_valid(self, received_packet,
 975                                   ignore_zero_checksum=True):
 976         self.assert_checksum_valid(received_packet, 'UDP',
 977                                    ignore_zero_checksum=ignore_zero_checksum)
 978
 979     def assert_embedded_icmp_checksum_valid(self, received_packet):
 980         if received_packet.haslayer(IPerror):
 981             self.assert_checksum_valid(received_packet, 'IPerror')
 982         if received_packet.haslayer(TCPerror):
 983             self.assert_checksum_valid(received_packet, 'TCPerror')
 984         if received_packet.haslayer(UDPerror):
 985             self.assert_checksum_valid(received_packet, 'UDPerror',
 986                                        ignore_zero_checksum=True)
 987         if received_packet.haslayer(ICMPerror):
 988             self.assert_checksum_valid(received_packet, 'ICMPerror')
 989
 990     def assert_icmp_checksum_valid(self, received_packet):
 991         self.assert_checksum_valid(received_packet, 'ICMP')
 992         self.assert_embedded_icmp_checksum_valid(received_packet)
 993
 994     def assert_icmpv6_checksum_valid(self, pkt):
 995         if pkt.haslayer(ICMPv6DestUnreach):
 996             self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
 997             self.assert_embedded_icmp_checksum_valid(pkt)
 998         if pkt.haslayer(ICMPv6EchoRequest):
 999             self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1000         if pkt.haslayer(ICMPv6EchoReply):
1001             self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1002
1003     def get_packet_counter(self, counter):
1004         if counter.startswith("/"):
1005             counter_value = self.statistics.get_counter(counter)
1006         else:
1007             counters = self.vapi.cli("sh errors").split('\n')
1008             counter_value = -1
1009             for i in range(1, len(counters) - 1):
1010                 results = counters[i].split()
1011                 if results[1] == counter:
1012                     counter_value = int(results[0])
1013                     break
1014         return counter_value
1015
1016     def assert_packet_counter_equal(self, counter, expected_value):
1017         if counter.startswith("/"):
1018             counter_value = self.statistics.get_counter(counter)
1019             self.assert_equal(counter_value, expected_value,
1020                               "packet counter `%s'" % counter)
1021         else:
1022             counters = self.vapi.cli("sh errors").split('\n')
1023             counter_value = -1
1024             for i in range(1, len(counters) - 1):
1025                 results = counters[i].split()
1026                 if results[1] == counter:
1027                     counter_value = int(results[0])
1028                     break
1029
1030     @classmethod
1031     def sleep(cls, timeout, remark=None):
1032
1033         # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1034         #  * by Guido, only the main thread can be interrupted.
1035         # */
1036         # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892  # noqa
1037         if timeout == 0:
1038             # yield quantum
1039             if hasattr(os, 'sched_yield'):
1040                 os.sched_yield()
1041             else:
1042                 time.sleep(0)
1043             return
1044
1045         if hasattr(cls, 'logger'):
1046             cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1047         before = time.time()
1048         time.sleep(timeout)
1049         after = time.time()
1050         if hasattr(cls, 'logger') and after - before > 2 * timeout:
1051             cls.logger.error("unexpected self.sleep() result - "
1052                              "slept for %es instead of ~%es!",
1053                              after - before, timeout)
1054         if hasattr(cls, 'logger'):
1055             cls.logger.debug(
1056                 "Finished sleep (%s) - slept %es (wanted %es)",
1057                 remark, after - before, timeout)
1058
1059     def pg_send(self, intf, pkts):
1060         self.vapi.cli("clear trace")
1061         intf.add_stream(pkts)
1062         self.pg_enable_capture(self.pg_interfaces)
1063         self.pg_start()
1064
1065     def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1066         self.pg_send(intf, pkts)
1067         if not timeout:
1068             timeout = 1
1069         for i in self.pg_interfaces:
1070             i.get_capture(0, timeout=timeout)
1071             i.assert_nothing_captured(remark=remark)
1072             timeout = 0.1
1073
1074     def send_and_expect(self, intf, pkts, output, n_rx=None):
1075         if not n_rx:
1076             n_rx = len(pkts)
1077         self.pg_send(intf, pkts)
1078         rx = output.get_capture(n_rx)
1079         return rx
1080
1081     def send_and_expect_only(self, intf, pkts, output, timeout=None):
1082         self.pg_send(intf, pkts)
1083         rx = output.get_capture(len(pkts))
1084         outputs = [output]
1085         if not timeout:
1086             timeout = 1
1087         for i in self.pg_interfaces:
1088             if i not in outputs:
1089                 i.get_capture(0, timeout=timeout)
1090                 i.assert_nothing_captured()
1091                 timeout = 0.1
1092
1093         return rx
1094
1095     def runTest(self):
1096         """ unittest calls runTest when TestCase is instantiated without a
1097         test case.  Use case: Writing unittests against VppTestCase"""
1098         pass
1099
1100
1101 def get_testcase_doc_name(test):
1102     return getdoc(test.__class__).splitlines()[0]
1103
1104
1105 def get_test_description(descriptions, test):
1106     short_description = test.shortDescription()
1107     if descriptions and short_description:
1108         return short_description
1109     else:
1110         return str(test)
1111
1112
1113 class TestCaseInfo(object):
1114     def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1115         self.logger = logger
1116         self.tempdir = tempdir
1117         self.vpp_pid = vpp_pid
1118         self.vpp_bin_path = vpp_bin_path
1119         self.core_crash_test = None
1120
1121
1122 class VppTestResult(unittest.TestResult):
1123     """
1124     @property result_string
1125      String variable to store the test case result string.
1126     @property errors
1127      List variable containing 2-tuples of TestCase instances and strings
1128      holding formatted tracebacks. Each tuple represents a test which
1129      raised an unexpected exception.
1130     @property failures
1131      List variable containing 2-tuples of TestCase instances and strings
1132      holding formatted tracebacks. Each tuple represents a test where
1133      a failure was explicitly signalled using the TestCase.assert*()
1134      methods.
1135     """
1136
1137     failed_test_cases_info = set()
1138     core_crash_test_cases_info = set()
1139     current_test_case_info = None
1140
1141     def __init__(self, stream=None, descriptions=None, verbosity=None,
1142                  runner=None):
1143         """
1144         :param stream File descriptor to store where to report test results.
1145             Set to the standard error stream by default.
1146         :param descriptions Boolean variable to store information if to use
1147             test case descriptions.
1148         :param verbosity Integer variable to store required verbosity level.
1149         """
1150         super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1151         self.stream = stream
1152         self.descriptions = descriptions
1153         self.verbosity = verbosity
1154         self.result_string = None
1155         self.runner = runner
1156
1157     def addSuccess(self, test):
1158         """
1159         Record a test succeeded result
1160
1161         :param test:
1162
1163         """
1164         if self.current_test_case_info:
1165             self.current_test_case_info.logger.debug(
1166                 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1167                                                        test._testMethodName,
1168                                                        test._testMethodDoc))
1169         unittest.TestResult.addSuccess(self, test)
1170         self.result_string = colorize("OK", GREEN)
1171
1172         self.send_result_through_pipe(test, PASS)
1173
1174     def addSkip(self, test, reason):
1175         """
1176         Record a test skipped.
1177
1178         :param test:
1179         :param reason:
1180
1181         """
1182         if self.current_test_case_info:
1183             self.current_test_case_info.logger.debug(
1184                 "--- addSkip() %s.%s(%s) called, reason is %s" %
1185                 (test.__class__.__name__, test._testMethodName,
1186                  test._testMethodDoc, reason))
1187         unittest.TestResult.addSkip(self, test, reason)
1188         self.result_string = colorize("SKIP", YELLOW)
1189
1190         self.send_result_through_pipe(test, SKIP)
1191
1192     def symlink_failed(self):
1193         if self.current_test_case_info:
1194             try:
1195                 failed_dir = os.getenv('FAILED_DIR')
1196                 link_path = os.path.join(
1197                     failed_dir,
1198                     '%s-FAILED' %
1199                     os.path.basename(self.current_test_case_info.tempdir))
1200                 if self.current_test_case_info.logger:
1201                     self.current_test_case_info.logger.debug(
1202                         "creating a link to the failed test")
1203                     self.current_test_case_info.logger.debug(
1204                         "os.symlink(%s, %s)" %
1205                         (self.current_test_case_info.tempdir, link_path))
1206                 if os.path.exists(link_path):
1207                     if self.current_test_case_info.logger:
1208                         self.current_test_case_info.logger.debug(
1209                             'symlink already exists')
1210                 else:
1211                     os.symlink(self.current_test_case_info.tempdir, link_path)
1212
1213             except Exception as e:
1214                 if self.current_test_case_info.logger:
1215                     self.current_test_case_info.logger.error(e)
1216
1217     def send_result_through_pipe(self, test, result):
1218         if hasattr(self, 'test_framework_result_pipe'):
1219             pipe = self.test_framework_result_pipe
1220             if pipe:
1221                 pipe.send((test.id(), result))
1222
1223     def log_error(self, test, err, fn_name):
1224         if self.current_test_case_info:
1225             if isinstance(test, unittest.suite._ErrorHolder):
1226                 test_name = test.description
1227             else:
1228                 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1229                                            test._testMethodName,
1230                                            test._testMethodDoc)
1231             self.current_test_case_info.logger.debug(
1232                 "--- %s() %s called, err is %s" %
1233                 (fn_name, test_name, err))
1234             self.current_test_case_info.logger.debug(
1235                 "formatted exception is:\n%s" %
1236                 "".join(format_exception(*err)))
1237
1238     def add_error(self, test, err, unittest_fn, error_type):
1239         if error_type == FAIL:
1240             self.log_error(test, err, 'addFailure')
1241             error_type_str = colorize("FAIL", RED)
1242         elif error_type == ERROR:
1243             self.log_error(test, err, 'addError')
1244             error_type_str = colorize("ERROR", RED)
1245         else:
1246             raise Exception('Error type %s cannot be used to record an '
1247                             'error or a failure' % error_type)
1248
1249         unittest_fn(self, test, err)
1250         if self.current_test_case_info:
1251             self.result_string = "%s [ temp dir used by test case: %s ]" % \
1252                                  (error_type_str,
1253                                   self.current_test_case_info.tempdir)
1254             self.symlink_failed()
1255             self.failed_test_cases_info.add(self.current_test_case_info)
1256             if is_core_present(self.current_test_case_info.tempdir):
1257                 if not self.current_test_case_info.core_crash_test:
1258                     if isinstance(test, unittest.suite._ErrorHolder):
1259                         test_name = str(test)
1260                     else:
1261                         test_name = "'{!s}' ({!s})".format(
1262                             get_testcase_doc_name(test), test.id())
1263                     self.current_test_case_info.core_crash_test = test_name
1264                 self.core_crash_test_cases_info.add(
1265                     self.current_test_case_info)
1266         else:
1267             self.result_string = '%s [no temp dir]' % error_type_str
1268
1269         self.send_result_through_pipe(test, error_type)
1270
1271     def addFailure(self, test, err):
1272         """
1273         Record a test failed result
1274
1275         :param test:
1276         :param err: error message
1277
1278         """
1279         self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1280
1281     def addError(self, test, err):
1282         """
1283         Record a test error result
1284
1285         :param test:
1286         :param err: error message
1287
1288         """
1289         self.add_error(test, err, unittest.TestResult.addError, ERROR)
1290
1291     def getDescription(self, test):
1292         """
1293         Get test description
1294
1295         :param test:
1296         :returns: test description
1297
1298         """
1299         return get_test_description(self.descriptions, test)
1300
1301     def startTest(self, test):
1302         """
1303         Start a test
1304
1305         :param test:
1306
1307         """
1308
1309         def print_header(test):
1310             if not hasattr(test.__class__, '_header_printed'):
1311                 print(double_line_delim)
1312                 print(colorize(getdoc(test).splitlines()[0], GREEN))
1313                 print(double_line_delim)
1314             test.__class__._header_printed = True
1315
1316         print_header(test)
1317
1318         unittest.TestResult.startTest(self, test)
1319         if self.verbosity > 0:
1320             self.stream.writeln(
1321                 "Starting " + self.getDescription(test) + " ...")
1322             self.stream.writeln(single_line_delim)
1323
1324     def stopTest(self, test):
1325         """
1326         Called when the given test has been run
1327
1328         :param test:
1329
1330         """
1331         unittest.TestResult.stopTest(self, test)
1332         if self.verbosity > 0:
1333             self.stream.writeln(single_line_delim)
1334             self.stream.writeln("%-73s%s" % (self.getDescription(test),
1335                                              self.result_string))
1336             self.stream.writeln(single_line_delim)
1337         else:
1338             self.stream.writeln("%-73s%s" % (self.getDescription(test),
1339                                              self.result_string))
1340
1341         self.send_result_through_pipe(test, TEST_RUN)
1342
1343     def printErrors(self):
1344         """
1345         Print errors from running the test case
1346         """
1347         if len(self.errors) > 0 or len(self.failures) > 0:
1348             self.stream.writeln()
1349             self.printErrorList('ERROR', self.errors)
1350             self.printErrorList('FAIL', self.failures)
1351
1352         # ^^ that is the last output from unittest before summary
1353         if not self.runner.print_summary:
1354             devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1355             self.stream = devnull
1356             self.runner.stream = devnull
1357
1358     def printErrorList(self, flavour, errors):
1359         """
1360         Print error list to the output stream together with error type
1361         and test case description.
1362
1363         :param flavour: error type
1364         :param errors: iterable errors
1365
1366         """
1367         for test, err in errors:
1368             self.stream.writeln(double_line_delim)
1369             self.stream.writeln("%s: %s" %
1370                                 (flavour, self.getDescription(test)))
1371             self.stream.writeln(single_line_delim)
1372             self.stream.writeln("%s" % err)
1373
1374
1375 class VppTestRunner(unittest.TextTestRunner):
1376     """
1377     A basic test runner implementation which prints results to standard error.
1378     """
1379
1380     @property
1381     def resultclass(self):
1382         """Class maintaining the results of the tests"""
1383         return VppTestResult
1384
1385     def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1386                  result_pipe=None, failfast=False, buffer=False,
1387                  resultclass=None, print_summary=True, **kwargs):
1388         # ignore stream setting here, use hard-coded stdout to be in sync
1389         # with prints from VppTestCase methods ...
1390         super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1391                                             verbosity, failfast, buffer,
1392                                             resultclass, **kwargs)
1393         KeepAliveReporter.pipe = keep_alive_pipe
1394
1395         self.orig_stream = self.stream
1396         self.resultclass.test_framework_result_pipe = result_pipe
1397
1398         self.print_summary = print_summary
1399
1400     def _makeResult(self):
1401         return self.resultclass(self.stream,
1402                                 self.descriptions,
1403                                 self.verbosity,
1404                                 self)
1405
1406     def run(self, test):
1407         """
1408         Run the tests
1409
1410         :param test:
1411
1412         """
1413         faulthandler.enable()  # emit stack trace to stderr if killed by signal
1414
1415         result = super(VppTestRunner, self).run(test)
1416         if not self.print_summary:
1417             self.stream = self.orig_stream
1418             result.stream = self.orig_stream
1419         return result
1420
1421
1422 class Worker(Thread):
1423     def __init__(self, args, logger, env={}):
1424         self.logger = logger
1425         self.args = args
1426         self.result = None
1427         self.env = copy.deepcopy(env)
1428         super(Worker, self).__init__()
1429
1430     def run(self):
1431         executable = self.args[0]
1432         self.logger.debug("Running executable w/args `%s'" % self.args)
1433         env = os.environ.copy()
1434         env.update(self.env)
1435         env["CK_LOG_FILE_NAME"] = "-"
1436         self.process = subprocess.Popen(
1437             self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1438             stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1439         out, err = self.process.communicate()
1440         self.logger.debug("Finished running `%s'" % executable)
1441         self.logger.info("Return code is `%s'" % self.process.returncode)
1442         self.logger.info(single_line_delim)
1443         self.logger.info("Executable `%s' wrote to stdout:" % executable)
1444         self.logger.info(single_line_delim)
1445         self.logger.info(out)
1446         self.logger.info(single_line_delim)
1447         self.logger.info("Executable `%s' wrote to stderr:" % executable)
1448         self.logger.info(single_line_delim)
1449         self.logger.info(err)
1450         self.logger.info(single_line_delim)
1451         self.result = self.process.returncode
1452
1453 if __name__ == '__main__':
1454     pass