nat: TCP state tracking based on RFC 7857/RFC 6146
[vpp.git] / test / framework.py
index f3c74ce..8c0df28 100644 (file)
@@ -22,15 +22,18 @@ from inspect import getdoc, isclass
 from traceback import format_exception
 from logging import FileHandler, DEBUG, Formatter
 from enum import Enum
+from abc import ABC, abstractmethod
+from struct import pack, unpack
 
 import scapy.compat
-from scapy.packet import Raw
+from scapy.packet import Raw, Packet
 import hook as hookmodule
 from vpp_pg_interface import VppPGInterface
 from vpp_sub_interface import VppSubInterface
 from vpp_lo_interface import VppLoInterface
 from vpp_bvi_interface import VppBviInterface
 from vpp_papi_provider import VppPapiProvider
+from vpp_papi import VppEnum
 import vpp_papi
 from vpp_papi.vpp_stats import VPPStats
 from vpp_papi.vpp_transport_socket import VppTransportSocketIOError
@@ -42,6 +45,8 @@ from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
 from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
 from scapy.layers.inet6 import ICMPv6EchoReply
 
+from cpu_config import available_cpus, num_cpus, max_vpp_cpus
+
 logger = logging.getLogger(__name__)
 
 # Set up an empty logger for the testcase that can be overridden as necessary
@@ -53,6 +58,7 @@ FAIL = 1
 ERROR = 2
 SKIP = 3
 TEST_RUN = 4
+SKIP_CPU_SHORTAGE = 5
 
 
 class BoolEnvironmentVariable(object):
@@ -223,6 +229,21 @@ def _running_gcov_tests():
 running_gcov_tests = _running_gcov_tests()
 
 
