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
  27 import scapy.compat
  28 from scapy.packet import Raw
  29 import hook as hookmodule
  30 from vpp_pg_interface import VppPGInterface
  31 from vpp_sub_interface import VppSubInterface
  32 from vpp_lo_interface import VppLoInterface
  33 from vpp_bvi_interface import VppBviInterface
  34 from vpp_papi_provider import VppPapiProvider
  35 from vpp_papi import VppEnum
  36 import vpp_papi
  37 from vpp_papi.vpp_stats import VPPStats
  38 from vpp_papi.vpp_transport_socket import VppTransportSocketIOError
  39 from log import RED, GREEN, YELLOW, double_line_delim, single_line_delim, \
  40     get_logger, colorize
  41 from vpp_object import VppObjectRegistry
  42 from util import ppp, is_core_present
  43 from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
  44 from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
  45 from scapy.layers.inet6 import ICMPv6EchoReply
  46
  47 from cpu_config import available_cpus, num_cpus, max_vpp_cpus
  48
  49 logger = logging.getLogger(__name__)
  50
  51 # Set up an empty logger for the testcase that can be overridden as necessary
  52 null_logger = logging.getLogger('VppTestCase')
  53 null_logger.addHandler(logging.NullHandler())
  54
  55 PASS = 0
  56 FAIL = 1
  57 ERROR = 2
  58 SKIP = 3
  59 TEST_RUN = 4
  60 SKIP_CPU_SHORTAGE = 5
  61
  62
  63 class BoolEnvironmentVariable(object):
  64
  65     def __init__(self, env_var_name, default='n', true_values=None):
  66         self.name = env_var_name
  67         self.default = default
  68         self.true_values = true_values if true_values is not None else \
  69             ("y", "yes", "1")
  70
  71     def __bool__(self):
  72         return os.getenv(self.name, self.default).lower() in self.true_values
  73
  74     if sys.version_info[0] == 2:
  75         __nonzero__ = __bool__
  76
  77     def __repr__(self):
  78         return 'BoolEnvironmentVariable(%r, default=%r, true_values=%r)' % \
  79                (self.name, self.default, self.true_values)
  80
  81
  82 debug_framework = BoolEnvironmentVariable('TEST_DEBUG')
  83 if debug_framework:
  84     import debug_internal
  85
  86 """
  87   Test framework module.
  88
  89   The module provides a set of tools for constructing and running tests and
  90   representing the results.
  91 """
  92
  93
  94 class VppDiedError(Exception):
  95     """ exception for reporting that the subprocess has died."""
  96
  97     signals_by_value = {v: k for k, v in signal.__dict__.items() if
  98                         k.startswith('SIG') and not k.startswith('SIG_')}
  99
 100     def __init__(self, rv=None, testcase=None, method_name=None):
 101         self.rv = rv
 102         self.signal_name = None
 103         self.testcase = testcase
 104         self.method_name = method_name
 105
 106         try:
 107             self.signal_name = VppDiedError.signals_by_value[-rv]
 108         except (KeyError, TypeError):
 109             pass
 110
 111         if testcase is None and method_name is None:
 112             in_msg = ''
 113         else:
 114             in_msg = ' while running %s.%s' % (testcase, method_name)
 115
 116         if self.rv:
 117             msg = "VPP subprocess died unexpectedly%s with return code: %d%s."\
 118                 % (in_msg, self.rv, ' [%s]' %
 119                    (self.signal_name if
 120                     self.signal_name is not None else ''))
 121         else:
 122             msg = "VPP subprocess died unexpectedly%s." % in_msg
 123
 124         super(VppDiedError, self).__init__(msg)
 125
 126
 127 class _PacketInfo(object):
 128     """Private class to create packet info object.
 129
 130     Help process information about the next packet.
 131     Set variables to default values.
 132     """
 133     #: Store the index of the packet.
 134     index = -1
 135     #: Store the index of the source packet generator interface of the packet.
 136     src = -1
 137     #: Store the index of the destination packet generator interface
 138     #: of the packet.
 139     dst = -1
 140     #: Store expected ip version
 141     ip = -1
 142     #: Store expected upper protocol
 143     proto = -1
 144     #: Store the copy of the former packet.
 145     data = None
 146
 147     def __eq__(self, other):
 148         index = self.index == other.index
 149         src = self.src == other.src
 150         dst = self.dst == other.dst
 151         data = self.data == other.data
 152         return index and src and dst and data
 153
 154
 155 def pump_output(testclass):
 156     """ pump output from vpp stdout/stderr to proper queues """
 157     stdout_fragment = ""
 158     stderr_fragment = ""
 159     while not testclass.pump_thread_stop_flag.is_set():
 160         readable = select.select([testclass.vpp.stdout.fileno(),
 161                                   testclass.vpp.stderr.fileno(),
 162                                   testclass.pump_thread_wakeup_pipe[0]],
 163                                  [], [])[0]
 164         if testclass.vpp.stdout.fileno() in readable:
 165             read = os.read(testclass.vpp.stdout.fileno(), 102400)
 166             if len(read) > 0:
 167                 split = read.decode('ascii',
 168                                     errors='backslashreplace').splitlines(True)
 169                 if len(stdout_fragment) > 0:
 170                     split[0] = "%s%s" % (stdout_fragment, split[0])
 171                 if len(split) > 0 and split[-1].endswith("\n"):
 172                     limit = None
 173                 else:
 174                     limit = -1
 175                     stdout_fragment = split[-1]
 176                 testclass.vpp_stdout_deque.extend(split[:limit])
 177                 if not testclass.cache_vpp_output:
 178                     for line in split[:limit]:
 179                         testclass.logger.info(
 180                             "VPP STDOUT: %s" % line.rstrip("\n"))
 181         if testclass.vpp.stderr.fileno() in readable:
 182             read = os.read(testclass.vpp.stderr.fileno(), 102400)
 183             if len(read) > 0:
 184                 split = read.decode('ascii',
 185                                     errors='backslashreplace').splitlines(True)
 186                 if len(stderr_fragment) > 0:
 187                     split[0] = "%s%s" % (stderr_fragment, split[0])
 188                 if len(split) > 0 and split[-1].endswith("\n"):
 189                     limit = None
 190                 else:
 191                     limit = -1
 192                     stderr_fragment = split[-1]
 193
 194                 testclass.vpp_stderr_deque.extend(split[:limit])
 195                 if not testclass.cache_vpp_output:
 196                     for line in split[:limit]:
 197                         testclass.logger.error(
 198                             "VPP STDERR: %s" % line.rstrip("\n"))
 199                         # ignoring the dummy pipe here intentionally - the
 200                         # flag will take care of properly terminating the loop
 201
 202
 203 def _is_skip_aarch64_set():
 204     return BoolEnvironmentVariable('SKIP_AARCH64')
 205
 206
 207 is_skip_aarch64_set = _is_skip_aarch64_set()
 208
 209
 210 def _is_platform_aarch64():
 211     return platform.machine() == 'aarch64'
 212
 213
 214 is_platform_aarch64 = _is_platform_aarch64()
 215
 216
 217 def _running_extended_tests():
 218     return BoolEnvironmentVariable("EXTENDED_TESTS")
 219
 220
 221 running_extended_tests = _running_extended_tests()
 222
 223
 224 def _running_gcov_tests():
 225     return BoolEnvironmentVariable("GCOV_TESTS")
 226
 227
 228 running_gcov_tests = _running_gcov_tests()
 229
 230
 231 def get_environ_vpp_worker_count():
 232     worker_config = os.getenv("VPP_WORKER_CONFIG", None)
 233     if worker_config:
 234         elems = worker_config.split(" ")
 235         if elems[0] != "workers" or len(elems) != 2:
 236             raise ValueError("Wrong VPP_WORKER_CONFIG == '%s' value." %
 237                              worker_config)
 238         return int(elems[1])
 239     else:
 240         return 0
 241
 242
 243 environ_vpp_worker_count = get_environ_vpp_worker_count()
 244
 245
 246 class KeepAliveReporter(object):
 247     """
 248     Singleton object which reports test start to parent process
 249     """
 250     _shared_state = {}
 251
 252     def __init__(self):
 253         self.__dict__ = self._shared_state
 254         self._pipe = None
 255
 256     @property
 257     def pipe(self):
 258         return self._pipe
 259
 260     @pipe.setter
 261     def pipe(self, pipe):
 262         if self._pipe is not None:
 263             raise Exception("Internal error - pipe should only be set once.")
 264         self._pipe = pipe
 265
 266     def send_keep_alive(self, test, desc=None):
 267         """
 268         Write current test tmpdir & desc to keep-alive pipe to signal liveness
 269         """
 270         if self.pipe is None:
 271             # if not running forked..
 272             return
 273
 274         if isclass(test):
 275             desc = '%s (%s)' % (desc, unittest.util.strclass(test))
 276         else:
 277             desc = test.id()
 278
 279         self.pipe.send((desc, test.vpp_bin, test.tempdir, test.vpp.pid))
 280
 281
 282 class TestCaseTag(Enum):
 283     # marks the suites that must run at the end
 284     # using only a single test runner
 285     RUN_SOLO = 1
 286     # marks the suites broken on VPP multi-worker
 287     FIXME_VPP_WORKERS = 2
 288
 289
 290 def create_tag_decorator(e):
 291     def decorator(cls):
 292         try:
 293             cls.test_tags.append(e)
 294         except AttributeError:
 295             cls.test_tags = [e]
 296         return cls
 297     return decorator
 298
 299
 300 tag_run_solo = create_tag_decorator(TestCaseTag.RUN_SOLO)
 301 tag_fixme_vpp_workers = create_tag_decorator(TestCaseTag.FIXME_VPP_WORKERS)
 302
 303
 304 class DummyVpp:
 305     returncode = None
 306     pid = 0xcafebafe
 307
 308     def poll(self):
 309         pass
 310
 311     def terminate(self):
 312         pass
 313
 314
 315 class CPUInterface(ABC):
 316     cpus = []
 317     skipped_due_to_cpu_lack = False
 318
 319     @classmethod
 320     @abstractmethod
 321     def get_cpus_required(cls):
 322         pass
 323
 324     @classmethod
 325     def assign_cpus(cls, cpus):
 326         cls.cpus = cpus
 327
 328
 329 class VppTestCase(CPUInterface, unittest.TestCase):
 330     """This subclass is a base class for VPP test cases that are implemented as
 331     classes. It provides methods to create and run test case.
 332     """
 333
 334     extra_vpp_statseg_config = ""
 335     extra_vpp_punt_config = []
 336     extra_vpp_plugin_config = []
 337     logger = null_logger
 338     vapi_response_timeout = 5
 339
 340     @property
 341     def packet_infos(self):
 342         """List of packet infos"""
 343         return self._packet_infos
 344
 345     @classmethod
 346     def get_packet_count_for_if_idx(cls, dst_if_index):
 347         """Get the number of packet info for specified destination if index"""
 348         if dst_if_index in cls._packet_count_for_dst_if_idx:
 349             return cls._packet_count_for_dst_if_idx[dst_if_index]
 350         else:
 351             return 0
 352
 353     @classmethod
 354     def has_tag(cls, tag):
 355         """ if the test case has a given tag - return true """
 356         try:
 357             return tag in cls.test_tags
 358         except AttributeError:
 359             pass
 360         return False
 361
 362     @classmethod
 363     def is_tagged_run_solo(cls):
 364         """ if the test case class is timing-sensitive - return true """
 365         return cls.has_tag(TestCaseTag.RUN_SOLO)
 366
 367     @classmethod
 368     def instance(cls):
 369         """Return the instance of this testcase"""
 370         return cls.test_instance
 371
 372     @classmethod
 373     def set_debug_flags(cls, d):
 374         cls.gdbserver_port = 7777
 375         cls.debug_core = False
 376         cls.debug_gdb = False
 377         cls.debug_gdbserver = False
 378         cls.debug_all = False
 379         cls.debug_attach = False
 380         if d is None:
 381             return
 382         dl = d.lower()
 383         if dl == "core":
 384             cls.debug_core = True
 385         elif dl == "gdb" or dl == "gdb-all":
 386             cls.debug_gdb = True
 387         elif dl == "gdbserver" or dl == "gdbserver-all":
 388             cls.debug_gdbserver = True
 389         elif dl == "attach":
 390             cls.debug_attach = True
 391         else:
 392             raise Exception("Unrecognized DEBUG option: '%s'" % d)
 393         if dl == "gdb-all" or dl == "gdbserver-all":
 394             cls.debug_all = True
 395
 396     @classmethod
 397     def get_vpp_worker_count(cls):
 398         if not hasattr(cls, "vpp_worker_count"):
 399             if cls.has_tag(TestCaseTag.FIXME_VPP_WORKERS):
 400                 cls.vpp_worker_count = 0
 401             else:
 402                 cls.vpp_worker_count = environ_vpp_worker_count
 403         return cls.vpp_worker_count
 404
 405     @classmethod
 406     def get_cpus_required(cls):
 407         return 1 + cls.get_vpp_worker_count()
 408
 409     @classmethod
 410     def setUpConstants(cls):
 411         """ Set-up the test case class based on environment variables """
 412         cls.step = BoolEnvironmentVariable('STEP')
 413         # inverted case to handle '' == True
 414         c = os.getenv("CACHE_OUTPUT", "1")
 415         cls.cache_vpp_output = False if c.lower() in ("n", "no", "0") else True
 416         cls.vpp_bin = os.getenv('VPP_BIN', "vpp")
 417         cls.plugin_path = os.getenv('VPP_PLUGIN_PATH')
 418         cls.test_plugin_path = os.getenv('VPP_TEST_PLUGIN_PATH')
 419         cls.extern_plugin_path = os.getenv('EXTERN_PLUGINS')
 420         plugin_path = None
 421         if cls.plugin_path is not None:
 422             if cls.extern_plugin_path is not None:
 423                 plugin_path = "%s:%s" % (
 424                     cls.plugin_path, cls.extern_plugin_path)
 425             else:
 426                 plugin_path = cls.plugin_path
 427         elif cls.extern_plugin_path is not None:
 428             plugin_path = cls.extern_plugin_path
 429         debug_cli = ""
 430         if cls.step or cls.debug_gdb or cls.debug_gdbserver:
 431             debug_cli = "cli-listen localhost:5002"
 432         coredump_size = None
 433         size = os.getenv("COREDUMP_SIZE")
 434         if size is not None:
 435             coredump_size = "coredump-size %s" % size
 436         if coredump_size is None:
 437             coredump_size = "coredump-size unlimited"
 438
 439         default_variant = os.getenv("VARIANT")
 440         if default_variant is not None:
 441             default_variant = "defaults { %s 100 }" % default_variant
 442         else:
 443             default_variant = ""
 444
 445         api_fuzzing = os.getenv("API_FUZZ")
 446         if api_fuzzing is None:
 447             api_fuzzing = 'off'
 448
 449         cls.vpp_cmdline = [
 450             cls.vpp_bin,
 451             "unix", "{", "nodaemon", debug_cli, "full-coredump",
 452             coredump_size, "runtime-dir", cls.tempdir, "}",
 453             "api-trace", "{", "on", "}",
 454             "api-segment", "{", "prefix", cls.get_api_segment_prefix(), "}",
 455             "cpu", "{", "main-core", str(cls.cpus[0]), ]
 456         if cls.get_vpp_worker_count():
 457             cls.vpp_cmdline.extend([
 458                 "corelist-workers", ",".join([str(x) for x in cls.cpus[1:]])])
 459         cls.vpp_cmdline.extend([
 460             "}",
 461             "physmem", "{", "max-size", "32m", "}",
 462             "statseg", "{", "socket-name", cls.get_stats_sock_path(),
 463             cls.extra_vpp_statseg_config, "}",
 464             "socksvr", "{", "socket-name", cls.get_api_sock_path(), "}",
 465             "node { ", default_variant, "}",
 466             "api-fuzz {", api_fuzzing, "}",
 467             "plugins", "{", "plugin", "dpdk_plugin.so", "{", "disable", "}",
 468             "plugin", "rdma_plugin.so", "{", "disable", "}",
 469             "plugin", "lisp_unittest_plugin.so", "{", "enable", "}",
 470             "plugin", "unittest_plugin.so", "{", "enable", "}"
 471         ] + cls.extra_vpp_plugin_config + ["}", ])
 472
 473         if cls.extra_vpp_punt_config is not None:
 474             cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
 475         if plugin_path is not None:
 476             cls.vpp_cmdline.extend(["plugin_path", plugin_path])
 477         if cls.test_plugin_path is not None:
 478             cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
 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         return "%d %d %d %d %d" % (info.index, info.src, info.dst,
1046                                    info.ip, info.proto)
1047
1048     @staticmethod
1049     def payload_to_info(payload, payload_field='load'):
1050         """
1051         Convert packet payload to _PacketInfo object
1052
1053         :param payload: packet payload
1054         :type payload:  <class 'scapy.packet.Raw'>
1055         :param payload_field: packet fieldname of payload "load" for
1056                 <class 'scapy.packet.Raw'>
1057         :type payload_field: str
1058         :returns: _PacketInfo object containing de-serialized data from payload
1059
1060         """
1061         numbers = getattr(payload, payload_field).split()
1062         info = _PacketInfo()
1063         info.index = int(numbers[0])
1064         info.src = int(numbers[1])
1065         info.dst = int(numbers[2])
1066         info.ip = int(numbers[3])
1067         info.proto = int(numbers[4])
1068         return info
1069
1070     def get_next_packet_info(self, info):
1071         """
1072         Iterate over the packet info list stored in the testcase
1073         Start iteration with first element if info is None
1074         Continue based on index in info if info is specified
1075
1076         :param info: info or None
1077         :returns: next info in list or None if no more infos
1078         """
1079         if info is None:
1080             next_index = 0
1081         else:
1082             next_index = info.index + 1
1083         if next_index == len(self._packet_infos):
1084             return None
1085         else:
1086             return self._packet_infos[next_index]
1087
1088     def get_next_packet_info_for_interface(self, src_index, info):
1089         """
1090         Search the packet info list for the next packet info with same source
1091         interface index
1092
1093         :param src_index: source interface index to search for
1094         :param info: packet info - where to start the search
1095         :returns: packet info or None
1096
1097         """
1098         while True:
1099             info = self.get_next_packet_info(info)
1100             if info is None:
1101                 return None
1102             if info.src == src_index:
1103                 return info
1104
1105     def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
1106         """
1107         Search the packet info list for the next packet info with same source
1108         and destination interface indexes
1109
1110         :param src_index: source interface index to search for
1111         :param dst_index: destination interface index to search for
1112         :param info: packet info - where to start the search
1113         :returns: packet info or None
1114
1115         """
1116         while True:
1117             info = self.get_next_packet_info_for_interface(src_index, info)
1118             if info is None:
1119                 return None
1120             if info.dst == dst_index:
1121                 return info
1122
1123     def assert_equal(self, real_value, expected_value, name_or_class=None):
1124         if name_or_class is None:
1125             self.assertEqual(real_value, expected_value)
1126             return
1127         try:
1128             msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
1129             msg = msg % (getdoc(name_or_class).strip(),
1130                          real_value, str(name_or_class(real_value)),
1131                          expected_value, str(name_or_class(expected_value)))
1132         except Exception:
1133             msg = "Invalid %s: %s does not match expected value %s" % (
1134                 name_or_class, real_value, expected_value)
1135
1136         self.assertEqual(real_value, expected_value, msg)
1137
1138     def assert_in_range(self,
1139                         real_value,
1140                         expected_min,
1141                         expected_max,
1142                         name=None):
1143         if name is None:
1144             msg = None
1145         else:
1146             msg = "Invalid %s: %s out of range <%s,%s>" % (
1147                 name, real_value, expected_min, expected_max)
1148         self.assertTrue(expected_min <= real_value <= expected_max, msg)
1149
1150     def assert_packet_checksums_valid(self, packet,
1151                                       ignore_zero_udp_checksums=True):
1152         received = packet.__class__(scapy.compat.raw(packet))
1153         udp_layers = ['UDP', 'UDPerror']
1154         checksum_fields = ['cksum', 'chksum']
1155         checksums = []
1156         counter = 0
1157         temp = received.__class__(scapy.compat.raw(received))
1158         while True:
1159             layer = temp.getlayer(counter)
1160             if layer:
1161                 layer = layer.copy()
1162                 layer.remove_payload()
1163                 for cf in checksum_fields:
1164                     if hasattr(layer, cf):
1165                         if ignore_zero_udp_checksums and \
1166                                 0 == getattr(layer, cf) and \
1167                                 layer.name in udp_layers:
1168                             continue
1169                         delattr(temp.getlayer(counter), cf)
1170                         checksums.append((counter, cf))
1171             else:
1172                 break
1173             counter = counter + 1
1174         if 0 == len(checksums):
1175             return
1176         temp = temp.__class__(scapy.compat.raw(temp))
1177         for layer, cf in checksums:
1178             calc_sum = getattr(temp[layer], cf)
1179             self.assert_equal(
1180                 getattr(received[layer], cf), calc_sum,
1181                 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1182             self.logger.debug(
1183                 "Checksum field `%s` on `%s` layer has correct value `%s`" %
1184                 (cf, temp[layer].name, calc_sum))
1185
1186     def assert_checksum_valid(self, received_packet, layer,
1187                               field_name='chksum',
1188                               ignore_zero_checksum=False):
1189         """ Check checksum of received packet on given layer """
1190         received_packet_checksum = getattr(received_packet[layer], field_name)
1191         if ignore_zero_checksum and 0 == received_packet_checksum:
1192             return
1193         recalculated = received_packet.__class__(
1194             scapy.compat.raw(received_packet))
1195         delattr(recalculated[layer], field_name)
1196         recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1197         self.assert_equal(received_packet_checksum,
1198                           getattr(recalculated[layer], field_name),
1199                           "packet checksum on layer: %s" % layer)
1200
1201     def assert_ip_checksum_valid(self, received_packet,
1202                                  ignore_zero_checksum=False):
1203         self.assert_checksum_valid(received_packet, 'IP',
1204                                    ignore_zero_checksum=ignore_zero_checksum)
1205
1206     def assert_tcp_checksum_valid(self, received_packet,
1207                                   ignore_zero_checksum=False):
1208         self.assert_checksum_valid(received_packet, 'TCP',
1209                                    ignore_zero_checksum=ignore_zero_checksum)
1210
1211     def assert_udp_checksum_valid(self, received_packet,
1212                                   ignore_zero_checksum=True):
1213         self.assert_checksum_valid(received_packet, 'UDP',
1214                                    ignore_zero_checksum=ignore_zero_checksum)
1215
1216     def assert_embedded_icmp_checksum_valid(self, received_packet):
1217         if received_packet.haslayer(IPerror):
1218             self.assert_checksum_valid(received_packet, 'IPerror')
1219         if received_packet.haslayer(TCPerror):
1220             self.assert_checksum_valid(received_packet, 'TCPerror')
1221         if received_packet.haslayer(UDPerror):
1222             self.assert_checksum_valid(received_packet, 'UDPerror',
1223                                        ignore_zero_checksum=True)
1224         if received_packet.haslayer(ICMPerror):
1225             self.assert_checksum_valid(received_packet, 'ICMPerror')
1226
1227     def assert_icmp_checksum_valid(self, received_packet):
1228         self.assert_checksum_valid(received_packet, 'ICMP')
1229         self.assert_embedded_icmp_checksum_valid(received_packet)
1230
1231     def assert_icmpv6_checksum_valid(self, pkt):
1232         if pkt.haslayer(ICMPv6DestUnreach):
1233             self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1234             self.assert_embedded_icmp_checksum_valid(pkt)
1235         if pkt.haslayer(ICMPv6EchoRequest):
1236             self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1237         if pkt.haslayer(ICMPv6EchoReply):
1238             self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1239
1240     def get_packet_counter(self, counter):
1241         if counter.startswith("/"):
1242             counter_value = self.statistics.get_counter(counter)
1243         else:
1244             counters = self.vapi.cli("sh errors").split('\n')
1245             counter_value = 0
1246             for i in range(1, len(counters) - 1):
1247                 results = counters[i].split()
1248                 if results[1] == counter:
1249                     counter_value = int(results[0])
1250                     break
1251         return counter_value
1252
1253     def assert_packet_counter_equal(self, counter, expected_value):
1254         counter_value = self.get_packet_counter(counter)
1255         self.assert_equal(counter_value, expected_value,
1256                           "packet counter `%s'" % counter)
1257
1258     def assert_error_counter_equal(self, counter, expected_value):
1259         counter_value = self.statistics[counter].sum()
1260         self.assert_equal(counter_value, expected_value,
1261                           "error counter `%s'" % counter)
1262
1263     @classmethod
1264     def sleep(cls, timeout, remark=None):
1265
1266         # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1267         #  * by Guido, only the main thread can be interrupted.
1268         # */
1269         # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892  # noqa
1270         if timeout == 0:
1271             # yield quantum
1272             if hasattr(os, 'sched_yield'):
1273                 os.sched_yield()
1274             else:
1275                 time.sleep(0)
1276             return
1277
1278         cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1279         before = time.time()
1280         time.sleep(timeout)
1281         after = time.time()
1282         if after - before > 2 * timeout:
1283             cls.logger.error("unexpected self.sleep() result - "
1284                              "slept for %es instead of ~%es!",
1285                              after - before, timeout)
1286
1287         cls.logger.debug(
1288             "Finished sleep (%s) - slept %es (wanted %es)",
1289             remark, after - before, timeout)
1290
1291     def pg_send(self, intf, pkts, worker=None, trace=True):
1292         intf.add_stream(pkts, worker=worker)
1293         self.pg_enable_capture(self.pg_interfaces)
1294         self.pg_start(trace=trace)
1295
1296     def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1297         self.pg_send(intf, pkts)
1298         if not timeout:
1299             timeout = 1
1300         for i in self.pg_interfaces:
1301             i.get_capture(0, timeout=timeout)
1302             i.assert_nothing_captured(remark=remark)
1303             timeout = 0.1
1304
1305     def send_and_expect(self, intf, pkts, output, n_rx=None, worker=None,
1306                         trace=True):
1307         if not n_rx:
1308             n_rx = len(pkts)
1309         self.pg_send(intf, pkts, worker=worker, trace=trace)
1310         rx = output.get_capture(n_rx)
1311         return rx
1312
1313     def send_and_expect_only(self, intf, pkts, output, timeout=None):
1314         self.pg_send(intf, pkts)
1315         rx = output.get_capture(len(pkts))
1316         outputs = [output]
1317         if not timeout:
1318             timeout = 1
1319         for i in self.pg_interfaces:
1320             if i not in outputs:
1321                 i.get_capture(0, timeout=timeout)
1322                 i.assert_nothing_captured()
1323                 timeout = 0.1
1324
1325         return rx
1326
1327
1328 def get_testcase_doc_name(test):
1329     return getdoc(test.__class__).splitlines()[0]
1330
1331
1332 def get_test_description(descriptions, test):
1333     short_description = test.shortDescription()
1334     if descriptions and short_description:
1335         return short_description
1336     else:
1337         return str(test)
1338
1339
1340 class TestCaseInfo(object):
1341     def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1342         self.logger = logger
1343         self.tempdir = tempdir
1344         self.vpp_pid = vpp_pid
1345         self.vpp_bin_path = vpp_bin_path
1346         self.core_crash_test = None
1347
1348
1349 class VppTestResult(unittest.TestResult):
1350     """
1351     @property result_string
1352      String variable to store the test case result string.
1353     @property errors
1354      List variable containing 2-tuples of TestCase instances and strings
1355      holding formatted tracebacks. Each tuple represents a test which
1356      raised an unexpected exception.
1357     @property failures
1358      List variable containing 2-tuples of TestCase instances and strings
1359      holding formatted tracebacks. Each tuple represents a test where
1360      a failure was explicitly signalled using the TestCase.assert*()
1361      methods.
1362     """
1363
1364     failed_test_cases_info = set()
1365     core_crash_test_cases_info = set()
1366     current_test_case_info = None
1367
1368     def __init__(self, stream=None, descriptions=None, verbosity=None,
1369                  runner=None):
1370         """
1371         :param stream File descriptor to store where to report test results.
1372             Set to the standard error stream by default.
1373         :param descriptions Boolean variable to store information if to use
1374             test case descriptions.
1375         :param verbosity Integer variable to store required verbosity level.
1376         """
1377         super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1378         self.stream = stream
1379         self.descriptions = descriptions
1380         self.verbosity = verbosity
1381         self.result_string = None
1382         self.runner = runner
1383         self.printed = []
1384
1385     def addSuccess(self, test):
1386         """
1387         Record a test succeeded result
1388
1389         :param test:
1390
1391         """
1392         if self.current_test_case_info:
1393             self.current_test_case_info.logger.debug(
1394                 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1395                                                        test._testMethodName,
1396                                                        test._testMethodDoc))
1397         unittest.TestResult.addSuccess(self, test)
1398         self.result_string = colorize("OK", GREEN)
1399
1400         self.send_result_through_pipe(test, PASS)
1401
1402     def addSkip(self, test, reason):
1403         """
1404         Record a test skipped.
1405
1406         :param test:
1407         :param reason:
1408
1409         """
1410         if self.current_test_case_info:
1411             self.current_test_case_info.logger.debug(
1412                 "--- addSkip() %s.%s(%s) called, reason is %s" %
1413                 (test.__class__.__name__, test._testMethodName,
1414                  test._testMethodDoc, reason))
1415         unittest.TestResult.addSkip(self, test, reason)
1416         self.result_string = colorize("SKIP", YELLOW)
1417
1418         if reason == "not enough cpus":
1419             self.send_result_through_pipe(test, SKIP_CPU_SHORTAGE)
1420         else:
1421             self.send_result_through_pipe(test, SKIP)
1422
1423     def symlink_failed(self):
1424         if self.current_test_case_info:
1425             try:
1426                 failed_dir = os.getenv('FAILED_DIR')
1427                 link_path = os.path.join(
1428                     failed_dir,
1429                     '%s-FAILED' %
1430                     os.path.basename(self.current_test_case_info.tempdir))
1431
1432                 self.current_test_case_info.logger.debug(
1433                     "creating a link to the failed test")
1434                 self.current_test_case_info.logger.debug(
1435                     "os.symlink(%s, %s)" %
1436                     (self.current_test_case_info.tempdir, link_path))
1437                 if os.path.exists(link_path):
1438                     self.current_test_case_info.logger.debug(
1439                         'symlink already exists')
1440                 else:
1441                     os.symlink(self.current_test_case_info.tempdir, link_path)
1442
1443             except Exception as e:
1444                 self.current_test_case_info.logger.error(e)
1445
1446     def send_result_through_pipe(self, test, result):
1447         if hasattr(self, 'test_framework_result_pipe'):
1448             pipe = self.test_framework_result_pipe
1449             if pipe:
1450                 pipe.send((test.id(), result))
1451
1452     def log_error(self, test, err, fn_name):
1453         if self.current_test_case_info:
1454             if isinstance(test, unittest.suite._ErrorHolder):
1455                 test_name = test.description
1456             else:
1457                 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1458                                            test._testMethodName,
1459                                            test._testMethodDoc)
1460             self.current_test_case_info.logger.debug(
1461                 "--- %s() %s called, err is %s" %
1462                 (fn_name, test_name, err))
1463             self.current_test_case_info.logger.debug(
1464                 "formatted exception is:\n%s" %
1465                 "".join(format_exception(*err)))
1466
1467     def add_error(self, test, err, unittest_fn, error_type):
1468         if error_type == FAIL:
1469             self.log_error(test, err, 'addFailure')
1470             error_type_str = colorize("FAIL", RED)
1471         elif error_type == ERROR:
1472             self.log_error(test, err, 'addError')
1473             error_type_str = colorize("ERROR", RED)
1474         else:
1475             raise Exception('Error type %s cannot be used to record an '
1476                             'error or a failure' % error_type)
1477
1478         unittest_fn(self, test, err)
1479         if self.current_test_case_info:
1480             self.result_string = "%s [ temp dir used by test case: %s ]" % \
1481                                  (error_type_str,
1482                                   self.current_test_case_info.tempdir)
1483             self.symlink_failed()
1484             self.failed_test_cases_info.add(self.current_test_case_info)
1485             if is_core_present(self.current_test_case_info.tempdir):
1486                 if not self.current_test_case_info.core_crash_test:
1487                     if isinstance(test, unittest.suite._ErrorHolder):
1488                         test_name = str(test)
1489                     else:
1490                         test_name = "'{!s}' ({!s})".format(
1491                             get_testcase_doc_name(test), test.id())
1492                     self.current_test_case_info.core_crash_test = test_name
1493                 self.core_crash_test_cases_info.add(
1494                     self.current_test_case_info)
1495         else:
1496             self.result_string = '%s [no temp dir]' % error_type_str
1497
1498         self.send_result_through_pipe(test, error_type)
1499
1500     def addFailure(self, test, err):
1501         """
1502         Record a test failed result
1503
1504         :param test:
1505         :param err: error message
1506
1507         """
1508         self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1509
1510     def addError(self, test, err):
1511         """
1512         Record a test error result
1513
1514         :param test:
1515         :param err: error message
1516
1517         """
1518         self.add_error(test, err, unittest.TestResult.addError, ERROR)
1519
1520     def getDescription(self, test):
1521         """
1522         Get test description
1523
1524         :param test:
1525         :returns: test description
1526
1527         """
1528         return get_test_description(self.descriptions, test)
1529
1530     def startTest(self, test):
1531         """
1532         Start a test
1533
1534         :param test:
1535
1536         """
1537
1538         def print_header(test):
1539             if test.__class__ in self.printed:
1540                 return
1541
1542             test_doc = getdoc(test)
1543             if not test_doc:
1544                 raise Exception("No doc string for test '%s'" % test.id())
1545
1546             test_title = test_doc.splitlines()[0].rstrip()
1547             test_title = colorize(test_title, GREEN)
1548             if test.is_tagged_run_solo():
1549                 test_title = colorize(f"SOLO RUN: {test_title}", YELLOW)
1550
1551             # This block may overwrite the colorized title above,
1552             # but we want this to stand out and be fixed
1553             if test.has_tag(TestCaseTag.FIXME_VPP_WORKERS):
1554                 test_title = colorize(
1555                     f"FIXME with VPP workers: {test_title}", RED)
1556
1557             if hasattr(test, 'vpp_worker_count'):
1558                 if test.vpp_worker_count == 0:
1559                     test_title += " [main thread only]"
1560                 elif test.vpp_worker_count == 1:
1561                     test_title += " [1 worker thread]"
1562                 else:
1563                     test_title += f" [{test.vpp_worker_count} worker threads]"
1564
1565             if test.__class__.skipped_due_to_cpu_lack:
1566                 test_title = colorize(
1567                     f"{test_title} [skipped - not enough cpus, "
1568                     f"required={test.__class__.get_cpus_required()}, "
1569                     f"available={max_vpp_cpus}]", YELLOW)
1570
1571             print(double_line_delim)
1572             print(test_title)
1573             print(double_line_delim)
1574             self.printed.append(test.__class__)
1575
1576         print_header(test)
1577         self.start_test = time.time()
1578         unittest.TestResult.startTest(self, test)
1579         if self.verbosity > 0:
1580             self.stream.writeln(
1581                 "Starting " + self.getDescription(test) + " ...")
1582             self.stream.writeln(single_line_delim)
1583
1584     def stopTest(self, test):
1585         """
1586         Called when the given test has been run
1587
1588         :param test:
1589
1590         """
1591         unittest.TestResult.stopTest(self, test)
1592
1593         if self.verbosity > 0:
1594             self.stream.writeln(single_line_delim)
1595             self.stream.writeln("%-73s%s" % (self.getDescription(test),
1596                                              self.result_string))
1597             self.stream.writeln(single_line_delim)
1598         else:
1599             self.stream.writeln("%-68s %4.2f %s" %
1600                                 (self.getDescription(test),
1601                                  time.time() - self.start_test,
1602                                  self.result_string))
1603
1604         self.send_result_through_pipe(test, TEST_RUN)
1605
1606     def printErrors(self):
1607         """
1608         Print errors from running the test case
1609         """
1610         if len(self.errors) > 0 or len(self.failures) > 0:
1611             self.stream.writeln()
1612             self.printErrorList('ERROR', self.errors)
1613             self.printErrorList('FAIL', self.failures)
1614
1615         # ^^ that is the last output from unittest before summary
1616         if not self.runner.print_summary:
1617             devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1618             self.stream = devnull
1619             self.runner.stream = devnull
1620
1621     def printErrorList(self, flavour, errors):
1622         """
1623         Print error list to the output stream together with error type
1624         and test case description.
1625
1626         :param flavour: error type
1627         :param errors: iterable errors
1628
1629         """
1630         for test, err in errors:
1631             self.stream.writeln(double_line_delim)
1632             self.stream.writeln("%s: %s" %
1633                                 (flavour, self.getDescription(test)))
1634             self.stream.writeln(single_line_delim)
1635             self.stream.writeln("%s" % err)
1636
1637
1638 class VppTestRunner(unittest.TextTestRunner):
1639     """
1640     A basic test runner implementation which prints results to standard error.
1641     """
1642
1643     @property
1644     def resultclass(self):
1645         """Class maintaining the results of the tests"""
1646         return VppTestResult
1647
1648     def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1649                  result_pipe=None, failfast=False, buffer=False,
1650                  resultclass=None, print_summary=True, **kwargs):
1651         # ignore stream setting here, use hard-coded stdout to be in sync
1652         # with prints from VppTestCase methods ...
1653         super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1654                                             verbosity, failfast, buffer,
1655                                             resultclass, **kwargs)
1656         KeepAliveReporter.pipe = keep_alive_pipe
1657
1658         self.orig_stream = self.stream
1659         self.resultclass.test_framework_result_pipe = result_pipe
1660
1661         self.print_summary = print_summary
1662
1663     def _makeResult(self):
1664         return self.resultclass(self.stream,
1665                                 self.descriptions,
1666                                 self.verbosity,
1667                                 self)
1668
1669     def run(self, test):
1670         """
1671         Run the tests
1672
1673         :param test:
1674
1675         """
1676         faulthandler.enable()  # emit stack trace to stderr if killed by signal
1677
1678         result = super(VppTestRunner, self).run(test)
1679         if not self.print_summary:
1680             self.stream = self.orig_stream
1681             result.stream = self.orig_stream
1682         return result
1683
1684
1685 class Worker(Thread):
1686     def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1687         super(Worker, self).__init__(*args, **kwargs)
1688         self.logger = logger
1689         self.args = executable_args
1690         if hasattr(self, 'testcase') and self.testcase.debug_all:
1691             if self.testcase.debug_gdbserver:
1692                 self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1693                              .format(port=self.testcase.gdbserver_port)] + args
1694             elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1695                 self.args.append(self.wait_for_gdb)
1696         self.app_bin = executable_args[0]
1697         self.app_name = os.path.basename(self.app_bin)
1698         if hasattr(self, 'role'):
1699             self.app_name += ' {role}'.format(role=self.role)
1700         self.process = None
1701         self.result = None
1702         env = {} if env is None else env
1703         self.env = copy.deepcopy(env)
1704
1705     def wait_for_enter(self):
1706         if not hasattr(self, 'testcase'):
1707             return
1708         if self.testcase.debug_all and self.testcase.debug_gdbserver:
1709             print()
1710             print(double_line_delim)
1711             print("Spawned GDB Server for '{app}' with PID: {pid}"
1712                   .format(app=self.app_name, pid=self.process.pid))
1713         elif self.testcase.debug_all and self.testcase.debug_gdb:
1714             print()
1715             print(double_line_delim)
1716             print("Spawned '{app}' with PID: {pid}"
1717                   .format(app=self.app_name, pid=self.process.pid))
1718         else:
1719             return
1720         print(single_line_delim)
1721         print("You can debug '{app}' using:".format(app=self.app_name))
1722         if self.testcase.debug_gdbserver:
1723             print("sudo gdb " + self.app_bin +
1724                   " -ex 'target remote localhost:{port}'"
1725                   .format(port=self.testcase.gdbserver_port))
1726             print("Now is the time to attach gdb by running the above "
1727                   "command, set up breakpoints etc., then resume from "
1728                   "within gdb by issuing the 'continue' command")
1729             self.testcase.gdbserver_port += 1
1730         elif self.testcase.debug_gdb:
1731             print("sudo gdb " + self.app_bin +
1732                   " -ex 'attach {pid}'".format(pid=self.process.pid))
1733             print("Now is the time to attach gdb by running the above "
1734                   "command and set up breakpoints etc., then resume from"
1735                   " within gdb by issuing the 'continue' command")
1736         print(single_line_delim)
1737         input("Press ENTER to continue running the testcase...")
1738
1739     def run(self):
1740         executable = self.args[0]
1741         if not os.path.exists(executable) or not os.access(
1742                 executable, os.F_OK | os.X_OK):
1743             # Exit code that means some system file did not exist,
1744             # could not be opened, or had some other kind of error.
1745             self.result = os.EX_OSFILE
1746             raise EnvironmentError(
1747                 "executable '%s' is not found or executable." % executable)
1748         self.logger.debug("Running executable '{app}': '{cmd}'"
1749                           .format(app=self.app_name,
1750                                   cmd=' '.join(self.args)))
1751         env = os.environ.copy()
1752         env.update(self.env)
1753         env["CK_LOG_FILE_NAME"] = "-"
1754         self.process = subprocess.Popen(
1755             ['stdbuf', '-o0', '-e0'] + self.args, shell=False, env=env,
1756             preexec_fn=os.setpgrp, stdout=subprocess.PIPE,
1757             stderr=subprocess.PIPE)
1758         self.wait_for_enter()
1759         out, err = self.process.communicate()
1760         self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1761         self.logger.info("Return code is `%s'" % self.process.returncode)
1762         self.logger.info(single_line_delim)
1763         self.logger.info("Executable `{app}' wrote to stdout:"
1764                          .format(app=self.app_name))
1765         self.logger.info(single_line_delim)
1766         self.logger.info(out.decode('utf-8'))
1767         self.logger.info(single_line_delim)
1768         self.logger.info("Executable `{app}' wrote to stderr:"
1769                          .format(app=self.app_name))
1770         self.logger.info(single_line_delim)
1771         self.logger.info(err.decode('utf-8'))
1772         self.logger.info(single_line_delim)
1773         self.result = self.process.returncode
1774
1775
1776 if __name__ == '__main__':
1777     pass