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