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