3 from __future__ import print_function
18 from pathlib import Path
19 from collections import deque
20 from threading import Thread, Event
21 from inspect import getdoc, isclass
22 from traceback import format_exception
23 from logging import FileHandler, DEBUG, Formatter
25 from abc import ABC, abstractmethod
27 from config import config, max_vpp_cpus
28 import hook as hookmodule
29 from vpp_lo_interface import VppLoInterface
30 from vpp_papi_provider import VppPapiProvider
32 from vpp_papi.vpp_stats import VPPStats
33 from vpp_papi.vpp_transport_socket import VppTransportSocketIOError
43 from vpp_object import VppObjectRegistry
44 from util import is_core_present
45 from test_result_code import TestResultCode
47 logger = logging.getLogger(__name__)
49 # Set up an empty logger for the testcase that can be overridden as necessary
50 null_logger = logging.getLogger("VppAsfTestCase")
51 null_logger.addHandler(logging.NullHandler())
54 if config.debug_framework:
58 Test framework module.
60 The module provides a set of tools for constructing and running tests and
61 representing the results.
65 class VppDiedError(Exception):
66 """exception for reporting that the subprocess has died."""
70 for k, v in signal.__dict__.items()
71 if k.startswith("SIG") and not k.startswith("SIG_")
74 def __init__(self, rv=None, testcase=None, method_name=None):
76 self.signal_name = None
77 self.testcase = testcase
78 self.method_name = method_name
81 self.signal_name = VppDiedError.signals_by_value[-rv]
82 except (KeyError, TypeError):
85 if testcase is None and method_name is None:
88 in_msg = " while running %s.%s" % (testcase, method_name)
91 msg = "VPP subprocess died unexpectedly%s with return code: %d%s." % (
94 " [%s]" % (self.signal_name if self.signal_name is not None else ""),
97 msg = "VPP subprocess died unexpectedly%s." % in_msg
99 super(VppDiedError, self).__init__(msg)
102 def pump_output(testclass):
103 """pump output from vpp stdout/stderr to proper queues"""
106 while not testclass.pump_thread_stop_flag.is_set():
107 readable = select.select(
109 testclass.vpp.stdout.fileno(),
110 testclass.vpp.stderr.fileno(),
111 testclass.pump_thread_wakeup_pipe[0],
116 if testclass.vpp.stdout.fileno() in readable:
117 read = os.read(testclass.vpp.stdout.fileno(), 102400)
119 split = read.decode("ascii", errors="backslashreplace").splitlines(True)
120 if len(stdout_fragment) > 0:
121 split[0] = "%s%s" % (stdout_fragment, split[0])
122 if len(split) > 0 and split[-1].endswith("\n"):
126 stdout_fragment = split[-1]
127 testclass.vpp_stdout_deque.extend(split[:limit])
128 if not config.cache_vpp_output:
129 for line in split[:limit]:
130 testclass.logger.info("VPP STDOUT: %s" % line.rstrip("\n"))
131 if testclass.vpp.stderr.fileno() in readable:
132 read = os.read(testclass.vpp.stderr.fileno(), 102400)
134 split = read.decode("ascii", errors="backslashreplace").splitlines(True)
135 if len(stderr_fragment) > 0:
136 split[0] = "%s%s" % (stderr_fragment, split[0])
137 if len(split) > 0 and split[-1].endswith("\n"):
141 stderr_fragment = split[-1]
143 testclass.vpp_stderr_deque.extend(split[:limit])
144 if not config.cache_vpp_output:
145 for line in split[:limit]:
146 testclass.logger.error("VPP STDERR: %s" % line.rstrip("\n"))
147 # ignoring the dummy pipe here intentionally - the
148 # flag will take care of properly terminating the loop
151 def _is_platform_aarch64():
152 return platform.machine() == "aarch64"
155 is_platform_aarch64 = _is_platform_aarch64()
158 def _is_distro_ubuntu2204():
159 with open("/etc/os-release") as f:
160 for line in f.readlines():
166 is_distro_ubuntu2204 = _is_distro_ubuntu2204()
169 def _is_distro_debian11():
170 with open("/etc/os-release") as f:
171 for line in f.readlines():
172 if "bullseye" in line:
177 is_distro_debian11 = _is_distro_debian11()
180 def _is_distro_ubuntu2204():
181 with open("/etc/os-release") as f:
182 for line in f.readlines():
188 class KeepAliveReporter(object):
190 Singleton object which reports test start to parent process
196 self.__dict__ = self._shared_state
204 def pipe(self, pipe):
205 if self._pipe is not None:
206 raise Exception("Internal error - pipe should only be set once.")
209 def send_keep_alive(self, test, desc=None):
211 Write current test tmpdir & desc to keep-alive pipe to signal liveness
213 if self.pipe is None:
214 # if not running forked..
218 desc = "%s (%s)" % (desc, unittest.util.strclass(test))
222 self.pipe.send((desc, config.vpp, test.tempdir, test.vpp.pid))
225 class TestCaseTag(Enum):
226 # marks the suites that must run at the end
227 # using only a single test runner
229 # marks the suites broken on VPP multi-worker
230 FIXME_VPP_WORKERS = 2
231 # marks the suites broken when ASan is enabled
233 # marks suites broken on Ubuntu-22.04
235 # marks suites broken on Debian-11
237 # marks suites broken on debug vpp image
241 def create_tag_decorator(e):
244 cls.test_tags.append(e)
245 except AttributeError:
252 tag_run_solo = create_tag_decorator(TestCaseTag.RUN_SOLO)
253 tag_fixme_vpp_workers = create_tag_decorator(TestCaseTag.FIXME_VPP_WORKERS)
254 tag_fixme_asan = create_tag_decorator(TestCaseTag.FIXME_ASAN)
255 tag_fixme_ubuntu2204 = create_tag_decorator(TestCaseTag.FIXME_UBUNTU2204)
256 tag_fixme_debian11 = create_tag_decorator(TestCaseTag.FIXME_DEBIAN11)
257 tag_fixme_vpp_debug = create_tag_decorator(TestCaseTag.FIXME_VPP_DEBUG)
271 class CPUInterface(ABC):
273 skipped_due_to_cpu_lack = False
277 def get_cpus_required(cls):
281 def assign_cpus(cls, cpus):
285 class VppAsfTestCase(CPUInterface, unittest.TestCase):
286 """This subclass is a base class for VPP test cases that are implemented as
287 classes. It provides methods to create and run test case.
290 extra_vpp_statseg_config = ""
291 extra_vpp_config = []
292 extra_vpp_plugin_config = []
294 vapi_response_timeout = 5
295 remove_configured_vpp_objects_on_tear_down = True
298 def has_tag(cls, tag):
299 """if the test case has a given tag - return true"""
301 return tag in cls.test_tags
302 except AttributeError:
307 def is_tagged_run_solo(cls):
308 """if the test case class is timing-sensitive - return true"""
309 return cls.has_tag(TestCaseTag.RUN_SOLO)
312 def skip_fixme_asan(cls):
313 """if @tag_fixme_asan & ASan is enabled - mark for skip"""
314 if cls.has_tag(TestCaseTag.FIXME_ASAN):
315 vpp_extra_cmake_args = os.environ.get("VPP_EXTRA_CMAKE_ARGS", "")
316 if "DVPP_ENABLE_SANITIZE_ADDR=ON" in vpp_extra_cmake_args:
317 cls = unittest.skip("Skipping @tag_fixme_asan tests")(cls)
321 """Return the instance of this testcase"""
322 return cls.test_instance
325 def set_debug_flags(cls, d):
326 cls.gdbserver_port = 7777
327 cls.debug_core = False
328 cls.debug_gdb = False
329 cls.debug_gdbserver = False
330 cls.debug_all = False
331 cls.debug_attach = False
336 cls.debug_core = True
337 elif dl == "gdb" or dl == "gdb-all":
339 elif dl == "gdbserver" or dl == "gdbserver-all":
340 cls.debug_gdbserver = True
342 cls.debug_attach = True
344 raise Exception("Unrecognized DEBUG option: '%s'" % d)
345 if dl == "gdb-all" or dl == "gdbserver-all":
349 def get_vpp_worker_count(cls):
350 if not hasattr(cls, "vpp_worker_count"):
351 if cls.has_tag(TestCaseTag.FIXME_VPP_WORKERS):
352 cls.vpp_worker_count = 0
354 cls.vpp_worker_count = config.vpp_worker_count
355 return cls.vpp_worker_count
358 def get_cpus_required(cls):
359 return 1 + cls.get_vpp_worker_count()
362 def setUpConstants(cls):
363 """Set-up the test case class based on environment variables"""
364 cls.step = config.step
365 cls.plugin_path = ":".join(config.vpp_plugin_dir)
366 cls.test_plugin_path = ":".join(config.vpp_test_plugin_dir)
367 cls.extern_plugin_path = ":".join(config.extern_plugin_dir)
369 if cls.step or cls.debug_gdb or cls.debug_gdbserver:
370 debug_cli = "cli-listen localhost:5002"
371 size = re.search(r"\d+[gG]", config.coredump_size)
373 coredump_size = f"coredump-size {config.coredump_size}".lower()
375 coredump_size = "coredump-size unlimited"
376 default_variant = config.variant
377 if default_variant is not None:
378 default_variant = "default { variant %s 100 }" % default_variant
382 api_fuzzing = config.api_fuzz
383 if api_fuzzing is None:
404 cls.get_api_segment_prefix(),
411 if cls.extern_plugin_path not in (None, ""):
412 cls.extra_vpp_plugin_config.append("add-path %s" % cls.extern_plugin_path)
413 if cls.get_vpp_worker_count():
414 cls.vpp_cmdline.extend(
415 ["corelist-workers", ",".join([str(x) for x in cls.cpus[1:]])]
417 cls.vpp_cmdline.extend(
428 cls.get_stats_sock_path(),
429 cls.extra_vpp_statseg_config,
434 cls.get_api_sock_path(),
455 "lisp_unittest_plugin.so",
460 "unittest_plugin.so",
465 + cls.extra_vpp_plugin_config
471 if cls.extra_vpp_config is not None:
472 cls.vpp_cmdline.extend(cls.extra_vpp_config)
474 if not cls.debug_attach:
475 cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
476 cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
479 def wait_for_enter(cls):
480 if cls.debug_gdbserver:
481 print(double_line_delim)
482 print("Spawned GDB server with PID: %d" % cls.vpp.pid)
484 print(double_line_delim)
485 print("Spawned VPP with PID: %d" % cls.vpp.pid)
487 cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
489 print(single_line_delim)
490 print("You can debug VPP using:")
491 if cls.debug_gdbserver:
493 f"sudo gdb {config.vpp} "
494 f"-ex 'target remote localhost:{cls.gdbserver_port}'"
497 "Now is the time to attach gdb by running the above "
498 "command, set up breakpoints etc., then resume VPP from "
499 "within gdb by issuing the 'continue' command"
501 cls.gdbserver_port += 1
503 print(f"sudo gdb {config.vpp} -ex 'attach {cls.vpp.pid}'")
505 "Now is the time to attach gdb by running the above "
506 "command and set up breakpoints etc., then resume VPP from"
507 " within gdb by issuing the 'continue' command"
509 print(single_line_delim)
510 input("Press ENTER to continue running the testcase...")
518 cls.logger.debug(f"Assigned cpus: {cls.cpus}")
519 cmdline = cls.vpp_cmdline
521 if cls.debug_gdbserver:
522 gdbserver = "/usr/bin/gdbserver"
523 if not os.path.isfile(gdbserver) or not os.access(gdbserver, os.X_OK):
525 "gdbserver binary '%s' does not exist or is "
526 "not executable" % gdbserver
531 "localhost:{port}".format(port=cls.gdbserver_port),
533 cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
536 cls.vpp = subprocess.Popen(
537 cmdline, stdout=subprocess.PIPE, stderr=subprocess.PIPE
539 except subprocess.CalledProcessError as e:
541 "Subprocess returned with non-0 return code: (%s)", e.returncode
546 "Subprocess returned with OS error: (%s) %s", e.errno, e.strerror
549 except Exception as e:
550 cls.logger.exception("Subprocess returned unexpected from %s:", cmdline)
556 def wait_for_coredump(cls):
557 corefile = cls.tempdir + "/core"
558 if os.path.isfile(corefile):
559 cls.logger.error("Waiting for coredump to complete: %s", corefile)
560 curr_size = os.path.getsize(corefile)
561 deadline = time.time() + 60
563 while time.time() < deadline:
566 curr_size = os.path.getsize(corefile)
567 if size == curr_size:
572 "Timed out waiting for coredump to complete: %s", corefile
575 cls.logger.error("Coredump complete: %s, size %d", corefile, curr_size)
578 def get_stats_sock_path(cls):
579 return "%s/stats.sock" % cls.tempdir
582 def get_api_sock_path(cls):
583 return "%s/api.sock" % cls.tempdir
586 def get_memif_sock_path(cls):
587 return "%s/memif.sock" % cls.tempdir
590 def get_api_segment_prefix(cls):
591 return os.path.basename(cls.tempdir) # Only used for VAPI
594 def get_tempdir(cls):
596 tmpdir = f"{config.tmp_dir}/unittest-attach-gdb"
598 tmpdir = f"{config.tmp_dir}/{get_testcase_dirname(cls.__name__)}"
599 if config.wipe_tmp_dir:
600 shutil.rmtree(tmpdir, ignore_errors=True)
605 def create_file_handler(cls):
606 if config.log_dir is None:
607 cls.file_handler = FileHandler(f"{cls.tempdir}/log.txt")
610 logdir = f"{config.log_dir}/{get_testcase_dirname(cls.__name__)}"
611 if config.wipe_tmp_dir:
612 shutil.rmtree(logdir, ignore_errors=True)
614 cls.file_handler = FileHandler(f"{logdir}/log.txt")
619 Perform class setup before running the testcase
620 Remove shared memory files, start vpp and connect the vpp-api
622 super(VppAsfTestCase, cls).setUpClass()
623 cls.logger = get_logger(cls.__name__)
624 cls.logger.debug(f"--- START setUpClass() {cls.__name__} ---")
625 random.seed(config.rnd_seed)
626 if hasattr(cls, "parallel_handler"):
627 cls.logger.addHandler(cls.parallel_handler)
628 cls.logger.propagate = False
629 cls.set_debug_flags(config.debug)
630 cls.tempdir = cls.get_tempdir()
631 cls.create_file_handler()
632 cls.file_handler.setFormatter(
633 Formatter(fmt="%(asctime)s,%(msecs)03d %(message)s", datefmt="%H:%M:%S")
635 cls.file_handler.setLevel(DEBUG)
636 cls.logger.addHandler(cls.file_handler)
637 cls.logger.debug("--- setUpClass() for %s called ---" % cls.__name__)
638 os.chdir(cls.tempdir)
640 "Temporary dir is %s, api socket is %s",
642 cls.get_api_sock_path(),
644 cls.logger.debug("Random seed is %s", config.rnd_seed)
648 cls.registry = VppObjectRegistry()
649 cls.vpp_startup_failed = False
650 cls.reporter = KeepAliveReporter()
651 # need to catch exceptions here because if we raise, then the cleanup
652 # doesn't get called and we might end with a zombie vpp
658 cls.reporter.send_keep_alive(cls, "setUpClass")
659 VppTestResult.current_test_case_info = TestCaseInfo(
660 cls.logger, cls.tempdir, cls.vpp.pid, config.vpp
662 cls.vpp_stdout_deque = deque()
663 cls.vpp_stderr_deque = deque()
664 if not cls.debug_attach:
665 cls.pump_thread_stop_flag = Event()
666 cls.pump_thread_wakeup_pipe = os.pipe()
667 cls.pump_thread = Thread(target=pump_output, args=(cls,))
668 cls.pump_thread.daemon = True
669 cls.pump_thread.start()
670 if cls.debug_gdb or cls.debug_gdbserver or cls.debug_attach:
671 cls.vapi_response_timeout = 0
672 cls.vapi = VppPapiProvider(cls.__name__, cls, cls.vapi_response_timeout)
674 hook = hookmodule.StepHook(cls)
676 hook = hookmodule.PollHook(cls)
677 cls.vapi.register_hook(hook)
678 cls.statistics = VPPStats(socketname=cls.get_stats_sock_path())
682 cls.wait_for_coredump()
683 cls.vpp_startup_failed = True
685 "VPP died shortly after startup, check the"
686 " output to standard error for possible cause"
691 except (vpp_papi.VPPIOError, Exception) as e:
692 cls.logger.debug("Exception connecting to vapi: %s" % e)
693 cls.vapi.disconnect()
695 if cls.debug_gdbserver:
698 "You're running VPP inside gdbserver but "
699 "VPP-API connection failed, did you forget "
700 "to 'continue' VPP from within gdb?",
706 last_line = cls.vapi.cli("show thread").split("\n")[-2]
707 cls.vpp_worker_count = int(last_line.split(" ")[0])
708 print("Detected VPP with %s workers." % cls.vpp_worker_count)
709 except vpp_papi.VPPRuntimeError as e:
710 cls.logger.debug("%s" % e)
713 except Exception as e:
714 cls.logger.debug("Exception connecting to VPP: %s" % e)
717 cls.logger.debug(f"--- END setUpClass() {cls.__name__} ---")
720 def _debug_quit(cls):
721 if cls.debug_gdbserver or cls.debug_gdb:
725 if cls.vpp.returncode is None:
727 print(double_line_delim)
728 print("VPP or GDB server is still running")
729 print(single_line_delim)
731 "When done debugging, press ENTER to kill the "
732 "process and finish running the testcase..."
734 except AttributeError:
740 Disconnect vpp-api, kill vpp and cleanup shared memory files
744 # first signal that we want to stop the pump thread, then wake it up
745 if hasattr(cls, "pump_thread_stop_flag"):
746 cls.pump_thread_stop_flag.set()
747 if hasattr(cls, "pump_thread_wakeup_pipe"):
748 os.write(cls.pump_thread_wakeup_pipe[1], b"ding dong wake up")
749 if hasattr(cls, "pump_thread"):
750 cls.logger.debug("Waiting for pump thread to stop")
751 cls.pump_thread.join()
752 if hasattr(cls, "vpp_stderr_reader_thread"):
753 cls.logger.debug("Waiting for stderr pump to stop")
754 cls.vpp_stderr_reader_thread.join()
756 if hasattr(cls, "vpp"):
757 if hasattr(cls, "vapi"):
758 cls.logger.debug(cls.vapi.vpp.get_stats())
759 cls.logger.debug("Disconnecting class vapi client on %s", cls.__name__)
760 cls.vapi.disconnect()
761 cls.logger.debug("Deleting class vapi attribute on %s", cls.__name__)
764 if not cls.debug_attach and cls.vpp.returncode is None:
765 cls.wait_for_coredump()
766 cls.logger.debug("Sending TERM to vpp")
768 cls.logger.debug("Waiting for vpp to die")
770 outs, errs = cls.vpp.communicate(timeout=5)
771 except subprocess.TimeoutExpired:
773 outs, errs = cls.vpp.communicate()
774 cls.logger.debug("Deleting class vpp attribute on %s", cls.__name__)
775 if not cls.debug_attach:
776 cls.vpp.stdout.close()
777 cls.vpp.stderr.close()
780 if cls.vpp_startup_failed:
781 stdout_log = cls.logger.info
782 stderr_log = cls.logger.critical
784 stdout_log = cls.logger.info
785 stderr_log = cls.logger.info
787 if hasattr(cls, "vpp_stdout_deque"):
788 stdout_log(single_line_delim)
789 stdout_log("VPP output to stdout while running %s:", cls.__name__)
790 stdout_log(single_line_delim)
791 vpp_output = "".join(cls.vpp_stdout_deque)
792 with open(cls.tempdir + "/vpp_stdout.txt", "w") as f:
794 stdout_log("\n%s", vpp_output)
795 stdout_log(single_line_delim)
797 if hasattr(cls, "vpp_stderr_deque"):
798 stderr_log(single_line_delim)
799 stderr_log("VPP output to stderr while running %s:", cls.__name__)
800 stderr_log(single_line_delim)
801 vpp_output = "".join(cls.vpp_stderr_deque)
802 with open(cls.tempdir + "/vpp_stderr.txt", "w") as f:
804 stderr_log("\n%s", vpp_output)
805 stderr_log(single_line_delim)
808 def tearDownClass(cls):
809 """Perform final cleanup after running all tests in this test-case"""
810 cls.logger.debug(f"--- START tearDownClass() {cls.__name__} ---")
811 cls.reporter.send_keep_alive(cls, "tearDownClass")
813 cls.file_handler.close()
814 if config.debug_framework:
815 debug_internal.on_tear_down_class(cls)
816 cls.logger.debug(f"--- END tearDownClass() {cls.__name__} ---")
818 def show_commands_at_teardown(self):
819 """Allow subclass specific teardown logging additions."""
820 self.logger.info("--- No test specific show commands provided. ---")
822 def unlink_testcase_file(self, path):
824 retries = MAX_ATTEMPTS
826 retries = retries - 1
827 self.logger.debug(f"Unlinking {path}")
830 # Loop until unlink() fails with FileNotFoundError to ensure file is removed
831 except FileNotFoundError:
834 self.logger.debug(f"OSError: unlinking {path}")
835 self.sleep(0.25, f"{retries} retries left")
836 if retries == 0 and os.path.isfile(path):
838 f"Unable to delete testcase file in {MAX_ATTEMPTS} attempts: {path}"
843 """Show various debug prints after each test"""
845 f"--- START tearDown() {self.__class__.__name__}.{self._testMethodName}({self._testMethodDoc}) ---"
849 if not self.vpp_dead:
850 self.logger.debug(self.vapi.cli("show trace max 1000"))
851 self.logger.info(self.vapi.ppcli("show interface"))
852 self.logger.info(self.vapi.ppcli("show hardware"))
853 self.logger.info(self.statistics.set_errors_str())
854 self.logger.info(self.vapi.ppcli("show run"))
855 self.logger.info(self.vapi.ppcli("show log"))
856 self.logger.info(self.vapi.ppcli("show bihash"))
857 self.logger.info("Logging testcase specific show commands.")
858 self.show_commands_at_teardown()
859 if self.remove_configured_vpp_objects_on_tear_down:
860 self.registry.remove_vpp_config(self.logger)
861 # Save/Dump VPP api trace log
862 m = self._testMethodName
863 api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
864 tmp_api_trace = "/tmp/%s" % api_trace
865 vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
866 self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
867 self.logger.info("Moving %s to %s\n" % (tmp_api_trace, vpp_api_trace_log))
868 shutil.move(tmp_api_trace, vpp_api_trace_log)
869 except VppTransportSocketIOError:
871 "VppTransportSocketIOError: Vpp dead. Cannot log show commands."
875 self.registry.unregister_all(self.logger)
876 # Remove any leftover pcap files
877 if hasattr(self, "pg_interfaces") and len(self.pg_interfaces) > 0:
878 testcase_dir = os.path.dirname(self.pg_interfaces[0].out_path)
879 for p in Path(testcase_dir).glob("pg*.pcap"):
880 self.unlink_testcase_file(p)
882 f"--- END tearDown() {self.__class__.__name__}.{self._testMethodName}('{self._testMethodDoc}') ---"
886 """Clear trace before running each test"""
887 super(VppAsfTestCase, self).setUp()
889 f"--- START setUp() {self.__class__.__name__}.{self._testMethodName}('{self._testMethodDoc}') ---"
891 # Save testname include in pcap history filenames
892 if hasattr(self, "pg_interfaces"):
893 for i in self.pg_interfaces:
894 i.test_name = self._testMethodName
895 self.reporter.send_keep_alive(self)
897 self.wait_for_coredump()
900 testcase=self.__class__.__name__,
901 method_name=self._testMethodName,
903 self.sleep(0.1, "during setUp")
904 self.vpp_stdout_deque.append(
905 "--- test setUp() for %s.%s(%s) starts here ---\n"
906 % (self.__class__.__name__, self._testMethodName, self._testMethodDoc)
908 self.vpp_stderr_deque.append(
909 "--- test setUp() for %s.%s(%s) starts here ---\n"
910 % (self.__class__.__name__, self._testMethodName, self._testMethodDoc)
912 self.vapi.cli("clear trace")
913 # store the test instance inside the test class - so that objects
914 # holding the class can access instance methods (like assertEqual)
915 type(self).test_instance = self
917 f"--- END setUp() {self.__class__.__name__}.{self._testMethodName}('{self._testMethodDoc}') ---"
921 def get_vpp_time(cls):
922 # processes e.g. "Time now 2.190522, Wed, 11 Mar 2020 17:29:54 GMT"
923 # returns float("2.190522")
924 timestr = cls.vapi.cli("show clock")
925 head, sep, tail = timestr.partition(",")
926 head, sep, tail = head.partition("Time now")
930 def sleep_on_vpp_time(cls, sec):
931 """Sleep according to time in VPP world"""
932 # On a busy system with many processes
933 # we might end up with VPP time being slower than real world
934 # So take that into account when waiting for VPP to do something
935 start_time = cls.get_vpp_time()
936 while cls.get_vpp_time() - start_time < sec:
940 def create_loopback_interfaces(cls, count):
942 Create loopback interfaces.
944 :param count: number of interfaces created.
945 :returns: List of created interfaces.
947 result = [VppLoInterface(cls) for i in range(count)]
949 setattr(cls, intf.name, intf)
950 cls.lo_interfaces = result
953 def assert_equal(self, real_value, expected_value, name_or_class=None):
954 if name_or_class is None:
955 self.assertEqual(real_value, expected_value)
958 msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
960 getdoc(name_or_class).strip(),
962 str(name_or_class(real_value)),
964 str(name_or_class(expected_value)),
967 msg = "Invalid %s: %s does not match expected value %s" % (
973 self.assertEqual(real_value, expected_value, msg)
975 def assert_in_range(self, real_value, expected_min, expected_max, name=None):
979 msg = "Invalid %s: %s out of range <%s,%s>" % (
985 self.assertTrue(expected_min <= real_value <= expected_max, msg)
987 def get_counter(self, counter):
988 if counter.startswith("/"):
989 counter_value = self.statistics.get_counter(counter)
991 counters = self.vapi.cli("sh errors").split("\n")
993 for i in range(1, len(counters) - 1):
994 results = counters[i].split()
995 if results[1] == counter:
996 counter_value = int(results[0])
1000 def assert_counter_equal(self, counter, expected_value, thread=None, index=0):
1001 c = self.get_counter(counter)
1002 if thread is not None:
1003 c = c[thread][index]
1005 c = sum(x[index] for x in c)
1007 "validate counter `%s[%s]', expected: %s, real value: %s"
1008 % (counter, index, expected_value, c)
1010 self.assert_equal(c, expected_value, "counter `%s[%s]'" % (counter, index))
1012 def assert_error_counter_equal(self, counter, expected_value):
1013 counter_value = self.statistics[counter].sum()
1014 self.assert_equal(counter_value, expected_value, "error counter `%s'" % counter)
1017 def sleep(cls, timeout, remark=None):
1018 # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1019 # * by Guido, only the main thread can be interrupted.
1021 # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892 # noqa
1024 if hasattr(os, "sched_yield"):
1030 cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1031 before = time.time()
1034 if after - before > 2 * timeout:
1036 "unexpected self.sleep() result - slept for %es instead of ~%es!",
1042 "Finished sleep (%s) - slept %es (wanted %es)",
1048 def virtual_sleep(self, timeout, remark=None):
1049 self.logger.debug("Moving VPP time by %s (%s)", timeout, remark)
1050 self.vapi.cli("set clock adjust %s" % timeout)
1052 def snapshot_stats(self, stats_diff):
1053 """Return snapshot of interesting stats based on diff dictionary."""
1055 for sw_if_index in stats_diff:
1056 for counter in stats_diff[sw_if_index]:
1057 stats_snapshot[counter] = self.statistics[counter]
1058 self.logger.debug(f"Took statistics stats_snapshot: {stats_snapshot}")
1059 return stats_snapshot
1061 def compare_stats_with_snapshot(self, stats_diff, stats_snapshot):
1062 """Assert appropriate difference between current stats and snapshot."""
1063 for sw_if_index in stats_diff:
1064 for cntr, diff in stats_diff[sw_if_index].items():
1065 if sw_if_index == "err":
1067 self.statistics[cntr].sum(),
1068 stats_snapshot[cntr].sum() + diff,
1069 f"'{cntr}' counter value (previous value: "
1070 f"{stats_snapshot[cntr].sum()}, "
1071 f"expected diff: {diff})",
1076 self.statistics[cntr][:, sw_if_index].sum(),
1077 stats_snapshot[cntr][:, sw_if_index].sum() + diff,
1078 f"'{cntr}' counter value (previous value: "
1079 f"{stats_snapshot[cntr][:, sw_if_index].sum()}, "
1080 f"expected diff: {diff})",
1082 except IndexError as e:
1083 # if diff is 0, then this most probably a case where
1084 # test declares multiple interfaces but traffic hasn't
1085 # passed through this one yet - which means the counter
1086 # value is 0 and can be ignored
1089 f"Couldn't sum counter: {cntr} on sw_if_index: {sw_if_index}"
1093 def get_testcase_doc_name(test):
1094 return getdoc(test.__class__).splitlines()[0]
1097 def get_test_description(descriptions, test):
1098 short_description = test.shortDescription()
1099 if descriptions and short_description:
1100 return short_description
1105 def get_failed_testcase_linkname(failed_dir, testcase_dirname):
1106 return os.path.join(failed_dir, f"{testcase_dirname}-FAILED")
1109 def get_testcase_dirname(testcase_class_name):
1110 return f"vpp-unittest-{testcase_class_name}"
1113 class TestCaseInfo(object):
1114 def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1115 self.logger = logger
1116 self.tempdir = tempdir
1117 self.vpp_pid = vpp_pid
1118 self.vpp_bin_path = vpp_bin_path
1119 self.core_crash_test = None
1122 class VppTestResult(unittest.TestResult):
1124 @property result_string
1125 String variable to store the test case result string.
1127 List variable containing 2-tuples of TestCase instances and strings
1128 holding formatted tracebacks. Each tuple represents a test which
1129 raised an unexpected exception.
1131 List variable containing 2-tuples of TestCase instances and strings
1132 holding formatted tracebacks. Each tuple represents a test where
1133 a failure was explicitly signalled using the TestCase.assert*()
1137 failed_test_cases_info = set()
1138 core_crash_test_cases_info = set()
1139 current_test_case_info = None
1141 def __init__(self, stream=None, descriptions=None, verbosity=None, runner=None):
1143 :param stream File descriptor to store where to report test results.
1144 Set to the standard error stream by default.
1145 :param descriptions Boolean variable to store information if to use
1146 test case descriptions.
1147 :param verbosity Integer variable to store required verbosity level.
1149 super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1150 self.stream = stream
1151 self.descriptions = descriptions
1152 self.verbosity = verbosity
1153 self.result_code = TestResultCode.TEST_RUN
1154 self.result_string = None
1155 self.runner = runner
1158 def decodePcapFiles(self, test, when_configured=False):
1159 if when_configured == False or config.decode_pcaps == True:
1160 if hasattr(test, "pg_interfaces") and len(test.pg_interfaces) > 0:
1161 testcase_dir = os.path.dirname(test.pg_interfaces[0].out_path)
1162 test.pg_interfaces[0].decode_pcap_files(
1163 testcase_dir, f"suite{test.__class__.__name__}"
1165 test.pg_interfaces[0].decode_pcap_files(
1166 testcase_dir, test._testMethodName
1169 def addSuccess(self, test):
1171 Record a test succeeded result
1176 self.log_result("addSuccess", test)
1177 self.decodePcapFiles(test, when_configured=True)
1178 unittest.TestResult.addSuccess(self, test)
1179 self.result_string = colorize("OK", GREEN)
1180 self.result_code = TestResultCode.PASS
1181 self.send_result_through_pipe(test, self.result_code)
1183 def addExpectedFailure(self, test, err):
1184 self.log_result("addExpectedFailure", test, err)
1185 self.decodePcapFiles(test)
1186 super().addExpectedFailure(test, err)
1187 self.result_string = colorize("FAIL", GREEN)
1188 self.result_code = TestResultCode.EXPECTED_FAIL
1189 self.send_result_through_pipe(test, self.result_code)
1191 def addUnexpectedSuccess(self, test):
1192 self.log_result("addUnexpectedSuccess", test)
1193 self.decodePcapFiles(test, when_configured=True)
1194 super().addUnexpectedSuccess(test)
1195 self.result_string = colorize("OK", RED)
1196 self.result_code = TestResultCode.UNEXPECTED_PASS
1197 self.send_result_through_pipe(test, self.result_code)
1199 def addSkip(self, test, reason):
1201 Record a test skipped.
1207 self.log_result("addSkip", test, reason=reason)
1208 unittest.TestResult.addSkip(self, test, reason)
1209 self.result_string = colorize("SKIP", YELLOW)
1211 if reason == "not enough cpus":
1212 self.result_code = TestResultCode.SKIP_CPU_SHORTAGE
1214 self.result_code = TestResultCode.SKIP
1215 self.send_result_through_pipe(test, self.result_code)
1217 def symlink_failed(self):
1218 if self.current_test_case_info:
1220 failed_dir = config.failed_dir
1221 link_path = get_failed_testcase_linkname(
1222 failed_dir, os.path.basename(self.current_test_case_info.tempdir)
1225 self.current_test_case_info.logger.debug(
1226 "creating a link to the failed test"
1228 self.current_test_case_info.logger.debug(
1229 "os.symlink(%s, %s)"
1230 % (self.current_test_case_info.tempdir, link_path)
1232 if os.path.exists(link_path):
1233 self.current_test_case_info.logger.debug("symlink already exists")
1235 os.symlink(self.current_test_case_info.tempdir, link_path)
1237 except Exception as e:
1238 self.current_test_case_info.logger.error(e)
1240 def send_result_through_pipe(self, test, result):
1241 if hasattr(self, "test_framework_result_pipe"):
1242 pipe = self.test_framework_result_pipe
1244 pipe.send((test.id(), result))
1246 def log_result(self, fn, test, err=None, reason=None):
1247 if self.current_test_case_info:
1248 if isinstance(test, unittest.suite._ErrorHolder):
1249 test_name = test.description
1251 test_name = "%s.%s(%s)" % (
1252 test.__class__.__name__,
1253 test._testMethodName,
1254 test._testMethodDoc,
1258 extra_msg += f", error is {err}"
1260 extra_msg += f", reason is {reason}"
1261 self.current_test_case_info.logger.debug(
1262 f"--- {fn}() {test_name} called{extra_msg}"
1265 self.current_test_case_info.logger.debug(
1266 "formatted exception is:\n%s" % "".join(format_exception(*err))
1269 def add_error(self, test, err, unittest_fn, result_code):
1270 self.result_code = result_code
1271 if result_code == TestResultCode.FAIL:
1272 self.log_result("addFailure", test, err=err)
1273 error_type_str = colorize("FAIL", RED)
1274 elif result_code == TestResultCode.ERROR:
1275 self.log_result("addError", test, err=err)
1276 error_type_str = colorize("ERROR", RED)
1278 raise Exception(f"Unexpected result code {result_code}")
1279 self.decodePcapFiles(test)
1281 unittest_fn(self, test, err)
1282 if self.current_test_case_info:
1283 self.result_string = "%s [ temp dir used by test case: %s ]" % (
1285 self.current_test_case_info.tempdir,
1287 self.symlink_failed()
1288 self.failed_test_cases_info.add(self.current_test_case_info)
1289 if is_core_present(self.current_test_case_info.tempdir):
1290 if not self.current_test_case_info.core_crash_test:
1291 if isinstance(test, unittest.suite._ErrorHolder):
1292 test_name = str(test)
1294 test_name = "'{!s}' ({!s})".format(
1295 get_testcase_doc_name(test), test.id()
1297 self.current_test_case_info.core_crash_test = test_name
1298 self.core_crash_test_cases_info.add(self.current_test_case_info)
1300 self.result_string = "%s [no temp dir]" % error_type_str
1302 self.send_result_through_pipe(test, result_code)
1304 def addFailure(self, test, err):
1306 Record a test failed result
1309 :param err: error message
1312 self.add_error(test, err, unittest.TestResult.addFailure, TestResultCode.FAIL)
1314 def addError(self, test, err):
1316 Record a test error result
1319 :param err: error message
1322 self.add_error(test, err, unittest.TestResult.addError, TestResultCode.ERROR)
1324 def getDescription(self, test):
1326 Get test description
1329 :returns: test description
1332 return get_test_description(self.descriptions, test)
1334 def startTest(self, test):
1342 def print_header(test):
1343 if test.__class__ in self.printed:
1346 test_doc = getdoc(test)
1348 raise Exception("No doc string for test '%s'" % test.id())
1350 test_title = test_doc.splitlines()[0].rstrip()
1351 test_title = colorize(test_title, GREEN)
1352 if test.is_tagged_run_solo():
1353 test_title = colorize(f"SOLO RUN: {test_title}", YELLOW)
1355 # This block may overwrite the colorized title above,
1356 # but we want this to stand out and be fixed
1357 if test.has_tag(TestCaseTag.FIXME_VPP_WORKERS):
1358 test_title = colorize(f"FIXME with VPP workers: {test_title}", RED)
1360 if test.has_tag(TestCaseTag.FIXME_ASAN):
1361 test_title = colorize(f"FIXME with ASAN: {test_title}", RED)
1362 test.skip_fixme_asan()
1364 if hasattr(test, "vpp_worker_count"):
1365 if test.vpp_worker_count == 0:
1366 test_title += " [main thread only]"
1367 elif test.vpp_worker_count == 1:
1368 test_title += " [1 worker thread]"
1370 test_title += f" [{test.vpp_worker_count} worker threads]"
1372 if test.__class__.skipped_due_to_cpu_lack:
1373 test_title = colorize(
1374 f"{test_title} [skipped - not enough cpus, "
1375 f"required={test.__class__.get_cpus_required()}, "
1376 f"available={max_vpp_cpus}]",
1380 print(double_line_delim)
1382 print(double_line_delim)
1383 self.printed.append(test.__class__)
1386 self.start_test = time.time()
1387 unittest.TestResult.startTest(self, test)
1388 if self.verbosity > 0:
1389 self.stream.writeln("Starting " + self.getDescription(test) + " ...")
1390 self.stream.writeln(single_line_delim)
1392 def stopTest(self, test):
1394 Called when the given test has been run
1399 unittest.TestResult.stopTest(self, test)
1401 result_code_to_suffix = {
1402 TestResultCode.PASS: "",
1403 TestResultCode.FAIL: "",
1404 TestResultCode.ERROR: "",
1405 TestResultCode.SKIP: "",
1406 TestResultCode.TEST_RUN: "",
1407 TestResultCode.SKIP_CPU_SHORTAGE: "",
1408 TestResultCode.EXPECTED_FAIL: " [EXPECTED FAIL]",
1409 TestResultCode.UNEXPECTED_PASS: " [UNEXPECTED PASS]",
1412 if self.verbosity > 0:
1413 self.stream.writeln(single_line_delim)
1414 self.stream.writeln(
1417 self.getDescription(test),
1419 result_code_to_suffix[self.result_code],
1422 self.stream.writeln(single_line_delim)
1424 self.stream.writeln(
1427 self.getDescription(test),
1428 time.time() - self.start_test,
1430 result_code_to_suffix[self.result_code],
1434 self.send_result_through_pipe(test, TestResultCode.TEST_RUN)
1436 def printErrors(self):
1438 Print errors from running the test case
1440 if len(self.errors) > 0 or len(self.failures) > 0:
1441 self.stream.writeln()
1442 self.printErrorList("ERROR", self.errors)
1443 self.printErrorList("FAIL", self.failures)
1445 # ^^ that is the last output from unittest before summary
1446 if not self.runner.print_summary:
1447 devnull = unittest.runner._WritelnDecorator(open(os.devnull, "w"))
1448 self.stream = devnull
1449 self.runner.stream = devnull
1451 def printErrorList(self, flavour, errors):
1453 Print error list to the output stream together with error type
1454 and test case description.
1456 :param flavour: error type
1457 :param errors: iterable errors
1460 for test, err in errors:
1461 self.stream.writeln(double_line_delim)
1462 self.stream.writeln("%s: %s" % (flavour, self.getDescription(test)))
1463 self.stream.writeln(single_line_delim)
1464 self.stream.writeln("%s" % err)
1467 class VppTestRunner(unittest.TextTestRunner):
1469 A basic test runner implementation which prints results to standard error.
1473 def resultclass(self):
1474 """Class maintaining the results of the tests"""
1475 return VppTestResult
1479 keep_alive_pipe=None,
1489 # ignore stream setting here, use hard-coded stdout to be in sync
1490 # with prints from VppAsfTestCase methods ...
1491 super(VppTestRunner, self).__init__(
1492 sys.stdout, descriptions, verbosity, failfast, buffer, resultclass, **kwargs
1494 KeepAliveReporter.pipe = keep_alive_pipe
1496 self.orig_stream = self.stream
1497 self.resultclass.test_framework_result_pipe = result_pipe
1499 self.print_summary = print_summary
1501 def _makeResult(self):
1502 return self.resultclass(self.stream, self.descriptions, self.verbosity, self)
1504 def run(self, test):
1511 faulthandler.enable() # emit stack trace to stderr if killed by signal
1513 result = super(VppTestRunner, self).run(test)
1514 if not self.print_summary:
1515 self.stream = self.orig_stream
1516 result.stream = self.orig_stream
1520 class Worker(Thread):
1521 def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1522 super(Worker, self).__init__(*args, **kwargs)
1523 self.logger = logger
1524 self.args = executable_args
1525 if hasattr(self, "testcase") and self.testcase.debug_all:
1526 if self.testcase.debug_gdbserver:
1528 "/usr/bin/gdbserver",
1529 "localhost:{port}".format(port=self.testcase.gdbserver_port),
1531 elif self.testcase.debug_gdb and hasattr(self, "wait_for_gdb"):
1532 self.args.append(self.wait_for_gdb)
1533 self.app_bin = executable_args[0]
1534 self.app_name = os.path.basename(self.app_bin)
1535 if hasattr(self, "role"):
1536 self.app_name += " {role}".format(role=self.role)
1539 env = {} if env is None else env
1540 self.env = copy.deepcopy(env)
1542 def wait_for_enter(self):
1543 if not hasattr(self, "testcase"):
1545 if self.testcase.debug_all and self.testcase.debug_gdbserver:
1547 print(double_line_delim)
1549 "Spawned GDB Server for '{app}' with PID: {pid}".format(
1550 app=self.app_name, pid=self.process.pid
1553 elif self.testcase.debug_all and self.testcase.debug_gdb:
1555 print(double_line_delim)
1557 "Spawned '{app}' with PID: {pid}".format(
1558 app=self.app_name, pid=self.process.pid
1563 print(single_line_delim)
1564 print("You can debug '{app}' using:".format(app=self.app_name))
1565 if self.testcase.debug_gdbserver:
1569 + " -ex 'target remote localhost:{port}'".format(
1570 port=self.testcase.gdbserver_port
1574 "Now is the time to attach gdb by running the above "
1575 "command, set up breakpoints etc., then resume from "
1576 "within gdb by issuing the 'continue' command"
1578 self.testcase.gdbserver_port += 1
1579 elif self.testcase.debug_gdb:
1583 + " -ex 'attach {pid}'".format(pid=self.process.pid)
1586 "Now is the time to attach gdb by running the above "
1587 "command and set up breakpoints etc., then resume from"
1588 " within gdb by issuing the 'continue' command"
1590 print(single_line_delim)
1591 input("Press ENTER to continue running the testcase...")
1594 executable = self.args[0]
1595 if not os.path.exists(executable) or not os.access(
1596 executable, os.F_OK | os.X_OK
1598 # Exit code that means some system file did not exist,
1599 # could not be opened, or had some other kind of error.
1600 self.result = os.EX_OSFILE
1601 raise EnvironmentError(
1602 "executable '%s' is not found or executable." % executable
1605 "Running executable '{app}': '{cmd}'".format(
1606 app=self.app_name, cmd=" ".join(self.args)
1609 env = os.environ.copy()
1610 env.update(self.env)
1611 env["CK_LOG_FILE_NAME"] = "-"
1612 self.process = subprocess.Popen(
1613 ["stdbuf", "-o0", "-e0"] + self.args,
1616 preexec_fn=os.setpgrp,
1617 stdout=subprocess.PIPE,
1618 stderr=subprocess.PIPE,
1620 self.wait_for_enter()
1621 out, err = self.process.communicate()
1622 self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1623 self.logger.info("Return code is `%s'" % self.process.returncode)
1624 self.logger.info(single_line_delim)
1626 "Executable `{app}' wrote to stdout:".format(app=self.app_name)
1628 self.logger.info(single_line_delim)
1629 self.logger.info(out.decode("utf-8"))
1630 self.logger.info(single_line_delim)
1632 "Executable `{app}' wrote to stderr:".format(app=self.app_name)
1634 self.logger.info(single_line_delim)
1635 self.logger.info(err.decode("utf-8"))
1636 self.logger.info(single_line_delim)
1637 self.result = self.process.returncode
1640 if __name__ == "__main__":