test/framework.py

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