test/framework.py

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