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 resource
  12 import faulthandler
  13 from collections import deque
  14 from threading import Thread, Event
  15 from inspect import getdoc, isclass
  16 from traceback import format_exception
  17 from logging import FileHandler, DEBUG, Formatter
  18 from scapy.packet import Raw
  19 from hook import StepHook, PollHook
  20 from vpp_pg_interface import VppPGInterface
  21 from vpp_sub_interface import VppSubInterface
  22 from vpp_lo_interface import VppLoInterface
  23 from vpp_papi_provider import VppPapiProvider
  24 from log import *
  25 from vpp_object import VppObjectRegistry
  26 if os.name == 'posix' and sys.version_info[0] < 3:
  27     # using subprocess32 is recommended by python official documentation
  28     # @ https://docs.python.org/2/library/subprocess.html
  29     import subprocess32 as subprocess
  30 else:
  31     import subprocess
  32
  33 """
  34   Test framework module.
  35
  36   The module provides a set of tools for constructing and running tests and
  37   representing the results.
  38 """
  39
  40
  41 class _PacketInfo(object):
  42     """Private class to create packet info object.
  43
  44     Help process information about the next packet.
  45     Set variables to default values.
  46     """
  47     #: Store the index of the packet.
  48     index = -1
  49     #: Store the index of the source packet generator interface of the packet.
  50     src = -1
  51     #: Store the index of the destination packet generator interface
  52     #: of the packet.
  53     dst = -1
  54     #: Store expected ip version
  55     ip = -1
  56     #: Store expected upper protocol
  57     proto = -1
  58     #: Store the copy of the former packet.
  59     data = None
  60
  61     def __eq__(self, other):
  62         index = self.index == other.index
  63         src = self.src == other.src
  64         dst = self.dst == other.dst
  65         data = self.data == other.data
  66         return index and src and dst and data
  67
  68
  69 def pump_output(testclass):
  70     """ pump output from vpp stdout/stderr to proper queues """
  71     while not testclass.pump_thread_stop_flag.wait(0):
  72         readable = select.select([testclass.vpp.stdout.fileno(),
  73                                   testclass.vpp.stderr.fileno(),
  74                                   testclass.pump_thread_wakeup_pipe[0]],
  75                                  [], [])[0]
  76         if testclass.vpp.stdout.fileno() in readable:
  77             read = os.read(testclass.vpp.stdout.fileno(), 1024)
  78             testclass.vpp_stdout_deque.append(read)
  79         if testclass.vpp.stderr.fileno() in readable:
  80             read = os.read(testclass.vpp.stderr.fileno(), 1024)
  81             testclass.vpp_stderr_deque.append(read)
  82         # ignoring the dummy pipe here intentionally - the flag will take care
  83         # of properly terminating the loop
  84
  85
  86 def running_extended_tests():
  87     try:
  88         s = os.getenv("EXTENDED_TESTS")
  89         return True if s.lower() in ("y", "yes", "1") else False
  90     except:
  91         return False
  92     return False
  93
  94
  95 class KeepAliveReporter(object):
  96     """
  97     Singleton object which reports test start to parent process
  98     """
  99     _shared_state = {}
 100
 101     def __init__(self):
 102         self.__dict__ = self._shared_state
 103
 104     @property
 105     def pipe(self):
 106         return self._pipe
 107
 108     @pipe.setter
 109     def pipe(self, pipe):
 110         if hasattr(self, '_pipe'):
 111             raise Exception("Internal error - pipe should only be set once.")
 112         self._pipe = pipe
 113
 114     def send_keep_alive(self, test):
 115         """
 116         Write current test tmpdir & desc to keep-alive pipe to signal liveness
 117         """
 118         if self.pipe is None:
 119             # if not running forked..
 120             return
 121
 122         if isclass(test):
 123             desc = test.__name__
 124         else:
 125             desc = test.shortDescription()
 126             if not desc:
 127                 desc = str(test)
 128
 129         self.pipe.send((desc, test.vpp_bin, test.tempdir))
 130
 131
 132 class VppTestCase(unittest.TestCase):
 133     """This subclass is a base class for VPP test cases that are implemented as
 134     classes. It provides methods to create and run test case.
 135     """
 136
 137     @property
 138     def packet_infos(self):
 139         """List of packet infos"""
 140         return self._packet_infos
 141
 142     @classmethod
 143     def get_packet_count_for_if_idx(cls, dst_if_index):
 144         """Get the number of packet info for specified destination if index"""
 145         if dst_if_index in cls._packet_count_for_dst_if_idx:
 146             return cls._packet_count_for_dst_if_idx[dst_if_index]
 147         else:
 148             return 0
 149
 150     @classmethod
 151     def instance(cls):
 152         """Return the instance of this testcase"""
 153         return cls.test_instance
 154
 155     @classmethod
 156     def set_debug_flags(cls, d):
 157         cls.debug_core = False
 158         cls.debug_gdb = False
 159         cls.debug_gdbserver = False
 160         if d is None:
 161             return
 162         dl = d.lower()
 163         if dl == "core":
 164             cls.debug_core = True
 165         elif dl == "gdb":
 166             cls.debug_gdb = True
 167         elif dl == "gdbserver":
 168             cls.debug_gdbserver = True
 169         else:
 170             raise Exception("Unrecognized DEBUG option: '%s'" % d)
 171
 172     @classmethod
 173     def setUpConstants(cls):
 174         """ Set-up the test case class based on environment variables """
 175         try:
 176             s = os.getenv("STEP")
 177             cls.step = True if s.lower() in ("y", "yes", "1") else False
 178         except:
 179             cls.step = False
 180         try:
 181             d = os.getenv("DEBUG")
 182         except:
 183             d = None
 184         cls.set_debug_flags(d)
 185         cls.vpp_bin = os.getenv('VPP_TEST_BIN', "vpp")
 186         cls.plugin_path = os.getenv('VPP_TEST_PLUGIN_PATH')
 187         cls.extern_plugin_path = os.getenv('EXTERN_PLUGINS')
 188         plugin_path = None
 189         if cls.plugin_path is not None:
 190             if cls.extern_plugin_path is not None:
 191                 plugin_path = "%s:%s" % (
 192                     cls.plugin_path, cls.extern_plugin_path)
 193             else:
 194                 plugin_path = cls.plugin_path
 195         elif cls.extern_plugin_path is not None:
 196             plugin_path = cls.extern_plugin_path
 197         debug_cli = ""
 198         if cls.step or cls.debug_gdb or cls.debug_gdbserver:
 199             debug_cli = "cli-listen localhost:5002"
 200         coredump_size = None
 201         try:
 202             size = os.getenv("COREDUMP_SIZE")
 203             if size is not None:
 204                 coredump_size = "coredump-size %s" % size
 205         except:
 206             pass
 207         if coredump_size is None:
 208             coredump_size = "coredump-size unlimited"
 209         cls.vpp_cmdline = [cls.vpp_bin, "unix",
 210                            "{", "nodaemon", debug_cli, coredump_size, "}",
 211                            "api-trace", "{", "on", "}",
 212                            "api-segment", "{", "prefix", cls.shm_prefix, "}",
 213                            "plugins", "{", "plugin", "dpdk_plugin.so", "{",
 214                            "disable", "}", "}"]
 215         if plugin_path is not None:
 216             cls.vpp_cmdline.extend(["plugin_path", plugin_path])
 217         cls.logger.info("vpp_cmdline: %s" % cls.vpp_cmdline)
 218
 219     @classmethod
 220     def wait_for_enter(cls):
 221         if cls.debug_gdbserver:
 222             print(double_line_delim)
 223             print("Spawned GDB server with PID: %d" % cls.vpp.pid)
 224         elif cls.debug_gdb:
 225             print(double_line_delim)
 226             print("Spawned VPP with PID: %d" % cls.vpp.pid)
 227         else:
 228             cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
 229             return
 230         print(single_line_delim)
 231         print("You can debug the VPP using e.g.:")
 232         if cls.debug_gdbserver:
 233             print("gdb " + cls.vpp_bin + " -ex 'target remote localhost:7777'")
 234             print("Now is the time to attach a gdb by running the above "
 235                   "command, set up breakpoints etc. and then resume VPP from "
 236                   "within gdb by issuing the 'continue' command")
 237         elif cls.debug_gdb:
 238             print("gdb " + cls.vpp_bin + " -ex 'attach %s'" % cls.vpp.pid)
 239             print("Now is the time to attach a gdb by running the above "
 240                   "command and set up breakpoints etc.")
 241         print(single_line_delim)
 242         raw_input("Press ENTER to continue running the testcase...")
 243
 244     @classmethod
 245     def run_vpp(cls):
 246         cmdline = cls.vpp_cmdline
 247
 248         if cls.debug_gdbserver:
 249             gdbserver = '/usr/bin/gdbserver'
 250             if not os.path.isfile(gdbserver) or \
 251                     not os.access(gdbserver, os.X_OK):
 252                 raise Exception("gdbserver binary '%s' does not exist or is "
 253                                 "not executable" % gdbserver)
 254
 255             cmdline = [gdbserver, 'localhost:7777'] + cls.vpp_cmdline
 256             cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
 257
 258         try:
 259             cls.vpp = subprocess.Popen(cmdline,
 260                                        stdout=subprocess.PIPE,
 261                                        stderr=subprocess.PIPE,
 262                                        bufsize=1)
 263         except Exception as e:
 264             cls.logger.critical("Couldn't start vpp: %s" % e)
 265             raise
 266
 267         cls.wait_for_enter()
 268
 269     @classmethod
 270     def setUpClass(cls):
 271         """
 272         Perform class setup before running the testcase
 273         Remove shared memory files, start vpp and connect the vpp-api
 274         """
 275         gc.collect()  # run garbage collection first
 276         cls.logger = getLogger(cls.__name__)
 277         cls.tempdir = tempfile.mkdtemp(
 278             prefix='vpp-unittest-%s-' % cls.__name__)
 279         cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
 280         cls.file_handler.setFormatter(
 281             Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
 282                       datefmt="%H:%M:%S"))
 283         cls.file_handler.setLevel(DEBUG)
 284         cls.logger.addHandler(cls.file_handler)
 285         cls.shm_prefix = cls.tempdir.split("/")[-1]
 286         os.chdir(cls.tempdir)
 287         cls.logger.info("Temporary dir is %s, shm prefix is %s",
 288                         cls.tempdir, cls.shm_prefix)
 289         cls.setUpConstants()
 290         cls.reset_packet_infos()
 291         cls._captures = []
 292         cls._zombie_captures = []
 293         cls.verbose = 0
 294         cls.vpp_dead = False
 295         cls.registry = VppObjectRegistry()
 296         cls.vpp_startup_failed = False
 297         cls.reporter = KeepAliveReporter()
 298         cls.reporter.send_keep_alive(cls)
 299         # need to catch exceptions here because if we raise, then the cleanup
 300         # doesn't get called and we might end with a zombie vpp
 301         try:
 302             cls.run_vpp()
 303             cls.vpp_stdout_deque = deque()
 304             cls.vpp_stderr_deque = deque()
 305             cls.pump_thread_stop_flag = Event()
 306             cls.pump_thread_wakeup_pipe = os.pipe()
 307             cls.pump_thread = Thread(target=pump_output, args=(cls,))
 308             cls.pump_thread.daemon = True
 309             cls.pump_thread.start()
 310             cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls)
 311             if cls.step:
 312                 hook = StepHook(cls)
 313             else:
 314                 hook = PollHook(cls)
 315             cls.vapi.register_hook(hook)
 316             cls.sleep(0.1, "after vpp startup, before initial poll")
 317             try:
 318                 hook.poll_vpp()
 319             except:
 320                 cls.vpp_startup_failed = True
 321                 cls.logger.critical(
 322                     "VPP died shortly after startup, check the"
 323                     " output to standard error for possible cause")
 324                 raise
 325             try:
 326                 cls.vapi.connect()
 327             except:
 328                 if cls.debug_gdbserver:
 329                     print(colorize("You're running VPP inside gdbserver but "
 330                                    "VPP-API connection failed, did you forget "
 331                                    "to 'continue' VPP from within gdb?", RED))
 332                 raise
 333         except:
 334             t, v, tb = sys.exc_info()
 335             try:
 336                 cls.quit()
 337             except:
 338                 pass
 339             raise t, v, tb
 340
 341     @classmethod
 342     def quit(cls):
 343         """
 344         Disconnect vpp-api, kill vpp and cleanup shared memory files
 345         """
 346         if (cls.debug_gdbserver or cls.debug_gdb) and hasattr(cls, 'vpp'):
 347             cls.vpp.poll()
 348             if cls.vpp.returncode is None:
 349                 print(double_line_delim)
 350                 print("VPP or GDB server is still running")
 351                 print(single_line_delim)
 352                 raw_input("When done debugging, press ENTER to kill the "
 353                           "process and finish running the testcase...")
 354
 355         os.write(cls.pump_thread_wakeup_pipe[1], 'ding dong wake up')
 356         cls.pump_thread_stop_flag.set()
 357         if hasattr(cls, 'pump_thread'):
 358             cls.logger.debug("Waiting for pump thread to stop")
 359             cls.pump_thread.join()
 360         if hasattr(cls, 'vpp_stderr_reader_thread'):
 361             cls.logger.debug("Waiting for stdderr pump to stop")
 362             cls.vpp_stderr_reader_thread.join()
 363
 364         if hasattr(cls, 'vpp'):
 365             if hasattr(cls, 'vapi'):
 366                 cls.vapi.disconnect()
 367                 del cls.vapi
 368             cls.vpp.poll()
 369             if cls.vpp.returncode is None:
 370                 cls.logger.debug("Sending TERM to vpp")
 371                 cls.vpp.terminate()
 372                 cls.logger.debug("Waiting for vpp to die")
 373                 cls.vpp.communicate()
 374             del cls.vpp
 375
 376         if cls.vpp_startup_failed:
 377             stdout_log = cls.logger.info
 378             stderr_log = cls.logger.critical
 379         else:
 380             stdout_log = cls.logger.info
 381             stderr_log = cls.logger.info
 382
 383         if hasattr(cls, 'vpp_stdout_deque'):
 384             stdout_log(single_line_delim)
 385             stdout_log('VPP output to stdout while running %s:', cls.__name__)
 386             stdout_log(single_line_delim)
 387             vpp_output = "".join(cls.vpp_stdout_deque)
 388             with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
 389                 f.write(vpp_output)
 390             stdout_log('\n%s', vpp_output)
 391             stdout_log(single_line_delim)
 392
 393         if hasattr(cls, 'vpp_stderr_deque'):
 394             stderr_log(single_line_delim)
 395             stderr_log('VPP output to stderr while running %s:', cls.__name__)
 396             stderr_log(single_line_delim)
 397             vpp_output = "".join(cls.vpp_stderr_deque)
 398             with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
 399                 f.write(vpp_output)
 400             stderr_log('\n%s', vpp_output)
 401             stderr_log(single_line_delim)
 402
 403     @classmethod
 404     def tearDownClass(cls):
 405         """ Perform final cleanup after running all tests in this test-case """
 406         cls.quit()
 407         cls.file_handler.close()
 408
 409     def tearDown(self):
 410         """ Show various debug prints after each test """
 411         self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
 412                           (self.__class__.__name__, self._testMethodName,
 413                            self._testMethodDoc))
 414         if not self.vpp_dead:
 415             self.logger.debug(self.vapi.cli("show trace"))
 416             self.logger.info(self.vapi.ppcli("show interface"))
 417             self.logger.info(self.vapi.ppcli("show hardware"))
 418             self.logger.info(self.vapi.ppcli("show error"))
 419             self.logger.info(self.vapi.ppcli("show run"))
 420             self.registry.remove_vpp_config(self.logger)
 421             # Save/Dump VPP api trace log
 422             api_trace = "vpp_api_trace.%s.log" % self._testMethodName
 423             tmp_api_trace = "/tmp/%s" % api_trace
 424             vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
 425             self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
 426             self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
 427                                                     vpp_api_trace_log))
 428             os.rename(tmp_api_trace, vpp_api_trace_log)
 429             self.logger.info(self.vapi.ppcli("api trace dump %s" %
 430                                              vpp_api_trace_log))
 431         else:
 432             self.registry.unregister_all(self.logger)
 433
 434     def setUp(self):
 435         """ Clear trace before running each test"""
 436         self.reporter.send_keep_alive(self)
 437         self.logger.debug("--- setUp() for %s.%s(%s) called ---" %
 438                           (self.__class__.__name__, self._testMethodName,
 439                            self._testMethodDoc))
 440         if self.vpp_dead:
 441             raise Exception("VPP is dead when setting up the test")
 442         self.sleep(.1, "during setUp")
 443         self.vpp_stdout_deque.append(
 444             "--- test setUp() for %s.%s(%s) starts here ---\n" %
 445             (self.__class__.__name__, self._testMethodName,
 446              self._testMethodDoc))
 447         self.vpp_stderr_deque.append(
 448             "--- test setUp() for %s.%s(%s) starts here ---\n" %
 449             (self.__class__.__name__, self._testMethodName,
 450              self._testMethodDoc))
 451         self.vapi.cli("clear trace")
 452         # store the test instance inside the test class - so that objects
 453         # holding the class can access instance methods (like assertEqual)
 454         type(self).test_instance = self
 455
 456     @classmethod
 457     def pg_enable_capture(cls, interfaces):
 458         """
 459         Enable capture on packet-generator interfaces
 460
 461         :param interfaces: iterable interface indexes
 462
 463         """
 464         for i in interfaces:
 465             i.enable_capture()
 466
 467     @classmethod
 468     def register_capture(cls, cap_name):
 469         """ Register a capture in the testclass """
 470         # add to the list of captures with current timestamp
 471         cls._captures.append((time.time(), cap_name))
 472         # filter out from zombies
 473         cls._zombie_captures = [(stamp, name)
 474                                 for (stamp, name) in cls._zombie_captures
 475                                 if name != cap_name]
 476
 477     @classmethod
 478     def pg_start(cls):
 479         """ Remove any zombie captures and enable the packet generator """
 480         # how long before capture is allowed to be deleted - otherwise vpp
 481         # crashes - 100ms seems enough (this shouldn't be needed at all)
 482         capture_ttl = 0.1
 483         now = time.time()
 484         for stamp, cap_name in cls._zombie_captures:
 485             wait = stamp + capture_ttl - now
 486             if wait > 0:
 487                 cls.sleep(wait, "before deleting capture %s" % cap_name)
 488                 now = time.time()
 489             cls.logger.debug("Removing zombie capture %s" % cap_name)
 490             cls.vapi.cli('packet-generator delete %s' % cap_name)
 491
 492         cls.vapi.cli("trace add pg-input 50")  # 50 is maximum
 493         cls.vapi.cli('packet-generator enable')
 494         cls._zombie_captures = cls._captures
 495         cls._captures = []
 496
 497     @classmethod
 498     def create_pg_interfaces(cls, interfaces):
 499         """
 500         Create packet-generator interfaces.
 501
 502         :param interfaces: iterable indexes of the interfaces.
 503         :returns: List of created interfaces.
 504
 505         """
 506         result = []
 507         for i in interfaces:
 508             intf = VppPGInterface(cls, i)
 509             setattr(cls, intf.name, intf)
 510             result.append(intf)
 511         cls.pg_interfaces = result
 512         return result
 513
 514     @classmethod
 515     def create_loopback_interfaces(cls, interfaces):
 516         """
 517         Create loopback interfaces.
 518
 519         :param interfaces: iterable indexes of the interfaces.
 520         :returns: List of created interfaces.
 521         """
 522         result = []
 523         for i in interfaces:
 524             intf = VppLoInterface(cls, i)
 525             setattr(cls, intf.name, intf)
 526             result.append(intf)
 527         cls.lo_interfaces = result
 528         return result
 529
 530     @staticmethod
 531     def extend_packet(packet, size):
 532         """
 533         Extend packet to given size by padding with spaces
 534         NOTE: Currently works only when Raw layer is present.
 535
 536         :param packet: packet
 537         :param size: target size
 538
 539         """
 540         packet_len = len(packet) + 4
 541         extend = size - packet_len
 542         if extend > 0:
 543             packet[Raw].load += ' ' * extend
 544
 545     @classmethod
 546     def reset_packet_infos(cls):
 547         """ Reset the list of packet info objects and packet counts to zero """
 548         cls._packet_infos = {}
 549         cls._packet_count_for_dst_if_idx = {}
 550
 551     @classmethod
 552     def create_packet_info(cls, src_if, dst_if):
 553         """
 554         Create packet info object containing the source and destination indexes
 555         and add it to the testcase's packet info list
 556
 557         :param VppInterface src_if: source interface
 558         :param VppInterface dst_if: destination interface
 559
 560         :returns: _PacketInfo object
 561
 562         """
 563         info = _PacketInfo()
 564         info.index = len(cls._packet_infos)
 565         info.src = src_if.sw_if_index
 566         info.dst = dst_if.sw_if_index
 567         if isinstance(dst_if, VppSubInterface):
 568             dst_idx = dst_if.parent.sw_if_index
 569         else:
 570             dst_idx = dst_if.sw_if_index
 571         if dst_idx in cls._packet_count_for_dst_if_idx:
 572             cls._packet_count_for_dst_if_idx[dst_idx] += 1
 573         else:
 574             cls._packet_count_for_dst_if_idx[dst_idx] = 1
 575         cls._packet_infos[info.index] = info
 576         return info
 577
 578     @staticmethod
 579     def info_to_payload(info):
 580         """
 581         Convert _PacketInfo object to packet payload
 582
 583         :param info: _PacketInfo object
 584
 585         :returns: string containing serialized data from packet info
 586         """
 587         return "%d %d %d %d %d" % (info.index, info.src, info.dst,
 588                                    info.ip, info.proto)
 589
 590     @staticmethod
 591     def payload_to_info(payload):
 592         """
 593         Convert packet payload to _PacketInfo object
 594
 595         :param payload: packet payload
 596
 597         :returns: _PacketInfo object containing de-serialized data from payload
 598
 599         """
 600         numbers = payload.split()
 601         info = _PacketInfo()
 602         info.index = int(numbers[0])
 603         info.src = int(numbers[1])
 604         info.dst = int(numbers[2])
 605         info.ip = int(numbers[3])
 606         info.proto = int(numbers[4])
 607         return info
 608
 609     def get_next_packet_info(self, info):
 610         """
 611         Iterate over the packet info list stored in the testcase
 612         Start iteration with first element if info is None
 613         Continue based on index in info if info is specified
 614
 615         :param info: info or None
 616         :returns: next info in list or None if no more infos
 617         """
 618         if info is None:
 619             next_index = 0
 620         else:
 621             next_index = info.index + 1
 622         if next_index == len(self._packet_infos):
 623             return None
 624         else:
 625             return self._packet_infos[next_index]
 626
 627     def get_next_packet_info_for_interface(self, src_index, info):
 628         """
 629         Search the packet info list for the next packet info with same source
 630         interface index
 631
 632         :param src_index: source interface index to search for
 633         :param info: packet info - where to start the search
 634         :returns: packet info or None
 635
 636         """
 637         while True:
 638             info = self.get_next_packet_info(info)
 639             if info is None:
 640                 return None
 641             if info.src == src_index:
 642                 return info
 643
 644     def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
 645         """
 646         Search the packet info list for the next packet info with same source
 647         and destination interface indexes
 648
 649         :param src_index: source interface index to search for
 650         :param dst_index: destination interface index to search for
 651         :param info: packet info - where to start the search
 652         :returns: packet info or None
 653
 654         """
 655         while True:
 656             info = self.get_next_packet_info_for_interface(src_index, info)
 657             if info is None:
 658                 return None
 659             if info.dst == dst_index:
 660                 return info
 661
 662     def assert_equal(self, real_value, expected_value, name_or_class=None):
 663         if name_or_class is None:
 664             self.assertEqual(real_value, expected_value)
 665             return
 666         try:
 667             msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
 668             msg = msg % (getdoc(name_or_class).strip(),
 669                          real_value, str(name_or_class(real_value)),
 670                          expected_value, str(name_or_class(expected_value)))
 671         except:
 672             msg = "Invalid %s: %s does not match expected value %s" % (
 673                 name_or_class, real_value, expected_value)
 674
 675         self.assertEqual(real_value, expected_value, msg)
 676
 677     def assert_in_range(self,
 678                         real_value,
 679                         expected_min,
 680                         expected_max,
 681                         name=None):
 682         if name is None:
 683             msg = None
 684         else:
 685             msg = "Invalid %s: %s out of range <%s,%s>" % (
 686                 name, real_value, expected_min, expected_max)
 687         self.assertTrue(expected_min <= real_value <= expected_max, msg)
 688
 689     @classmethod
 690     def sleep(cls, timeout, remark=None):
 691         if hasattr(cls, 'logger'):
 692             cls.logger.debug("Starting sleep for %ss (%s)" % (timeout, remark))
 693         before = time.time()
 694         time.sleep(timeout)
 695         after = time.time()
 696         if after - before > 2 * timeout:
 697             cls.logger.error("unexpected time.sleep() result - "
 698                              "slept for %ss instead of ~%ss!" % (
 699                                  after - before, timeout))
 700         if hasattr(cls, 'logger'):
 701             cls.logger.debug(
 702                 "Finished sleep (%s) - slept %ss (wanted %ss)" % (
 703                     remark, after - before, timeout))
 704
 705
 706 class TestCasePrinter(object):
 707     _shared_state = {}
 708
 709     def __init__(self):
 710         self.__dict__ = self._shared_state
 711         if not hasattr(self, "_test_case_set"):
 712             self._test_case_set = set()
 713
 714     def print_test_case_heading_if_first_time(self, case):
 715         if case.__class__ not in self._test_case_set:
 716             print(double_line_delim)
 717             print(colorize(getdoc(case.__class__).splitlines()[0], YELLOW))
 718             print(double_line_delim)
 719             self._test_case_set.add(case.__class__)
 720
 721
 722 class VppTestResult(unittest.TestResult):
 723     """
 724     @property result_string
 725      String variable to store the test case result string.
 726     @property errors
 727      List variable containing 2-tuples of TestCase instances and strings
 728      holding formatted tracebacks. Each tuple represents a test which
 729      raised an unexpected exception.
 730     @property failures
 731      List variable containing 2-tuples of TestCase instances and strings
 732      holding formatted tracebacks. Each tuple represents a test where
 733      a failure was explicitly signalled using the TestCase.assert*()
 734      methods.
 735     """
 736
 737     def __init__(self, stream, descriptions, verbosity):
 738         """
 739         :param stream File descriptor to store where to report test results.
 740             Set to the standard error stream by default.
 741         :param descriptions Boolean variable to store information if to use
 742             test case descriptions.
 743         :param verbosity Integer variable to store required verbosity level.
 744         """
 745         unittest.TestResult.__init__(self, stream, descriptions, verbosity)
 746         self.stream = stream
 747         self.descriptions = descriptions
 748         self.verbosity = verbosity
 749         self.result_string = None
 750         self.printer = TestCasePrinter()
 751
 752     def addSuccess(self, test):
 753         """
 754         Record a test succeeded result
 755
 756         :param test:
 757
 758         """
 759         if hasattr(test, 'logger'):
 760             test.logger.debug("--- addSuccess() %s.%s(%s) called"
 761                               % (test.__class__.__name__,
 762                                  test._testMethodName,
 763                                  test._testMethodDoc))
 764         unittest.TestResult.addSuccess(self, test)
 765         self.result_string = colorize("OK", GREEN)
 766
 767     def addSkip(self, test, reason):
 768         """
 769         Record a test skipped.
 770
 771         :param test:
 772         :param reason:
 773
 774         """
 775         if hasattr(test, 'logger'):
 776             test.logger.debug("--- addSkip() %s.%s(%s) called, reason is %s"
 777                               % (test.__class__.__name__,
 778                                  test._testMethodName,
 779                                  test._testMethodDoc,
 780                                  reason))
 781         unittest.TestResult.addSkip(self, test, reason)
 782         self.result_string = colorize("SKIP", YELLOW)
 783
 784     def symlink_failed(self, test):
 785         logger = None
 786         if hasattr(test, 'logger'):
 787             logger = test.logger
 788         if hasattr(test, 'tempdir'):
 789             try:
 790                 failed_dir = os.getenv('VPP_TEST_FAILED_DIR')
 791                 link_path = '%s/%s-FAILED' % (failed_dir,
 792                                               test.tempdir.split("/")[-1])
 793                 if logger:
 794                     logger.debug("creating a link to the failed test")
 795                     logger.debug("os.symlink(%s, %s)" %
 796                                  (test.tempdir, link_path))
 797                 os.symlink(test.tempdir, link_path)
 798             except Exception as e:
 799                 if logger:
 800                     logger.error(e)
 801
 802     def addFailure(self, test, err):
 803         """
 804         Record a test failed result
 805
 806         :param test:
 807         :param err: error message
 808
 809         """
 810         if hasattr(test, 'logger'):
 811             test.logger.debug("--- addFailure() %s.%s(%s) called, err is %s"
 812                               % (test.__class__.__name__,
 813                                  test._testMethodName,
 814                                  test._testMethodDoc, err))
 815             test.logger.debug("formatted exception is:\n%s" %
 816                               "".join(format_exception(*err)))
 817         unittest.TestResult.addFailure(self, test, err)
 818         if hasattr(test, 'tempdir'):
 819             self.result_string = colorize("FAIL", RED) + \
 820                 ' [ temp dir used by test case: ' + test.tempdir + ' ]'
 821             self.symlink_failed(test)
 822         else:
 823             self.result_string = colorize("FAIL", RED) + ' [no temp dir]'
 824
 825     def addError(self, test, err):
 826         """
 827         Record a test error result
 828
 829         :param test:
 830         :param err: error message
 831
 832         """
 833         if hasattr(test, 'logger'):
 834             test.logger.debug("--- addError() %s.%s(%s) called, err is %s"
 835                               % (test.__class__.__name__,
 836                                  test._testMethodName,
 837                                  test._testMethodDoc, err))
 838             test.logger.debug("formatted exception is:\n%s" %
 839                               "".join(format_exception(*err)))
 840         unittest.TestResult.addError(self, test, err)
 841         if hasattr(test, 'tempdir'):
 842             self.result_string = colorize("ERROR", RED) + \
 843                 ' [ temp dir used by test case: ' + test.tempdir + ' ]'
 844             self.symlink_failed(test)
 845         else:
 846             self.result_string = colorize("ERROR", RED) + ' [no temp dir]'
 847
 848     def getDescription(self, test):
 849         """
 850         Get test description
 851
 852         :param test:
 853         :returns: test description
 854
 855         """
 856         # TODO: if none print warning not raise exception
 857         short_description = test.shortDescription()
 858         if self.descriptions and short_description:
 859             return short_description
 860         else:
 861             return str(test)
 862
 863     def startTest(self, test):
 864         """
 865         Start a test
 866
 867         :param test:
 868
 869         """
 870         self.printer.print_test_case_heading_if_first_time(test)
 871         unittest.TestResult.startTest(self, test)
 872         if self.verbosity > 0:
 873             self.stream.writeln(
 874                 "Starting " + self.getDescription(test) + " ...")
 875             self.stream.writeln(single_line_delim)
 876
 877     def stopTest(self, test):
 878         """
 879         Stop a test
 880
 881         :param test:
 882
 883         """
 884         unittest.TestResult.stopTest(self, test)
 885         if self.verbosity > 0:
 886             self.stream.writeln(single_line_delim)
 887             self.stream.writeln("%-73s%s" % (self.getDescription(test),
 888                                              self.result_string))
 889             self.stream.writeln(single_line_delim)
 890         else:
 891             self.stream.writeln("%-73s%s" % (self.getDescription(test),
 892                                              self.result_string))
 893
 894     def printErrors(self):
 895         """
 896         Print errors from running the test case
 897         """
 898         self.stream.writeln()
 899         self.printErrorList('ERROR', self.errors)
 900         self.printErrorList('FAIL', self.failures)
 901
 902     def printErrorList(self, flavour, errors):
 903         """
 904         Print error list to the output stream together with error type
 905         and test case description.
 906
 907         :param flavour: error type
 908         :param errors: iterable errors
 909
 910         """
 911         for test, err in errors:
 912             self.stream.writeln(double_line_delim)
 913             self.stream.writeln("%s: %s" %
 914                                 (flavour, self.getDescription(test)))
 915             self.stream.writeln(single_line_delim)
 916             self.stream.writeln("%s" % err)
 917
 918
 919 class VppTestRunner(unittest.TextTestRunner):
 920     """
 921     A basic test runner implementation which prints results to standard error.
 922     """
 923     @property
 924     def resultclass(self):
 925         """Class maintaining the results of the tests"""
 926         return VppTestResult
 927
 928     def __init__(self, pipe=None, stream=sys.stderr, descriptions=True,
 929                  verbosity=1, failfast=False, buffer=False, resultclass=None):
 930         # ignore stream setting here, use hard-coded stdout to be in sync
 931         # with prints from VppTestCase methods ...
 932         super(VppTestRunner, self).__init__(sys.stdout, descriptions,
 933                                             verbosity, failfast, buffer,
 934                                             resultclass)
 935         reporter = KeepAliveReporter()
 936         reporter.pipe = pipe
 937
 938     test_option = "TEST"
 939
 940     def parse_test_option(self):
 941         try:
 942             f = os.getenv(self.test_option)
 943         except:
 944             f = None
 945         filter_file_name = None
 946         filter_class_name = None
 947         filter_func_name = None
 948         if f:
 949             if '.' in f:
 950                 parts = f.split('.')
 951                 if len(parts) > 3:
 952                     raise Exception("Unrecognized %s option: %s" %
 953                                     (self.test_option, f))
 954                 if len(parts) > 2:
 955                     if parts[2] not in ('*', ''):
 956                         filter_func_name = parts[2]
 957                 if parts[1] not in ('*', ''):
 958                     filter_class_name = parts[1]
 959                 if parts[0] not in ('*', ''):
 960                     if parts[0].startswith('test_'):
 961                         filter_file_name = parts[0]
 962                     else:
 963                         filter_file_name = 'test_%s' % parts[0]
 964             else:
 965                 if f.startswith('test_'):
 966                     filter_file_name = f
 967                 else:
 968                     filter_file_name = 'test_%s' % f
 969         return filter_file_name, filter_class_name, filter_func_name
 970
 971     def filter_tests(self, tests, filter_file, filter_class, filter_func):
 972         result = unittest.suite.TestSuite()
 973         for t in tests:
 974             if isinstance(t, unittest.suite.TestSuite):
 975                 # this is a bunch of tests, recursively filter...
 976                 x = self.filter_tests(t, filter_file, filter_class,
 977                                       filter_func)
 978                 if x.countTestCases() > 0:
 979                     result.addTest(x)
 980             elif isinstance(t, unittest.TestCase):
 981                 # this is a single test
 982                 parts = t.id().split('.')
 983                 # t.id() for common cases like this:
 984                 # test_classifier.TestClassifier.test_acl_ip
 985                 # apply filtering only if it is so
 986                 if len(parts) == 3:
 987                     if filter_file and filter_file != parts[0]:
 988                         continue
 989                     if filter_class and filter_class != parts[1]:
 990                         continue
 991                     if filter_func and filter_func != parts[2]:
 992                         continue
 993                 result.addTest(t)
 994             else:
 995                 # unexpected object, don't touch it
 996                 result.addTest(t)
 997         return result
 998
 999     def run(self, test):
1000         """
1001         Run the tests
1002
1003         :param test:
1004
1005         """
1006         faulthandler.enable()  # emit stack trace to stderr if killed by signal
1007         print("Running tests using custom test runner")  # debug message
1008         filter_file, filter_class, filter_func = self.parse_test_option()
1009         print("Active filters: file=%s, class=%s, function=%s" % (
1010             filter_file, filter_class, filter_func))
1011         filtered = self.filter_tests(test, filter_file, filter_class,
1012                                      filter_func)
1013         print("%s out of %s tests match specified filters" % (
1014             filtered.countTestCases(), test.countTestCases()))
1015         if not running_extended_tests():
1016             print("Not running extended tests (some tests will be skipped)")
1017         return super(VppTestRunner, self).run(filtered)