test/asf/asfframework.py

   1 #!/usr/bin/env python3
   2
   3 from __future__ import print_function
   4 import logging
   5 import sys
   6 import os
   7 import select
   8 import signal
   9 import subprocess
  10 import unittest
  11 import re
  12 import time
  13 import faulthandler
  14 import random
  15 import copy
  16 import platform
  17 import shutil
  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
  24 from enum import Enum
  25 from abc import ABC, abstractmethod
  26
  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
  31 import vpp_papi
  32 from vpp_papi.vpp_stats import VPPStats
  33 from vpp_papi.vpp_transport_socket import VppTransportSocketIOError
  34 from log import (
  35     RED,
  36     GREEN,
  37     YELLOW,
  38     double_line_delim,
  39     single_line_delim,
  40     get_logger,
  41     colorize,
  42 )
  43 from vpp_object import VppObjectRegistry
  44 from util import is_core_present
  45 from test_result_code import TestResultCode
  46
  47 logger = logging.getLogger(__name__)
  48
  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())
  52
  53
  54 if config.debug_framework:
  55     import debug_internal
  56
  57 """
  58   Test framework module.
  59
  60   The module provides a set of tools for constructing and running tests and
  61   representing the results.
  62 """
  63
  64
  65 class VppDiedError(Exception):
  66     """exception for reporting that the subprocess has died."""
  67
  68     signals_by_value = {
  69         v: k
  70         for k, v in signal.__dict__.items()
  71         if k.startswith("SIG") and not k.startswith("SIG_")
  72     }
  73
  74     def __init__(self, rv=None, testcase=None, method_name=None):
  75         self.rv = rv
  76         self.signal_name = None
  77         self.testcase = testcase
  78         self.method_name = method_name
  79
  80         try:
  81             self.signal_name = VppDiedError.signals_by_value[-rv]
  82         except (KeyError, TypeError):
  83             pass
  84
  85         if testcase is None and method_name is None:
  86             in_msg = ""
  87         else:
  88             in_msg = " while running %s.%s" % (testcase, method_name)
  89
  90         if self.rv:
  91             msg = "VPP subprocess died unexpectedly%s with return code: %d%s." % (
  92                 in_msg,
  93                 self.rv,
  94                 " [%s]" % (self.signal_name if self.signal_name is not None else ""),
  95             )
  96         else:
  97             msg = "VPP subprocess died unexpectedly%s." % in_msg
  98
  99         super(VppDiedError, self).__init__(msg)
 100
 101
 102 def pump_output(testclass):
 103     """pump output from vpp stdout/stderr to proper queues"""
 104     stdout_fragment = ""
 105     stderr_fragment = ""
 106     while not testclass.pump_thread_stop_flag.is_set():
 107         readable = select.select(
 108             [
 109                 testclass.vpp.stdout.fileno(),
 110                 testclass.vpp.stderr.fileno(),
 111                 testclass.pump_thread_wakeup_pipe[0],
 112             ],
 113             [],
 114             [],
 115         )[0]
 116         if testclass.vpp.stdout.fileno() in readable:
 117             read = os.read(testclass.vpp.stdout.fileno(), 102400)
 118             if len(read) > 0:
 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"):
 123                     limit = None
 124                 else:
 125                     limit = -1
 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)
 133             if len(read) > 0:
 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"):
 138                     limit = None
 139                 else:
 140                     limit = -1
 141                     stderr_fragment = split[-1]
 142
 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
 149
 150
 151 def _is_platform_aarch64():
 152     return platform.machine() == "aarch64"
 153
 154
 155 is_platform_aarch64 = _is_platform_aarch64()
 156
 157
 158 def _is_distro_ubuntu2204():
 159     with open("/etc/os-release") as f:
 160         for line in f.readlines():
 161             if "jammy" in line:
 162                 return True
 163     return False
 164
 165
 166 is_distro_ubuntu2204 = _is_distro_ubuntu2204()
 167
 168
 169 def _is_distro_debian11():
 170     with open("/etc/os-release") as f:
 171         for line in f.readlines():
 172             if "bullseye" in line:
 173                 return True
 174     return False
 175
 176
 177 is_distro_debian11 = _is_distro_debian11()
 178
 179
 180 def _is_distro_ubuntu2204():
 181     with open("/etc/os-release") as f:
 182         for line in f.readlines():
 183             if "jammy" in line:
 184                 return True
 185     return False
 186
 187
 188 class KeepAliveReporter(object):
 189     """
 190     Singleton object which reports test start to parent process
 191     """
 192
 193     _shared_state = {}
 194
 195     def __init__(self):
 196         self.__dict__ = self._shared_state
 197         self._pipe = None
 198
 199     @property
 200     def pipe(self):
 201         return self._pipe
 202
 203     @pipe.setter
 204     def pipe(self, pipe):
 205         if self._pipe is not None:
 206             raise Exception("Internal error - pipe should only be set once.")
 207         self._pipe = pipe
 208
 209     def send_keep_alive(self, test, desc=None):
 210         """
 211         Write current test tmpdir & desc to keep-alive pipe to signal liveness
 212         """
 213         if self.pipe is None:
 214             # if not running forked..
 215             return
 216
 217         if isclass(test):
 218             desc = "%s (%s)" % (desc, unittest.util.strclass(test))
 219         else:
 220             desc = test.id()
 221
 222         self.pipe.send((desc, config.vpp, test.tempdir, test.vpp.pid))
 223
 224
 225 class TestCaseTag(Enum):
 226     # marks the suites that must run at the end
 227     # using only a single test runner
 228     RUN_SOLO = 1
 229     # marks the suites broken on VPP multi-worker
 230     FIXME_VPP_WORKERS = 2
 231     # marks the suites broken when ASan is enabled
 232     FIXME_ASAN = 3
 233     # marks suites broken on Ubuntu-22.04
 234     FIXME_UBUNTU2204 = 4
 235     # marks suites broken on Debian-11
 236     FIXME_DEBIAN11 = 5
 237     # marks suites broken on debug vpp image
 238     FIXME_VPP_DEBUG = 6
 239
 240
 241 def create_tag_decorator(e):
 242     def decorator(cls):
 243         try:
 244             cls.test_tags.append(e)
 245         except AttributeError:
 246             cls.test_tags = [e]
 247         return cls
 248
 249     return decorator
 250
 251
 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)
 258
 259
 260 class DummyVpp:
 261     returncode = None
 262     pid = 0xCAFEBAFE
 263
 264     def poll(self):
 265         pass
 266
 267     def terminate(self):
 268         pass
 269
 270
 271 class CPUInterface(ABC):
 272     cpus = []
 273     skipped_due_to_cpu_lack = False
 274
 275     @classmethod
 276     @abstractmethod
 277     def get_cpus_required(cls):
 278         pass
 279
 280     @classmethod
 281     def assign_cpus(cls, cpus):
 282         cls.cpus = cpus
 283
 284
 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.
 288     """
 289
 290     extra_vpp_statseg_config = ""
 291     extra_vpp_config = []
 292     extra_vpp_plugin_config = []
 293     logger = null_logger
 294     vapi_response_timeout = 5
 295     remove_configured_vpp_objects_on_tear_down = True
 296
 297     @classmethod
 298     def has_tag(cls, tag):
 299         """if the test case has a given tag - return true"""
 300         try:
 301             return tag in cls.test_tags
 302         except AttributeError:
 303             pass
 304         return False
 305
 306     @classmethod
 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)
 310
 311     @classmethod
 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)
 318
 319     @classmethod
 320     def instance(cls):
 321         """Return the instance of this testcase"""
 322         return cls.test_instance
 323
 324     @classmethod
 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
 332         if d is None:
 333             return
 334         dl = d.lower()
 335         if dl == "core":
 336             cls.debug_core = True
 337         elif dl == "gdb" or dl == "gdb-all":
 338             cls.debug_gdb = True
 339         elif dl == "gdbserver" or dl == "gdbserver-all":
 340             cls.debug_gdbserver = True
 341         elif dl == "attach":
 342             cls.debug_attach = True
 343         else:
 344             raise Exception("Unrecognized DEBUG option: '%s'" % d)
 345         if dl == "gdb-all" or dl == "gdbserver-all":
 346             cls.debug_all = True
 347
 348     @classmethod
 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
 353             else:
 354                 cls.vpp_worker_count = config.vpp_worker_count
 355         return cls.vpp_worker_count
 356
 357     @classmethod
 358     def get_cpus_required(cls):
 359         return 1 + cls.get_vpp_worker_count()
 360
 361     @classmethod
 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)
 368         debug_cli = ""
 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)
 372         if size:
 373             coredump_size = f"coredump-size {config.coredump_size}".lower()
 374         else:
 375             coredump_size = "coredump-size unlimited"
 376         default_variant = config.variant
 377         if default_variant is not None:
 378             default_variant = "defaults { %s 100 }" % default_variant
 379         else:
 380             default_variant = ""
 381
 382         api_fuzzing = config.api_fuzz
 383         if api_fuzzing is None:
 384             api_fuzzing = "off"
 385
 386         cls.vpp_cmdline = [
 387             config.vpp,
 388             "unix",
 389             "{",
 390             "nodaemon",
 391             debug_cli,
 392             "full-coredump",
 393             coredump_size,
 394             "runtime-dir",
 395             cls.tempdir,
 396             "}",
 397             "api-trace",
 398             "{",
 399             "on",
 400             "}",
 401             "api-segment",
 402             "{",
 403             "prefix",
 404             cls.get_api_segment_prefix(),
 405             "}",
 406             "cpu",
 407             "{",
 408             "main-core",
 409             str(cls.cpus[0]),
 410         ]
 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:]])]
 416             )
 417         cls.vpp_cmdline.extend(
 418             [
 419                 "}",
 420                 "physmem",
 421                 "{",
 422                 "max-size",
 423                 "32m",
 424                 "}",
 425                 "statseg",
 426                 "{",
 427                 "socket-name",
 428                 cls.get_stats_sock_path(),
 429                 cls.extra_vpp_statseg_config,
 430                 "}",
 431                 "socksvr",
 432                 "{",
 433                 "socket-name",
 434                 cls.get_api_sock_path(),
 435                 "}",
 436                 "node { ",
 437                 default_variant,
 438                 "}",
 439                 "api-fuzz {",
 440                 api_fuzzing,
 441                 "}",
 442                 "plugins",
 443                 "{",
 444                 "plugin",
 445                 "dpdk_plugin.so",
 446                 "{",
 447                 "disable",
 448                 "}",
 449                 "plugin",
 450                 "rdma_plugin.so",
 451                 "{",
 452                 "disable",
 453                 "}",
 454                 "plugin",
 455                 "lisp_unittest_plugin.so",
 456                 "{",
 457                 "enable",
 458                 "}",
 459                 "plugin",
 460                 "unittest_plugin.so",
 461                 "{",
 462                 "enable",
 463                 "}",
 464             ]
 465             + cls.extra_vpp_plugin_config
 466             + [
 467                 "}",
 468             ]
 469         )
 470
 471         if cls.extra_vpp_config is not None:
 472             cls.vpp_cmdline.extend(cls.extra_vpp_config)
 473
 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))
 477
 478     @classmethod
 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)
 483         elif cls.debug_gdb:
 484             print(double_line_delim)
 485             print("Spawned VPP with PID: %d" % cls.vpp.pid)
 486         else:
 487             cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
 488             return
 489         print(single_line_delim)
 490         print("You can debug VPP using:")
 491         if cls.debug_gdbserver:
 492             print(
 493                 f"sudo gdb {config.vpp} "
 494                 f"-ex 'target remote localhost:{cls.gdbserver_port}'"
 495             )
 496             print(
 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"
 500             )
 501             cls.gdbserver_port += 1
 502         elif cls.debug_gdb:
 503             print(f"sudo gdb {config.vpp} -ex 'attach {cls.vpp.pid}'")
 504             print(
 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"
 508             )
 509         print(single_line_delim)
 510         input("Press ENTER to continue running the testcase...")
 511
 512     @classmethod
 513     def attach_vpp(cls):
 514         cls.vpp = DummyVpp()
 515
 516     @classmethod
 517     def run_vpp(cls):
 518         cls.logger.debug(f"Assigned cpus: {cls.cpus}")
 519         cmdline = cls.vpp_cmdline
 520
 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):
 524                 raise Exception(
 525                     "gdbserver binary '%s' does not exist or is "
 526                     "not executable" % gdbserver
 527                 )
 528
 529             cmdline = [
 530                 gdbserver,
 531                 "localhost:{port}".format(port=cls.gdbserver_port),
 532             ] + cls.vpp_cmdline
 533             cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
 534
 535         try:
 536             cls.vpp = subprocess.Popen(
 537                 cmdline, stdout=subprocess.PIPE, stderr=subprocess.PIPE
 538             )
 539         except subprocess.CalledProcessError as e:
 540             cls.logger.critical(
 541                 "Subprocess returned with non-0 return code: (%s)", e.returncode
 542             )
 543             raise
 544         except OSError as e:
 545             cls.logger.critical(
 546                 "Subprocess returned with OS error: (%s) %s", e.errno, e.strerror
 547             )
 548             raise
 549         except Exception as e:
 550             cls.logger.exception("Subprocess returned unexpected from %s:", cmdline)
 551             raise
 552
 553         cls.wait_for_enter()
 554
 555     @classmethod
 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
 562             ok = False
 563             while time.time() < deadline:
 564                 cls.sleep(1)
 565                 size = curr_size
 566                 curr_size = os.path.getsize(corefile)
 567                 if size == curr_size:
 568                     ok = True
 569                     break
 570             if not ok:
 571                 cls.logger.error(
 572                     "Timed out waiting for coredump to complete: %s", corefile
 573                 )
 574             else:
 575                 cls.logger.error("Coredump complete: %s, size %d", corefile, curr_size)
 576
 577     @classmethod
 578     def get_stats_sock_path(cls):
 579         return "%s/stats.sock" % cls.tempdir
 580
 581     @classmethod
 582     def get_api_sock_path(cls):
 583         return "%s/api.sock" % cls.tempdir
 584
 585     @classmethod
 586     def get_api_segment_prefix(cls):
 587         return os.path.basename(cls.tempdir)  # Only used for VAPI
 588
 589     @classmethod
 590     def get_tempdir(cls):
 591         if cls.debug_attach:
 592             tmpdir = f"{config.tmp_dir}/unittest-attach-gdb"
 593         else:
 594             tmpdir = f"{config.tmp_dir}/{get_testcase_dirname(cls.__name__)}"
 595             if config.wipe_tmp_dir:
 596                 shutil.rmtree(tmpdir, ignore_errors=True)
 597             os.mkdir(tmpdir)
 598         return tmpdir
 599
 600     @classmethod
 601     def create_file_handler(cls):
 602         if config.log_dir is None:
 603             cls.file_handler = FileHandler(f"{cls.tempdir}/log.txt")
 604             return
 605
 606         logdir = f"{config.log_dir}/{get_testcase_dirname(cls.__name__)}"
 607         if config.wipe_tmp_dir:
 608             shutil.rmtree(logdir, ignore_errors=True)
 609         os.mkdir(logdir)
 610         cls.file_handler = FileHandler(f"{logdir}/log.txt")
 611
 612     @classmethod
 613     def setUpClass(cls):
 614         """
 615         Perform class setup before running the testcase
 616         Remove shared memory files, start vpp and connect the vpp-api
 617         """
 618         super(VppAsfTestCase, cls).setUpClass()
 619         cls.logger = get_logger(cls.__name__)
 620         cls.logger.debug(f"--- START setUpClass() {cls.__name__} ---")
 621         random.seed(config.rnd_seed)
 622         if hasattr(cls, "parallel_handler"):
 623             cls.logger.addHandler(cls.parallel_handler)
 624             cls.logger.propagate = False
 625         cls.set_debug_flags(config.debug)
 626         cls.tempdir = cls.get_tempdir()
 627         cls.create_file_handler()
 628         cls.file_handler.setFormatter(
 629             Formatter(fmt="%(asctime)s,%(msecs)03d %(message)s", datefmt="%H:%M:%S")
 630         )
 631         cls.file_handler.setLevel(DEBUG)
 632         cls.logger.addHandler(cls.file_handler)
 633         cls.logger.debug("--- setUpClass() for %s called ---" % cls.__name__)
 634         os.chdir(cls.tempdir)
 635         cls.logger.info(
 636             "Temporary dir is %s, api socket is %s",
 637             cls.tempdir,
 638             cls.get_api_sock_path(),
 639         )
 640         cls.logger.debug("Random seed is %s", config.rnd_seed)
 641         cls.setUpConstants()
 642         cls.verbose = 0
 643         cls.vpp_dead = False
 644         cls.registry = VppObjectRegistry()
 645         cls.vpp_startup_failed = False
 646         cls.reporter = KeepAliveReporter()
 647         # need to catch exceptions here because if we raise, then the cleanup
 648         # doesn't get called and we might end with a zombie vpp
 649         try:
 650             if cls.debug_attach:
 651                 cls.attach_vpp()
 652             else:
 653                 cls.run_vpp()
 654             cls.reporter.send_keep_alive(cls, "setUpClass")
 655             VppTestResult.current_test_case_info = TestCaseInfo(
 656                 cls.logger, cls.tempdir, cls.vpp.pid, config.vpp
 657             )
 658             cls.vpp_stdout_deque = deque()
 659             cls.vpp_stderr_deque = deque()
 660             if not cls.debug_attach:
 661                 cls.pump_thread_stop_flag = Event()
 662                 cls.pump_thread_wakeup_pipe = os.pipe()
 663                 cls.pump_thread = Thread(target=pump_output, args=(cls,))
 664                 cls.pump_thread.daemon = True
 665                 cls.pump_thread.start()
 666             if cls.debug_gdb or cls.debug_gdbserver or cls.debug_attach:
 667                 cls.vapi_response_timeout = 0
 668             cls.vapi = VppPapiProvider(cls.__name__, cls, cls.vapi_response_timeout)
 669             if cls.step:
 670                 hook = hookmodule.StepHook(cls)
 671             else:
 672                 hook = hookmodule.PollHook(cls)
 673             cls.vapi.register_hook(hook)
 674             cls.statistics = VPPStats(socketname=cls.get_stats_sock_path())
 675             try:
 676                 hook.poll_vpp()
 677             except VppDiedError:
 678                 cls.wait_for_coredump()
 679                 cls.vpp_startup_failed = True
 680                 cls.logger.critical(
 681                     "VPP died shortly after startup, check the"
 682                     " output to standard error for possible cause"
 683                 )
 684                 raise
 685             try:
 686                 cls.vapi.connect()
 687             except (vpp_papi.VPPIOError, Exception) as e:
 688                 cls.logger.debug("Exception connecting to vapi: %s" % e)
 689                 cls.vapi.disconnect()
 690
 691                 if cls.debug_gdbserver:
 692                     print(
 693                         colorize(
 694                             "You're running VPP inside gdbserver but "
 695                             "VPP-API connection failed, did you forget "
 696                             "to 'continue' VPP from within gdb?",
 697                             RED,
 698                         )
 699                     )
 700                 raise e
 701             if cls.debug_attach:
 702                 last_line = cls.vapi.cli("show thread").split("\n")[-2]
 703                 cls.vpp_worker_count = int(last_line.split(" ")[0])
 704                 print("Detected VPP with %s workers." % cls.vpp_worker_count)
 705         except vpp_papi.VPPRuntimeError as e:
 706             cls.logger.debug("%s" % e)
 707             cls.quit()
 708             raise e
 709         except Exception as e:
 710             cls.logger.debug("Exception connecting to VPP: %s" % e)
 711             cls.quit()
 712             raise e
 713         cls.logger.debug(f"--- END setUpClass() {cls.__name__} ---")
 714
 715     @classmethod
 716     def _debug_quit(cls):
 717         if cls.debug_gdbserver or cls.debug_gdb:
 718             try:
 719                 cls.vpp.poll()
 720
 721                 if cls.vpp.returncode is None:
 722                     print()
 723                     print(double_line_delim)
 724                     print("VPP or GDB server is still running")
 725                     print(single_line_delim)
 726                     input(
 727                         "When done debugging, press ENTER to kill the "
 728                         "process and finish running the testcase..."
 729                     )
 730             except AttributeError:
 731                 pass
 732
 733     @classmethod
 734     def quit(cls):
 735         """
 736         Disconnect vpp-api, kill vpp and cleanup shared memory files
 737         """
 738         cls._debug_quit()
 739
 740         # first signal that we want to stop the pump thread, then wake it up
 741         if hasattr(cls, "pump_thread_stop_flag"):
 742             cls.pump_thread_stop_flag.set()
 743         if hasattr(cls, "pump_thread_wakeup_pipe"):
 744             os.write(cls.pump_thread_wakeup_pipe[1], b"ding dong wake up")
 745         if hasattr(cls, "pump_thread"):
 746             cls.logger.debug("Waiting for pump thread to stop")
 747             cls.pump_thread.join()
 748         if hasattr(cls, "vpp_stderr_reader_thread"):
 749             cls.logger.debug("Waiting for stderr pump to stop")
 750             cls.vpp_stderr_reader_thread.join()
 751
 752         if hasattr(cls, "vpp"):
 753             if hasattr(cls, "vapi"):
 754                 cls.logger.debug(cls.vapi.vpp.get_stats())
 755                 cls.logger.debug("Disconnecting class vapi client on %s", cls.__name__)
 756                 cls.vapi.disconnect()
 757                 cls.logger.debug("Deleting class vapi attribute on %s", cls.__name__)
 758                 del cls.vapi
 759             cls.vpp.poll()
 760             if not cls.debug_attach and cls.vpp.returncode is None:
 761                 cls.wait_for_coredump()
 762                 cls.logger.debug("Sending TERM to vpp")
 763                 cls.vpp.terminate()
 764                 cls.logger.debug("Waiting for vpp to die")
 765                 try:
 766                     outs, errs = cls.vpp.communicate(timeout=5)
 767                 except subprocess.TimeoutExpired:
 768                     cls.vpp.kill()
 769                     outs, errs = cls.vpp.communicate()
 770             cls.logger.debug("Deleting class vpp attribute on %s", cls.__name__)
 771             if not cls.debug_attach:
 772                 cls.vpp.stdout.close()
 773                 cls.vpp.stderr.close()
 774             del cls.vpp
 775
 776         if cls.vpp_startup_failed:
 777             stdout_log = cls.logger.info
 778             stderr_log = cls.logger.critical
 779         else:
 780             stdout_log = cls.logger.info
 781             stderr_log = cls.logger.info
 782
 783         if hasattr(cls, "vpp_stdout_deque"):
 784             stdout_log(single_line_delim)
 785             stdout_log("VPP output to stdout while running %s:", cls.__name__)
 786             stdout_log(single_line_delim)
 787             vpp_output = "".join(cls.vpp_stdout_deque)
 788             with open(cls.tempdir + "/vpp_stdout.txt", "w") as f:
 789                 f.write(vpp_output)
 790             stdout_log("\n%s", vpp_output)
 791             stdout_log(single_line_delim)
 792
 793         if hasattr(cls, "vpp_stderr_deque"):
 794             stderr_log(single_line_delim)
 795             stderr_log("VPP output to stderr while running %s:", cls.__name__)
 796             stderr_log(single_line_delim)
 797             vpp_output = "".join(cls.vpp_stderr_deque)
 798             with open(cls.tempdir + "/vpp_stderr.txt", "w") as f:
 799                 f.write(vpp_output)
 800             stderr_log("\n%s", vpp_output)
 801             stderr_log(single_line_delim)
 802
 803     @classmethod
 804     def tearDownClass(cls):
 805         """Perform final cleanup after running all tests in this test-case"""
 806         cls.logger.debug(f"--- START tearDownClass() {cls.__name__} ---")
 807         cls.reporter.send_keep_alive(cls, "tearDownClass")
 808         cls.quit()
 809         cls.file_handler.close()
 810         if config.debug_framework:
 811             debug_internal.on_tear_down_class(cls)
 812         cls.logger.debug(f"--- END tearDownClass() {cls.__name__} ---")
 813
 814     def show_commands_at_teardown(self):
 815         """Allow subclass specific teardown logging additions."""
 816         self.logger.info("--- No test specific show commands provided. ---")
 817
 818     def tearDown(self):
 819         """Show various debug prints after each test"""
 820         self.logger.debug(
 821             f"--- START tearDown() {self.__class__.__name__}.{self._testMethodName}({self._testMethodDoc}) ---"
 822         )
 823
 824         try:
 825             if not self.vpp_dead:
 826                 self.logger.debug(self.vapi.cli("show trace max 1000"))
 827                 self.logger.info(self.vapi.ppcli("show interface"))
 828                 self.logger.info(self.vapi.ppcli("show hardware"))
 829                 self.logger.info(self.statistics.set_errors_str())
 830                 self.logger.info(self.vapi.ppcli("show run"))
 831                 self.logger.info(self.vapi.ppcli("show log"))
 832                 self.logger.info(self.vapi.ppcli("show bihash"))
 833                 self.logger.info("Logging testcase specific show commands.")
 834                 self.show_commands_at_teardown()
 835                 if self.remove_configured_vpp_objects_on_tear_down:
 836                     self.registry.remove_vpp_config(self.logger)
 837             # Save/Dump VPP api trace log
 838             m = self._testMethodName
 839             api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
 840             tmp_api_trace = "/tmp/%s" % api_trace
 841             vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
 842             self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
 843             self.logger.info("Moving %s to %s\n" % (tmp_api_trace, vpp_api_trace_log))
 844             shutil.move(tmp_api_trace, vpp_api_trace_log)
 845         except VppTransportSocketIOError:
 846             self.logger.debug(
 847                 "VppTransportSocketIOError: Vpp dead. Cannot log show commands."
 848             )
 849             self.vpp_dead = True
 850         else:
 851             self.registry.unregister_all(self.logger)
 852         # Remove any leftover pcap files
 853         if hasattr(self, "pg_interfaces") and len(self.pg_interfaces) > 0:
 854             testcase_dir = os.path.dirname(self.pg_interfaces[0].out_path)
 855             for p in Path(testcase_dir).glob("pg*.pcap"):
 856                 self.logger.debug(f"Removing {p}")
 857                 p.unlink()
 858         self.logger.debug(
 859             f"--- END tearDown() {self.__class__.__name__}.{self._testMethodName}('{self._testMethodDoc}') ---"
 860         )
 861
 862     def setUp(self):
 863         """Clear trace before running each test"""
 864         super(VppAsfTestCase, self).setUp()
 865         self.logger.debug(
 866             f"--- START setUp() {self.__class__.__name__}.{self._testMethodName}('{self._testMethodDoc}') ---"
 867         )
 868         # Save testname include in pcap history filenames
 869         if hasattr(self, "pg_interfaces"):
 870             for i in self.pg_interfaces:
 871                 i.test_name = self._testMethodName
 872         self.reporter.send_keep_alive(self)
 873         if self.vpp_dead:
 874             self.wait_for_coredump()
 875             raise VppDiedError(
 876                 rv=None,
 877                 testcase=self.__class__.__name__,
 878                 method_name=self._testMethodName,
 879             )
 880         self.sleep(0.1, "during setUp")
 881         self.vpp_stdout_deque.append(
 882             "--- test setUp() for %s.%s(%s) starts here ---\n"
 883             % (self.__class__.__name__, self._testMethodName, self._testMethodDoc)
 884         )
 885         self.vpp_stderr_deque.append(
 886             "--- test setUp() for %s.%s(%s) starts here ---\n"
 887             % (self.__class__.__name__, self._testMethodName, self._testMethodDoc)
 888         )
 889         self.vapi.cli("clear trace")
 890         # store the test instance inside the test class - so that objects
 891         # holding the class can access instance methods (like assertEqual)
 892         type(self).test_instance = self
 893         self.logger.debug(
 894             f"--- END setUp() {self.__class__.__name__}.{self._testMethodName}('{self._testMethodDoc}') ---"
 895         )
 896
 897     @classmethod
 898     def get_vpp_time(cls):
 899         # processes e.g. "Time now 2.190522, Wed, 11 Mar 2020 17:29:54 GMT"
 900         # returns float("2.190522")
 901         timestr = cls.vapi.cli("show clock")
 902         head, sep, tail = timestr.partition(",")
 903         head, sep, tail = head.partition("Time now")
 904         return float(tail)
 905
 906     @classmethod
 907     def sleep_on_vpp_time(cls, sec):
 908         """Sleep according to time in VPP world"""
 909         # On a busy system with many processes
 910         # we might end up with VPP time being slower than real world
 911         # So take that into account when waiting for VPP to do something
 912         start_time = cls.get_vpp_time()
 913         while cls.get_vpp_time() - start_time < sec:
 914             cls.sleep(0.1)
 915
 916     @classmethod
 917     def create_loopback_interfaces(cls, count):
 918         """
 919         Create loopback interfaces.
 920
 921         :param count: number of interfaces created.
 922         :returns: List of created interfaces.
 923         """
 924         result = [VppLoInterface(cls) for i in range(count)]
 925         for intf in result:
 926             setattr(cls, intf.name, intf)
 927         cls.lo_interfaces = result
 928         return result
 929
 930     def assert_equal(self, real_value, expected_value, name_or_class=None):
 931         if name_or_class is None:
 932             self.assertEqual(real_value, expected_value)
 933             return
 934         try:
 935             msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
 936             msg = msg % (
 937                 getdoc(name_or_class).strip(),
 938                 real_value,
 939                 str(name_or_class(real_value)),
 940                 expected_value,
 941                 str(name_or_class(expected_value)),
 942             )
 943         except Exception:
 944             msg = "Invalid %s: %s does not match expected value %s" % (
 945                 name_or_class,
 946                 real_value,
 947                 expected_value,
 948             )
 949
 950         self.assertEqual(real_value, expected_value, msg)
 951
 952     def assert_in_range(self, real_value, expected_min, expected_max, name=None):
 953         if name is None:
 954             msg = None
 955         else:
 956             msg = "Invalid %s: %s out of range <%s,%s>" % (
 957                 name,
 958                 real_value,
 959                 expected_min,
 960                 expected_max,
 961             )
 962         self.assertTrue(expected_min <= real_value <= expected_max, msg)
 963
 964     def get_counter(self, counter):
 965         if counter.startswith("/"):
 966             counter_value = self.statistics.get_counter(counter)
 967         else:
 968             counters = self.vapi.cli("sh errors").split("\n")
 969             counter_value = 0
 970             for i in range(1, len(counters) - 1):
 971                 results = counters[i].split()
 972                 if results[1] == counter:
 973                     counter_value = int(results[0])
 974                     break
 975         return counter_value
 976
 977     def assert_counter_equal(self, counter, expected_value, thread=None, index=0):
 978         c = self.get_counter(counter)
 979         if thread is not None:
 980             c = c[thread][index]
 981         else:
 982             c = sum(x[index] for x in c)
 983         self.logger.debug(
 984             "validate counter `%s[%s]', expected: %s, real value: %s"
 985             % (counter, index, expected_value, c)
 986         )
 987         self.assert_equal(c, expected_value, "counter `%s[%s]'" % (counter, index))
 988
 989     def assert_error_counter_equal(self, counter, expected_value):
 990         counter_value = self.statistics[counter].sum()
 991         self.assert_equal(counter_value, expected_value, "error counter `%s'" % counter)
 992
 993     @classmethod
 994     def sleep(cls, timeout, remark=None):
 995         # /* Allow sleep(0) to maintain win32 semantics, and as decreed
 996         #  * by Guido, only the main thread can be interrupted.
 997         # */
 998         # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892  # noqa
 999         if timeout == 0:
1000             # yield quantum
1001             if hasattr(os, "sched_yield"):
1002                 os.sched_yield()
1003             else:
1004                 time.sleep(0)
1005             return
1006
1007         cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1008         before = time.time()
1009         time.sleep(timeout)
1010         after = time.time()
1011         if after - before > 2 * timeout:
1012             cls.logger.error(
1013                 "unexpected self.sleep() result - slept for %es instead of ~%es!",
1014                 after - before,
1015                 timeout,
1016             )
1017
1018         cls.logger.debug(
1019             "Finished sleep (%s) - slept %es (wanted %es)",
1020             remark,
1021             after - before,
1022             timeout,
1023         )
1024
1025     def virtual_sleep(self, timeout, remark=None):
1026         self.logger.debug("Moving VPP time by %s (%s)", timeout, remark)
1027         self.vapi.cli("set clock adjust %s" % timeout)
1028
1029     def snapshot_stats(self, stats_diff):
1030         """Return snapshot of interesting stats based on diff dictionary."""
1031         stats_snapshot = {}
1032         for sw_if_index in stats_diff:
1033             for counter in stats_diff[sw_if_index]:
1034                 stats_snapshot[counter] = self.statistics[counter]
1035         self.logger.debug(f"Took statistics stats_snapshot: {stats_snapshot}")
1036         return stats_snapshot
1037
1038     def compare_stats_with_snapshot(self, stats_diff, stats_snapshot):
1039         """Assert appropriate difference between current stats and snapshot."""
1040         for sw_if_index in stats_diff:
1041             for cntr, diff in stats_diff[sw_if_index].items():
1042                 if sw_if_index == "err":
1043                     self.assert_equal(
1044                         self.statistics[cntr].sum(),
1045                         stats_snapshot[cntr].sum() + diff,
1046                         f"'{cntr}' counter value (previous value: "
1047                         f"{stats_snapshot[cntr].sum()}, "
1048                         f"expected diff: {diff})",
1049                     )
1050                 else:
1051                     try:
1052                         self.assert_equal(
1053                             self.statistics[cntr][:, sw_if_index].sum(),
1054                             stats_snapshot[cntr][:, sw_if_index].sum() + diff,
1055                             f"'{cntr}' counter value (previous value: "
1056                             f"{stats_snapshot[cntr][:, sw_if_index].sum()}, "
1057                             f"expected diff: {diff})",
1058                         )
1059                     except IndexError as e:
1060                         # if diff is 0, then this most probably a case where
1061                         # test declares multiple interfaces but traffic hasn't
1062                         # passed through this one yet - which means the counter
1063                         # value is 0 and can be ignored
1064                         if 0 != diff:
1065                             raise Exception(
1066                                 f"Couldn't sum counter: {cntr} on sw_if_index: {sw_if_index}"
1067                             ) from e
1068
1069
1070 def get_testcase_doc_name(test):
1071     return getdoc(test.__class__).splitlines()[0]
1072
1073
1074 def get_test_description(descriptions, test):
1075     short_description = test.shortDescription()
1076     if descriptions and short_description:
1077         return short_description
1078     else:
1079         return str(test)
1080
1081
1082 def get_failed_testcase_linkname(failed_dir, testcase_dirname):
1083     return os.path.join(failed_dir, f"{testcase_dirname}-FAILED")
1084
1085
1086 def get_testcase_dirname(testcase_class_name):
1087     return f"vpp-unittest-{testcase_class_name}"
1088
1089
1090 class TestCaseInfo(object):
1091     def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1092         self.logger = logger
1093         self.tempdir = tempdir
1094         self.vpp_pid = vpp_pid
1095         self.vpp_bin_path = vpp_bin_path
1096         self.core_crash_test = None
1097
1098
1099 class VppTestResult(unittest.TestResult):
1100     """
1101     @property result_string
1102      String variable to store the test case result string.
1103     @property errors
1104      List variable containing 2-tuples of TestCase instances and strings
1105      holding formatted tracebacks. Each tuple represents a test which
1106      raised an unexpected exception.
1107     @property failures
1108      List variable containing 2-tuples of TestCase instances and strings
1109      holding formatted tracebacks. Each tuple represents a test where
1110      a failure was explicitly signalled using the TestCase.assert*()
1111      methods.
1112     """
1113
1114     failed_test_cases_info = set()
1115     core_crash_test_cases_info = set()
1116     current_test_case_info = None
1117
1118     def __init__(self, stream=None, descriptions=None, verbosity=None, runner=None):
1119         """
1120         :param stream File descriptor to store where to report test results.
1121             Set to the standard error stream by default.
1122         :param descriptions Boolean variable to store information if to use
1123             test case descriptions.
1124         :param verbosity Integer variable to store required verbosity level.
1125         """
1126         super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1127         self.stream = stream
1128         self.descriptions = descriptions
1129         self.verbosity = verbosity
1130         self.result_code = TestResultCode.TEST_RUN
1131         self.result_string = None
1132         self.runner = runner
1133         self.printed = []
1134
1135     def decodePcapFiles(self, test, when_configured=False):
1136         if when_configured == False or config.decode_pcaps == True:
1137             if hasattr(test, "pg_interfaces") and len(test.pg_interfaces) > 0:
1138                 testcase_dir = os.path.dirname(test.pg_interfaces[0].out_path)
1139                 test.pg_interfaces[0].decode_pcap_files(
1140                     testcase_dir, f"suite{test.__class__.__name__}"
1141                 )
1142                 test.pg_interfaces[0].decode_pcap_files(
1143                     testcase_dir, test._testMethodName
1144                 )
1145
1146     def addSuccess(self, test):
1147         """
1148         Record a test succeeded result
1149
1150         :param test:
1151
1152         """
1153         self.log_result("addSuccess", test)
1154         self.decodePcapFiles(test, when_configured=True)
1155         unittest.TestResult.addSuccess(self, test)
1156         self.result_string = colorize("OK", GREEN)
1157         self.result_code = TestResultCode.PASS
1158         self.send_result_through_pipe(test, self.result_code)
1159
1160     def addExpectedFailure(self, test, err):
1161         self.log_result("addExpectedFailure", test, err)
1162         self.decodePcapFiles(test)
1163         super().addExpectedFailure(test, err)
1164         self.result_string = colorize("FAIL", GREEN)
1165         self.result_code = TestResultCode.EXPECTED_FAIL
1166         self.send_result_through_pipe(test, self.result_code)
1167
1168     def addUnexpectedSuccess(self, test):
1169         self.log_result("addUnexpectedSuccess", test)
1170         self.decodePcapFiles(test, when_configured=True)
1171         super().addUnexpectedSuccess(test)
1172         self.result_string = colorize("OK", RED)
1173         self.result_code = TestResultCode.UNEXPECTED_PASS
1174         self.send_result_through_pipe(test, self.result_code)
1175
1176     def addSkip(self, test, reason):
1177         """
1178         Record a test skipped.
1179
1180         :param test:
1181         :param reason:
1182
1183         """
1184         self.log_result("addSkip", test, reason=reason)
1185         unittest.TestResult.addSkip(self, test, reason)
1186         self.result_string = colorize("SKIP", YELLOW)
1187
1188         if reason == "not enough cpus":
1189             self.result_code = TestResultCode.SKIP_CPU_SHORTAGE
1190         else:
1191             self.result_code = TestResultCode.SKIP
1192         self.send_result_through_pipe(test, self.result_code)
1193
1194     def symlink_failed(self):
1195         if self.current_test_case_info:
1196             try:
1197                 failed_dir = config.failed_dir
1198                 link_path = get_failed_testcase_linkname(
1199                     failed_dir, os.path.basename(self.current_test_case_info.tempdir)
1200                 )
1201
1202                 self.current_test_case_info.logger.debug(
1203                     "creating a link to the failed test"
1204                 )
1205                 self.current_test_case_info.logger.debug(
1206                     "os.symlink(%s, %s)"
1207                     % (self.current_test_case_info.tempdir, link_path)
1208                 )
1209                 if os.path.exists(link_path):
1210                     self.current_test_case_info.logger.debug("symlink already exists")
1211                 else:
1212                     os.symlink(self.current_test_case_info.tempdir, link_path)
1213
1214             except Exception as e:
1215                 self.current_test_case_info.logger.error(e)
1216
1217     def send_result_through_pipe(self, test, result):
1218         if hasattr(self, "test_framework_result_pipe"):
1219             pipe = self.test_framework_result_pipe
1220             if pipe:
1221                 pipe.send((test.id(), result))
1222
1223     def log_result(self, fn, test, err=None, reason=None):
1224         if self.current_test_case_info:
1225             if isinstance(test, unittest.suite._ErrorHolder):
1226                 test_name = test.description
1227             else:
1228                 test_name = "%s.%s(%s)" % (
1229                     test.__class__.__name__,
1230                     test._testMethodName,
1231                     test._testMethodDoc,
1232                 )
1233             extra_msg = ""
1234             if err:
1235                 extra_msg += f", error is {err}"
1236             if reason:
1237                 extra_msg += f", reason is {reason}"
1238             self.current_test_case_info.logger.debug(
1239                 f"--- {fn}() {test_name} called{extra_msg}"
1240             )
1241             if err:
1242                 self.current_test_case_info.logger.debug(
1243                     "formatted exception is:\n%s" % "".join(format_exception(*err))
1244                 )
1245
1246     def add_error(self, test, err, unittest_fn, result_code):
1247         self.result_code = result_code
1248         if result_code == TestResultCode.FAIL:
1249             self.log_result("addFailure", test, err=err)
1250             error_type_str = colorize("FAIL", RED)
1251         elif result_code == TestResultCode.ERROR:
1252             self.log_result("addError", test, err=err)
1253             error_type_str = colorize("ERROR", RED)
1254         else:
1255             raise Exception(f"Unexpected result code {result_code}")
1256         self.decodePcapFiles(test)
1257
1258         unittest_fn(self, test, err)
1259         if self.current_test_case_info:
1260             self.result_string = "%s [ temp dir used by test case: %s ]" % (
1261                 error_type_str,
1262                 self.current_test_case_info.tempdir,
1263             )
1264             self.symlink_failed()
1265             self.failed_test_cases_info.add(self.current_test_case_info)
1266             if is_core_present(self.current_test_case_info.tempdir):
1267                 if not self.current_test_case_info.core_crash_test:
1268                     if isinstance(test, unittest.suite._ErrorHolder):
1269                         test_name = str(test)
1270                     else:
1271                         test_name = "'{!s}' ({!s})".format(
1272                             get_testcase_doc_name(test), test.id()
1273                         )
1274                     self.current_test_case_info.core_crash_test = test_name
1275                 self.core_crash_test_cases_info.add(self.current_test_case_info)
1276         else:
1277             self.result_string = "%s [no temp dir]" % error_type_str
1278
1279         self.send_result_through_pipe(test, result_code)
1280
1281     def addFailure(self, test, err):
1282         """
1283         Record a test failed result
1284
1285         :param test:
1286         :param err: error message
1287
1288         """
1289         self.add_error(test, err, unittest.TestResult.addFailure, TestResultCode.FAIL)
1290
1291     def addError(self, test, err):
1292         """
1293         Record a test error result
1294
1295         :param test:
1296         :param err: error message
1297
1298         """
1299         self.add_error(test, err, unittest.TestResult.addError, TestResultCode.ERROR)
1300
1301     def getDescription(self, test):
1302         """
1303         Get test description
1304
1305         :param test:
1306         :returns: test description
1307
1308         """
1309         return get_test_description(self.descriptions, test)
1310
1311     def startTest(self, test):
1312         """
1313         Start a test
1314
1315         :param test:
1316
1317         """
1318
1319         def print_header(test):
1320             if test.__class__ in self.printed:
1321                 return
1322
1323             test_doc = getdoc(test)
1324             if not test_doc:
1325                 raise Exception("No doc string for test '%s'" % test.id())
1326
1327             test_title = test_doc.splitlines()[0].rstrip()
1328             test_title = colorize(test_title, GREEN)
1329             if test.is_tagged_run_solo():
1330                 test_title = colorize(f"SOLO RUN: {test_title}", YELLOW)
1331
1332             # This block may overwrite the colorized title above,
1333             # but we want this to stand out and be fixed
1334             if test.has_tag(TestCaseTag.FIXME_VPP_WORKERS):
1335                 test_title = colorize(f"FIXME with VPP workers: {test_title}", RED)
1336
1337             if test.has_tag(TestCaseTag.FIXME_ASAN):
1338                 test_title = colorize(f"FIXME with ASAN: {test_title}", RED)
1339                 test.skip_fixme_asan()
1340
1341             if hasattr(test, "vpp_worker_count"):
1342                 if test.vpp_worker_count == 0:
1343                     test_title += " [main thread only]"
1344                 elif test.vpp_worker_count == 1:
1345                     test_title += " [1 worker thread]"
1346                 else:
1347                     test_title += f" [{test.vpp_worker_count} worker threads]"
1348
1349             if test.__class__.skipped_due_to_cpu_lack:
1350                 test_title = colorize(
1351                     f"{test_title} [skipped - not enough cpus, "
1352                     f"required={test.__class__.get_cpus_required()}, "
1353                     f"available={max_vpp_cpus}]",
1354                     YELLOW,
1355                 )
1356
1357             print(double_line_delim)
1358             print(test_title)
1359             print(double_line_delim)
1360             self.printed.append(test.__class__)
1361
1362         print_header(test)
1363         self.start_test = time.time()
1364         unittest.TestResult.startTest(self, test)
1365         if self.verbosity > 0:
1366             self.stream.writeln("Starting " + self.getDescription(test) + " ...")
1367             self.stream.writeln(single_line_delim)
1368
1369     def stopTest(self, test):
1370         """
1371         Called when the given test has been run
1372
1373         :param test:
1374
1375         """
1376         unittest.TestResult.stopTest(self, test)
1377
1378         result_code_to_suffix = {
1379             TestResultCode.PASS: "",
1380             TestResultCode.FAIL: "",
1381             TestResultCode.ERROR: "",
1382             TestResultCode.SKIP: "",
1383             TestResultCode.TEST_RUN: "",
1384             TestResultCode.SKIP_CPU_SHORTAGE: "",
1385             TestResultCode.EXPECTED_FAIL: " [EXPECTED FAIL]",
1386             TestResultCode.UNEXPECTED_PASS: " [UNEXPECTED PASS]",
1387         }
1388
1389         if self.verbosity > 0:
1390             self.stream.writeln(single_line_delim)
1391             self.stream.writeln(
1392                 "%-72s%s%s"
1393                 % (
1394                     self.getDescription(test),
1395                     self.result_string,
1396                     result_code_to_suffix[self.result_code],
1397                 )
1398             )
1399             self.stream.writeln(single_line_delim)
1400         else:
1401             self.stream.writeln(
1402                 "%-67s %4.2f %s%s"
1403                 % (
1404                     self.getDescription(test),
1405                     time.time() - self.start_test,
1406                     self.result_string,
1407                     result_code_to_suffix[self.result_code],
1408                 )
1409             )
1410
1411         self.send_result_through_pipe(test, TestResultCode.TEST_RUN)
1412
1413     def printErrors(self):
1414         """
1415         Print errors from running the test case
1416         """
1417         if len(self.errors) > 0 or len(self.failures) > 0:
1418             self.stream.writeln()
1419             self.printErrorList("ERROR", self.errors)
1420             self.printErrorList("FAIL", self.failures)
1421
1422         # ^^ that is the last output from unittest before summary
1423         if not self.runner.print_summary:
1424             devnull = unittest.runner._WritelnDecorator(open(os.devnull, "w"))
1425             self.stream = devnull
1426             self.runner.stream = devnull
1427
1428     def printErrorList(self, flavour, errors):
1429         """
1430         Print error list to the output stream together with error type
1431         and test case description.
1432
1433         :param flavour: error type
1434         :param errors: iterable errors
1435
1436         """
1437         for test, err in errors:
1438             self.stream.writeln(double_line_delim)
1439             self.stream.writeln("%s: %s" % (flavour, self.getDescription(test)))
1440             self.stream.writeln(single_line_delim)
1441             self.stream.writeln("%s" % err)
1442
1443
1444 class VppTestRunner(unittest.TextTestRunner):
1445     """
1446     A basic test runner implementation which prints results to standard error.
1447     """
1448
1449     @property
1450     def resultclass(self):
1451         """Class maintaining the results of the tests"""
1452         return VppTestResult
1453
1454     def __init__(
1455         self,
1456         keep_alive_pipe=None,
1457         descriptions=True,
1458         verbosity=1,
1459         result_pipe=None,
1460         failfast=False,
1461         buffer=False,
1462         resultclass=None,
1463         print_summary=True,
1464         **kwargs,
1465     ):
1466         # ignore stream setting here, use hard-coded stdout to be in sync
1467         # with prints from VppAsfTestCase methods ...
1468         super(VppTestRunner, self).__init__(
1469             sys.stdout, descriptions, verbosity, failfast, buffer, resultclass, **kwargs
1470         )
1471         KeepAliveReporter.pipe = keep_alive_pipe
1472
1473         self.orig_stream = self.stream
1474         self.resultclass.test_framework_result_pipe = result_pipe
1475
1476         self.print_summary = print_summary
1477
1478     def _makeResult(self):
1479         return self.resultclass(self.stream, self.descriptions, self.verbosity, self)
1480
1481     def run(self, test):
1482         """
1483         Run the tests
1484
1485         :param test:
1486
1487         """
1488         faulthandler.enable()  # emit stack trace to stderr if killed by signal
1489
1490         result = super(VppTestRunner, self).run(test)
1491         if not self.print_summary:
1492             self.stream = self.orig_stream
1493             result.stream = self.orig_stream
1494         return result
1495
1496
1497 class Worker(Thread):
1498     def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1499         super(Worker, self).__init__(*args, **kwargs)
1500         self.logger = logger
1501         self.args = executable_args
1502         if hasattr(self, "testcase") and self.testcase.debug_all:
1503             if self.testcase.debug_gdbserver:
1504                 self.args = [
1505                     "/usr/bin/gdbserver",
1506                     "localhost:{port}".format(port=self.testcase.gdbserver_port),
1507                 ] + args
1508             elif self.testcase.debug_gdb and hasattr(self, "wait_for_gdb"):
1509                 self.args.append(self.wait_for_gdb)
1510         self.app_bin = executable_args[0]
1511         self.app_name = os.path.basename(self.app_bin)
1512         if hasattr(self, "role"):
1513             self.app_name += " {role}".format(role=self.role)
1514         self.process = None
1515         self.result = None
1516         env = {} if env is None else env
1517         self.env = copy.deepcopy(env)
1518
1519     def wait_for_enter(self):
1520         if not hasattr(self, "testcase"):
1521             return
1522         if self.testcase.debug_all and self.testcase.debug_gdbserver:
1523             print()
1524             print(double_line_delim)
1525             print(
1526                 "Spawned GDB Server for '{app}' with PID: {pid}".format(
1527                     app=self.app_name, pid=self.process.pid
1528                 )
1529             )
1530         elif self.testcase.debug_all and self.testcase.debug_gdb:
1531             print()
1532             print(double_line_delim)
1533             print(
1534                 "Spawned '{app}' with PID: {pid}".format(
1535                     app=self.app_name, pid=self.process.pid
1536                 )
1537             )
1538         else:
1539             return
1540         print(single_line_delim)
1541         print("You can debug '{app}' using:".format(app=self.app_name))
1542         if self.testcase.debug_gdbserver:
1543             print(
1544                 "sudo gdb "
1545                 + self.app_bin
1546                 + " -ex 'target remote localhost:{port}'".format(
1547                     port=self.testcase.gdbserver_port
1548                 )
1549             )
1550             print(
1551                 "Now is the time to attach gdb by running the above "
1552                 "command, set up breakpoints etc., then resume from "
1553                 "within gdb by issuing the 'continue' command"
1554             )
1555             self.testcase.gdbserver_port += 1
1556         elif self.testcase.debug_gdb:
1557             print(
1558                 "sudo gdb "
1559                 + self.app_bin
1560                 + " -ex 'attach {pid}'".format(pid=self.process.pid)
1561             )
1562             print(
1563                 "Now is the time to attach gdb by running the above "
1564                 "command and set up breakpoints etc., then resume from"
1565                 " within gdb by issuing the 'continue' command"
1566             )
1567         print(single_line_delim)
1568         input("Press ENTER to continue running the testcase...")
1569
1570     def run(self):
1571         executable = self.args[0]
1572         if not os.path.exists(executable) or not os.access(
1573             executable, os.F_OK | os.X_OK
1574         ):
1575             # Exit code that means some system file did not exist,
1576             # could not be opened, or had some other kind of error.
1577             self.result = os.EX_OSFILE
1578             raise EnvironmentError(
1579                 "executable '%s' is not found or executable." % executable
1580             )
1581         self.logger.debug(
1582             "Running executable '{app}': '{cmd}'".format(
1583                 app=self.app_name, cmd=" ".join(self.args)
1584             )
1585         )
1586         env = os.environ.copy()
1587         env.update(self.env)
1588         env["CK_LOG_FILE_NAME"] = "-"
1589         self.process = subprocess.Popen(
1590             ["stdbuf", "-o0", "-e0"] + self.args,
1591             shell=False,
1592             env=env,
1593             preexec_fn=os.setpgrp,
1594             stdout=subprocess.PIPE,
1595             stderr=subprocess.PIPE,
1596         )
1597         self.wait_for_enter()
1598         out, err = self.process.communicate()
1599         self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1600         self.logger.info("Return code is `%s'" % self.process.returncode)
1601         self.logger.info(single_line_delim)
1602         self.logger.info(
1603             "Executable `{app}' wrote to stdout:".format(app=self.app_name)
1604         )
1605         self.logger.info(single_line_delim)
1606         self.logger.info(out.decode("utf-8"))
1607         self.logger.info(single_line_delim)
1608         self.logger.info(
1609             "Executable `{app}' wrote to stderr:".format(app=self.app_name)
1610         )
1611         self.logger.info(single_line_delim)
1612         self.logger.info(err.decode("utf-8"))
1613         self.logger.info(single_line_delim)
1614         self.result = self.process.returncode
1615
1616
1617 if __name__ == "__main__":
1618     pass