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