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     get_logger, 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         cls.logger = get_logger(cls.__name__)
 373         if hasattr(cls, 'parallel_handler'):
 374             cls.logger.addHandler(cls.parallel_handler)
 375         cls.tempdir = tempfile.mkdtemp(
 376             prefix='vpp-unittest-%s-' % cls.__name__)
 377         cls.stats_sock = "%s/stats.sock" % cls.tempdir
 378         cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
 379         cls.file_handler.setFormatter(
 380             Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
 381                       datefmt="%H:%M:%S"))
 382         cls.file_handler.setLevel(DEBUG)
 383         cls.logger.addHandler(cls.file_handler)
 384         cls.shm_prefix = os.path.basename(cls.tempdir)
 385         os.chdir(cls.tempdir)
 386         cls.logger.info("Temporary dir is %s, shm prefix is %s",
 387                         cls.tempdir, cls.shm_prefix)
 388         cls.setUpConstants()
 389         cls.reset_packet_infos()
 390         cls._captures = []
 391         cls._zombie_captures = []
 392         cls.verbose = 0
 393         cls.vpp_dead = False
 394         cls.registry = VppObjectRegistry()
 395         cls.vpp_startup_failed = False
 396         cls.reporter = KeepAliveReporter()
 397         # need to catch exceptions here because if we raise, then the cleanup
 398         # doesn't get called and we might end with a zombie vpp
 399         try:
 400             cls.run_vpp()
 401             cls.reporter.send_keep_alive(cls, 'setUpClass')
 402             VppTestResult.current_test_case_info = TestCaseInfo(
 403                 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
 404             cls.vpp_stdout_deque = deque()
 405             cls.vpp_stderr_deque = deque()
 406             cls.pump_thread_stop_flag = Event()
 407             cls.pump_thread_wakeup_pipe = os.pipe()
 408             cls.pump_thread = Thread(target=pump_output, args=(cls,))
 409             cls.pump_thread.daemon = True
 410             cls.pump_thread.start()
 411             if cls.debug_gdb or cls.debug_gdbserver:
 412                 read_timeout = 0
 413             else:
 414                 read_timeout = 5
 415             cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
 416                                        read_timeout)
 417             if cls.step:
 418                 hook = StepHook(cls)
 419             else:
 420                 hook = PollHook(cls)
 421             cls.vapi.register_hook(hook)
 422             cls.wait_for_stats_socket()
 423             cls.statistics = VPPStats(socketname=cls.stats_sock)
 424             try:
 425                 hook.poll_vpp()
 426             except VppDiedError:
 427                 cls.vpp_startup_failed = True
 428                 cls.logger.critical(
 429                     "VPP died shortly after startup, check the"
 430                     " output to standard error for possible cause")
 431                 raise
 432             try:
 433                 cls.vapi.connect()
 434             except Exception:
 435                 try:
 436                     cls.vapi.disconnect()
 437                 except Exception:
 438                     pass
 439                 if cls.debug_gdbserver:
 440                     print(colorize("You're running VPP inside gdbserver but "
 441                                    "VPP-API connection failed, did you forget "
 442                                    "to 'continue' VPP from within gdb?", RED))
 443                 raise
 444         except Exception:
 445             try:
 446                 cls.quit()
 447             except Exception:
 448                 pass
 449             raise
 450
 451     @classmethod
 452     def quit(cls):
 453         """
 454         Disconnect vpp-api, kill vpp and cleanup shared memory files
 455         """
 456         if (cls.debug_gdbserver or cls.debug_gdb) and hasattr(cls, 'vpp'):
 457             cls.vpp.poll()
 458             if cls.vpp.returncode is None:
 459                 print(double_line_delim)
 460                 print("VPP or GDB server is still running")
 461                 print(single_line_delim)
 462                 raw_input("When done debugging, press ENTER to kill the "
 463                           "process and finish running the testcase...")
 464
 465         # first signal that we want to stop the pump thread, then wake it up
 466         if hasattr(cls, 'pump_thread_stop_flag'):
 467             cls.pump_thread_stop_flag.set()
 468         if hasattr(cls, 'pump_thread_wakeup_pipe'):
 469             os.write(cls.pump_thread_wakeup_pipe[1], 'ding dong wake up')
 470         if hasattr(cls, 'pump_thread'):
 471             cls.logger.debug("Waiting for pump thread to stop")
 472             cls.pump_thread.join()
 473         if hasattr(cls, 'vpp_stderr_reader_thread'):
 474             cls.logger.debug("Waiting for stdderr pump to stop")
 475             cls.vpp_stderr_reader_thread.join()
 476
 477         if hasattr(cls, 'vpp'):
 478             if hasattr(cls, 'vapi'):
 479                 cls.vapi.disconnect()
 480                 del cls.vapi
 481             cls.vpp.poll()
 482             if cls.vpp.returncode is None:
 483                 cls.logger.debug("Sending TERM to vpp")
 484                 cls.vpp.kill()
 485                 cls.logger.debug("Waiting for vpp to die")
 486                 cls.vpp.communicate()
 487             del cls.vpp
 488
 489         if cls.vpp_startup_failed:
 490             stdout_log = cls.logger.info
 491             stderr_log = cls.logger.critical
 492         else:
 493             stdout_log = cls.logger.info
 494             stderr_log = cls.logger.info
 495
 496         if hasattr(cls, 'vpp_stdout_deque'):
 497             stdout_log(single_line_delim)
 498             stdout_log('VPP output to stdout while running %s:', cls.__name__)
 499             stdout_log(single_line_delim)
 500             vpp_output = "".join(cls.vpp_stdout_deque)
 501             with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
 502                 f.write(vpp_output)
 503             stdout_log('\n%s', vpp_output)
 504             stdout_log(single_line_delim)
 505
 506         if hasattr(cls, 'vpp_stderr_deque'):
 507             stderr_log(single_line_delim)
 508             stderr_log('VPP output to stderr while running %s:', cls.__name__)
 509             stderr_log(single_line_delim)
 510             vpp_output = "".join(cls.vpp_stderr_deque)
 511             with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
 512                 f.write(vpp_output)
 513             stderr_log('\n%s', vpp_output)
 514             stderr_log(single_line_delim)
 515
 516     @classmethod
 517     def tearDownClass(cls):
 518         """ Perform final cleanup after running all tests in this test-case """
 519         cls.reporter.send_keep_alive(cls, 'tearDownClass')
 520         cls.quit()
 521         cls.file_handler.close()
 522         cls.reset_packet_infos()
 523         if debug_framework:
 524             debug_internal.on_tear_down_class(cls)
 525
 526     def tearDown(self):
 527         """ Show various debug prints after each test """
 528         self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
 529                           (self.__class__.__name__, self._testMethodName,
 530                            self._testMethodDoc))
 531         if not self.vpp_dead:
 532             self.logger.debug(self.vapi.cli("show trace"))
 533             self.logger.info(self.vapi.ppcli("show interface"))
 534             self.logger.info(self.vapi.ppcli("show hardware"))
 535             self.logger.info(self.statistics.set_errors_str())
 536             self.logger.info(self.vapi.ppcli("show run"))
 537             self.logger.info(self.vapi.ppcli("show log"))
 538             self.registry.remove_vpp_config(self.logger)
 539             # Save/Dump VPP api trace log
 540             api_trace = "vpp_api_trace.%s.log" % self._testMethodName
 541             tmp_api_trace = "/tmp/%s" % api_trace
 542             vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
 543             self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
 544             self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
 545                                                     vpp_api_trace_log))
 546             os.rename(tmp_api_trace, vpp_api_trace_log)
 547             self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
 548                                              vpp_api_trace_log))
 549         else:
 550             self.registry.unregister_all(self.logger)
 551
 552     def setUp(self):
 553         """ Clear trace before running each test"""
 554         self.reporter.send_keep_alive(self)
 555         self.logger.debug("--- setUp() for %s.%s(%s) called ---" %
 556                           (self.__class__.__name__, self._testMethodName,
 557                            self._testMethodDoc))
 558         if self.vpp_dead:
 559             raise Exception("VPP is dead when setting up the test")
 560         self.sleep(.1, "during setUp")
 561         self.vpp_stdout_deque.append(
 562             "--- test setUp() for %s.%s(%s) starts here ---\n" %
 563             (self.__class__.__name__, self._testMethodName,
 564              self._testMethodDoc))
 565         self.vpp_stderr_deque.append(
 566             "--- test setUp() for %s.%s(%s) starts here ---\n" %
 567             (self.__class__.__name__, self._testMethodName,
 568              self._testMethodDoc))
 569         self.vapi.cli("clear trace")
 570         # store the test instance inside the test class - so that objects
 571         # holding the class can access instance methods (like assertEqual)
 572         type(self).test_instance = self
 573
 574     @classmethod
 575     def pg_enable_capture(cls, interfaces=None):
 576         """
 577         Enable capture on packet-generator interfaces
 578
 579         :param interfaces: iterable interface indexes (if None,
 580                            use self.pg_interfaces)
 581
 582         """
 583         if interfaces is None:
 584             interfaces = cls.pg_interfaces
 585         for i in interfaces:
 586             i.enable_capture()
 587
 588     @classmethod
 589     def register_capture(cls, cap_name):
 590         """ Register a capture in the testclass """
 591         # add to the list of captures with current timestamp
 592         cls._captures.append((time.time(), cap_name))
 593         # filter out from zombies
 594         cls._zombie_captures = [(stamp, name)
 595                                 for (stamp, name) in cls._zombie_captures
 596                                 if name != cap_name]
 597
 598     @classmethod
 599     def pg_start(cls):
 600         """ Remove any zombie captures and enable the packet generator """
 601         # how long before capture is allowed to be deleted - otherwise vpp
 602         # crashes - 100ms seems enough (this shouldn't be needed at all)
 603         capture_ttl = 0.1
 604         now = time.time()
 605         for stamp, cap_name in cls._zombie_captures:
 606             wait = stamp + capture_ttl - now
 607             if wait > 0:
 608                 cls.sleep(wait, "before deleting capture %s" % cap_name)
 609                 now = time.time()
 610             cls.logger.debug("Removing zombie capture %s" % cap_name)
 611             cls.vapi.cli('packet-generator delete %s' % cap_name)
 612
 613         cls.vapi.cli("trace add pg-input 50")  # 50 is maximum
 614         cls.vapi.cli('packet-generator enable')
 615         cls._zombie_captures = cls._captures
 616         cls._captures = []
 617
 618     @classmethod
 619     def create_pg_interfaces(cls, interfaces):
 620         """
 621         Create packet-generator interfaces.
 622
 623         :param interfaces: iterable indexes of the interfaces.
 624         :returns: List of created interfaces.
 625
 626         """
 627         result = []
 628         for i in interfaces:
 629             intf = VppPGInterface(cls, i)
 630             setattr(cls, intf.name, intf)
 631             result.append(intf)
 632         cls.pg_interfaces = result
 633         return result
 634
 635     @classmethod
 636     def create_loopback_interfaces(cls, count):
 637         """
 638         Create loopback interfaces.
 639
 640         :param count: number of interfaces created.
 641         :returns: List of created interfaces.
 642         """
 643         result = [VppLoInterface(cls) for i in range(count)]
 644         for intf in result:
 645             setattr(cls, intf.name, intf)
 646         cls.lo_interfaces = result
 647         return result
 648
 649     @staticmethod
 650     def extend_packet(packet, size, padding=' '):
 651         """
 652         Extend packet to given size by padding with spaces or custom padding
 653         NOTE: Currently works only when Raw layer is present.
 654
 655         :param packet: packet
 656         :param size: target size
 657         :param padding: padding used to extend the payload
 658
 659         """
 660         packet_len = len(packet) + 4
 661         extend = size - packet_len
 662         if extend > 0:
 663             num = (extend / len(padding)) + 1
 664             packet[Raw].load += (padding * num)[:extend]
 665
 666     @classmethod
 667     def reset_packet_infos(cls):
 668         """ Reset the list of packet info objects and packet counts to zero """
 669         cls._packet_infos = {}
 670         cls._packet_count_for_dst_if_idx = {}
 671
 672     @classmethod
 673     def create_packet_info(cls, src_if, dst_if):
 674         """
 675         Create packet info object containing the source and destination indexes
 676         and add it to the testcase's packet info list
 677
 678         :param VppInterface src_if: source interface
 679         :param VppInterface dst_if: destination interface
 680
 681         :returns: _PacketInfo object
 682
 683         """
 684         info = _PacketInfo()
 685         info.index = len(cls._packet_infos)
 686         info.src = src_if.sw_if_index
 687         info.dst = dst_if.sw_if_index
 688         if isinstance(dst_if, VppSubInterface):
 689             dst_idx = dst_if.parent.sw_if_index
 690         else:
 691             dst_idx = dst_if.sw_if_index
 692         if dst_idx in cls._packet_count_for_dst_if_idx:
 693             cls._packet_count_for_dst_if_idx[dst_idx] += 1
 694         else:
 695             cls._packet_count_for_dst_if_idx[dst_idx] = 1
 696         cls._packet_infos[info.index] = info
 697         return info
 698
 699     @staticmethod
 700     def info_to_payload(info):
 701         """
 702         Convert _PacketInfo object to packet payload
 703
 704         :param info: _PacketInfo object
 705
 706         :returns: string containing serialized data from packet info
 707         """
 708         return "%d %d %d %d %d" % (info.index, info.src, info.dst,
 709                                    info.ip, info.proto)
 710
 711     @staticmethod
 712     def payload_to_info(payload):
 713         """
 714         Convert packet payload to _PacketInfo object
 715
 716         :param payload: packet payload
 717
 718         :returns: _PacketInfo object containing de-serialized data from payload
 719
 720         """
 721         numbers = payload.split()
 722         info = _PacketInfo()
 723         info.index = int(numbers[0])
 724         info.src = int(numbers[1])
 725         info.dst = int(numbers[2])
 726         info.ip = int(numbers[3])
 727         info.proto = int(numbers[4])
 728         return info
 729
 730     def get_next_packet_info(self, info):
 731         """
 732         Iterate over the packet info list stored in the testcase
 733         Start iteration with first element if info is None
 734         Continue based on index in info if info is specified
 735
 736         :param info: info or None
 737         :returns: next info in list or None if no more infos
 738         """
 739         if info is None:
 740             next_index = 0
 741         else:
 742             next_index = info.index + 1
 743         if next_index == len(self._packet_infos):
 744             return None
 745         else:
 746             return self._packet_infos[next_index]
 747
 748     def get_next_packet_info_for_interface(self, src_index, info):
 749         """
 750         Search the packet info list for the next packet info with same source
 751         interface index
 752
 753         :param src_index: source interface index to search for
 754         :param info: packet info - where to start the search
 755         :returns: packet info or None
 756
 757         """
 758         while True:
 759             info = self.get_next_packet_info(info)
 760             if info is None:
 761                 return None
 762             if info.src == src_index:
 763                 return info
 764
 765     def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
 766         """
 767         Search the packet info list for the next packet info with same source
 768         and destination interface indexes
 769
 770         :param src_index: source interface index to search for
 771         :param dst_index: destination interface index to search for
 772         :param info: packet info - where to start the search
 773         :returns: packet info or None
 774
 775         """
 776         while True:
 777             info = self.get_next_packet_info_for_interface(src_index, info)
 778             if info is None:
 779                 return None
 780             if info.dst == dst_index:
 781                 return info
 782
 783     def assert_equal(self, real_value, expected_value, name_or_class=None):
 784         if name_or_class is None:
 785             self.assertEqual(real_value, expected_value)
 786             return
 787         try:
 788             msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
 789             msg = msg % (getdoc(name_or_class).strip(),
 790                          real_value, str(name_or_class(real_value)),
 791                          expected_value, str(name_or_class(expected_value)))
 792         except Exception:
 793             msg = "Invalid %s: %s does not match expected value %s" % (
 794                 name_or_class, real_value, expected_value)
 795
 796         self.assertEqual(real_value, expected_value, msg)
 797
 798     def assert_in_range(self,
 799                         real_value,
 800                         expected_min,
 801                         expected_max,
 802                         name=None):
 803         if name is None:
 804             msg = None
 805         else:
 806             msg = "Invalid %s: %s out of range <%s,%s>" % (
 807                 name, real_value, expected_min, expected_max)
 808         self.assertTrue(expected_min <= real_value <= expected_max, msg)
 809
 810     def assert_packet_checksums_valid(self, packet,
 811                                       ignore_zero_udp_checksums=True):
 812         received = packet.__class__(str(packet))
 813         self.logger.debug(
 814             ppp("Verifying packet checksums for packet:", received))
 815         udp_layers = ['UDP', 'UDPerror']
 816         checksum_fields = ['cksum', 'chksum']
 817         checksums = []
 818         counter = 0
 819         temp = received.__class__(str(received))
 820         while True:
 821             layer = temp.getlayer(counter)
 822             if layer:
 823                 for cf in checksum_fields:
 824                     if hasattr(layer, cf):
 825                         if ignore_zero_udp_checksums and \
 826                                 0 == getattr(layer, cf) and \
 827                                 layer.name in udp_layers:
 828                             continue
 829                         delattr(layer, cf)
 830                         checksums.append((counter, cf))
 831             else:
 832                 break
 833             counter = counter + 1
 834         if 0 == len(checksums):
 835             return
 836         temp = temp.__class__(str(temp))
 837         for layer, cf in checksums:
 838             calc_sum = getattr(temp[layer], cf)
 839             self.assert_equal(
 840                 getattr(received[layer], cf), calc_sum,
 841                 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
 842             self.logger.debug(
 843                 "Checksum field `%s` on `%s` layer has correct value `%s`" %
 844                 (cf, temp[layer].name, calc_sum))
 845
 846     def assert_checksum_valid(self, received_packet, layer,
 847                               field_name='chksum',
 848                               ignore_zero_checksum=False):
 849         """ Check checksum of received packet on given layer """
 850         received_packet_checksum = getattr(received_packet[layer], field_name)
 851         if ignore_zero_checksum and 0 == received_packet_checksum:
 852             return
 853         recalculated = received_packet.__class__(str(received_packet))
 854         delattr(recalculated[layer], field_name)
 855         recalculated = recalculated.__class__(str(recalculated))
 856         self.assert_equal(received_packet_checksum,
 857                           getattr(recalculated[layer], field_name),
 858                           "packet checksum on layer: %s" % layer)
 859
 860     def assert_ip_checksum_valid(self, received_packet,
 861                                  ignore_zero_checksum=False):
 862         self.assert_checksum_valid(received_packet, 'IP',
 863                                    ignore_zero_checksum=ignore_zero_checksum)
 864
 865     def assert_tcp_checksum_valid(self, received_packet,
 866                                   ignore_zero_checksum=False):
 867         self.assert_checksum_valid(received_packet, 'TCP',
 868                                    ignore_zero_checksum=ignore_zero_checksum)
 869
 870     def assert_udp_checksum_valid(self, received_packet,
 871                                   ignore_zero_checksum=True):
 872         self.assert_checksum_valid(received_packet, 'UDP',
 873                                    ignore_zero_checksum=ignore_zero_checksum)
 874
 875     def assert_embedded_icmp_checksum_valid(self, received_packet):
 876         if received_packet.haslayer(IPerror):
 877             self.assert_checksum_valid(received_packet, 'IPerror')
 878         if received_packet.haslayer(TCPerror):
 879             self.assert_checksum_valid(received_packet, 'TCPerror')
 880         if received_packet.haslayer(UDPerror):
 881             self.assert_checksum_valid(received_packet, 'UDPerror',
 882                                        ignore_zero_checksum=True)
 883         if received_packet.haslayer(ICMPerror):
 884             self.assert_checksum_valid(received_packet, 'ICMPerror')
 885
 886     def assert_icmp_checksum_valid(self, received_packet):
 887         self.assert_checksum_valid(received_packet, 'ICMP')
 888         self.assert_embedded_icmp_checksum_valid(received_packet)
 889
 890     def assert_icmpv6_checksum_valid(self, pkt):
 891         if pkt.haslayer(ICMPv6DestUnreach):
 892             self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
 893             self.assert_embedded_icmp_checksum_valid(pkt)
 894         if pkt.haslayer(ICMPv6EchoRequest):
 895             self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
 896         if pkt.haslayer(ICMPv6EchoReply):
 897             self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
 898
 899     def assert_packet_counter_equal(self, counter, expected_value):
 900         counters = self.vapi.cli("sh errors").split('\n')
 901         counter_value = -1
 902         for i in range(1, len(counters)-1):
 903             results = counters[i].split()
 904             if results[1] == counter:
 905                 counter_value = int(results[0])
 906                 break
 907         self.assert_equal(counter_value, expected_value,
 908                           "packet counter `%s'" % counter)
 909
 910     @classmethod
 911     def sleep(cls, timeout, remark=None):
 912         if hasattr(cls, 'logger'):
 913             cls.logger.debug("Starting sleep for %ss (%s)" % (timeout, remark))
 914         before = time.time()
 915         time.sleep(timeout)
 916         after = time.time()
 917         if after - before > 2 * timeout:
 918             cls.logger.error("unexpected time.sleep() result - "
 919                              "slept for %ss instead of ~%ss!" % (
 920                                  after - before, timeout))
 921         if hasattr(cls, 'logger'):
 922             cls.logger.debug(
 923                 "Finished sleep (%s) - slept %ss (wanted %ss)" % (
 924                     remark, after - before, timeout))
 925
 926     def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
 927         self.vapi.cli("clear trace")
 928         intf.add_stream(pkts)
 929         self.pg_enable_capture(self.pg_interfaces)
 930         self.pg_start()
 931         if not timeout:
 932             timeout = 1
 933         for i in self.pg_interfaces:
 934             i.get_capture(0, timeout=timeout)
 935             i.assert_nothing_captured(remark=remark)
 936             timeout = 0.1
 937
 938     def send_and_expect(self, input, pkts, output):
 939         self.vapi.cli("clear trace")
 940         input.add_stream(pkts)
 941         self.pg_enable_capture(self.pg_interfaces)
 942         self.pg_start()
 943         if isinstance(object, (list,)):
 944             rx = []
 945             for o in output:
 946                 rx.append(output.get_capture(len(pkts)))
 947         else:
 948             rx = output.get_capture(len(pkts))
 949         return rx
 950
 951     def send_and_expect_only(self, input, pkts, output, timeout=None):
 952         self.vapi.cli("clear trace")
 953         input.add_stream(pkts)
 954         self.pg_enable_capture(self.pg_interfaces)
 955         self.pg_start()
 956         if isinstance(object, (list,)):
 957             outputs = output
 958             rx = []
 959             for o in outputs:
 960                 rx.append(output.get_capture(len(pkts)))
 961         else:
 962             rx = output.get_capture(len(pkts))
 963             outputs = [output]
 964         if not timeout:
 965             timeout = 1
 966         for i in self.pg_interfaces:
 967             if i not in outputs:
 968                 i.get_capture(0, timeout=timeout)
 969                 i.assert_nothing_captured()
 970                 timeout = 0.1
 971
 972         return rx
 973
 974
 975 def get_testcase_doc_name(test):
 976     return getdoc(test.__class__).splitlines()[0]
 977
 978
 979 def get_test_description(descriptions, test):
 980     short_description = test.shortDescription()
 981     if descriptions and short_description:
 982         return short_description
 983     else:
 984         return str(test)
 985
 986
 987 class TestCaseInfo(object):
 988     def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
 989         self.logger = logger
 990         self.tempdir = tempdir
 991         self.vpp_pid = vpp_pid
 992         self.vpp_bin_path = vpp_bin_path
 993         self.core_crash_test = None
 994
 995
 996 class VppTestResult(unittest.TestResult):
 997     """
 998     @property result_string
 999      String variable to store the test case result string.
1000     @property errors
1001      List variable containing 2-tuples of TestCase instances and strings
1002      holding formatted tracebacks. Each tuple represents a test which
1003      raised an unexpected exception.
1004     @property failures
1005      List variable containing 2-tuples of TestCase instances and strings
1006      holding formatted tracebacks. Each tuple represents a test where
1007      a failure was explicitly signalled using the TestCase.assert*()
1008      methods.
1009     """
1010
1011     failed_test_cases_info = set()
1012     core_crash_test_cases_info = set()
1013     current_test_case_info = None
1014
1015     def __init__(self, stream, descriptions, verbosity):
1016         """
1017         :param stream File descriptor to store where to report test results.
1018             Set to the standard error stream by default.
1019         :param descriptions Boolean variable to store information if to use
1020             test case descriptions.
1021         :param verbosity Integer variable to store required verbosity level.
1022         """
1023         unittest.TestResult.__init__(self, stream, descriptions, verbosity)
1024         self.stream = stream
1025         self.descriptions = descriptions
1026         self.verbosity = verbosity
1027         self.result_string = None
1028
1029     def addSuccess(self, test):
1030         """
1031         Record a test succeeded result
1032
1033         :param test:
1034
1035         """
1036         if self.current_test_case_info:
1037             self.current_test_case_info.logger.debug(
1038                 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1039                                                        test._testMethodName,
1040                                                        test._testMethodDoc))
1041         unittest.TestResult.addSuccess(self, test)
1042         self.result_string = colorize("OK", GREEN)
1043
1044         self.send_result_through_pipe(test, PASS)
1045
1046     def addSkip(self, test, reason):
1047         """
1048         Record a test skipped.
1049
1050         :param test:
1051         :param reason:
1052
1053         """
1054         if self.current_test_case_info:
1055             self.current_test_case_info.logger.debug(
1056                 "--- addSkip() %s.%s(%s) called, reason is %s" %
1057                 (test.__class__.__name__, test._testMethodName,
1058                  test._testMethodDoc, reason))
1059         unittest.TestResult.addSkip(self, test, reason)
1060         self.result_string = colorize("SKIP", YELLOW)
1061
1062         self.send_result_through_pipe(test, SKIP)
1063
1064     def symlink_failed(self):
1065         if self.current_test_case_info:
1066             try:
1067                 failed_dir = os.getenv('VPP_TEST_FAILED_DIR')
1068                 link_path = os.path.join(
1069                     failed_dir,
1070                     '%s-FAILED' %
1071                     os.path.basename(self.current_test_case_info.tempdir))
1072                 if self.current_test_case_info.logger:
1073                     self.current_test_case_info.logger.debug(
1074                         "creating a link to the failed test")
1075                     self.current_test_case_info.logger.debug(
1076                         "os.symlink(%s, %s)" %
1077                         (self.current_test_case_info.tempdir, link_path))
1078                 if os.path.exists(link_path):
1079                     if self.current_test_case_info.logger:
1080                         self.current_test_case_info.logger.debug(
1081                             'symlink already exists')
1082                 else:
1083                     os.symlink(self.current_test_case_info.tempdir, link_path)
1084
1085             except Exception as e:
1086                 if self.current_test_case_info.logger:
1087                     self.current_test_case_info.logger.error(e)
1088
1089     def send_result_through_pipe(self, test, result):
1090         if hasattr(self, 'test_framework_result_pipe'):
1091             pipe = self.test_framework_result_pipe
1092             if pipe:
1093                 pipe.send((test.id(), result))
1094
1095     def log_error(self, test, err, fn_name):
1096         if self.current_test_case_info:
1097             if isinstance(test, unittest.suite._ErrorHolder):
1098                 test_name = test.description
1099             else:
1100                 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1101                                            test._testMethodName,
1102                                            test._testMethodDoc)
1103             self.current_test_case_info.logger.debug(
1104                 "--- %s() %s called, err is %s" %
1105                 (fn_name, test_name, err))
1106             self.current_test_case_info.logger.debug(
1107                 "formatted exception is:\n%s" %
1108                 "".join(format_exception(*err)))
1109
1110     def add_error(self, test, err, unittest_fn, error_type):
1111         if error_type == FAIL:
1112             self.log_error(test, err, 'addFailure')
1113             error_type_str = colorize("FAIL", RED)
1114         elif error_type == ERROR:
1115             self.log_error(test, err, 'addError')
1116             error_type_str = colorize("ERROR", RED)
1117         else:
1118             raise Exception('Error type %s cannot be used to record an '
1119                             'error or a failure' % error_type)
1120
1121         unittest_fn(self, test, err)
1122         if self.current_test_case_info:
1123             self.result_string = "%s [ temp dir used by test case: %s ]" % \
1124                                  (error_type_str,
1125                                   self.current_test_case_info.tempdir)
1126             self.symlink_failed()
1127             self.failed_test_cases_info.add(self.current_test_case_info)
1128             if is_core_present(self.current_test_case_info.tempdir):
1129                 if not self.current_test_case_info.core_crash_test:
1130                     if isinstance(test, unittest.suite._ErrorHolder):
1131                         test_name = str(test)
1132                     else:
1133                         test_name = "'{}' ({})".format(
1134                             get_testcase_doc_name(test), test.id())
1135                     self.current_test_case_info.core_crash_test = test_name
1136                 self.core_crash_test_cases_info.add(
1137                     self.current_test_case_info)
1138         else:
1139             self.result_string = '%s [no temp dir]' % error_type_str
1140
1141         self.send_result_through_pipe(test, error_type)
1142
1143     def addFailure(self, test, err):
1144         """
1145         Record a test failed result
1146
1147         :param test:
1148         :param err: error message
1149
1150         """
1151         self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1152
1153     def addError(self, test, err):
1154         """
1155         Record a test error result
1156
1157         :param test:
1158         :param err: error message
1159
1160         """
1161         self.add_error(test, err, unittest.TestResult.addError, ERROR)
1162
1163     def getDescription(self, test):
1164         """
1165         Get test description
1166
1167         :param test:
1168         :returns: test description
1169
1170         """
1171         return get_test_description(self.descriptions, test)
1172
1173     def startTest(self, test):
1174         """
1175         Start a test
1176
1177         :param test:
1178
1179         """
1180         test.print_header(test.__class__)
1181
1182         unittest.TestResult.startTest(self, test)
1183         if self.verbosity > 0:
1184             self.stream.writeln(
1185                 "Starting " + self.getDescription(test) + " ...")
1186             self.stream.writeln(single_line_delim)
1187
1188     def stopTest(self, test):
1189         """
1190         Called when the given test has been run
1191
1192         :param test:
1193
1194         """
1195         unittest.TestResult.stopTest(self, test)
1196         if self.verbosity > 0:
1197             self.stream.writeln(single_line_delim)
1198             self.stream.writeln("%-73s%s" % (self.getDescription(test),
1199                                              self.result_string))
1200             self.stream.writeln(single_line_delim)
1201         else:
1202             self.stream.writeln("%-73s%s" % (self.getDescription(test),
1203                                              self.result_string))
1204
1205         self.send_result_through_pipe(test, TEST_RUN)
1206
1207     def printErrors(self):
1208         """
1209         Print errors from running the test case
1210         """
1211         self.stream.writeln()
1212         self.printErrorList('ERROR', self.errors)
1213         self.printErrorList('FAIL', self.failures)
1214
1215     def printErrorList(self, flavour, errors):
1216         """
1217         Print error list to the output stream together with error type
1218         and test case description.
1219
1220         :param flavour: error type
1221         :param errors: iterable errors
1222
1223         """
1224         for test, err in errors:
1225             self.stream.writeln(double_line_delim)
1226             self.stream.writeln("%s: %s" %
1227                                 (flavour, self.getDescription(test)))
1228             self.stream.writeln(single_line_delim)
1229             self.stream.writeln("%s" % err)
1230
1231
1232 class VppTestRunner(unittest.TextTestRunner):
1233     """
1234     A basic test runner implementation which prints results to standard error.
1235     """
1236     @property
1237     def resultclass(self):
1238         """Class maintaining the results of the tests"""
1239         return VppTestResult
1240
1241     def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1242                  result_pipe=None, failfast=False, buffer=False,
1243                  resultclass=None):
1244
1245         # ignore stream setting here, use hard-coded stdout to be in sync
1246         # with prints from VppTestCase methods ...
1247         super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1248                                             verbosity, failfast, buffer,
1249                                             resultclass)
1250         reporter = KeepAliveReporter()
1251         reporter.pipe = keep_alive_pipe
1252
1253         VppTestResult.test_framework_result_pipe = result_pipe
1254
1255     def run(self, test):
1256         """
1257         Run the tests
1258
1259         :param test:
1260
1261         """
1262         faulthandler.enable()  # emit stack trace to stderr if killed by signal
1263
1264         result = super(VppTestRunner, self).run(test)
1265         return result
1266
1267
1268 class Worker(Thread):
1269     def __init__(self, args, logger, env={}):
1270         self.logger = logger
1271         self.args = args
1272         self.result = None
1273         self.env = copy.deepcopy(env)
1274         super(Worker, self).__init__()
1275
1276     def run(self):
1277         executable = self.args[0]
1278         self.logger.debug("Running executable w/args `%s'" % self.args)
1279         env = os.environ.copy()
1280         env.update(self.env)
1281         env["CK_LOG_FILE_NAME"] = "-"
1282         self.process = subprocess.Popen(
1283             self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1284             stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1285         out, err = self.process.communicate()
1286         self.logger.debug("Finished running `%s'" % executable)
1287         self.logger.info("Return code is `%s'" % self.process.returncode)
1288         self.logger.info(single_line_delim)
1289         self.logger.info("Executable `%s' wrote to stdout:" % executable)
1290         self.logger.info(single_line_delim)
1291         self.logger.info(out)
1292         self.logger.info(single_line_delim)
1293         self.logger.info("Executable `%s' wrote to stderr:" % executable)
1294         self.logger.info(single_line_delim)
1295         self.logger.info(err)
1296         self.logger.info(single_line_delim)
1297         self.result = self.process.returncode