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