+def get_environ_vpp_worker_count():
+    worker_config = os.getenv("VPP_WORKER_CONFIG", None)
+    if worker_config:
+        elems = worker_config.split(" ")
+        if elems[0] != "workers" or len(elems) != 2:
+            raise ValueError("Wrong VPP_WORKER_CONFIG == '%s' value." %
+                             worker_config)
+        return int(elems[1])
+    else:
+        return 0
+
+
+environ_vpp_worker_count = get_environ_vpp_worker_count()
+
+
 class KeepAliveReporter(object):
     """
     Singleton object which reports test start to parent process
@@ -281,11 +302,37 @@ tag_run_solo = create_tag_decorator(TestCaseTag.RUN_SOLO)
 tag_fixme_vpp_workers = create_tag_decorator(TestCaseTag.FIXME_VPP_WORKERS)
 
 
-class VppTestCase(unittest.TestCase):
+class DummyVpp:
+    returncode = None
+    pid = 0xcafebafe
+
+    def poll(self):
+        pass
+
+    def terminate(self):
+        pass
+
+
+class CPUInterface(ABC):
+    cpus = []
+    skipped_due_to_cpu_lack = False
+
+    @classmethod
+    @abstractmethod
+    def get_cpus_required(cls):
+        pass
+
+    @classmethod
+    def assign_cpus(cls, cpus):
+        cls.cpus = cpus
+
+
+class VppTestCase(CPUInterface, unittest.TestCase):
     """This subclass is a base class for VPP test cases that are implemented as
     classes. It provides methods to create and run test case.
     """
 
+    extra_vpp_statseg_config = ""
     extra_vpp_punt_config = []
     extra_vpp_plugin_config = []
     logger = null_logger
@@ -330,6 +377,7 @@ class VppTestCase(unittest.TestCase):
         cls.debug_gdb = False
         cls.debug_gdbserver = False
         cls.debug_all = False
+        cls.debug_attach = False
         if d is None:
             return
         dl = d.lower()
@@ -339,62 +387,35 @@ class VppTestCase(unittest.TestCase):
             cls.debug_gdb = True
         elif dl == "gdbserver" or dl == "gdbserver-all":
             cls.debug_gdbserver = True
+        elif dl == "attach":
+            cls.debug_attach = True
         else:
             raise Exception("Unrecognized DEBUG option: '%s'" % d)
         if dl == "gdb-all" or dl == "gdbserver-all":
             cls.debug_all = True
 
-    @staticmethod
-    def get_least_used_cpu():
-        cpu_usage_list = [set(range(psutil.cpu_count()))]
-        vpp_processes = [p for p in psutil.process_iter(attrs=['pid', 'name'])
-                         if 'vpp_main' == p.info['name']]
-        for vpp_process in vpp_processes:
-            for cpu_usage_set in cpu_usage_list:
-                try:
-                    cpu_num = vpp_process.cpu_num()
-                    if cpu_num in cpu_usage_set:
-                        cpu_usage_set_index = cpu_usage_list.index(
-                            cpu_usage_set)
-                        if cpu_usage_set_index == len(cpu_usage_list) - 1:
-                            cpu_usage_list.append({cpu_num})
-                        else:
-                            cpu_usage_list[cpu_usage_set_index + 1].add(
-                                cpu_num)
-                        cpu_usage_set.remove(cpu_num)
-                        break
-                except psutil.NoSuchProcess:
-                    pass
-
-        for cpu_usage_set in cpu_usage_list:
-            if len(cpu_usage_set) > 0:
-                min_usage_set = cpu_usage_set
-                break
+    @classmethod
+    def get_vpp_worker_count(cls):
+        if not hasattr(cls, "vpp_worker_count"):
+            if cls.has_tag(TestCaseTag.FIXME_VPP_WORKERS):
+                cls.vpp_worker_count = 0
+            else:
+                cls.vpp_worker_count = environ_vpp_worker_count
+        return cls.vpp_worker_count
 
-        return random.choice(tuple(min_usage_set))
+    @classmethod
+    def get_cpus_required(cls):
+        return 1 + cls.get_vpp_worker_count()
 
     @classmethod
     def setUpConstants(cls):
         """ Set-up the test case class based on environment variables """
         cls.step = BoolEnvironmentVariable('STEP')
-        d = os.getenv("DEBUG", None)
         # inverted case to handle '' == True
         c = os.getenv("CACHE_OUTPUT", "1")
         cls.cache_vpp_output = False if c.lower() in ("n", "no", "0") else True
-        cls.set_debug_flags(d)
         cls.vpp_bin = os.getenv('VPP_BIN', "vpp")
-        cls.plugin_path = os.getenv('VPP_PLUGIN_PATH')
-        cls.test_plugin_path = os.getenv('VPP_TEST_PLUGIN_PATH')
-        cls.extern_plugin_path = os.getenv('EXTERN_PLUGINS')
-        plugin_path = None
-        if cls.plugin_path is not None:
-            if cls.extern_plugin_path is not None:
-                plugin_path = "%s:%s" % (
-                    cls.plugin_path, cls.extern_plugin_path)
-            else:
-                plugin_path = cls.plugin_path
-        elif cls.extern_plugin_path is not None:
-            plugin_path = cls.extern_plugin_path
+        extern_plugin_path = os.getenv('EXTERN_PLUGINS')
         debug_cli = ""
         if cls.step or cls.debug_gdb or cls.debug_gdbserver:
             debug_cli = "cli-listen localhost:5002"
@@ -405,20 +426,6 @@ class VppTestCase(unittest.TestCase):
         if coredump_size is None:
             coredump_size = "coredump-size unlimited"
 
-        cpu_core_number = cls.get_least_used_cpu()
-        if not hasattr(cls, "vpp_worker_count"):
-            cls.vpp_worker_count = 0
-            worker_config = os.getenv("VPP_WORKER_CONFIG", "")
-            if worker_config:
-                elems = worker_config.split(" ")
-                if elems[0] != "workers" or len(elems) != 2:
-                    raise ValueError("Wrong VPP_WORKER_CONFIG == '%s' value." %
-                                     worker_config)
-                cls.vpp_worker_count = int(elems[1])
-                if cls.vpp_worker_count > 0 and\
-                        cls.has_tag(TestCaseTag.FIXME_VPP_WORKERS):
-                    cls.vpp_worker_count = 0
-
         default_variant = os.getenv("VARIANT")
         if default_variant is not None:
             default_variant = "defaults { %s 100 }" % default_variant
@@ -434,15 +441,20 @@ class VppTestCase(unittest.TestCase):
             "unix", "{", "nodaemon", debug_cli, "full-coredump",
             coredump_size, "runtime-dir", cls.tempdir, "}",
             "api-trace", "{", "on", "}",
-            "api-segment", "{", "prefix", cls.shm_prefix, "}",
-            "cpu", "{", "main-core", str(cpu_core_number), ]
-        if cls.vpp_worker_count:
-            cls.vpp_cmdline.extend(["workers", str(cls.vpp_worker_count)])
+            "api-segment", "{", "prefix", cls.get_api_segment_prefix(), "}",
+            "cpu", "{", "main-core", str(cls.cpus[0]), ]
+        if extern_plugin_path is not None:
+            cls.extra_vpp_plugin_config.append(
+                "add-path %s" % extern_plugin_path)
+        if cls.get_vpp_worker_count():
+            cls.vpp_cmdline.extend([
+                "corelist-workers", ",".join([str(x) for x in cls.cpus[1:]])])
         cls.vpp_cmdline.extend([
             "}",
             "physmem", "{", "max-size", "32m", "}",
-            "statseg", "{", "socket-name", cls.stats_sock, "}",
-            "socksvr", "{", "socket-name", cls.api_sock, "}",
+            "statseg", "{", "socket-name", cls.get_stats_sock_path(),
+            cls.extra_vpp_statseg_config, "}",
+            "socksvr", "{", "socket-name", cls.get_api_sock_path(), "}",
             "node { ", default_variant, "}",
             "api-fuzz {", api_fuzzing, "}",
             "plugins", "{", "plugin", "dpdk_plugin.so", "{", "disable", "}",
@@ -453,13 +465,10 @@ class VppTestCase(unittest.TestCase):
 
         if cls.extra_vpp_punt_config is not None:
             cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
-        if plugin_path is not None:
-            cls.vpp_cmdline.extend(["plugin_path", plugin_path])
-        if cls.test_plugin_path is not None:
-            cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
 
-        cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
-        cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
+        if not cls.debug_attach:
+            cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
+            cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
 
     @classmethod
     def wait_for_enter(cls):
@@ -490,13 +499,18 @@ class VppTestCase(unittest.TestCase):
         print(single_line_delim)
         input("Press ENTER to continue running the testcase...")
 
+    @classmethod
+    def attach_vpp(cls):
+        cls.vpp = DummyVpp()
+
     @classmethod
     def run_vpp(cls):
+        cls.logger.debug(f"Assigned cpus: {cls.cpus}")
         cmdline = cls.vpp_cmdline
 
         if cls.debug_gdbserver:
             gdbserver = '/usr/bin/gdbserver'
-            if not os.path.isfile(gdbserver) or \
+            if not os.path.isfile(gdbserver) or\
                     not os.access(gdbserver, os.X_OK):
                 raise Exception("gdbserver binary '%s' does not exist or is "
                                 "not executable" % gdbserver)
@@ -546,6 +560,26 @@ class VppTestCase(unittest.TestCase):
                 cls.logger.error("Coredump complete: %s, size %d",
                                  corefile, curr_size)
 
+    @classmethod
+    def get_stats_sock_path(cls):
+        return "%s/stats.sock" % cls.tempdir
+
+    @classmethod
+    def get_api_sock_path(cls):
+        return "%s/api.sock" % cls.tempdir
+
+    @classmethod
+    def get_api_segment_prefix(cls):
+        return os.path.basename(cls.tempdir)  # Only used for VAPI
+
+    @classmethod
+    def get_tempdir(cls):
+        if cls.debug_attach:
+            return os.getenv("VPP_IN_GDB_TMP_DIR",
+                             "/tmp/unittest-attach-gdb")
+        else:
+            return tempfile.mkdtemp(prefix='vpp-unittest-%s-' % cls.__name__)
+
     @classmethod
     def setUpClass(cls):
         """
