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