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