@@ -553,34 +587,30 @@ class VppTestCase(unittest.TestCase):
         Remove shared memory files, start vpp and connect the vpp-api
         """
         super(VppTestCase, cls).setUpClass()
-        gc.collect()  # run garbage collection first
         cls.logger = get_logger(cls.__name__)
         seed = os.environ["RND_SEED"]
         random.seed(seed)
         if hasattr(cls, 'parallel_handler'):
             cls.logger.addHandler(cls.parallel_handler)
             cls.logger.propagate = False
-
-        cls.tempdir = tempfile.mkdtemp(
-            prefix='vpp-unittest-%s-' % cls.__name__)
-        cls.stats_sock = "%s/stats.sock" % cls.tempdir
-        cls.api_sock = "%s/api.sock" % cls.tempdir
+        d = os.getenv("DEBUG", None)
+        cls.set_debug_flags(d)
+        cls.tempdir = cls.get_tempdir()
         cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
         cls.file_handler.setFormatter(
             Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
                       datefmt="%H:%M:%S"))
         cls.file_handler.setLevel(DEBUG)
         cls.logger.addHandler(cls.file_handler)
-        cls.logger.debug("--- setUpClass() for %s called ---" %
-                         cls.__name__)
-        cls.shm_prefix = os.path.basename(cls.tempdir)  # Only used for VAPI
+        cls.logger.debug("--- setUpClass() for %s called ---" % cls.__name__)
         os.chdir(cls.tempdir)
         cls.logger.info("Temporary dir is %s, api socket is %s",
-                        cls.tempdir, cls.api_sock)
-        cls.logger.debug("Random seed is %s" % seed)
+                        cls.tempdir, cls.get_api_sock_path())
+        cls.logger.debug("Random seed is %s", seed)
         cls.setUpConstants()
         cls.reset_packet_infos()
-        cls._captures = []
+        cls._pcaps = []
+        cls._old_pcaps = []
         cls.verbose = 0
         cls.vpp_dead = False
         cls.registry = VppObjectRegistry()
@@ -589,18 +619,22 @@ class VppTestCase(unittest.TestCase):
         # need to catch exceptions here because if we raise, then the cleanup
         # doesn't get called and we might end with a zombie vpp
         try:
-            cls.run_vpp()
+            if cls.debug_attach:
+                cls.attach_vpp()
+            else:
+                cls.run_vpp()
             cls.reporter.send_keep_alive(cls, 'setUpClass')
             VppTestResult.current_test_case_info = TestCaseInfo(
                 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
             cls.vpp_stdout_deque = deque()
             cls.vpp_stderr_deque = deque()
-            cls.pump_thread_stop_flag = Event()
-            cls.pump_thread_wakeup_pipe = os.pipe()
-            cls.pump_thread = Thread(target=pump_output, args=(cls,))
-            cls.pump_thread.daemon = True
-            cls.pump_thread.start()
-            if cls.debug_gdb or cls.debug_gdbserver:
+            if not cls.debug_attach:
+                cls.pump_thread_stop_flag = Event()
+                cls.pump_thread_wakeup_pipe = os.pipe()
+                cls.pump_thread = Thread(target=pump_output, args=(cls,))
+                cls.pump_thread.daemon = True
+                cls.pump_thread.start()
+            if cls.debug_gdb or cls.debug_gdbserver or cls.debug_attach:
                 cls.vapi_response_timeout = 0
             cls.vapi = VppPapiProvider(cls.__name__, cls,
                                        cls.vapi_response_timeout)
@@ -609,7 +643,7 @@ class VppTestCase(unittest.TestCase):
             else:
                 hook = hookmodule.PollHook(cls)
             cls.vapi.register_hook(hook)
-            cls.statistics = VPPStats(socketname=cls.stats_sock)
+            cls.statistics = VPPStats(socketname=cls.get_stats_sock_path())
             try:
                 hook.poll_vpp()
             except VppDiedError:
@@ -629,6 +663,10 @@ class VppTestCase(unittest.TestCase):
                                    "VPP-API connection failed, did you forget "
                                    "to 'continue' VPP from within gdb?", RED))
                 raise e
+            if cls.debug_attach:
+                last_line = cls.vapi.cli("show thread").split("\n")[-2]
+                cls.vpp_worker_count = int(last_line.split(" ")[0])
+                print("Detected VPP with %s workers." % cls.vpp_worker_count)
         except vpp_papi.VPPRuntimeError as e:
             cls.logger.debug("%s" % e)
             cls.quit()
@@ -683,7 +721,7 @@ class VppTestCase(unittest.TestCase):
                                  cls.__name__)
                 del cls.vapi
             cls.vpp.poll()
-            if cls.vpp.returncode is None:
+            if not cls.debug_attach and cls.vpp.returncode is None:
                 cls.wait_for_coredump()
                 cls.logger.debug("Sending TERM to vpp")
                 cls.vpp.terminate()
@@ -695,8 +733,9 @@ class VppTestCase(unittest.TestCase):
                     outs, errs = cls.vpp.communicate()
             cls.logger.debug("Deleting class vpp attribute on %s",
                              cls.__name__)
-            cls.vpp.stdout.close()
-            cls.vpp.stderr.close()
+            if not cls.debug_attach:
+                cls.vpp.stdout.close()
+                cls.vpp.stderr.close()
             del cls.vpp
 
         if cls.vpp_startup_failed:
@@ -769,8 +808,6 @@ class VppTestCase(unittest.TestCase):
             self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
                                                     vpp_api_trace_log))
             os.rename(tmp_api_trace, vpp_api_trace_log)
-            self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
-                                             vpp_api_trace_log))
         except VppTransportSocketIOError:
             self.logger.debug("VppTransportSocketIOError: Vpp dead. "
                               "Cannot log show commands.")
@@ -814,10 +851,10 @@ class VppTestCase(unittest.TestCase):
             i.enable_capture()
 
     @classmethod
-    def register_capture(cls, cap_name):
-        """ Register a capture in the testclass """
+    def register_pcap(cls, intf, worker):
+        """ Register a pcap in the testclass """
         # add to the list of captures with current timestamp
-        cls._captures.append((time.time(), cap_name))
+        cls._pcaps.append((intf, worker))
 
     @classmethod
     def get_vpp_time(cls):
@@ -841,6 +878,10 @@ class VppTestCase(unittest.TestCase):
     @classmethod
     def pg_start(cls, trace=True):
         """ Enable the PG, wait till it is done, then clean up """
+        for (intf, worker) in cls._old_pcaps:
+            intf.rename_old_pcap_file(intf.get_in_path(worker),
+                                      intf.in_history_counter)
+        cls._old_pcaps = []
         if trace:
             cls.vapi.cli("clear trace")
             cls.vapi.cli("trace add pg-input 1000")
@@ -855,12 +896,15 @@ class VppTestCase(unittest.TestCase):
             if time.time() > deadline:
                 cls.logger.error("Timeout waiting for pg to stop")
                 break
-        for stamp, cap_name in cls._captures:
-            cls.vapi.cli('packet-generator delete %s' % cap_name)
-        cls._captures = []
+        for intf, worker in cls._pcaps:
+            cls.vapi.cli('packet-generator delete %s' %
+                         intf.get_cap_name(worker))
+        cls._old_pcaps = cls._pcaps
+        cls._pcaps = []
 
     @classmethod
-    def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
+    def create_pg_interfaces_internal(cls, interfaces, gso=0, gso_size=0,
+                                      mode=None):
         """
         Create packet-generator interfaces.
 
