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                 False if c.lower() in ("n", "no", "0") else True
 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     def send_and_assert_no_replies(self, intf, pkts, remark=""):
 751         self.vapi.cli("clear trace")
 752         intf.add_stream(pkts)
 753         self.pg_enable_capture(self.pg_interfaces)
 754         self.pg_start()
 755         timeout = 1
 756         for i in self.pg_interfaces:
 757             i.get_capture(0, timeout=timeout)
 758             i.assert_nothing_captured(remark=remark)
 759             timeout = 0.1
 760
 761     def send_and_expect(self, input, pkts, output):
 762         self.vapi.cli("clear trace")
 763         input.add_stream(pkts)
 764         self.pg_enable_capture(self.pg_interfaces)
 765         self.pg_start()
 766         rx = output.get_capture(len(pkts))
 767         return rx
 768
 769
 770 class TestCasePrinter(object):
 771     _shared_state = {}
 772
 773     def __init__(self):
 774         self.__dict__ = self._shared_state
 775         if not hasattr(self, "_test_case_set"):
 776             self._test_case_set = set()
 777
 778     def print_test_case_heading_if_first_time(self, case):
 779         if case.__class__ not in self._test_case_set:
 780             print(double_line_delim)
 781             print(colorize(getdoc(case.__class__).splitlines()[0], YELLOW))
 782             print(double_line_delim)
 783             self._test_case_set.add(case.__class__)
 784
 785
 786 class VppTestResult(unittest.TestResult):
 787     """
 788     @property result_string
 789      String variable to store the test case result string.
 790     @property errors
 791      List variable containing 2-tuples of TestCase instances and strings
 792      holding formatted tracebacks. Each tuple represents a test which
 793      raised an unexpected exception.
 794     @property failures
 795      List variable containing 2-tuples of TestCase instances and strings
 796      holding formatted tracebacks. Each tuple represents a test where
 797      a failure was explicitly signalled using the TestCase.assert*()
 798      methods.
 799     """
 800
 801     def __init__(self, stream, descriptions, verbosity):
 802         """
 803         :param stream File descriptor to store where to report test results.
 804             Set to the standard error stream by default.
 805         :param descriptions Boolean variable to store information if to use
 806             test case descriptions.
 807         :param verbosity Integer variable to store required verbosity level.
 808         """
 809         unittest.TestResult.__init__(self, stream, descriptions, verbosity)
 810         self.stream = stream
 811         self.descriptions = descriptions
 812         self.verbosity = verbosity
 813         self.result_string = None
 814         self.printer = TestCasePrinter()
 815
 816     def addSuccess(self, test):
 817         """
 818         Record a test succeeded result
 819
 820         :param test:
 821
 822         """
 823         if hasattr(test, 'logger'):
 824             test.logger.debug("--- addSuccess() %s.%s(%s) called"
 825                               % (test.__class__.__name__,
 826                                  test._testMethodName,
 827                                  test._testMethodDoc))
 828         unittest.TestResult.addSuccess(self, test)
 829         self.result_string = colorize("OK", GREEN)
 830
 831     def addSkip(self, test, reason):
 832         """
 833         Record a test skipped.
 834
 835         :param test:
 836         :param reason:
 837
 838         """
 839         if hasattr(test, 'logger'):
 840             test.logger.debug("--- addSkip() %s.%s(%s) called, reason is %s"
 841                               % (test.__class__.__name__,
 842                                  test._testMethodName,
 843                                  test._testMethodDoc,
 844                                  reason))
 845         unittest.TestResult.addSkip(self, test, reason)
 846         self.result_string = colorize("SKIP", YELLOW)
 847
 848     def symlink_failed(self, test):
 849         logger = None
 850         if hasattr(test, 'logger'):
 851             logger = test.logger
 852         if hasattr(test, 'tempdir'):
 853             try:
 854                 failed_dir = os.getenv('VPP_TEST_FAILED_DIR')
 855                 link_path = '%s/%s-FAILED' % (failed_dir,
 856                                               test.tempdir.split("/")[-1])
 857                 if logger:
 858                     logger.debug("creating a link to the failed test")
 859                     logger.debug("os.symlink(%s, %s)" %
 860                                  (test.tempdir, link_path))
 861                 os.symlink(test.tempdir, link_path)
 862             except Exception as e:
 863                 if logger:
 864                     logger.error(e)
 865
 866     def send_failure_through_pipe(self, test):
 867         if hasattr(self, 'test_framework_failed_pipe'):
 868             pipe = self.test_framework_failed_pipe
 869             if pipe:
 870                 pipe.send(test.__class__)
 871
 872     def addFailure(self, test, err):
 873         """
 874         Record a test failed result
 875
 876         :param test:
 877         :param err: error message
 878
 879         """
 880         if hasattr(test, 'logger'):
 881             test.logger.debug("--- addFailure() %s.%s(%s) called, err is %s"
 882                               % (test.__class__.__name__,
 883                                  test._testMethodName,
 884                                  test._testMethodDoc, err))
 885             test.logger.debug("formatted exception is:\n%s" %
 886                               "".join(format_exception(*err)))
 887         unittest.TestResult.addFailure(self, test, err)
 888         if hasattr(test, 'tempdir'):
 889             self.result_string = colorize("FAIL", RED) + \
 890                 ' [ temp dir used by test case: ' + test.tempdir + ' ]'
 891             self.symlink_failed(test)
 892         else:
 893             self.result_string = colorize("FAIL", RED) + ' [no temp dir]'
 894
 895         self.send_failure_through_pipe(test)
 896
 897     def addError(self, test, err):
 898         """
 899         Record a test error result
 900
 901         :param test:
 902         :param err: error message
 903
 904         """
 905         if hasattr(test, 'logger'):
 906             test.logger.debug("--- addError() %s.%s(%s) called, err is %s"
 907                               % (test.__class__.__name__,
 908                                  test._testMethodName,
 909                                  test._testMethodDoc, err))
 910             test.logger.debug("formatted exception is:\n%s" %
 911                               "".join(format_exception(*err)))
 912         unittest.TestResult.addError(self, test, err)
 913         if hasattr(test, 'tempdir'):
 914             self.result_string = colorize("ERROR", RED) + \
 915                 ' [ temp dir used by test case: ' + test.tempdir + ' ]'
 916             self.symlink_failed(test)
 917         else:
 918             self.result_string = colorize("ERROR", RED) + ' [no temp dir]'
 919
 920         self.send_failure_through_pipe(test)
 921
 922     def getDescription(self, test):
 923         """
 924         Get test description
 925
 926         :param test:
 927         :returns: test description
 928
 929         """
 930         # TODO: if none print warning not raise exception
 931         short_description = test.shortDescription()
 932         if self.descriptions and short_description:
 933             return short_description
 934         else:
 935             return str(test)
 936
 937     def startTest(self, test):
 938         """
 939         Start a test
 940
 941         :param test:
 942
 943         """
 944         self.printer.print_test_case_heading_if_first_time(test)
 945         unittest.TestResult.startTest(self, test)
 946         if self.verbosity > 0:
 947             self.stream.writeln(
 948                 "Starting " + self.getDescription(test) + " ...")
 949             self.stream.writeln(single_line_delim)
 950
 951     def stopTest(self, test):
 952         """
 953         Stop a test
 954
 955         :param test:
 956
 957         """
 958         unittest.TestResult.stopTest(self, test)
 959         if self.verbosity > 0:
 960             self.stream.writeln(single_line_delim)
 961             self.stream.writeln("%-73s%s" % (self.getDescription(test),
 962                                              self.result_string))
 963             self.stream.writeln(single_line_delim)
 964         else:
 965             self.stream.writeln("%-73s%s" % (self.getDescription(test),
 966                                              self.result_string))
 967
 968     def printErrors(self):
 969         """
 970         Print errors from running the test case
 971         """
 972         self.stream.writeln()
 973         self.printErrorList('ERROR', self.errors)
 974         self.printErrorList('FAIL', self.failures)
 975
 976     def printErrorList(self, flavour, errors):
 977         """
 978         Print error list to the output stream together with error type
 979         and test case description.
 980
 981         :param flavour: error type
 982         :param errors: iterable errors
 983
 984         """
 985         for test, err in errors:
 986             self.stream.writeln(double_line_delim)
 987             self.stream.writeln("%s: %s" %
 988                                 (flavour, self.getDescription(test)))
 989             self.stream.writeln(single_line_delim)
 990             self.stream.writeln("%s" % err)
 991
 992
 993 class Filter_by_test_option:
 994     def __init__(self, filter_file_name, filter_class_name, filter_func_name):
 995         self.filter_file_name = filter_file_name
 996         self.filter_class_name = filter_class_name
 997         self.filter_func_name = filter_func_name
 998
 999     def __call__(self, file_name, class_name, func_name):
