test/framework.py

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