@@ -870,12 +914,36 @@ class VppTestCase(unittest.TestCase):
         """
         result = []
         for i in interfaces:
-            intf = VppPGInterface(cls, i, gso, gso_size)
+            intf = VppPGInterface(cls, i, gso, gso_size, mode)
             setattr(cls, intf.name, intf)
             result.append(intf)
         cls.pg_interfaces = result
         return result
 
+    @classmethod
+    def create_pg_ip4_interfaces(cls, interfaces, gso=0, gso_size=0):
+        pgmode = VppEnum.vl_api_pg_interface_mode_t
+        return cls.create_pg_interfaces_internal(interfaces, gso, gso_size,
+                                                 pgmode.PG_API_MODE_IP4)
+
+    @classmethod
+    def create_pg_ip6_interfaces(cls, interfaces, gso=0, gso_size=0):
+        pgmode = VppEnum.vl_api_pg_interface_mode_t
+        return cls.create_pg_interfaces_internal(interfaces, gso, gso_size,
+                                                 pgmode.PG_API_MODE_IP6)
+
+    @classmethod
+    def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
+        pgmode = VppEnum.vl_api_pg_interface_mode_t
+        return cls.create_pg_interfaces_internal(interfaces, gso, gso_size,
+                                                 pgmode.PG_API_MODE_ETHERNET)
+
+    @classmethod
+    def create_pg_ethernet_interfaces(cls, interfaces, gso=0, gso_size=0):
+        pgmode = VppEnum.vl_api_pg_interface_mode_t
+        return cls.create_pg_interfaces_internal(interfaces, gso, gso_size,
+                                                 pgmode.PG_API_MODE_ETHERNET)
+
     @classmethod
     def create_loopback_interfaces(cls, count):
         """
