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         # processes e.g. "Time now 2.190522, Wed, 11 Mar 2020 17:29:54 GMT"
 762         # returns float("2.190522")
 763         timestr = cls.vapi.cli('show clock')
 764         head, sep, tail = timestr.partition(',')
 765         head, sep, tail = head.partition('Time now')
 766         return float(tail)
 767
 768     @classmethod
 769     def sleep_on_vpp_time(cls, sec):
 770         """ Sleep according to time in VPP world """
 771         # On a busy system with many processes
 772         # we might end up with VPP time being slower than real world
 773         # So take that into account when waiting for VPP to do something
 774         start_time = cls.get_vpp_time()
 775         while cls.get_vpp_time() - start_time < sec:
 776             cls.sleep(0.1)
 777
 778     @classmethod
 779     def pg_start(cls):
 780         """ Enable the PG, wait till it is done, then clean up """
 781         cls.vapi.cli("trace add pg-input 1000")
 782         cls.vapi.cli('packet-generator enable')
 783         # PG, when starts, runs to completion -
 784         # so let's avoid a race condition,
 785         # and wait a little till it's done.
 786         # Then clean it up  - and then be gone.
 787         deadline = time.time() + 300
 788         while cls.vapi.cli('show packet-generator').find("Yes") != -1:
 789             cls.sleep(0.01)  # yield
 790             if time.time() > deadline:
 791                 cls.logger.error("Timeout waiting for pg to stop")
 792                 break
 793         for stamp, cap_name in cls._captures:
 794             cls.vapi.cli('packet-generator delete %s' % cap_name)
 795         cls._captures = []
 796
 797     @classmethod
 798     def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
 799         """
 800         Create packet-generator interfaces.
 801
 802         :param interfaces: iterable indexes of the interfaces.
 803         :returns: List of created interfaces.
 804
 805         """
 806         result = []
 807         for i in interfaces:
 808             intf = VppPGInterface(cls, i, gso, gso_size)
 809             setattr(cls, intf.name, intf)
 810             result.append(intf)
 811         cls.pg_interfaces = result
 812         return result
 813
 814     @classmethod
 815     def create_loopback_interfaces(cls, count):
 816         """
 817         Create loopback interfaces.
 818
 819         :param count: number of interfaces created.
 820         :returns: List of created interfaces.
 821         """
 822         result = [VppLoInterface(cls) for i in range(count)]
 823         for intf in result:
 824             setattr(cls, intf.name, intf)
 825         cls.lo_interfaces = result
 826         return result
 827
 828     @classmethod
 829     def create_bvi_interfaces(cls, count):
 830         """
 831         Create BVI interfaces.
 832
 833         :param count: number of interfaces created.
 834         :returns: List of created interfaces.
 835         """
 836         result = [VppBviInterface(cls) for i in range(count)]
 837         for intf in result:
 838             setattr(cls, intf.name, intf)
 839         cls.bvi_interfaces = result
 840         return result
 841
 842     @staticmethod
 843     def extend_packet(packet, size, padding=' '):
 844         """
 845         Extend packet to given size by padding with spaces or custom padding
 846         NOTE: Currently works only when Raw layer is present.
 847
 848         :param packet: packet
 849         :param size: target size
 850         :param padding: padding used to extend the payload
 851
 852         """
 853         packet_len = len(packet) + 4
 854         extend = size - packet_len
 855         if extend > 0:
 856             num = (extend // len(padding)) + 1
 857             packet[Raw].load += (padding * num)[:extend].encode("ascii")
 858
 859     @classmethod
 860     def reset_packet_infos(cls):
 861         """ Reset the list of packet info objects and packet counts to zero """
 862         cls._packet_infos = {}
 863         cls._packet_count_for_dst_if_idx = {}
 864
 865     @classmethod
 866     def create_packet_info(cls, src_if, dst_if):
 867         """
 868         Create packet info object containing the source and destination indexes
 869         and add it to the testcase's packet info list
 870
 871         :param VppInterface src_if: source interface
 872         :param VppInterface dst_if: destination interface
 873
 874         :returns: _PacketInfo object
 875
 876         """
 877         info = _PacketInfo()
 878         info.index = len(cls._packet_infos)
 879         info.src = src_if.sw_if_index
 880         info.dst = dst_if.sw_if_index
 881         if isinstance(dst_if, VppSubInterface):
 882             dst_idx = dst_if.parent.sw_if_index
 883         else:
 884             dst_idx = dst_if.sw_if_index
 885         if dst_idx in cls._packet_count_for_dst_if_idx:
 886             cls._packet_count_for_dst_if_idx[dst_idx] += 1
 887         else:
 888             cls._packet_count_for_dst_if_idx[dst_idx] = 1
 889         cls._packet_infos[info.index] = info
 890         return info
 891
 892     @staticmethod
 893     def info_to_payload(info):
 894         """
 895         Convert _PacketInfo object to packet payload
 896
 897         :param info: _PacketInfo object
 898
 899         :returns: string containing serialized data from packet info
 900         """
 901         return "%d %d %d %d %d" % (info.index, info.src, info.dst,
 902                                    info.ip, info.proto)
 903
 904     @staticmethod
 905     def payload_to_info(payload, payload_field='load'):
 906         """
 907         Convert packet payload to _PacketInfo object
 908
 909         :param payload: packet payload
 910         :type payload:  <class 'scapy.packet.Raw'>
 911         :param payload_field: packet fieldname of payload "load" for
 912                 <class 'scapy.packet.Raw'>
 913         :type payload_field: str
 914         :returns: _PacketInfo object containing de-serialized data from payload
 915
 916         """
 917         numbers = getattr(payload, payload_field).split()
 918         info = _PacketInfo()
 919         info.index = int(numbers[0])
 920         info.src = int(numbers[1])
 921         info.dst = int(numbers[2])
 922         info.ip = int(numbers[3])
 923         info.proto = int(numbers[4])
 924         return info
 925
 926     def get_next_packet_info(self, info):
 927         """
 928         Iterate over the packet info list stored in the testcase
 929         Start iteration with first element if info is None
 930         Continue based on index in info if info is specified
 931
 932         :param info: info or None
 933         :returns: next info in list or None if no more infos
 934         """
 935         if info is None:
 936             next_index = 0
 937         else:
 938             next_index = info.index + 1
 939         if next_index == len(self._packet_infos):
 940             return None
 941         else:
 942             return self._packet_infos[next_index]
 943
 944     def get_next_packet_info_for_interface(self, src_index, info):
 945         """
 946         Search the packet info list for the next packet info with same source
 947         interface index
 948
 949         :param src_index: source interface index to search for
 950         :param info: packet info - where to start the search
 951         :returns: packet info or None
 952
 953         """
 954         while True:
 955             info = self.get_next_packet_info(info)
 956             if info is None:
 957                 return None
 958             if info.src == src_index:
 959                 return info
 960
 961     def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
 962         """
 963         Search the packet info list for the next packet info with same source
 964         and destination interface indexes
 965
 966         :param src_index: source interface index to search for
 967         :param dst_index: destination interface index to search for
 968         :param info: packet info - where to start the search
 969         :returns: packet info or None
 970
 971         """
 972         while True:
 973             info = self.get_next_packet_info_for_interface(src_index, info)
 974             if info is None:
 975                 return None
 976             if info.dst == dst_index:
 977                 return info
 978
 979     def assert_equal(self, real_value, expected_value, name_or_class=None):
 980         if name_or_class is None:
 981             self.assertEqual(real_value, expected_value)
 982             return
 983         try:
 984             msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
 985             msg = msg % (getdoc(name_or_class).strip(),
 986                          real_value, str(name_or_class(real_value)),
 987                          expected_value, str(name_or_class(expected_value)))
 988         except Exception:
 989             msg = "Invalid %s: %s does not match expected value %s" % (
 990                 name_or_class, real_value, expected_value)
 991
 992         self.assertEqual(real_value, expected_value, msg)
 993
 994     def assert_in_range(self,
 995                         real_value,
 996                         expected_min,
 997                         expected_max,
 998                         name=None):
 999         if name is None:
1000             msg = None
1001         else:
1002             msg = "Invalid %s: %s out of range <%s,%s>" % (
1003                 name, real_value, expected_min, expected_max)
1004         self.assertTrue(expected_min <= real_value <= expected_max, msg)
1005
1006     def assert_packet_checksums_valid(self, packet,
1007                                       ignore_zero_udp_checksums=True):
1008         received = packet.__class__(scapy.compat.raw(packet))
1009         udp_layers = ['UDP', 'UDPerror']
1010         checksum_fields = ['cksum', 'chksum']
1011         checksums = []
1012         counter = 0
1013         temp = received.__class__(scapy.compat.raw(received))
1014         while True:
1015             layer = temp.getlayer(counter)
1016             if layer:
1017                 layer = layer.copy()
1018                 layer.remove_payload()
1019                 for cf in checksum_fields:
1020                     if hasattr(layer, cf):
1021                         if ignore_zero_udp_checksums and \
1022                                 0 == getattr(layer, cf) and \
1023                                 layer.name in udp_layers:
1024                             continue
1025                         delattr(temp.getlayer(counter), cf)
1026                         checksums.append((counter, cf))
1027             else:
1028                 break
1029             counter = counter + 1
1030         if 0 == len(checksums):
1031             return
1032         temp = temp.__class__(scapy.compat.raw(temp))
1033         for layer, cf in checksums:
1034             calc_sum = getattr(temp[layer], cf)
1035             self.assert_equal(
1036                 getattr(received[layer], cf), calc_sum,
1037                 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1038             self.logger.debug(
1039                 "Checksum field `%s` on `%s` layer has correct value `%s`" %
1040                 (cf, temp[layer].name, calc_sum))
1041
1042     def assert_checksum_valid(self, received_packet, layer,
1043                               field_name='chksum',
1044                               ignore_zero_checksum=False):
1045         """ Check checksum of received packet on given layer """
1046         received_packet_checksum = getattr(received_packet[layer], field_name)
1047         if ignore_zero_checksum and 0 == received_packet_checksum:
1048             return
1049         recalculated = received_packet.__class__(
1050             scapy.compat.raw(received_packet))
1051         delattr(recalculated[layer], field_name)
1052         recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1053         self.assert_equal(received_packet_checksum,
1054                           getattr(recalculated[layer], field_name),
1055                           "packet checksum on layer: %s" % layer)
1056
1057     def assert_ip_checksum_valid(self, received_packet,
1058                                  ignore_zero_checksum=False):
1059         self.assert_checksum_valid(received_packet, 'IP',
1060                                    ignore_zero_checksum=ignore_zero_checksum)
1061
1062     def assert_tcp_checksum_valid(self, received_packet,
1063                                   ignore_zero_checksum=False):
1064         self.assert_checksum_valid(received_packet, 'TCP',
1065                                    ignore_zero_checksum=ignore_zero_checksum)
1066
1067     def assert_udp_checksum_valid(self, received_packet,
1068                                   ignore_zero_checksum=True):
1069         self.assert_checksum_valid(received_packet, 'UDP',
1070                                    ignore_zero_checksum=ignore_zero_checksum)
1071
1072     def assert_embedded_icmp_checksum_valid(self, received_packet):
1073         if received_packet.haslayer(IPerror):
1074             self.assert_checksum_valid(received_packet, 'IPerror')
1075         if received_packet.haslayer(TCPerror):
1076             self.assert_checksum_valid(received_packet, 'TCPerror')
1077         if received_packet.haslayer(UDPerror):
1078             self.assert_checksum_valid(received_packet, 'UDPerror',
1079                                        ignore_zero_checksum=True)
1080         if received_packet.haslayer(ICMPerror):
1081             self.assert_checksum_valid(received_packet, 'ICMPerror')
1082
1083     def assert_icmp_checksum_valid(self, received_packet):
1084         self.assert_checksum_valid(received_packet, 'ICMP')
1085         self.assert_embedded_icmp_checksum_valid(received_packet)
1086
1087     def assert_icmpv6_checksum_valid(self, pkt):
1088         if pkt.haslayer(ICMPv6DestUnreach):
1089             self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1090             self.assert_embedded_icmp_checksum_valid(pkt)
1091         if pkt.haslayer(ICMPv6EchoRequest):
1092             self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1093         if pkt.haslayer(ICMPv6EchoReply):
1094             self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1095
1096     def get_packet_counter(self, counter):
1097         if counter.startswith("/"):
1098             counter_value = self.statistics.get_counter(counter)
1099         else:
1100             counters = self.vapi.cli("sh errors").split('\n')
1101             counter_value = 0
1102             for i in range(1, len(counters) - 1):
1103                 results = counters[i].split()
1104                 if results[1] == counter:
1105                     counter_value = int(results[0])
1106                     break
1107         return counter_value
1108
1109     def assert_packet_counter_equal(self, counter, expected_value):
1110         counter_value = self.get_packet_counter(counter)
1111         self.assert_equal(counter_value, expected_value,
1112                           "packet counter `%s'" % counter)
1113
1114     def assert_error_counter_equal(self, counter, expected_value):
1115         counter_value = self.statistics.get_err_counter(counter)
1116         self.assert_equal(counter_value, expected_value,
1117                           "error counter `%s'" % counter)
1118
1119     @classmethod
1120     def sleep(cls, timeout, remark=None):
1121
1122         # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1123         #  * by Guido, only the main thread can be interrupted.
1124         # */
1125         # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892  # noqa
1126         if timeout == 0:
1127             # yield quantum
1128             if hasattr(os, 'sched_yield'):
1129                 os.sched_yield()
1130             else:
1131                 time.sleep(0)
1132             return
1133
1134         if hasattr(cls, 'logger'):
1135             cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1136         before = time.time()
1137         time.sleep(timeout)
1138         after = time.time()
1139         if hasattr(cls, 'logger') and after - before > 2 * timeout:
1140             cls.logger.error("unexpected self.sleep() result - "
1141                              "slept for %es instead of ~%es!",
1142                              after - before, timeout)
1143         if hasattr(cls, 'logger'):
1144             cls.logger.debug(
1145                 "Finished sleep (%s) - slept %es (wanted %es)",
1146                 remark, after - before, timeout)
1147
1148     def pg_send(self, intf, pkts, worker=None):
1149         self.vapi.cli("clear trace")
1150         intf.add_stream(pkts, worker=worker)
1151         self.pg_enable_capture(self.pg_interfaces)
1152         self.pg_start()
1153
1154     def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1155         self.pg_send(intf, pkts)
1156         if not timeout:
1157             timeout = 1
1158         for i in self.pg_interfaces:
1159             i.get_capture(0, timeout=timeout)
1160             i.assert_nothing_captured(remark=remark)
1161             timeout = 0.1
1162
1163     def send_and_expect(self, intf, pkts, output, n_rx=None, worker=None):
1164         if not n_rx:
1165             n_rx = len(pkts)
1166         self.pg_send(intf, pkts, worker=worker)
1167         rx = output.get_capture(n_rx)
1168         return rx
1169
1170     def send_and_expect_only(self, intf, pkts, output, timeout=None):
1171         self.pg_send(intf, pkts)
1172         rx = output.get_capture(len(pkts))
1173         outputs = [output]
1174         if not timeout:
1175             timeout = 1
1176         for i in self.pg_interfaces:
1177             if i not in outputs:
1178                 i.get_capture(0, timeout=timeout)
1179                 i.assert_nothing_captured()
1180                 timeout = 0.1
1181
1182         return rx
1183
1184
1185 def get_testcase_doc_name(test):
1186     return getdoc(test.__class__).splitlines()[0]
1187
1188
1189 def get_test_description(descriptions, test):
1190     short_description = test.shortDescription()
1191     if descriptions and short_description:
1192         return short_description
1193     else:
1194         return str(test)
1195
1196
1197 class TestCaseInfo(object):
1198     def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1199         self.logger = logger
1200         self.tempdir = tempdir
1201         self.vpp_pid = vpp_pid
1202         self.vpp_bin_path = vpp_bin_path
1203         self.core_crash_test = None
1204
1205
1206 class VppTestResult(unittest.TestResult):
1207     """
1208     @property result_string
1209      String variable to store the test case result string.
1210     @property errors
1211      List variable containing 2-tuples of TestCase instances and strings
1212      holding formatted tracebacks. Each tuple represents a test which
1213      raised an unexpected exception.
1214     @property failures
1215      List variable containing 2-tuples of TestCase instances and strings
1216      holding formatted tracebacks. Each tuple represents a test where
1217      a failure was explicitly signalled using the TestCase.assert*()
1218      methods.
1219     """
1220
1221     failed_test_cases_info = set()
1222     core_crash_test_cases_info = set()
1223     current_test_case_info = None
1224
1225     def __init__(self, stream=None, descriptions=None, verbosity=None,
1226                  runner=None):
1227         """
1228         :param stream File descriptor to store where to report test results.
1229             Set to the standard error stream by default.
1230         :param descriptions Boolean variable to store information if to use
1231             test case descriptions.
1232         :param verbosity Integer variable to store required verbosity level.
1233         """
1234         super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1235         self.stream = stream
1236         self.descriptions = descriptions
1237         self.verbosity = verbosity
1238         self.result_string = None
1239         self.runner = runner
1240
1241     def addSuccess(self, test):
1242         """
1243         Record a test succeeded result
1244
1245         :param test:
1246
1247         """
1248         if self.current_test_case_info:
1249             self.current_test_case_info.logger.debug(
1250                 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1251                                                        test._testMethodName,
1252                                                        test._testMethodDoc))
1253         unittest.TestResult.addSuccess(self, test)
1254         self.result_string = colorize("OK", GREEN)
1255
1256         self.send_result_through_pipe(test, PASS)
1257
1258     def addSkip(self, test, reason):
1259         """
1260         Record a test skipped.
1261
1262         :param test:
1263         :param reason:
1264
1265         """
1266         if self.current_test_case_info:
1267             self.current_test_case_info.logger.debug(
1268                 "--- addSkip() %s.%s(%s) called, reason is %s" %
1269                 (test.__class__.__name__, test._testMethodName,
1270                  test._testMethodDoc, reason))
1271         unittest.TestResult.addSkip(self, test, reason)
1272         self.result_string = colorize("SKIP", YELLOW)
1273
1274         self.send_result_through_pipe(test, SKIP)
1275
1276     def symlink_failed(self):
1277         if self.current_test_case_info:
1278             try:
1279                 failed_dir = os.getenv('FAILED_DIR')
1280                 link_path = os.path.join(
1281                     failed_dir,
1282                     '%s-FAILED' %
1283                     os.path.basename(self.current_test_case_info.tempdir))
1284                 if self.current_test_case_info.logger:
1285                     self.current_test_case_info.logger.debug(
1286                         "creating a link to the failed test")
1287                     self.current_test_case_info.logger.debug(
1288                         "os.symlink(%s, %s)" %
1289                         (self.current_test_case_info.tempdir, link_path))
1290                 if os.path.exists(link_path):
1291                     if self.current_test_case_info.logger:
1292                         self.current_test_case_info.logger.debug(
1293                             'symlink already exists')
1294                 else:
1295                     os.symlink(self.current_test_case_info.tempdir, link_path)
1296
1297             except Exception as e:
1298                 if self.current_test_case_info.logger:
1299                     self.current_test_case_info.logger.error(e)
1300
1301     def send_result_through_pipe(self, test, result):
1302         if hasattr(self, 'test_framework_result_pipe'):
1303             pipe = self.test_framework_result_pipe
1304             if pipe:
1305                 pipe.send((test.id(), result))
1306
1307     def log_error(self, test, err, fn_name):
1308         if self.current_test_case_info:
1309             if isinstance(test, unittest.suite._ErrorHolder):
1310                 test_name = test.description
1311             else:
1312                 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1313                                            test._testMethodName,
1314                                            test._testMethodDoc)
1315             self.current_test_case_info.logger.debug(
1316                 "--- %s() %s called, err is %s" %
1317                 (fn_name, test_name, err))
1318             self.current_test_case_info.logger.debug(
1319                 "formatted exception is:\n%s" %
1320                 "".join(format_exception(*err)))
1321
1322     def add_error(self, test, err, unittest_fn, error_type):
1323         if error_type == FAIL:
1324             self.log_error(test, err, 'addFailure')
1325             error_type_str = colorize("FAIL", RED)
1326         elif error_type == ERROR:
1327             self.log_error(test, err, 'addError')
1328             error_type_str = colorize("ERROR", RED)
1329         else:
1330             raise Exception('Error type %s cannot be used to record an '
1331                             'error or a failure' % error_type)
1332
1333         unittest_fn(self, test, err)
1334         if self.current_test_case_info:
1335             self.result_string = "%s [ temp dir used by test case: %s ]" % \
1336                                  (error_type_str,
1337                                   self.current_test_case_info.tempdir)
1338             self.symlink_failed()
1339             self.failed_test_cases_info.add(self.current_test_case_info)
1340             if is_core_present(self.current_test_case_info.tempdir):
1341                 if not self.current_test_case_info.core_crash_test:
1342                     if isinstance(test, unittest.suite._ErrorHolder):
1343                         test_name = str(test)
1344                     else:
1345                         test_name = "'{!s}' ({!s})".format(
1346                             get_testcase_doc_name(test), test.id())
1347                     self.current_test_case_info.core_crash_test = test_name
1348                 self.core_crash_test_cases_info.add(
1349                     self.current_test_case_info)
1350         else:
1351             self.result_string = '%s [no temp dir]' % error_type_str
1352
1353         self.send_result_through_pipe(test, error_type)
1354
1355     def addFailure(self, test, err):
1356         """
1357         Record a test failed result
1358
1359         :param test:
1360         :param err: error message
1361
1362         """
1363         self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1364
1365     def addError(self, test, err):
1366         """
1367         Record a test error result
1368
1369         :param test:
1370         :param err: error message
1371
1372         """
1373         self.add_error(test, err, unittest.TestResult.addError, ERROR)
1374
1375     def getDescription(self, test):
1376         """
1377         Get test description
1378
1379         :param test:
1380         :returns: test description
1381
1382         """
1383         return get_test_description(self.descriptions, test)
1384
1385     def startTest(self, test):
1386         """
1387         Start a test
1388
1389         :param test:
1390
1391         """
1392
1393         def print_header(test):
1394             if not hasattr(test.__class__, '_header_printed'):
1395                 print(double_line_delim)
1396                 print(colorize(getdoc(test).splitlines()[0], GREEN))
1397                 print(double_line_delim)
1398             test.__class__._header_printed = True
1399
1400         print_header(test)
1401         self.start_test = time.time()
1402         unittest.TestResult.startTest(self, test)
1403         if self.verbosity > 0:
1404             self.stream.writeln(
1405                 "Starting " + self.getDescription(test) + " ...")
1406             self.stream.writeln(single_line_delim)
1407
1408     def stopTest(self, test):
1409         """
1410         Called when the given test has been run
1411
1412         :param test:
1413
1414         """
1415         unittest.TestResult.stopTest(self, test)
1416
1417         if self.verbosity > 0:
1418             self.stream.writeln(single_line_delim)
1419             self.stream.writeln("%-73s%s" % (self.getDescription(test),
1420                                              self.result_string))
1421             self.stream.writeln(single_line_delim)
1422         else:
1423             self.stream.writeln("%-68s %4.2f %s" %
1424                                 (self.getDescription(test),
1425                                  time.time() - self.start_test,
1426                                  self.result_string))
1427
1428         self.send_result_through_pipe(test, TEST_RUN)
1429
1430     def printErrors(self):
1431         """
1432         Print errors from running the test case
1433         """
1434         if len(self.errors) > 0 or len(self.failures) > 0:
1435             self.stream.writeln()
1436             self.printErrorList('ERROR', self.errors)
1437             self.printErrorList('FAIL', self.failures)
1438
1439         # ^^ that is the last output from unittest before summary
1440         if not self.runner.print_summary:
1441             devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1442             self.stream = devnull
1443             self.runner.stream = devnull
1444
1445     def printErrorList(self, flavour, errors):
1446         """
1447         Print error list to the output stream together with error type
1448         and test case description.
1449
1450         :param flavour: error type
1451         :param errors: iterable errors
1452
1453         """
1454         for test, err in errors:
1455             self.stream.writeln(double_line_delim)
1456             self.stream.writeln("%s: %s" %
1457                                 (flavour, self.getDescription(test)))
1458             self.stream.writeln(single_line_delim)
1459             self.stream.writeln("%s" % err)
1460
1461
1462 class VppTestRunner(unittest.TextTestRunner):
1463     """
1464     A basic test runner implementation which prints results to standard error.
1465     """
1466
1467     @property
1468     def resultclass(self):
1469         """Class maintaining the results of the tests"""
1470         return VppTestResult
1471
1472     def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1473                  result_pipe=None, failfast=False, buffer=False,
1474                  resultclass=None, print_summary=True, **kwargs):
1475         # ignore stream setting here, use hard-coded stdout to be in sync
1476         # with prints from VppTestCase methods ...
1477         super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1478                                             verbosity, failfast, buffer,
1479                                             resultclass, **kwargs)
1480         KeepAliveReporter.pipe = keep_alive_pipe
1481
1482         self.orig_stream = self.stream
1483         self.resultclass.test_framework_result_pipe = result_pipe
1484
1485         self.print_summary = print_summary
1486
1487     def _makeResult(self):
1488         return self.resultclass(self.stream,
1489                                 self.descriptions,
1490                                 self.verbosity,
1491                                 self)
1492
1493     def run(self, test):
1494         """
1495         Run the tests
1496
1497         :param test:
1498
1499         """
1500         faulthandler.enable()  # emit stack trace to stderr if killed by signal
1501
1502         result = super(VppTestRunner, self).run(test)
1503         if not self.print_summary:
1504             self.stream = self.orig_stream
1505             result.stream = self.orig_stream
1506         return result
1507
1508
1509 class Worker(Thread):
1510     def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1511         super(Worker, self).__init__(*args, **kwargs)
1512         self.logger = logger
1513         self.args = executable_args
1514         if hasattr(self, 'testcase') and self.testcase.debug_all:
1515             if self.testcase.debug_gdbserver:
1516                 self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1517                              .format(port=self.testcase.gdbserver_port)] + args
1518             elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1519                 self.args.append(self.wait_for_gdb)
1520         self.app_bin = executable_args[0]
1521         self.app_name = os.path.basename(self.app_bin)
1522         if hasattr(self, 'role'):
1523             self.app_name += ' {role}'.format(role=self.role)
1524         self.process = None
1525         self.result = None
1526         env = {} if env is None else env
1527         self.env = copy.deepcopy(env)
1528
1529     def wait_for_enter(self):
1530         if not hasattr(self, 'testcase'):
1531             return
1532         if self.testcase.debug_all and self.testcase.debug_gdbserver:
1533             print()
1534             print(double_line_delim)
1535             print("Spawned GDB Server for '{app}' with PID: {pid}"
1536                   .format(app=self.app_name, pid=self.process.pid))
1537         elif self.testcase.debug_all and self.testcase.debug_gdb:
1538             print()
1539             print(double_line_delim)
1540             print("Spawned '{app}' with PID: {pid}"
1541                   .format(app=self.app_name, pid=self.process.pid))
1542         else:
1543             return
1544         print(single_line_delim)
1545         print("You can debug '{app}' using:".format(app=self.app_name))
1546         if self.testcase.debug_gdbserver:
1547             print("sudo gdb " + self.app_bin +
1548                   " -ex 'target remote localhost:{port}'"
1549                   .format(port=self.testcase.gdbserver_port))
1550             print("Now is the time to attach gdb by running the above "
1551                   "command, set up breakpoints etc., then resume from "
1552                   "within gdb by issuing the 'continue' command")
1553             self.testcase.gdbserver_port += 1
1554         elif self.testcase.debug_gdb:
1555             print("sudo gdb " + self.app_bin +
1556                   " -ex 'attach {pid}'".format(pid=self.process.pid))
1557             print("Now is the time to attach gdb by running the above "
1558                   "command and set up breakpoints etc., then resume from"
1559                   " within gdb by issuing the 'continue' command")
1560         print(single_line_delim)
1561         input("Press ENTER to continue running the testcase...")
1562
1563     def run(self):
1564         executable = self.args[0]
1565         if not os.path.exists(executable) or not os.access(
1566                 executable, os.F_OK | os.X_OK):
1567             # Exit code that means some system file did not exist,
1568             # could not be opened, or had some other kind of error.
1569             self.result = os.EX_OSFILE
1570             raise EnvironmentError(
1571                 "executable '%s' is not found or executable." % executable)
1572         self.logger.debug("Running executable: '{app}'"
1573                           .format(app=' '.join(self.args)))
1574         env = os.environ.copy()
1575         env.update(self.env)
1576         env["CK_LOG_FILE_NAME"] = "-"
1577         self.process = subprocess.Popen(
1578             self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1579             stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1580         self.wait_for_enter()
1581         out, err = self.process.communicate()
1582         self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1583         self.logger.info("Return code is `%s'" % self.process.returncode)
1584         self.logger.info(single_line_delim)
1585         self.logger.info("Executable `{app}' wrote to stdout:"
1586                          .format(app=self.app_name))
1587         self.logger.info(single_line_delim)
1588         self.logger.info(out.decode('utf-8'))
1589         self.logger.info(single_line_delim)
1590         self.logger.info("Executable `{app}' wrote to stderr:"
1591                          .format(app=self.app_name))
1592         self.logger.info(single_line_delim)
1593         self.logger.info(err.decode('utf-8'))
1594         self.logger.info(single_line_delim)
1595         self.result = self.process.returncode
1596
1597
1598 if __name__ == '__main__':
1599     pass