test/framework.py

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