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