test/framework.py

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