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