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