test/framework.py

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