@@ -963,8 +1031,10 @@ class VppTestCase(unittest.TestCase):
 
         :returns: string containing serialized data from packet info
         """
-        return "%d %d %d %d %d" % (info.index, info.src, info.dst,
-                                   info.ip, info.proto)
+
+        # retrieve payload, currently 18 bytes (4 x ints + 1 short)
+        return pack('iiiih', info.index, info.src,
+                    info.dst, info.ip, info.proto)
 
     @staticmethod
     def payload_to_info(payload, payload_field='load'):
@@ -979,13 +1049,18 @@ class VppTestCase(unittest.TestCase):
         :returns: _PacketInfo object containing de-serialized data from payload
 
         """
-        numbers = getattr(payload, payload_field).split()
+
+        # retrieve payload, currently 18 bytes (4 x ints + 1 short)
+        payload_b = getattr(payload, payload_field)[:18]
+
         info = _PacketInfo()
-        info.index = int(numbers[0])
-        info.src = int(numbers[1])
-        info.dst = int(numbers[2])
-        info.ip = int(numbers[3])
-        info.proto = int(numbers[4])
+        info.index, info.src, info.dst, info.ip, info.proto \
+            = unpack('iiiih', payload_b)
+
+        # some SRv6 TCs depend on get an exception if bad values are detected
+        if info.index > 0x4000:
+            raise ValueError('Index value is invalid')
+
         return info
 
     def get_next_packet_info(self, info):
