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