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