@@ -1209,12 +1284,17 @@ class VppTestCase(unittest.TestCase):
             "Finished sleep (%s) - slept %es (wanted %es)",
             remark, after - before, timeout)
 
+    def virtual_sleep(self, timeout, remark=None):
+        self.logger.debug("Moving VPP time by %s (%s)", timeout, remark)
+        self.vapi.cli("set clock adjust %s" % timeout)
+
     def pg_send(self, intf, pkts, worker=None, trace=True):
         intf.add_stream(pkts, worker=worker)
         self.pg_enable_capture(self.pg_interfaces)
         self.pg_start(trace=trace)
 
-    def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
+    def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None,
+                                   trace=True):
         self.pg_send(intf, pkts)
         if not timeout:
             timeout = 1
@@ -1222,13 +1302,17 @@ class VppTestCase(unittest.TestCase):
             i.get_capture(0, timeout=timeout)
             i.assert_nothing_captured(remark=remark)
             timeout = 0.1
+        if trace:
+            self.logger.debug(self.vapi.cli("show trace"))
 
     def send_and_expect(self, intf, pkts, output, n_rx=None, worker=None,
                         trace=True):
         if not n_rx:
-            n_rx = len(pkts)
+            n_rx = 1 if isinstance(pkts, Packet) else len(pkts)
         self.pg_send(intf, pkts, worker=worker, trace=trace)
         rx = output.get_capture(n_rx)
+        if trace:
+            self.logger.debug(self.vapi.cli("show trace"))
         return rx
 
     def send_and_expect_only(self, intf, pkts, output, timeout=None):
