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