framework.py revision 0c629323
1#!/usr/bin/env python3
2
3from __future__ import print_function
4import gc
5import sys
6import os
7import select
8import signal
9import unittest
10import tempfile
11import time
12import faulthandler
13import random
14import copy
15import psutil
16import platform
17from collections import deque
18from threading import Thread, Event
19from inspect import getdoc, isclass
20from traceback import format_exception
21from logging import FileHandler, DEBUG, Formatter
22
23import scapy.compat
24from scapy.packet import Raw
25import hook as hookmodule
26from vpp_pg_interface import VppPGInterface
27from vpp_sub_interface import VppSubInterface
28from vpp_lo_interface import VppLoInterface
29from vpp_bvi_interface import VppBviInterface
30from vpp_papi_provider import VppPapiProvider
31import vpp_papi
32from vpp_papi.vpp_stats import VPPStats
33from vpp_papi.vpp_transport_shmem import VppTransportShmemIOError
34from log import RED, GREEN, YELLOW, double_line_delim, single_line_delim, \
35    get_logger, colorize
36from vpp_object import VppObjectRegistry
37from util import ppp, is_core_present
38from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
39from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
40from scapy.layers.inet6 import ICMPv6EchoReply
41
42if os.name == 'posix' and sys.version_info[0] < 3:
43    # using subprocess32 is recommended by python official documentation
44    # @ https://docs.python.org/2/library/subprocess.html
45    import subprocess32 as subprocess
46else:
47    import subprocess
48
49#  Python2/3 compatible
50try:
51    input = raw_input
52except NameError:
53    pass
54
55PASS = 0
56FAIL = 1
57ERROR = 2
58SKIP = 3
59TEST_RUN = 4
60
61
62class BoolEnvironmentVariable(object):
63
64    def __init__(self, env_var_name, default='n', true_values=None):
65        self.name = env_var_name
66        self.default = default
67        self.true_values = true_values if true_values is not None else \
68            ("y", "yes", "1")
69
70    def __bool__(self):
71        return os.getenv(self.name, self.default).lower() in self.true_values
72
73    if sys.version_info[0] == 2:
74        __nonzero__ = __bool__
75
76    def __repr__(self):
77        return 'BoolEnvironmentVariable(%r, default=%r, true_values=%r)' % \
78               (self.name, self.default, self.true_values)
79
80
81debug_framework = BoolEnvironmentVariable('TEST_DEBUG')
82if debug_framework:
83    import debug_internal
84
85"""
86  Test framework module.
87
88  The module provides a set of tools for constructing and running tests and
89  representing the results.
90"""
91
92
93class VppDiedError(Exception):
94    """ exception for reporting that the subprocess has died."""
95
96    signals_by_value = {v: k for k, v in signal.__dict__.items() if
97                        k.startswith('SIG') and not k.startswith('SIG_')}
98
99    def __init__(self, rv=None, testcase=None, method_name=None):
100        self.rv = rv
101        self.signal_name = None
102        self.testcase = testcase
103        self.method_name = method_name
104
105        try:
106            self.signal_name = VppDiedError.signals_by_value[-rv]
107        except (KeyError, TypeError):
108            pass
109
110        if testcase is None and method_name is None:
111            in_msg = ''
112        else:
113            in_msg = 'running %s.%s ' % (testcase, method_name)
114
115        msg = "VPP subprocess died %sunexpectedly with return code: %d%s." % (
116            in_msg,
117            self.rv,
118            ' [%s]' % (self.signal_name if
119                       self.signal_name is not None else ''))
120        super(VppDiedError, self).__init__(msg)
121
122
123class _PacketInfo(object):
124    """Private class to create packet info object.
125
126    Help process information about the next packet.
127    Set variables to default values.
128    """
129    #: Store the index of the packet.
130    index = -1
131    #: Store the index of the source packet generator interface of the packet.
132    src = -1
133    #: Store the index of the destination packet generator interface
134    #: of the packet.
135    dst = -1
136    #: Store expected ip version
137    ip = -1
138    #: Store expected upper protocol
139    proto = -1
140    #: Store the copy of the former packet.
141    data = None
142
143    def __eq__(self, other):
144        index = self.index == other.index
145        src = self.src == other.src
146        dst = self.dst == other.dst
147        data = self.data == other.data
148        return index and src and dst and data
149
150
151def pump_output(testclass):
152    """ pump output from vpp stdout/stderr to proper queues """
153    stdout_fragment = ""
154    stderr_fragment = ""
155    while not testclass.pump_thread_stop_flag.is_set():
156        readable = select.select([testclass.vpp.stdout.fileno(),
157                                  testclass.vpp.stderr.fileno(),
158                                  testclass.pump_thread_wakeup_pipe[0]],
159                                 [], [])[0]
160        if testclass.vpp.stdout.fileno() in readable:
161            read = os.read(testclass.vpp.stdout.fileno(), 102400)
162            if len(read) > 0:
163                split = read.decode('ascii',
164                                    errors='backslashreplace').splitlines(True)
165                if len(stdout_fragment) > 0:
166                    split[0] = "%s%s" % (stdout_fragment, split[0])
167                if len(split) > 0 and split[-1].endswith("\n"):
168                    limit = None
169                else:
170                    limit = -1
171                    stdout_fragment = split[-1]
172                testclass.vpp_stdout_deque.extend(split[:limit])
173                if not testclass.cache_vpp_output:
174                    for line in split[:limit]:
175                        testclass.logger.info(
176                            "VPP STDOUT: %s" % line.rstrip("\n"))
177        if testclass.vpp.stderr.fileno() in readable:
178            read = os.read(testclass.vpp.stderr.fileno(), 102400)
179            if len(read) > 0:
180                split = read.decode('ascii',
181                                    errors='backslashreplace').splitlines(True)
182                if len(stderr_fragment) > 0:
183                    split[0] = "%s%s" % (stderr_fragment, split[0])
184                if len(split) > 0 and split[-1].endswith("\n"):
185                    limit = None
186                else:
187                    limit = -1
188                    stderr_fragment = split[-1]
189
190                testclass.vpp_stderr_deque.extend(split[:limit])
191                if not testclass.cache_vpp_output:
192                    for line in split[:limit]:
193                        testclass.logger.error(
194                            "VPP STDERR: %s" % line.rstrip("\n"))
195                        # ignoring the dummy pipe here intentionally - the
196                        # flag will take care of properly terminating the loop
197
198
199def _is_skip_aarch64_set():
200    return BoolEnvironmentVariable('SKIP_AARCH64')
201
202
203is_skip_aarch64_set = _is_skip_aarch64_set()
204
205
206def _is_platform_aarch64():
207    return platform.machine() == 'aarch64'
208
209
210is_platform_aarch64 = _is_platform_aarch64()
211
212
213def _running_extended_tests():
214    return BoolEnvironmentVariable("EXTENDED_TESTS")
215
216
217running_extended_tests = _running_extended_tests()
218
219
220def _running_on_centos():
221    os_id = os.getenv("OS_ID", "")
222    return True if "centos" in os_id.lower() else False
223
224
225running_on_centos = _running_on_centos()
226
227
228class KeepAliveReporter(object):
229    """
230    Singleton object which reports test start to parent process
231    """
232    _shared_state = {}
233
234    def __init__(self):
235        self.__dict__ = self._shared_state
236        self._pipe = None
237
238    @property
239    def pipe(self):
240        return self._pipe
241
242    @pipe.setter
243    def pipe(self, pipe):
244        if self._pipe is not None:
245            raise Exception("Internal error - pipe should only be set once.")
246        self._pipe = pipe
247
248    def send_keep_alive(self, test, desc=None):
249        """
250        Write current test tmpdir & desc to keep-alive pipe to signal liveness
251        """
252        if self.pipe is None:
253            # if not running forked..
254            return
255
256        if isclass(test):
257            desc = '%s (%s)' % (desc, unittest.util.strclass(test))
258        else:
259            desc = test.id()
260
261        self.pipe.send((desc, test.vpp_bin, test.tempdir, test.vpp.pid))
262
263
264class VppTestCase(unittest.TestCase):
265    """This subclass is a base class for VPP test cases that are implemented as
266    classes. It provides methods to create and run test case.
267    """
268
269    extra_vpp_punt_config = []
270    extra_vpp_plugin_config = []
271    vapi_response_timeout = 5
272
273    @property
274    def packet_infos(self):
275        """List of packet infos"""
276        return self._packet_infos
277
278    @classmethod
279    def get_packet_count_for_if_idx(cls, dst_if_index):
280        """Get the number of packet info for specified destination if index"""
281        if dst_if_index in cls._packet_count_for_dst_if_idx:
282            return cls._packet_count_for_dst_if_idx[dst_if_index]
283        else:
284            return 0
285
286    @classmethod
287    def instance(cls):
288        """Return the instance of this testcase"""
289        return cls.test_instance
290
291    @classmethod
292    def set_debug_flags(cls, d):
293        cls.gdbserver_port = 7777
294        cls.debug_core = False
295        cls.debug_gdb = False
296        cls.debug_gdbserver = False
297        cls.debug_all = False
298        if d is None:
299            return
300        dl = d.lower()
301        if dl == "core":
302            cls.debug_core = True
303        elif dl == "gdb" or dl == "gdb-all":
304            cls.debug_gdb = True
305        elif dl == "gdbserver" or dl == "gdbserver-all":
306            cls.debug_gdbserver = True
307        else:
308            raise Exception("Unrecognized DEBUG option: '%s'" % d)
309        if dl == "gdb-all" or dl == "gdbserver-all":
310            cls.debug_all = True
311
312    @staticmethod
313    def get_least_used_cpu():
314        cpu_usage_list = [set(range(psutil.cpu_count()))]
315        vpp_processes = [p for p in psutil.process_iter(attrs=['pid', 'name'])
316                         if 'vpp_main' == p.info['name']]
317        for vpp_process in vpp_processes:
318            for cpu_usage_set in cpu_usage_list:
319                try:
320                    cpu_num = vpp_process.cpu_num()
321                    if cpu_num in cpu_usage_set:
322                        cpu_usage_set_index = cpu_usage_list.index(
323                            cpu_usage_set)
324                        if cpu_usage_set_index == len(cpu_usage_list) - 1:
325                            cpu_usage_list.append({cpu_num})
326                        else:
327                            cpu_usage_list[cpu_usage_set_index + 1].add(
328                                cpu_num)
329                        cpu_usage_set.remove(cpu_num)
330                        break
331                except psutil.NoSuchProcess:
332                    pass
333
334        for cpu_usage_set in cpu_usage_list:
335            if len(cpu_usage_set) > 0:
336                min_usage_set = cpu_usage_set
337                break
338
339        return random.choice(tuple(min_usage_set))
340
341    @classmethod
342    def setUpConstants(cls):
343        """ Set-up the test case class based on environment variables """
344        cls.step = BoolEnvironmentVariable('STEP')
345        d = os.getenv("DEBUG", None)
346        # inverted case to handle '' == True
347        c = os.getenv("CACHE_OUTPUT", "1")
348        cls.cache_vpp_output = False if c.lower() in ("n", "no", "0") else True
349        cls.set_debug_flags(d)
350        cls.vpp_bin = os.getenv('VPP_BIN', "vpp")
351        cls.plugin_path = os.getenv('VPP_PLUGIN_PATH')
352        cls.test_plugin_path = os.getenv('VPP_TEST_PLUGIN_PATH')
353        cls.extern_plugin_path = os.getenv('EXTERN_PLUGINS')
354        plugin_path = None
355        if cls.plugin_path is not None:
356            if cls.extern_plugin_path is not None:
357                plugin_path = "%s:%s" % (
358                    cls.plugin_path, cls.extern_plugin_path)
359            else:
360                plugin_path = cls.plugin_path
361        elif cls.extern_plugin_path is not None:
362            plugin_path = cls.extern_plugin_path
363        debug_cli = ""
364        if cls.step or cls.debug_gdb or cls.debug_gdbserver:
365            debug_cli = "cli-listen localhost:5002"
366        coredump_size = None
367        size = os.getenv("COREDUMP_SIZE")
368        if size is not None:
369            coredump_size = "coredump-size %s" % size
370        if coredump_size is None:
371            coredump_size = "coredump-size unlimited"
372
373        cpu_core_number = cls.get_least_used_cpu()
374        if not hasattr(cls, "worker_config"):
375            cls.worker_config = ""
376
377        cls.vpp_cmdline = [cls.vpp_bin, "unix",
378                           "{", "nodaemon", debug_cli, "full-coredump",
379                           coredump_size, "runtime-dir", cls.tempdir, "}",
380                           "api-trace", "{", "on", "}", "api-segment", "{",
381                           "prefix", cls.shm_prefix, "}", "cpu", "{",
382                           "main-core", str(cpu_core_number),
383                           cls.worker_config, "}",
384                           "statseg", "{", "socket-name", cls.stats_sock, "}",
385                           "socksvr", "{", "socket-name", cls.api_sock, "}",
386                           "plugins",
387                           "{", "plugin", "dpdk_plugin.so", "{", "disable",
388                           "}", "plugin", "rdma_plugin.so", "{", "disable",
389                           "}", "plugin", "unittest_plugin.so", "{", "enable",
390                           "}"] + cls.extra_vpp_plugin_config + ["}", ]
391        if cls.extra_vpp_punt_config is not None:
392            cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
393        if plugin_path is not None:
394            cls.vpp_cmdline.extend(["plugin_path", plugin_path])
395        if cls.test_plugin_path is not None:
396            cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
397
398        cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
399        cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
400
401    @classmethod
402    def wait_for_enter(cls):
403        if cls.debug_gdbserver:
404            print(double_line_delim)
405            print("Spawned GDB server with PID: %d" % cls.vpp.pid)
406        elif cls.debug_gdb:
407            print(double_line_delim)
408            print("Spawned VPP with PID: %d" % cls.vpp.pid)
409        else:
410            cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
411            return
412        print(single_line_delim)
413        print("You can debug VPP using:")
414        if cls.debug_gdbserver:
415            print("sudo gdb " + cls.vpp_bin +
416                  " -ex 'target remote localhost:{port}'"
417                  .format(port=cls.gdbserver_port))
418            print("Now is the time to attach gdb by running the above "
419                  "command, set up breakpoints etc., then resume VPP from "
420                  "within gdb by issuing the 'continue' command")
421            cls.gdbserver_port += 1
422        elif cls.debug_gdb:
423            print("sudo gdb " + cls.vpp_bin + " -ex 'attach %s'" % cls.vpp.pid)
424            print("Now is the time to attach gdb by running the above "
425                  "command and set up breakpoints etc., then resume VPP from"
426                  " within gdb by issuing the 'continue' command")
427        print(single_line_delim)
428        input("Press ENTER to continue running the testcase...")
429
430    @classmethod
431    def run_vpp(cls):
432        cmdline = cls.vpp_cmdline
433
434        if cls.debug_gdbserver:
435            gdbserver = '/usr/bin/gdbserver'
436            if not os.path.isfile(gdbserver) or \
437                    not os.access(gdbserver, os.X_OK):
438                raise Exception("gdbserver binary '%s' does not exist or is "
439                                "not executable" % gdbserver)
440
441            cmdline = [gdbserver, 'localhost:{port}'
442                       .format(port=cls.gdbserver_port)] + cls.vpp_cmdline
443            cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
444
445        try:
446            cls.vpp = subprocess.Popen(cmdline,
447                                       stdout=subprocess.PIPE,
448                                       stderr=subprocess.PIPE,
449                                       bufsize=1)
450        except subprocess.CalledProcessError as e:
451            cls.logger.critical("Subprocess returned with non-0 return code: ("
452                                "%s)", e.returncode)
453            raise
454        except OSError as e:
455            cls.logger.critical("Subprocess returned with OS error: "
456                                "(%s) %s", e.errno, e.strerror)
457            raise
458        except Exception as e:
459            cls.logger.exception("Subprocess returned unexpected from "
460                                 "%s:", cmdline)
461            raise
462
463        cls.wait_for_enter()
464
465    @classmethod
466    def wait_for_stats_socket(cls):
467        deadline = time.time() + 300
468        ok = False
469        while time.time() < deadline or \
470                cls.debug_gdb or cls.debug_gdbserver:
471            if os.path.exists(cls.stats_sock):
472                ok = True
473                break
474            cls.sleep(0.8)
475        if not ok:
476            cls.logger.critical("Couldn't stat : {}".format(cls.stats_sock))
477
478    @classmethod
479    def wait_for_coredump(cls):
480        corefile = cls.tempdir + "/core"
481        if os.path.isfile(corefile):
482            cls.logger.error("Waiting for coredump to complete: %s", corefile)
483            curr_size = os.path.getsize(corefile)
484            deadline = time.time() + 60
485            ok = False
486            while time.time() < deadline:
487                cls.sleep(1)
488                size = curr_size
489                curr_size = os.path.getsize(corefile)
490                if size == curr_size:
491                    ok = True
492                    break
493            if not ok:
494                cls.logger.error("Timed out waiting for coredump to complete:"
495                                 " %s", corefile)
496            else:
497                cls.logger.error("Coredump complete: %s, size %d",
498                                 corefile, curr_size)
499
500    @classmethod
501    def setUpClass(cls):
502        """
503        Perform class setup before running the testcase
504        Remove shared memory files, start vpp and connect the vpp-api
505        """
506        super(VppTestCase, cls).setUpClass()
507        gc.collect()  # run garbage collection first
508        cls.logger = get_logger(cls.__name__)
509        seed = os.environ["RND_SEED"]
510        random.seed(seed)
511        if hasattr(cls, 'parallel_handler'):
512            cls.logger.addHandler(cls.parallel_handler)
513            cls.logger.propagate = False
514
515        cls.tempdir = tempfile.mkdtemp(
516            prefix='vpp-unittest-%s-' % cls.__name__)
517        cls.stats_sock = "%s/stats.sock" % cls.tempdir
518        cls.api_sock = "%s/api.sock" % cls.tempdir
519        cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
520        cls.file_handler.setFormatter(
521            Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
522                      datefmt="%H:%M:%S"))
523        cls.file_handler.setLevel(DEBUG)
524        cls.logger.addHandler(cls.file_handler)
525        cls.logger.debug("--- setUpClass() for %s called ---" %
526                         cls.__name__)
527        cls.shm_prefix = os.path.basename(cls.tempdir)
528        os.chdir(cls.tempdir)
529        cls.logger.info("Temporary dir is %s, shm prefix is %s",
530                        cls.tempdir, cls.shm_prefix)
531        cls.logger.debug("Random seed is %s" % seed)
532        cls.setUpConstants()
533        cls.reset_packet_infos()
534        cls._captures = []
535        cls.verbose = 0
536        cls.vpp_dead = False
537        cls.registry = VppObjectRegistry()
538        cls.vpp_startup_failed = False
539        cls.reporter = KeepAliveReporter()
540        # need to catch exceptions here because if we raise, then the cleanup
541        # doesn't get called and we might end with a zombie vpp
542        try:
543            cls.run_vpp()
544            cls.reporter.send_keep_alive(cls, 'setUpClass')
545            VppTestResult.current_test_case_info = TestCaseInfo(
546                cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
547            cls.vpp_stdout_deque = deque()
548            cls.vpp_stderr_deque = deque()
549            cls.pump_thread_stop_flag = Event()
550            cls.pump_thread_wakeup_pipe = os.pipe()
551            cls.pump_thread = Thread(target=pump_output, args=(cls,))
552            cls.pump_thread.daemon = True
553            cls.pump_thread.start()
554            if cls.debug_gdb or cls.debug_gdbserver:
555                cls.vapi_response_timeout = 0
556            cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
557                                       cls.vapi_response_timeout)
558            if cls.step:
559                hook = hookmodule.StepHook(cls)
560            else:
561                hook = hookmodule.PollHook(cls)
562            cls.vapi.register_hook(hook)
563            cls.wait_for_stats_socket()
564            cls.statistics = VPPStats(socketname=cls.stats_sock)
565            try:
566                hook.poll_vpp()
567            except VppDiedError:
568                cls.vpp_startup_failed = True
569                cls.logger.critical(
570                    "VPP died shortly after startup, check the"
571                    " output to standard error for possible cause")
572                raise
573            try:
574                cls.vapi.connect()
575            except vpp_papi.VPPIOError as e:
576                cls.logger.debug("Exception connecting to vapi: %s" % e)
577                cls.vapi.disconnect()
578
579                if cls.debug_gdbserver:
580                    print(colorize("You're running VPP inside gdbserver but "
581                                   "VPP-API connection failed, did you forget "
582                                   "to 'continue' VPP from within gdb?", RED))
583                raise
584        except Exception as e:
585            cls.logger.debug("Exception connecting to VPP: %s" % e)
586
587            cls.quit()
588            raise
589
590    @classmethod
591    def quit(cls):
592        """
593        Disconnect vpp-api, kill vpp and cleanup shared memory files
594        """
595        if (cls.debug_gdbserver or cls.debug_gdb) and hasattr(cls, 'vpp'):
596            cls.vpp.poll()
597            if cls.vpp.returncode is None:
598                print()
599                print(double_line_delim)
600                print("VPP or GDB server is still running")
601                print(single_line_delim)
602                input("When done debugging, press ENTER to kill the "
603                      "process and finish running the testcase...")
604
605        # first signal that we want to stop the pump thread, then wake it up
606        if hasattr(cls, 'pump_thread_stop_flag'):
607            cls.pump_thread_stop_flag.set()
608        if hasattr(cls, 'pump_thread_wakeup_pipe'):
609            os.write(cls.pump_thread_wakeup_pipe[1], b'ding dong wake up')
610        if hasattr(cls, 'pump_thread'):
611            cls.logger.debug("Waiting for pump thread to stop")
612            cls.pump_thread.join()
613        if hasattr(cls, 'vpp_stderr_reader_thread'):
614            cls.logger.debug("Waiting for stdderr pump to stop")
615            cls.vpp_stderr_reader_thread.join()
616
617        if hasattr(cls, 'vpp'):
618            if hasattr(cls, 'vapi'):
619                cls.logger.debug("Disconnecting class vapi client on %s",
620                                 cls.__name__)
621                cls.vapi.disconnect()
622                cls.logger.debug("Deleting class vapi attribute on %s",
623                                 cls.__name__)
624                del cls.vapi
625            cls.vpp.poll()
626            if cls.vpp.returncode is None:
627                cls.wait_for_coredump()
628                cls.logger.debug("Sending TERM to vpp")
629                cls.vpp.terminate()
630                cls.logger.debug("Waiting for vpp to die")
631                cls.vpp.communicate()
632            cls.logger.debug("Deleting class vpp attribute on %s",
633                             cls.__name__)
634            del cls.vpp
635
636        if cls.vpp_startup_failed:
637            stdout_log = cls.logger.info
638            stderr_log = cls.logger.critical
639        else:
640            stdout_log = cls.logger.info
641            stderr_log = cls.logger.info
642
643        if hasattr(cls, 'vpp_stdout_deque'):
644            stdout_log(single_line_delim)
645            stdout_log('VPP output to stdout while running %s:', cls.__name__)
646            stdout_log(single_line_delim)
647            vpp_output = "".join(cls.vpp_stdout_deque)
648            with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
649                f.write(vpp_output)
650            stdout_log('\n%s', vpp_output)
651            stdout_log(single_line_delim)
652
653        if hasattr(cls, 'vpp_stderr_deque'):
654            stderr_log(single_line_delim)
655            stderr_log('VPP output to stderr while running %s:', cls.__name__)
656            stderr_log(single_line_delim)
657            vpp_output = "".join(cls.vpp_stderr_deque)
658            with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
659                f.write(vpp_output)
660            stderr_log('\n%s', vpp_output)
661            stderr_log(single_line_delim)
662
663    @classmethod
664    def tearDownClass(cls):
665        """ Perform final cleanup after running all tests in this test-case """
666        cls.logger.debug("--- tearDownClass() for %s called ---" %
667                         cls.__name__)
668        cls.reporter.send_keep_alive(cls, 'tearDownClass')
669        cls.quit()
670        cls.file_handler.close()
671        cls.reset_packet_infos()
672        if debug_framework:
673            debug_internal.on_tear_down_class(cls)
674
675    def show_commands_at_teardown(self):
676        """ Allow subclass specific teardown logging additions."""
677        self.logger.info("--- No test specific show commands provided. ---")
678
679    def tearDown(self):
680        """ Show various debug prints after each test """
681        self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
682                          (self.__class__.__name__, self._testMethodName,
683                           self._testMethodDoc))
684
685        try:
686            if not self.vpp_dead:
687                self.logger.debug(self.vapi.cli("show trace max 1000"))
688                self.logger.info(self.vapi.ppcli("show interface"))
689                self.logger.info(self.vapi.ppcli("show hardware"))
690                self.logger.info(self.statistics.set_errors_str())
691                self.logger.info(self.vapi.ppcli("show run"))
692                self.logger.info(self.vapi.ppcli("show log"))
693                self.logger.info(self.vapi.ppcli("show bihash"))
694                self.logger.info("Logging testcase specific show commands.")
695                self.show_commands_at_teardown()
696                self.registry.remove_vpp_config(self.logger)
697            # Save/Dump VPP api trace log
698            m = self._testMethodName
699            api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
700            tmp_api_trace = "/tmp/%s" % api_trace
701            vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
702            self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
703            self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
704                                                    vpp_api_trace_log))
705            os.rename(tmp_api_trace, vpp_api_trace_log)
706            self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
707                                             vpp_api_trace_log))
708        except VppTransportShmemIOError:
709            self.logger.debug("VppTransportShmemIOError: Vpp dead. "
710                              "Cannot log show commands.")
711            self.vpp_dead = True
712        else:
713            self.registry.unregister_all(self.logger)
714
715    def setUp(self):
716        """ Clear trace before running each test"""
717        super(VppTestCase, self).setUp()
718        self.reporter.send_keep_alive(self)
719        if self.vpp_dead:
720
721            raise VppDiedError(rv=None, testcase=self.__class__.__name__,
722                               method_name=self._testMethodName)
723        self.sleep(.1, "during setUp")
724        self.vpp_stdout_deque.append(
725            "--- test setUp() for %s.%s(%s) starts here ---\n" %
726            (self.__class__.__name__, self._testMethodName,
727             self._testMethodDoc))
728        self.vpp_stderr_deque.append(
729            "--- test setUp() for %s.%s(%s) starts here ---\n" %
730            (self.__class__.__name__, self._testMethodName,
731             self._testMethodDoc))
732        self.vapi.cli("clear trace")
733        # store the test instance inside the test class - so that objects
734        # holding the class can access instance methods (like assertEqual)
735        type(self).test_instance = self
736
737    @classmethod
738    def pg_enable_capture(cls, interfaces=None):
739        """
740        Enable capture on packet-generator interfaces
741
742        :param interfaces: iterable interface indexes (if None,
743                           use self.pg_interfaces)
744
745        """
746        if interfaces is None:
747            interfaces = cls.pg_interfaces
748        for i in interfaces:
749            i.enable_capture()
750
751    @classmethod
752    def register_capture(cls, cap_name):
753        """ Register a capture in the testclass """
754        # add to the list of captures with current timestamp
755        cls._captures.append((time.time(), cap_name))
756
757    @classmethod
758    def get_vpp_time(cls):
759        return float(cls.vapi.cli('show clock').replace("Time now ", ""))
760
761    @classmethod
762    def sleep_on_vpp_time(cls, sec):
763        """ Sleep according to time in VPP world """
764        # On a busy system with many processes
765        # we might end up with VPP time being slower than real world
766        # So take that into account when waiting for VPP to do something
767        start_time = cls.get_vpp_time()
768        while cls.get_vpp_time() - start_time < sec:
769            cls.sleep(0.1)
770
771    @classmethod
772    def pg_start(cls):
773        """ Enable the PG, wait till it is done, then clean up """
774        cls.vapi.cli("trace add pg-input 1000")
775        cls.vapi.cli('packet-generator enable')
776        # PG, when starts, runs to completion -
777        # so let's avoid a race condition,
778        # and wait a little till it's done.
779        # Then clean it up  - and then be gone.
780        deadline = time.time() + 300
781        while cls.vapi.cli('show packet-generator').find("Yes") != -1:
782            cls.sleep(0.01)  # yield
783            if time.time() > deadline:
784                cls.logger.error("Timeout waiting for pg to stop")
785                break
786        for stamp, cap_name in cls._captures:
787            cls.vapi.cli('packet-generator delete %s' % cap_name)
788        cls._captures = []
789
790    @classmethod
791    def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
792        """
793        Create packet-generator interfaces.
794
795        :param interfaces: iterable indexes of the interfaces.
796        :returns: List of created interfaces.
797
798        """
799        result = []
800        for i in interfaces:
801            intf = VppPGInterface(cls, i, gso, gso_size)
802            setattr(cls, intf.name, intf)
803            result.append(intf)
804        cls.pg_interfaces = result
805        return result
806
807    @classmethod
808    def create_loopback_interfaces(cls, count):
809        """
810        Create loopback interfaces.
811
812        :param count: number of interfaces created.
813        :returns: List of created interfaces.
814        """
815        result = [VppLoInterface(cls) for i in range(count)]
816        for intf in result:
817            setattr(cls, intf.name, intf)
818        cls.lo_interfaces = result
819        return result
820
821    @classmethod
822    def create_bvi_interfaces(cls, count):
823        """
824        Create BVI interfaces.
825
826        :param count: number of interfaces created.
827        :returns: List of created interfaces.
828        """
829        result = [VppBviInterface(cls) for i in range(count)]
830        for intf in result:
831            setattr(cls, intf.name, intf)
832        cls.bvi_interfaces = result
833        return result
834
835    @staticmethod
836    def extend_packet(packet, size, padding=' '):
837        """
838        Extend packet to given size by padding with spaces or custom padding
839        NOTE: Currently works only when Raw layer is present.
840
841        :param packet: packet
842        :param size: target size
843        :param padding: padding used to extend the payload
844
845        """
846        packet_len = len(packet) + 4
847        extend = size - packet_len
848        if extend > 0:
849            num = (extend // len(padding)) + 1
850            packet[Raw].load += (padding * num)[:extend].encode("ascii")
851
852    @classmethod
853    def reset_packet_infos(cls):
854        """ Reset the list of packet info objects and packet counts to zero """
855        cls._packet_infos = {}
856        cls._packet_count_for_dst_if_idx = {}
857
858    @classmethod
859    def create_packet_info(cls, src_if, dst_if):
860        """
861        Create packet info object containing the source and destination indexes
862        and add it to the testcase's packet info list
863
864        :param VppInterface src_if: source interface
865        :param VppInterface dst_if: destination interface
866
867        :returns: _PacketInfo object
868
869        """
870        info = _PacketInfo()
871        info.index = len(cls._packet_infos)
872        info.src = src_if.sw_if_index
873        info.dst = dst_if.sw_if_index
874        if isinstance(dst_if, VppSubInterface):
875            dst_idx = dst_if.parent.sw_if_index
876        else:
877            dst_idx = dst_if.sw_if_index
878        if dst_idx in cls._packet_count_for_dst_if_idx:
879            cls._packet_count_for_dst_if_idx[dst_idx] += 1
880        else:
881            cls._packet_count_for_dst_if_idx[dst_idx] = 1
882        cls._packet_infos[info.index] = info
883        return info
884
885    @staticmethod
886    def info_to_payload(info):
887        """
888        Convert _PacketInfo object to packet payload
889
890        :param info: _PacketInfo object
891
892        :returns: string containing serialized data from packet info
893        """
894        return "%d %d %d %d %d" % (info.index, info.src, info.dst,
895                                   info.ip, info.proto)
896
897    @staticmethod
898    def payload_to_info(payload, payload_field='load'):
899        """
900        Convert packet payload to _PacketInfo object
901
902        :param payload: packet payload
903        :type payload:  <class 'scapy.packet.Raw'>
904        :param payload_field: packet fieldname of payload "load" for
905                <class 'scapy.packet.Raw'>
906        :type payload_field: str
907        :returns: _PacketInfo object containing de-serialized data from payload
908
909        """
910        numbers = getattr(payload, payload_field).split()
911        info = _PacketInfo()
912        info.index = int(numbers[0])
913        info.src = int(numbers[1])
914        info.dst = int(numbers[2])
915        info.ip = int(numbers[3])
916        info.proto = int(numbers[4])
917        return info
918
919    def get_next_packet_info(self, info):
920        """
921        Iterate over the packet info list stored in the testcase
922        Start iteration with first element if info is None
923        Continue based on index in info if info is specified
924
925        :param info: info or None
926        :returns: next info in list or None if no more infos
927        """
928        if info is None:
929            next_index = 0
930        else:
931            next_index = info.index + 1
932        if next_index == len(self._packet_infos):
933            return None
934        else:
935            return self._packet_infos[next_index]
936
937    def get_next_packet_info_for_interface(self, src_index, info):
938        """
939        Search the packet info list for the next packet info with same source
940        interface index
941
942        :param src_index: source interface index to search for
943        :param info: packet info - where to start the search
944        :returns: packet info or None
945
946        """
947        while True:
948            info = self.get_next_packet_info(info)
949            if info is None:
950                return None
951            if info.src == src_index:
952                return info
953
954    def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
955        """
956        Search the packet info list for the next packet info with same source
957        and destination interface indexes
958
959        :param src_index: source interface index to search for
960        :param dst_index: destination interface index to search for
961        :param info: packet info - where to start the search
962        :returns: packet info or None
963
964        """
965        while True:
966            info = self.get_next_packet_info_for_interface(src_index, info)
967            if info is None:
968                return None
969            if info.dst == dst_index:
970                return info
971
972    def assert_equal(self, real_value, expected_value, name_or_class=None):
973        if name_or_class is None:
974            self.assertEqual(real_value, expected_value)
975            return
976        try:
977            msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
978            msg = msg % (getdoc(name_or_class).strip(),
979                         real_value, str(name_or_class(real_value)),
980                         expected_value, str(name_or_class(expected_value)))
981        except Exception:
982            msg = "Invalid %s: %s does not match expected value %s" % (
983                name_or_class, real_value, expected_value)
984
985        self.assertEqual(real_value, expected_value, msg)
986
987    def assert_in_range(self,
988                        real_value,
989                        expected_min,
990                        expected_max,
991                        name=None):
992        if name is None:
993            msg = None
994        else:
995            msg = "Invalid %s: %s out of range <%s,%s>" % (
996                name, real_value, expected_min, expected_max)
997        self.assertTrue(expected_min <= real_value <= expected_max, msg)
998
999    def assert_packet_checksums_valid(self, packet,
1000                                      ignore_zero_udp_checksums=True):
1001        received = packet.__class__(scapy.compat.raw(packet))
1002        udp_layers = ['UDP', 'UDPerror']
1003        checksum_fields = ['cksum', 'chksum']
1004        checksums = []
1005        counter = 0
1006        temp = received.__class__(scapy.compat.raw(received))
1007        while True:
1008            layer = temp.getlayer(counter)
1009            if layer:
1010                for cf in checksum_fields:
1011                    if hasattr(layer, cf):
1012                        if ignore_zero_udp_checksums and \
1013                                0 == getattr(layer, cf) and \
1014                                layer.name in udp_layers:
1015                            continue
1016                        delattr(layer, cf)
1017                        checksums.append((counter, cf))
1018            else:
1019                break
1020            counter = counter + 1
1021        if 0 == len(checksums):
1022            return
1023        temp = temp.__class__(scapy.compat.raw(temp))
1024        for layer, cf in checksums:
1025            calc_sum = getattr(temp[layer], cf)
1026            self.assert_equal(
1027                getattr(received[layer], cf), calc_sum,
1028                "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1029            self.logger.debug(
1030                "Checksum field `%s` on `%s` layer has correct value `%s`" %
1031                (cf, temp[layer].name, calc_sum))
1032
1033    def assert_checksum_valid(self, received_packet, layer,
1034                              field_name='chksum',
1035                              ignore_zero_checksum=False):
1036        """ Check checksum of received packet on given layer """
1037        received_packet_checksum = getattr(received_packet[layer], field_name)
1038        if ignore_zero_checksum and 0 == received_packet_checksum:
1039            return
1040        recalculated = received_packet.__class__(
1041            scapy.compat.raw(received_packet))
1042        delattr(recalculated[layer], field_name)
1043        recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1044        self.assert_equal(received_packet_checksum,
1045                          getattr(recalculated[layer], field_name),
1046                          "packet checksum on layer: %s" % layer)
1047
1048    def assert_ip_checksum_valid(self, received_packet,
1049                                 ignore_zero_checksum=False):
1050        self.assert_checksum_valid(received_packet, 'IP',
1051                                   ignore_zero_checksum=ignore_zero_checksum)
1052
1053    def assert_tcp_checksum_valid(self, received_packet,
1054                                  ignore_zero_checksum=False):
1055        self.assert_checksum_valid(received_packet, 'TCP',
1056                                   ignore_zero_checksum=ignore_zero_checksum)
1057
1058    def assert_udp_checksum_valid(self, received_packet,
1059                                  ignore_zero_checksum=True):
1060        self.assert_checksum_valid(received_packet, 'UDP',
1061                                   ignore_zero_checksum=ignore_zero_checksum)
1062
1063    def assert_embedded_icmp_checksum_valid(self, received_packet):
1064        if received_packet.haslayer(IPerror):
1065            self.assert_checksum_valid(received_packet, 'IPerror')
1066        if received_packet.haslayer(TCPerror):
1067            self.assert_checksum_valid(received_packet, 'TCPerror')
1068        if received_packet.haslayer(UDPerror):
1069            self.assert_checksum_valid(received_packet, 'UDPerror',
1070                                       ignore_zero_checksum=True)
1071        if received_packet.haslayer(ICMPerror):
1072            self.assert_checksum_valid(received_packet, 'ICMPerror')
1073
1074    def assert_icmp_checksum_valid(self, received_packet):
1075        self.assert_checksum_valid(received_packet, 'ICMP')
1076        self.assert_embedded_icmp_checksum_valid(received_packet)
1077
1078    def assert_icmpv6_checksum_valid(self, pkt):
1079        if pkt.haslayer(ICMPv6DestUnreach):
1080            self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1081            self.assert_embedded_icmp_checksum_valid(pkt)
1082        if pkt.haslayer(ICMPv6EchoRequest):
1083            self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1084        if pkt.haslayer(ICMPv6EchoReply):
1085            self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1086
1087    def get_packet_counter(self, counter):
1088        if counter.startswith("/"):
1089            counter_value = self.statistics.get_counter(counter)
1090        else:
1091            counters = self.vapi.cli("sh errors").split('\n')
1092            counter_value = 0
1093            for i in range(1, len(counters) - 1):
1094                results = counters[i].split()
1095                if results[1] == counter:
1096                    counter_value = int(results[0])
1097                    break
1098        return counter_value
1099
1100    def assert_packet_counter_equal(self, counter, expected_value):
1101        counter_value = self.get_packet_counter(counter)
1102        self.assert_equal(counter_value, expected_value,
1103                          "packet counter `%s'" % counter)
1104
1105    def assert_error_counter_equal(self, counter, expected_value):
1106        counter_value = self.statistics.get_err_counter(counter)
1107        self.assert_equal(counter_value, expected_value,
1108                          "error counter `%s'" % counter)
1109
1110    @classmethod
1111    def sleep(cls, timeout, remark=None):
1112
1113        # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1114        #  * by Guido, only the main thread can be interrupted.
1115        # */
1116        # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892  # noqa
1117        if timeout == 0:
1118            # yield quantum
1119            if hasattr(os, 'sched_yield'):
1120                os.sched_yield()
1121            else:
1122                time.sleep(0)
1123            return
1124
1125        if hasattr(cls, 'logger'):
1126            cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1127        before = time.time()
1128        time.sleep(timeout)
1129        after = time.time()
1130        if hasattr(cls, 'logger') and after - before > 2 * timeout:
1131            cls.logger.error("unexpected self.sleep() result - "
1132                             "slept for %es instead of ~%es!",
1133                             after - before, timeout)
1134        if hasattr(cls, 'logger'):
1135            cls.logger.debug(
1136                "Finished sleep (%s) - slept %es (wanted %es)",
1137                remark, after - before, timeout)
1138
1139    def pg_send(self, intf, pkts):
1140        self.vapi.cli("clear trace")
1141        intf.add_stream(pkts)
1142        self.pg_enable_capture(self.pg_interfaces)
1143        self.pg_start()
1144
1145    def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1146        self.pg_send(intf, pkts)
1147        if not timeout:
1148            timeout = 1
1149        for i in self.pg_interfaces:
1150            i.get_capture(0, timeout=timeout)
1151            i.assert_nothing_captured(remark=remark)
1152            timeout = 0.1
1153
1154    def send_and_expect(self, intf, pkts, output, n_rx=None):
1155        if not n_rx:
1156            n_rx = len(pkts)
1157        self.pg_send(intf, pkts)
1158        rx = output.get_capture(n_rx)
1159        return rx
1160
1161    def send_and_expect_only(self, intf, pkts, output, timeout=None):
1162        self.pg_send(intf, pkts)
1163        rx = output.get_capture(len(pkts))
1164        outputs = [output]
1165        if not timeout:
1166            timeout = 1
1167        for i in self.pg_interfaces:
1168            if i not in outputs:
1169                i.get_capture(0, timeout=timeout)
1170                i.assert_nothing_captured()
1171                timeout = 0.1
1172
1173        return rx
1174
1175    def runTest(self):
1176        """ unittest calls runTest when TestCase is instantiated without a
1177        test case.  Use case: Writing unittests against VppTestCase"""
1178        pass
1179
1180
1181def get_testcase_doc_name(test):
1182    return getdoc(test.__class__).splitlines()[0]
1183
1184
1185def get_test_description(descriptions, test):
1186    short_description = test.shortDescription()
1187    if descriptions and short_description:
1188        return short_description
1189    else:
1190        return str(test)
1191
1192
1193class TestCaseInfo(object):
1194    def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1195        self.logger = logger
1196        self.tempdir = tempdir
1197        self.vpp_pid = vpp_pid
1198        self.vpp_bin_path = vpp_bin_path
1199        self.core_crash_test = None
1200
1201
1202class VppTestResult(unittest.TestResult):
1203    """
1204    @property result_string
1205     String variable to store the test case result string.
1206    @property errors
1207     List variable containing 2-tuples of TestCase instances and strings
1208     holding formatted tracebacks. Each tuple represents a test which
1209     raised an unexpected exception.
1210    @property failures
1211     List variable containing 2-tuples of TestCase instances and strings
1212     holding formatted tracebacks. Each tuple represents a test where
1213     a failure was explicitly signalled using the TestCase.assert*()
1214     methods.
1215    """
1216
1217    failed_test_cases_info = set()
1218    core_crash_test_cases_info = set()
1219    current_test_case_info = None
1220
1221    def __init__(self, stream=None, descriptions=None, verbosity=None,
1222                 runner=None):
1223        """
1224        :param stream File descriptor to store where to report test results.
1225            Set to the standard error stream by default.
1226        :param descriptions Boolean variable to store information if to use
1227            test case descriptions.
1228        :param verbosity Integer variable to store required verbosity level.
1229        """
1230        super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1231        self.stream = stream
1232        self.descriptions = descriptions
1233        self.verbosity = verbosity
1234        self.result_string = None
1235        self.runner = runner
1236
1237    def addSuccess(self, test):
1238        """
1239        Record a test succeeded result
1240
1241        :param test:
1242
1243        """
1244        if self.current_test_case_info:
1245            self.current_test_case_info.logger.debug(
1246                "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1247                                                       test._testMethodName,
1248                                                       test._testMethodDoc))
1249        unittest.TestResult.addSuccess(self, test)
1250        self.result_string = colorize("OK", GREEN)
1251
1252        self.send_result_through_pipe(test, PASS)
1253
1254    def addSkip(self, test, reason):
1255        """
1256        Record a test skipped.
1257
1258        :param test:
1259        :param reason:
1260
1261        """
1262        if self.current_test_case_info:
1263            self.current_test_case_info.logger.debug(
1264                "--- addSkip() %s.%s(%s) called, reason is %s" %
1265                (test.__class__.__name__, test._testMethodName,
1266                 test._testMethodDoc, reason))
1267        unittest.TestResult.addSkip(self, test, reason)
1268        self.result_string = colorize("SKIP", YELLOW)
1269
1270        self.send_result_through_pipe(test, SKIP)
1271
1272    def symlink_failed(self):
1273        if self.current_test_case_info:
1274            try:
1275                failed_dir = os.getenv('FAILED_DIR')
1276                link_path = os.path.join(
1277                    failed_dir,
1278                    '%s-FAILED' %
1279                    os.path.basename(self.current_test_case_info.tempdir))
1280                if self.current_test_case_info.logger:
1281                    self.current_test_case_info.logger.debug(
1282                        "creating a link to the failed test")
1283                    self.current_test_case_info.logger.debug(
1284                        "os.symlink(%s, %s)" %
1285                        (self.current_test_case_info.tempdir, link_path))
1286                if os.path.exists(link_path):
1287                    if self.current_test_case_info.logger:
1288                        self.current_test_case_info.logger.debug(
1289                            'symlink already exists')
1290                else:
1291                    os.symlink(self.current_test_case_info.tempdir, link_path)
1292
1293            except Exception as e:
1294                if self.current_test_case_info.logger:
1295                    self.current_test_case_info.logger.error(e)
1296
1297    def send_result_through_pipe(self, test, result):
1298        if hasattr(self, 'test_framework_result_pipe'):
1299            pipe = self.test_framework_result_pipe
1300            if pipe:
1301                pipe.send((test.id(), result))
1302
1303    def log_error(self, test, err, fn_name):
1304        if self.current_test_case_info:
1305            if isinstance(test, unittest.suite._ErrorHolder):
1306                test_name = test.description
1307            else:
1308                test_name = '%s.%s(%s)' % (test.__class__.__name__,
1309                                           test._testMethodName,
1310                                           test._testMethodDoc)
1311            self.current_test_case_info.logger.debug(
1312                "--- %s() %s called, err is %s" %
1313                (fn_name, test_name, err))
1314            self.current_test_case_info.logger.debug(
1315                "formatted exception is:\n%s" %
1316                "".join(format_exception(*err)))
1317
1318    def add_error(self, test, err, unittest_fn, error_type):
1319        if error_type == FAIL:
1320            self.log_error(test, err, 'addFailure')
1321            error_type_str = colorize("FAIL", RED)
1322        elif error_type == ERROR:
1323            self.log_error(test, err, 'addError')
1324            error_type_str = colorize("ERROR", RED)
1325        else:
1326            raise Exception('Error type %s cannot be used to record an '
1327                            'error or a failure' % error_type)
1328
1329        unittest_fn(self, test, err)
1330        if self.current_test_case_info:
1331            self.result_string = "%s [ temp dir used by test case: %s ]" % \
1332                                 (error_type_str,
1333                                  self.current_test_case_info.tempdir)
1334            self.symlink_failed()
1335            self.failed_test_cases_info.add(self.current_test_case_info)
1336            if is_core_present(self.current_test_case_info.tempdir):
1337                if not self.current_test_case_info.core_crash_test:
1338                    if isinstance(test, unittest.suite._ErrorHolder):
1339                        test_name = str(test)
1340                    else:
1341                        test_name = "'{!s}' ({!s})".format(
1342                            get_testcase_doc_name(test), test.id())
1343                    self.current_test_case_info.core_crash_test = test_name
1344                self.core_crash_test_cases_info.add(
1345                    self.current_test_case_info)
1346        else:
1347            self.result_string = '%s [no temp dir]' % error_type_str
1348
1349        self.send_result_through_pipe(test, error_type)
1350
1351    def addFailure(self, test, err):
1352        """
1353        Record a test failed result
1354
1355        :param test:
1356        :param err: error message
1357
1358        """
1359        self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1360
1361    def addError(self, test, err):
1362        """
1363        Record a test error result
1364
1365        :param test:
1366        :param err: error message
1367
1368        """
1369        self.add_error(test, err, unittest.TestResult.addError, ERROR)
1370
1371    def getDescription(self, test):
1372        """
1373        Get test description
1374
1375        :param test:
1376        :returns: test description
1377
1378        """
1379        return get_test_description(self.descriptions, test)
1380
1381    def startTest(self, test):
1382        """
1383        Start a test
1384
1385        :param test:
1386
1387        """
1388
1389        def print_header(test):
1390            if not hasattr(test.__class__, '_header_printed'):
1391                print(double_line_delim)
1392                print(colorize(getdoc(test).splitlines()[0], GREEN))
1393                print(double_line_delim)
1394            test.__class__._header_printed = True
1395
1396        print_header(test)
1397        self.start_test = time.time()
1398        unittest.TestResult.startTest(self, test)
1399        if self.verbosity > 0:
1400            self.stream.writeln(
1401                "Starting " + self.getDescription(test) + " ...")
1402            self.stream.writeln(single_line_delim)
1403
1404    def stopTest(self, test):
1405        """
1406        Called when the given test has been run
1407
1408        :param test:
1409
1410        """
1411        unittest.TestResult.stopTest(self, test)
1412
1413        if self.verbosity > 0:
1414            self.stream.writeln(single_line_delim)
1415            self.stream.writeln("%-73s%s" % (self.getDescription(test),
1416                                             self.result_string))
1417            self.stream.writeln(single_line_delim)
1418        else:
1419            self.stream.writeln("%-68s %4.2f %s" %
1420                                (self.getDescription(test),
1421                                 time.time() - self.start_test,
1422                                 self.result_string))
1423
1424        self.send_result_through_pipe(test, TEST_RUN)
1425
1426    def printErrors(self):
1427        """
1428        Print errors from running the test case
1429        """
1430        if len(self.errors) > 0 or len(self.failures) > 0:
1431            self.stream.writeln()
1432            self.printErrorList('ERROR', self.errors)
1433            self.printErrorList('FAIL', self.failures)
1434
1435        # ^^ that is the last output from unittest before summary
1436        if not self.runner.print_summary:
1437            devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1438            self.stream = devnull
1439            self.runner.stream = devnull
1440
1441    def printErrorList(self, flavour, errors):
1442        """
1443        Print error list to the output stream together with error type
1444        and test case description.
1445
1446        :param flavour: error type
1447        :param errors: iterable errors
1448
1449        """
1450        for test, err in errors:
1451            self.stream.writeln(double_line_delim)
1452            self.stream.writeln("%s: %s" %
1453                                (flavour, self.getDescription(test)))
1454            self.stream.writeln(single_line_delim)
1455            self.stream.writeln("%s" % err)
1456
1457
1458class VppTestRunner(unittest.TextTestRunner):
1459    """
1460    A basic test runner implementation which prints results to standard error.
1461    """
1462
1463    @property
1464    def resultclass(self):
1465        """Class maintaining the results of the tests"""
1466        return VppTestResult
1467
1468    def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1469                 result_pipe=None, failfast=False, buffer=False,
1470                 resultclass=None, print_summary=True, **kwargs):
1471        # ignore stream setting here, use hard-coded stdout to be in sync
1472        # with prints from VppTestCase methods ...
1473        super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1474                                            verbosity, failfast, buffer,
1475                                            resultclass, **kwargs)
1476        KeepAliveReporter.pipe = keep_alive_pipe
1477
1478        self.orig_stream = self.stream
1479        self.resultclass.test_framework_result_pipe = result_pipe
1480
1481        self.print_summary = print_summary
1482
1483    def _makeResult(self):
1484        return self.resultclass(self.stream,
1485                                self.descriptions,
1486                                self.verbosity,
1487                                self)
1488
1489    def run(self, test):
1490        """
1491        Run the tests
1492
1493        :param test:
1494
1495        """
1496        faulthandler.enable()  # emit stack trace to stderr if killed by signal
1497
1498        result = super(VppTestRunner, self).run(test)
1499        if not self.print_summary:
1500            self.stream = self.orig_stream
1501            result.stream = self.orig_stream
1502        return result
1503
1504
1505class Worker(Thread):
1506    def __init__(self, args, logger, env=None):
1507        self.logger = logger
1508        self.args = args
1509        if hasattr(self, 'testcase') and self.testcase.debug_all:
1510            if self.testcase.debug_gdbserver:
1511                self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1512                             .format(port=self.testcase.gdbserver_port)] + args
1513            elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1514                self.args.append(self.wait_for_gdb)
1515        self.app_bin = args[0]
1516        self.app_name = os.path.basename(self.app_bin)
1517        if hasattr(self, 'role'):
1518            self.app_name += ' {role}'.format(role=self.role)
1519        self.process = None
1520        self.result = None
1521        env = {} if env is None else env
1522        self.env = copy.deepcopy(env)
1523        super(Worker, self).__init__()
1524
1525    def wait_for_enter(self):
1526        if not hasattr(self, 'testcase'):
1527            return
1528        if self.testcase.debug_all and self.testcase.debug_gdbserver:
1529            print()
1530            print(double_line_delim)
1531            print("Spawned GDB Server for '{app}' with PID: {pid}"
1532                  .format(app=self.app_name, pid=self.process.pid))
1533        elif self.testcase.debug_all and self.testcase.debug_gdb:
1534            print()
1535            print(double_line_delim)
1536            print("Spawned '{app}' with PID: {pid}"
1537                  .format(app=self.app_name, pid=self.process.pid))
1538        else:
1539            return
1540        print(single_line_delim)
1541        print("You can debug '{app}' using:".format(app=self.app_name))
1542        if self.testcase.debug_gdbserver:
1543            print("sudo gdb " + self.app_bin +
1544                  " -ex 'target remote localhost:{port}'"
1545                  .format(port=self.testcase.gdbserver_port))
1546            print("Now is the time to attach gdb by running the above "
1547                  "command, set up breakpoints etc., then resume from "
1548                  "within gdb by issuing the 'continue' command")
1549            self.testcase.gdbserver_port += 1
1550        elif self.testcase.debug_gdb:
1551            print("sudo gdb " + self.app_bin +
1552                  " -ex 'attach {pid}'".format(pid=self.process.pid))
1553            print("Now is the time to attach gdb by running the above "
1554                  "command and set up breakpoints etc., then resume from"
1555                  " within gdb by issuing the 'continue' command")
1556        print(single_line_delim)
1557        input("Press ENTER to continue running the testcase...")
1558
1559    def run(self):
1560        executable = self.args[0]
1561        if not os.path.exists(executable) or not os.access(
1562                executable, os.F_OK | os.X_OK):
1563            # Exit code that means some system file did not exist,
1564            # could not be opened, or had some other kind of error.
1565            self.result = os.EX_OSFILE
1566            raise EnvironmentError(
1567                "executable '%s' is not found or executable." % executable)
1568        self.logger.debug("Running executable: '{app}'"
1569                          .format(app=' '.join(self.args)))
1570        env = os.environ.copy()
1571        env.update(self.env)
1572        env["CK_LOG_FILE_NAME"] = "-"
1573        self.process = subprocess.Popen(
1574            self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1575            stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1576        self.wait_for_enter()
1577        out, err = self.process.communicate()
1578        self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1579        self.logger.info("Return code is `%s'" % self.process.returncode)
1580        self.logger.info(single_line_delim)
1581        self.logger.info("Executable `{app}' wrote to stdout:"
1582                         .format(app=self.app_name))
1583        self.logger.info(single_line_delim)
1584        self.logger.info(out.decode('utf-8'))
1585        self.logger.info(single_line_delim)
1586        self.logger.info("Executable `{app}' wrote to stderr:"
1587                         .format(app=self.app_name))
1588        self.logger.info(single_line_delim)
1589        self.logger.info(err.decode('utf-8'))
1590        self.logger.info(single_line_delim)
1591        self.result = self.process.returncode
1592
1593
1594if __name__ == '__main__':
1595    pass
1596