1000         if self.filter_file_name and file_name != self.filter_file_name:
1001             return False
1002         if self.filter_class_name and class_name != self.filter_class_name:
1003             return False
1004         if self.filter_func_name and func_name != self.filter_func_name:
1005             return False
1006         return True
1007
1008
1009 class VppTestRunner(unittest.TextTestRunner):
1010     """
1011     A basic test runner implementation which prints results to standard error.
1012     """
1013     @property
1014     def resultclass(self):
1015         """Class maintaining the results of the tests"""
1016         return VppTestResult
1017
1018     def __init__(self, keep_alive_pipe=None, failed_pipe=None,
1019                  stream=sys.stderr, descriptions=True,
1020                  verbosity=1, failfast=False, buffer=False, resultclass=None):
1021         # ignore stream setting here, use hard-coded stdout to be in sync
1022         # with prints from VppTestCase methods ...
1023         super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1024                                             verbosity, failfast, buffer,
1025                                             resultclass)
1026         reporter = KeepAliveReporter()
1027         reporter.pipe = keep_alive_pipe
1028         # this is super-ugly, but very simple to implement and works as long
1029         # as we run only one test at the same time
1030         VppTestResult.test_framework_failed_pipe = failed_pipe
1031
1032     test_option = "TEST"
1033
1034     def parse_test_option(self):
1035         try:
1036             f = os.getenv(self.test_option)
1037         except:
1038             f = None
1039         filter_file_name = None
1040         filter_class_name = None
1041         filter_func_name = None
1042         if f:
1043             if '.' in f:
1044                 parts = f.split('.')
1045                 if len(parts) > 3:
1046                     raise Exception("Unrecognized %s option: %s" %
1047                                     (self.test_option, f))
1048                 if len(parts) > 2:
1049                     if parts[2] not in ('*', ''):
1050                         filter_func_name = parts[2]
1051                 if parts[1] not in ('*', ''):
1052                     filter_class_name = parts[1]
1053                 if parts[0] not in ('*', ''):
1054                     if parts[0].startswith('test_'):
1055                         filter_file_name = parts[0]
1056                     else:
1057                         filter_file_name = 'test_%s' % parts[0]
1058             else:
1059                 if f.startswith('test_'):
1060                     filter_file_name = f
1061                 else:
1062                     filter_file_name = 'test_%s' % f
1063         return filter_file_name, filter_class_name, filter_func_name
1064
1065     @staticmethod
1066     def filter_tests(tests, filter_cb):
1067         result = unittest.suite.TestSuite()
1068         for t in tests:
1069             if isinstance(t, unittest.suite.TestSuite):
1070                 # this is a bunch of tests, recursively filter...
1071                 x = filter_tests(t, filter_cb)
1072                 if x.countTestCases() > 0:
1073                     result.addTest(x)
1074             elif isinstance(t, unittest.TestCase):
1075                 # this is a single test
1076                 parts = t.id().split('.')
1077                 # t.id() for common cases like this:
1078                 # test_classifier.TestClassifier.test_acl_ip
1079                 # apply filtering only if it is so
1080                 if len(parts) == 3:
1081                     if not filter_cb(parts[0], parts[1], parts[2]):
1082                         continue
1083                 result.addTest(t)
1084             else:
1085                 # unexpected object, don't touch it
1086                 result.addTest(t)
1087         return result
1088
1089     def run(self, test):
1090         """
1091         Run the tests
1092
1093         :param test:
1094
1095         """
1096         faulthandler.enable()  # emit stack trace to stderr if killed by signal
1097         print("Running tests using custom test runner")  # debug message
1098         filter_file, filter_class, filter_func = self.parse_test_option()
1099         print("Active filters: file=%s, class=%s, function=%s" % (
1100             filter_file, filter_class, filter_func))
1101         filter_cb = Filter_by_test_option(
1102             filter_file, filter_class, filter_func)
1103         filtered = self.filter_tests(test, filter_cb)
1104         print("%s out of %s tests match specified filters" % (
1105             filtered.countTestCases(), test.countTestCases()))
1106         if not running_extended_tests():
1107             print("Not running extended tests (some tests will be skipped)")
1108         return super(VppTestRunner, self).run(filtered)
1109
1110
1111 class Worker(Thread):
1112     def __init__(self, args, logger):
1113         self.logger = logger
1114         self.args = args
1115         self.result = None
1116         super(Worker, self).__init__()
1117
1118     def run(self):
1119         executable = self.args[0]
1120         self.logger.debug("Running executable w/args `%s'" % self.args)
1121         env = os.environ.copy()
1122         env["CK_LOG_FILE_NAME"] = "-"
1123         self.process = subprocess.Popen(
1124             self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1125             stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1126         out, err = self.process.communicate()
1127         self.logger.debug("Finished running `%s'" % executable)
1128         self.logger.info("Return code is `%s'" % self.process.returncode)
1129         self.logger.info(single_line_delim)
1130         self.logger.info("Executable `%s' wrote to stdout:" % executable)
1131         self.logger.info(single_line_delim)
1132         self.logger.info(out)
1133         self.logger.info(single_line_delim)
1134         self.logger.info("Executable `%s' wrote to stderr:" % executable)
1135         self.logger.info(single_line_delim)
1136         self.logger.error(err)
1137         self.logger.info(single_line_delim)
1138         self.result = self.process.returncode