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