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