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