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