test/framework.py

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