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