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