@@ -1301,6 +1385,7 @@ class VppTestResult(unittest.TestResult):
         self.verbosity = verbosity
         self.result_string = None
         self.runner = runner
+        self.printed = []
 
     def addSuccess(self, test):
         """
@@ -1335,7 +1420,10 @@ class VppTestResult(unittest.TestResult):
         unittest.TestResult.addSkip(self, test, reason)
         self.result_string = colorize("SKIP", YELLOW)
 
-        self.send_result_through_pipe(test, SKIP)
+        if reason == "not enough cpus":
+            self.send_result_through_pipe(test, SKIP_CPU_SHORTAGE)
+        else:
+            self.send_result_through_pipe(test, SKIP)
 
     def symlink_failed(self):
         if self.current_test_case_info:
@@ -1453,28 +1541,42 @@ class VppTestResult(unittest.TestResult):
         """
 
         def print_header(test):
+            if test.__class__ in self.printed:
+                return
+
             test_doc = getdoc(test)
             if not test_doc:
                 raise Exception("No doc string for test '%s'" % test.id())
-            test_title = test_doc.splitlines()[0]
-            test_title_colored = colorize(test_title, GREEN)
+
+            test_title = test_doc.splitlines()[0].rstrip()
+            test_title = colorize(test_title, GREEN)
             if test.is_tagged_run_solo():
-                # long live PEP-8 and 80 char width limitation...
-                c = YELLOW
-                test_title_colored = colorize("SOLO RUN: " + test_title, c)
+                test_title = colorize(f"SOLO RUN: {test_title}", YELLOW)
 
             # This block may overwrite the colorized title above,
             # but we want this to stand out and be fixed
             if test.has_tag(TestCaseTag.FIXME_VPP_WORKERS):
-                c = RED
-                w = "FIXME with VPP workers: "
-                test_title_colored = colorize(w + test_title, c)
+                test_title = colorize(
+                    f"FIXME with VPP workers: {test_title}", RED)
+
+            if hasattr(test, 'vpp_worker_count'):
+                if test.vpp_worker_count == 0:
+                    test_title += " [main thread only]"
+                elif test.vpp_worker_count == 1:
+                    test_title += " [1 worker thread]"
+                else:
+                    test_title += f" [{test.vpp_worker_count} worker threads]"
+
+            if test.__class__.skipped_due_to_cpu_lack:
+                test_title = colorize(
+                    f"{test_title} [skipped - not enough cpus, "
+                    f"required={test.__class__.get_cpus_required()}, "
+                    f"available={max_vpp_cpus}]", YELLOW)
 
-            if not hasattr(test.__class__, '_header_printed'):
-                print(double_line_delim)
-                print(test_title_colored)
-                print(double_line_delim)
-            test.__class__._header_printed = True
+            print(double_line_delim)
+            print(test_title)
+            print(double_line_delim)
+            self.printed.append(test.__class__)
 
         print_header(test)
         self.start_test = time.time()
@@ -1648,14 +1750,16 @@ class Worker(Thread):
             self.result = os.EX_OSFILE
             raise EnvironmentError(
                 "executable '%s' is not found or executable." % executable)
-        self.logger.debug("Running executable: '{app}'"
-                          .format(app=' '.join(self.args)))
+        self.logger.debug("Running executable '{app}': '{cmd}'"
+                          .format(app=self.app_name,
+                                  cmd=' '.join(self.args)))
         env = os.environ.copy()
         env.update(self.env)
         env["CK_LOG_FILE_NAME"] = "-"
         self.process = subprocess.Popen(
-            self.args, shell=False, env=env, preexec_fn=os.setpgrp,
-            stdout=subprocess.PIPE, stderr=subprocess.PIPE)
+            ['stdbuf', '-o0', '-e0'] + self.args, shell=False, env=env,
+            preexec_fn=os.setpgrp, stdout=subprocess.PIPE,
+            stderr=subprocess.PIPE)
         self.wait_for_enter()
         out, err = self.process.communicate()
         self.logger.debug("Finished running `{app}'".format(app=self.app_name))