3 from __future__ import print_function
17 from collections import deque
18 from threading import Thread, Event
19 from inspect import getdoc, isclass
20 from traceback import format_exception
21 from logging import FileHandler, DEBUG, Formatter
24 from scapy.packet import Raw
25 import hook as hookmodule
26 from vpp_pg_interface import VppPGInterface
27 from vpp_sub_interface import VppSubInterface
28 from vpp_lo_interface import VppLoInterface
29 from vpp_bvi_interface import VppBviInterface
30 from vpp_papi_provider import VppPapiProvider
32 from vpp_papi.vpp_stats import VPPStats
33 from vpp_papi.vpp_transport_shmem import VppTransportShmemIOError
34 from log import RED, GREEN, YELLOW, double_line_delim, single_line_delim, \
36 from vpp_object import VppObjectRegistry
37 from util import ppp, is_core_present
38 from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
39 from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
40 from scapy.layers.inet6 import ICMPv6EchoReply
42 if os.name == 'posix' and sys.version_info[0] < 3:
43 # using subprocess32 is recommended by python official documentation
44 # @ https://docs.python.org/2/library/subprocess.html
45 import subprocess32 as subprocess
49 # Python2/3 compatible
62 class BoolEnvironmentVariable(object):
64 def __init__(self, env_var_name, default='n', true_values=None):
65 self.name = env_var_name
66 self.default = default
67 self.true_values = true_values if true_values is not None else \
71 return os.getenv(self.name, self.default).lower() in self.true_values
73 if sys.version_info[0] == 2:
74 __nonzero__ = __bool__
77 return 'BoolEnvironmentVariable(%r, default=%r, true_values=%r)' % \
78 (self.name, self.default, self.true_values)
81 debug_framework = BoolEnvironmentVariable('TEST_DEBUG')
86 Test framework module.
88 The module provides a set of tools for constructing and running tests and
89 representing the results.
93 class VppDiedError(Exception):
94 """ exception for reporting that the subprocess has died."""
96 signals_by_value = {v: k for k, v in signal.__dict__.items() if
97 k.startswith('SIG') and not k.startswith('SIG_')}
99 def __init__(self, rv=None, testcase=None, method_name=None):
101 self.signal_name = None
102 self.testcase = testcase
103 self.method_name = method_name
106 self.signal_name = VppDiedError.signals_by_value[-rv]
107 except (KeyError, TypeError):
110 if testcase is None and method_name is None:
113 in_msg = 'running %s.%s ' % (testcase, method_name)
115 msg = "VPP subprocess died %sunexpectedly with return code: %d%s." % (
118 ' [%s]' % (self.signal_name if
119 self.signal_name is not None else ''))
120 super(VppDiedError, self).__init__(msg)
123 class _PacketInfo(object):
124 """Private class to create packet info object.
126 Help process information about the next packet.
127 Set variables to default values.
129 #: Store the index of the packet.
131 #: Store the index of the source packet generator interface of the packet.
133 #: Store the index of the destination packet generator interface
136 #: Store expected ip version
138 #: Store expected upper protocol
140 #: Store the copy of the former packet.
143 def __eq__(self, other):
144 index = self.index == other.index
145 src = self.src == other.src
146 dst = self.dst == other.dst
147 data = self.data == other.data
148 return index and src and dst and data
151 def pump_output(testclass):
152 """ pump output from vpp stdout/stderr to proper queues """
155 while not testclass.pump_thread_stop_flag.is_set():
156 readable = select.select([testclass.vpp.stdout.fileno(),
157 testclass.vpp.stderr.fileno(),
158 testclass.pump_thread_wakeup_pipe[0]],
160 if testclass.vpp.stdout.fileno() in readable:
161 read = os.read(testclass.vpp.stdout.fileno(), 102400)
163 split = read.decode('ascii',
164 errors='backslashreplace').splitlines(True)
165 if len(stdout_fragment) > 0:
166 split[0] = "%s%s" % (stdout_fragment, split[0])
167 if len(split) > 0 and split[-1].endswith("\n"):
171 stdout_fragment = split[-1]
172 testclass.vpp_stdout_deque.extend(split[:limit])
173 if not testclass.cache_vpp_output:
174 for line in split[:limit]:
175 testclass.logger.info(
176 "VPP STDOUT: %s" % line.rstrip("\n"))
177 if testclass.vpp.stderr.fileno() in readable:
178 read = os.read(testclass.vpp.stderr.fileno(), 102400)
180 split = read.decode('ascii',
181 errors='backslashreplace').splitlines(True)
182 if len(stderr_fragment) > 0:
183 split[0] = "%s%s" % (stderr_fragment, split[0])
184 if len(split) > 0 and split[-1].endswith("\n"):
188 stderr_fragment = split[-1]
190 testclass.vpp_stderr_deque.extend(split[:limit])
191 if not testclass.cache_vpp_output:
192 for line in split[:limit]:
193 testclass.logger.error(
194 "VPP STDERR: %s" % line.rstrip("\n"))
195 # ignoring the dummy pipe here intentionally - the
196 # flag will take care of properly terminating the loop
199 def _is_skip_aarch64_set():
200 return BoolEnvironmentVariable('SKIP_AARCH64')
203 is_skip_aarch64_set = _is_skip_aarch64_set()
206 def _is_platform_aarch64():
207 return platform.machine() == 'aarch64'
210 is_platform_aarch64 = _is_platform_aarch64()
213 def _running_extended_tests():
214 return BoolEnvironmentVariable("EXTENDED_TESTS")
217 running_extended_tests = _running_extended_tests()
220 def _running_on_centos():
221 os_id = os.getenv("OS_ID", "")
222 return True if "centos" in os_id.lower() else False
225 running_on_centos = _running_on_centos()
228 class KeepAliveReporter(object):
230 Singleton object which reports test start to parent process
235 self.__dict__ = self._shared_state
243 def pipe(self, pipe):
244 if self._pipe is not None:
245 raise Exception("Internal error - pipe should only be set once.")
248 def send_keep_alive(self, test, desc=None):
250 Write current test tmpdir & desc to keep-alive pipe to signal liveness
252 if self.pipe is None:
253 # if not running forked..
257 desc = '%s (%s)' % (desc, unittest.util.strclass(test))
261 self.pipe.send((desc, test.vpp_bin, test.tempdir, test.vpp.pid))
264 class VppTestCase(unittest.TestCase):
265 """This subclass is a base class for VPP test cases that are implemented as
266 classes. It provides methods to create and run test case.
269 extra_vpp_punt_config = []
270 extra_vpp_plugin_config = []
271 vapi_response_timeout = 5
274 def packet_infos(self):
275 """List of packet infos"""
276 return self._packet_infos
279 def get_packet_count_for_if_idx(cls, dst_if_index):
280 """Get the number of packet info for specified destination if index"""
281 if dst_if_index in cls._packet_count_for_dst_if_idx:
282 return cls._packet_count_for_dst_if_idx[dst_if_index]
288 """Return the instance of this testcase"""
289 return cls.test_instance
292 def set_debug_flags(cls, d):
293 cls.gdbserver_port = 7777
294 cls.debug_core = False
295 cls.debug_gdb = False
296 cls.debug_gdbserver = False
297 cls.debug_all = False
302 cls.debug_core = True
303 elif dl == "gdb" or dl == "gdb-all":
305 elif dl == "gdbserver" or dl == "gdbserver-all":
306 cls.debug_gdbserver = True
308 raise Exception("Unrecognized DEBUG option: '%s'" % d)
309 if dl == "gdb-all" or dl == "gdbserver-all":
313 def get_least_used_cpu():
314 cpu_usage_list = [set(range(psutil.cpu_count()))]
315 vpp_processes = [p for p in psutil.process_iter(attrs=['pid', 'name'])
316 if 'vpp_main' == p.info['name']]
317 for vpp_process in vpp_processes:
318 for cpu_usage_set in cpu_usage_list:
320 cpu_num = vpp_process.cpu_num()
321 if cpu_num in cpu_usage_set:
322 cpu_usage_set_index = cpu_usage_list.index(
324 if cpu_usage_set_index == len(cpu_usage_list) - 1:
325 cpu_usage_list.append({cpu_num})
327 cpu_usage_list[cpu_usage_set_index + 1].add(
329 cpu_usage_set.remove(cpu_num)
331 except psutil.NoSuchProcess:
334 for cpu_usage_set in cpu_usage_list:
335 if len(cpu_usage_set) > 0:
336 min_usage_set = cpu_usage_set
339 return random.choice(tuple(min_usage_set))
342 def setUpConstants(cls):
343 """ Set-up the test case class based on environment variables """
344 cls.step = BoolEnvironmentVariable('STEP')
345 d = os.getenv("DEBUG", None)
346 # inverted case to handle '' == True
347 c = os.getenv("CACHE_OUTPUT", "1")
348 cls.cache_vpp_output = False if c.lower() in ("n", "no", "0") else True
349 cls.set_debug_flags(d)
350 cls.vpp_bin = os.getenv('VPP_BIN', "vpp")
351 cls.plugin_path = os.getenv('VPP_PLUGIN_PATH')
352 cls.test_plugin_path = os.getenv('VPP_TEST_PLUGIN_PATH')
353 cls.extern_plugin_path = os.getenv('EXTERN_PLUGINS')
355 if cls.plugin_path is not None:
356 if cls.extern_plugin_path is not None:
357 plugin_path = "%s:%s" % (
358 cls.plugin_path, cls.extern_plugin_path)
360 plugin_path = cls.plugin_path
361 elif cls.extern_plugin_path is not None:
362 plugin_path = cls.extern_plugin_path
364 if cls.step or cls.debug_gdb or cls.debug_gdbserver:
365 debug_cli = "cli-listen localhost:5002"
367 size = os.getenv("COREDUMP_SIZE")
369 coredump_size = "coredump-size %s" % size
370 if coredump_size is None:
371 coredump_size = "coredump-size unlimited"
373 cpu_core_number = cls.get_least_used_cpu()
374 if not hasattr(cls, "worker_config"):
375 cls.worker_config = ""
377 cls.vpp_cmdline = [cls.vpp_bin, "unix",
378 "{", "nodaemon", debug_cli, "full-coredump",
379 coredump_size, "runtime-dir", cls.tempdir, "}",
380 "api-trace", "{", "on", "}", "api-segment", "{",
381 "prefix", cls.shm_prefix, "}", "cpu", "{",
382 "main-core", str(cpu_core_number),
383 cls.worker_config, "}",
384 "statseg", "{", "socket-name", cls.stats_sock, "}",
385 "socksvr", "{", "socket-name", cls.api_sock, "}",
387 "{", "plugin", "dpdk_plugin.so", "{", "disable",
388 "}", "plugin", "rdma_plugin.so", "{", "disable",
389 "}", "plugin", "unittest_plugin.so", "{", "enable",
390 "}"] + cls.extra_vpp_plugin_config + ["}", ]
391 if cls.extra_vpp_punt_config is not None:
392 cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
393 if plugin_path is not None:
394 cls.vpp_cmdline.extend(["plugin_path", plugin_path])
395 if cls.test_plugin_path is not None:
396 cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
398 cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
399 cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
402 def wait_for_enter(cls):
403 if cls.debug_gdbserver:
404 print(double_line_delim)
405 print("Spawned GDB server with PID: %d" % cls.vpp.pid)
407 print(double_line_delim)
408 print("Spawned VPP with PID: %d" % cls.vpp.pid)
410 cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
412 print(single_line_delim)
413 print("You can debug VPP using:")
414 if cls.debug_gdbserver:
415 print("sudo gdb " + cls.vpp_bin +
416 " -ex 'target remote localhost:{port}'"
417 .format(port=cls.gdbserver_port))
418 print("Now is the time to attach gdb by running the above "
419 "command, set up breakpoints etc., then resume VPP from "
420 "within gdb by issuing the 'continue' command")
421 cls.gdbserver_port += 1
423 print("sudo gdb " + cls.vpp_bin + " -ex 'attach %s'" % cls.vpp.pid)
424 print("Now is the time to attach gdb by running the above "
425 "command and set up breakpoints etc., then resume VPP from"
426 " within gdb by issuing the 'continue' command")
427 print(single_line_delim)
428 input("Press ENTER to continue running the testcase...")
432 cmdline = cls.vpp_cmdline
434 if cls.debug_gdbserver:
435 gdbserver = '/usr/bin/gdbserver'
436 if not os.path.isfile(gdbserver) or \
437 not os.access(gdbserver, os.X_OK):
438 raise Exception("gdbserver binary '%s' does not exist or is "
439 "not executable" % gdbserver)
441 cmdline = [gdbserver, 'localhost:{port}'
442 .format(port=cls.gdbserver_port)] + cls.vpp_cmdline
443 cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
446 cls.vpp = subprocess.Popen(cmdline,
447 stdout=subprocess.PIPE,
448 stderr=subprocess.PIPE,
450 except subprocess.CalledProcessError as e:
451 cls.logger.critical("Subprocess returned with non-0 return code: ("
455 cls.logger.critical("Subprocess returned with OS error: "
456 "(%s) %s", e.errno, e.strerror)
458 except Exception as e:
459 cls.logger.exception("Subprocess returned unexpected from "
466 def wait_for_stats_socket(cls):
467 deadline = time.time() + 300
469 while time.time() < deadline or \
470 cls.debug_gdb or cls.debug_gdbserver:
471 if os.path.exists(cls.stats_sock):
476 cls.logger.critical("Couldn't stat : {}".format(cls.stats_sock))
479 def wait_for_coredump(cls):
480 corefile = cls.tempdir + "/core"
481 if os.path.isfile(corefile):
482 cls.logger.error("Waiting for coredump to complete: %s", corefile)
483 curr_size = os.path.getsize(corefile)
484 deadline = time.time() + 60
486 while time.time() < deadline:
489 curr_size = os.path.getsize(corefile)
490 if size == curr_size:
494 cls.logger.error("Timed out waiting for coredump to complete:"
497 cls.logger.error("Coredump complete: %s, size %d",
503 Perform class setup before running the testcase
504 Remove shared memory files, start vpp and connect the vpp-api
506 super(VppTestCase, cls).setUpClass()
507 gc.collect() # run garbage collection first
508 cls.logger = get_logger(cls.__name__)
509 seed = os.environ["RND_SEED"]
511 if hasattr(cls, 'parallel_handler'):
512 cls.logger.addHandler(cls.parallel_handler)
513 cls.logger.propagate = False
515 cls.tempdir = tempfile.mkdtemp(
516 prefix='vpp-unittest-%s-' % cls.__name__)
517 cls.stats_sock = "%s/stats.sock" % cls.tempdir
518 cls.api_sock = "%s/api.sock" % cls.tempdir
519 cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
520 cls.file_handler.setFormatter(
521 Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
523 cls.file_handler.setLevel(DEBUG)
524 cls.logger.addHandler(cls.file_handler)
525 cls.logger.debug("--- setUpClass() for %s called ---" %
527 cls.shm_prefix = os.path.basename(cls.tempdir)
528 os.chdir(cls.tempdir)
529 cls.logger.info("Temporary dir is %s, shm prefix is %s",
530 cls.tempdir, cls.shm_prefix)
531 cls.logger.debug("Random seed is %s" % seed)
533 cls.reset_packet_infos()
537 cls.registry = VppObjectRegistry()
538 cls.vpp_startup_failed = False
539 cls.reporter = KeepAliveReporter()
540 # need to catch exceptions here because if we raise, then the cleanup
541 # doesn't get called and we might end with a zombie vpp
544 cls.reporter.send_keep_alive(cls, 'setUpClass')
545 VppTestResult.current_test_case_info = TestCaseInfo(
546 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
547 cls.vpp_stdout_deque = deque()
548 cls.vpp_stderr_deque = deque()
549 cls.pump_thread_stop_flag = Event()
550 cls.pump_thread_wakeup_pipe = os.pipe()
551 cls.pump_thread = Thread(target=pump_output, args=(cls,))
552 cls.pump_thread.daemon = True
553 cls.pump_thread.start()
554 if cls.debug_gdb or cls.debug_gdbserver:
555 cls.vapi_response_timeout = 0
556 cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
557 cls.vapi_response_timeout)
559 hook = hookmodule.StepHook(cls)
561 hook = hookmodule.PollHook(cls)
562 cls.vapi.register_hook(hook)
563 cls.wait_for_stats_socket()
564 cls.statistics = VPPStats(socketname=cls.stats_sock)
568 cls.vpp_startup_failed = True
570 "VPP died shortly after startup, check the"
571 " output to standard error for possible cause")
575 except vpp_papi.VPPIOError as e:
576 cls.logger.debug("Exception connecting to vapi: %s" % e)
577 cls.vapi.disconnect()
579 if cls.debug_gdbserver:
580 print(colorize("You're running VPP inside gdbserver but "
581 "VPP-API connection failed, did you forget "
582 "to 'continue' VPP from within gdb?", RED))
584 except Exception as e:
585 cls.logger.debug("Exception connecting to VPP: %s" % e)
593 Disconnect vpp-api, kill vpp and cleanup shared memory files
595 if (cls.debug_gdbserver or cls.debug_gdb) and hasattr(cls, 'vpp'):
597 if cls.vpp.returncode is None:
599 print(double_line_delim)
600 print("VPP or GDB server is still running")
601 print(single_line_delim)
602 input("When done debugging, press ENTER to kill the "
603 "process and finish running the testcase...")
605 # first signal that we want to stop the pump thread, then wake it up
606 if hasattr(cls, 'pump_thread_stop_flag'):
607 cls.pump_thread_stop_flag.set()
608 if hasattr(cls, 'pump_thread_wakeup_pipe'):
609 os.write(cls.pump_thread_wakeup_pipe[1], b'ding dong wake up')
610 if hasattr(cls, 'pump_thread'):
611 cls.logger.debug("Waiting for pump thread to stop")
612 cls.pump_thread.join()
613 if hasattr(cls, 'vpp_stderr_reader_thread'):
614 cls.logger.debug("Waiting for stdderr pump to stop")
615 cls.vpp_stderr_reader_thread.join()
617 if hasattr(cls, 'vpp'):
618 if hasattr(cls, 'vapi'):
619 cls.logger.debug(cls.vapi.vpp.get_stats())
620 cls.logger.debug("Disconnecting class vapi client on %s",
622 cls.vapi.disconnect()
623 cls.logger.debug("Deleting class vapi attribute on %s",
627 if cls.vpp.returncode is None:
628 cls.wait_for_coredump()
629 cls.logger.debug("Sending TERM to vpp")
631 cls.logger.debug("Waiting for vpp to die")
632 cls.vpp.communicate()
633 cls.logger.debug("Deleting class vpp attribute on %s",
637 if cls.vpp_startup_failed:
638 stdout_log = cls.logger.info
639 stderr_log = cls.logger.critical
641 stdout_log = cls.logger.info
642 stderr_log = cls.logger.info
644 if hasattr(cls, 'vpp_stdout_deque'):
645 stdout_log(single_line_delim)
646 stdout_log('VPP output to stdout while running %s:', cls.__name__)
647 stdout_log(single_line_delim)
648 vpp_output = "".join(cls.vpp_stdout_deque)
649 with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
651 stdout_log('\n%s', vpp_output)
652 stdout_log(single_line_delim)
654 if hasattr(cls, 'vpp_stderr_deque'):
655 stderr_log(single_line_delim)
656 stderr_log('VPP output to stderr while running %s:', cls.__name__)
657 stderr_log(single_line_delim)
658 vpp_output = "".join(cls.vpp_stderr_deque)
659 with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
661 stderr_log('\n%s', vpp_output)
662 stderr_log(single_line_delim)
665 def tearDownClass(cls):
666 """ Perform final cleanup after running all tests in this test-case """
667 cls.logger.debug("--- tearDownClass() for %s called ---" %
669 cls.reporter.send_keep_alive(cls, 'tearDownClass')
671 cls.file_handler.close()
672 cls.reset_packet_infos()
674 debug_internal.on_tear_down_class(cls)
676 def show_commands_at_teardown(self):
677 """ Allow subclass specific teardown logging additions."""
678 self.logger.info("--- No test specific show commands provided. ---")
681 """ Show various debug prints after each test """
682 self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
683 (self.__class__.__name__, self._testMethodName,
684 self._testMethodDoc))
687 if not self.vpp_dead:
688 self.logger.debug(self.vapi.cli("show trace max 1000"))
689 self.logger.info(self.vapi.ppcli("show interface"))
690 self.logger.info(self.vapi.ppcli("show hardware"))
691 self.logger.info(self.statistics.set_errors_str())
692 self.logger.info(self.vapi.ppcli("show run"))
693 self.logger.info(self.vapi.ppcli("show log"))
694 self.logger.info(self.vapi.ppcli("show bihash"))
695 self.logger.info("Logging testcase specific show commands.")
696 self.show_commands_at_teardown()
697 self.registry.remove_vpp_config(self.logger)
698 # Save/Dump VPP api trace log
699 m = self._testMethodName
700 api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
701 tmp_api_trace = "/tmp/%s" % api_trace
702 vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
703 self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
704 self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
706 os.rename(tmp_api_trace, vpp_api_trace_log)
707 self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
709 except VppTransportShmemIOError:
710 self.logger.debug("VppTransportShmemIOError: Vpp dead. "
711 "Cannot log show commands.")
714 self.registry.unregister_all(self.logger)
717 """ Clear trace before running each test"""
718 super(VppTestCase, self).setUp()
719 self.reporter.send_keep_alive(self)
722 raise VppDiedError(rv=None, testcase=self.__class__.__name__,
723 method_name=self._testMethodName)
724 self.sleep(.1, "during setUp")
725 self.vpp_stdout_deque.append(
726 "--- test setUp() for %s.%s(%s) starts here ---\n" %
727 (self.__class__.__name__, self._testMethodName,
728 self._testMethodDoc))
729 self.vpp_stderr_deque.append(
730 "--- test setUp() for %s.%s(%s) starts here ---\n" %
731 (self.__class__.__name__, self._testMethodName,
732 self._testMethodDoc))
733 self.vapi.cli("clear trace")
734 # store the test instance inside the test class - so that objects
735 # holding the class can access instance methods (like assertEqual)
736 type(self).test_instance = self
739 def pg_enable_capture(cls, interfaces=None):
741 Enable capture on packet-generator interfaces
743 :param interfaces: iterable interface indexes (if None,
744 use self.pg_interfaces)
747 if interfaces is None:
748 interfaces = cls.pg_interfaces
753 def register_capture(cls, cap_name):
754 """ Register a capture in the testclass """
755 # add to the list of captures with current timestamp
756 cls._captures.append((time.time(), cap_name))
759 def get_vpp_time(cls):
760 return float(cls.vapi.cli('show clock').replace("Time now ", ""))
763 def sleep_on_vpp_time(cls, sec):
764 """ Sleep according to time in VPP world """
765 # On a busy system with many processes
766 # we might end up with VPP time being slower than real world
767 # So take that into account when waiting for VPP to do something
768 start_time = cls.get_vpp_time()
769 while cls.get_vpp_time() - start_time < sec:
774 """ Enable the PG, wait till it is done, then clean up """
775 cls.vapi.cli("trace add pg-input 1000")
776 cls.vapi.cli('packet-generator enable')
777 # PG, when starts, runs to completion -
778 # so let's avoid a race condition,
779 # and wait a little till it's done.
780 # Then clean it up - and then be gone.
781 deadline = time.time() + 300
782 while cls.vapi.cli('show packet-generator').find("Yes") != -1:
783 cls.sleep(0.01) # yield
784 if time.time() > deadline:
785 cls.logger.error("Timeout waiting for pg to stop")
787 for stamp, cap_name in cls._captures:
788 cls.vapi.cli('packet-generator delete %s' % cap_name)
792 def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
794 Create packet-generator interfaces.
796 :param interfaces: iterable indexes of the interfaces.
797 :returns: List of created interfaces.
802 intf = VppPGInterface(cls, i, gso, gso_size)
803 setattr(cls, intf.name, intf)
805 cls.pg_interfaces = result
809 def create_loopback_interfaces(cls, count):
811 Create loopback interfaces.
813 :param count: number of interfaces created.
814 :returns: List of created interfaces.
816 result = [VppLoInterface(cls) for i in range(count)]
818 setattr(cls, intf.name, intf)
819 cls.lo_interfaces = result
823 def create_bvi_interfaces(cls, count):
825 Create BVI interfaces.
827 :param count: number of interfaces created.
828 :returns: List of created interfaces.
830 result = [VppBviInterface(cls) for i in range(count)]
832 setattr(cls, intf.name, intf)
833 cls.bvi_interfaces = result
837 def extend_packet(packet, size, padding=' '):
839 Extend packet to given size by padding with spaces or custom padding
840 NOTE: Currently works only when Raw layer is present.
842 :param packet: packet
843 :param size: target size
844 :param padding: padding used to extend the payload
847 packet_len = len(packet) + 4
848 extend = size - packet_len
850 num = (extend // len(padding)) + 1
851 packet[Raw].load += (padding * num)[:extend].encode("ascii")
854 def reset_packet_infos(cls):
855 """ Reset the list of packet info objects and packet counts to zero """
856 cls._packet_infos = {}
857 cls._packet_count_for_dst_if_idx = {}
860 def create_packet_info(cls, src_if, dst_if):
862 Create packet info object containing the source and destination indexes
863 and add it to the testcase's packet info list
865 :param VppInterface src_if: source interface
866 :param VppInterface dst_if: destination interface
868 :returns: _PacketInfo object
872 info.index = len(cls._packet_infos)
873 info.src = src_if.sw_if_index
874 info.dst = dst_if.sw_if_index
875 if isinstance(dst_if, VppSubInterface):
876 dst_idx = dst_if.parent.sw_if_index
878 dst_idx = dst_if.sw_if_index
879 if dst_idx in cls._packet_count_for_dst_if_idx:
880 cls._packet_count_for_dst_if_idx[dst_idx] += 1
882 cls._packet_count_for_dst_if_idx[dst_idx] = 1
883 cls._packet_infos[info.index] = info
887 def info_to_payload(info):
889 Convert _PacketInfo object to packet payload
891 :param info: _PacketInfo object
893 :returns: string containing serialized data from packet info
895 return "%d %d %d %d %d" % (info.index, info.src, info.dst,
899 def payload_to_info(payload, payload_field='load'):
901 Convert packet payload to _PacketInfo object
903 :param payload: packet payload
904 :type payload: <class 'scapy.packet.Raw'>
905 :param payload_field: packet fieldname of payload "load" for
906 <class 'scapy.packet.Raw'>
907 :type payload_field: str
908 :returns: _PacketInfo object containing de-serialized data from payload
911 numbers = getattr(payload, payload_field).split()
913 info.index = int(numbers[0])
914 info.src = int(numbers[1])
915 info.dst = int(numbers[2])
916 info.ip = int(numbers[3])
917 info.proto = int(numbers[4])
920 def get_next_packet_info(self, info):
922 Iterate over the packet info list stored in the testcase
923 Start iteration with first element if info is None
924 Continue based on index in info if info is specified
926 :param info: info or None
927 :returns: next info in list or None if no more infos
932 next_index = info.index + 1
933 if next_index == len(self._packet_infos):
936 return self._packet_infos[next_index]
938 def get_next_packet_info_for_interface(self, src_index, info):
940 Search the packet info list for the next packet info with same source
943 :param src_index: source interface index to search for
944 :param info: packet info - where to start the search
945 :returns: packet info or None
949 info = self.get_next_packet_info(info)
952 if info.src == src_index:
955 def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
957 Search the packet info list for the next packet info with same source
958 and destination interface indexes
960 :param src_index: source interface index to search for
961 :param dst_index: destination interface index to search for
962 :param info: packet info - where to start the search
963 :returns: packet info or None
967 info = self.get_next_packet_info_for_interface(src_index, info)
970 if info.dst == dst_index:
973 def assert_equal(self, real_value, expected_value, name_or_class=None):
974 if name_or_class is None:
975 self.assertEqual(real_value, expected_value)
978 msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
979 msg = msg % (getdoc(name_or_class).strip(),
980 real_value, str(name_or_class(real_value)),
981 expected_value, str(name_or_class(expected_value)))
983 msg = "Invalid %s: %s does not match expected value %s" % (
984 name_or_class, real_value, expected_value)
986 self.assertEqual(real_value, expected_value, msg)
988 def assert_in_range(self,
996 msg = "Invalid %s: %s out of range <%s,%s>" % (
997 name, real_value, expected_min, expected_max)
998 self.assertTrue(expected_min <= real_value <= expected_max, msg)
1000 def assert_packet_checksums_valid(self, packet,
1001 ignore_zero_udp_checksums=True):
1002 received = packet.__class__(scapy.compat.raw(packet))
1003 udp_layers = ['UDP', 'UDPerror']
1004 checksum_fields = ['cksum', 'chksum']
1007 temp = received.__class__(scapy.compat.raw(received))
1009 layer = temp.getlayer(counter)
1011 layer = layer.copy()
1012 layer.remove_payload()
1013 for cf in checksum_fields:
1014 if hasattr(layer, cf):
1015 if ignore_zero_udp_checksums and \
1016 0 == getattr(layer, cf) and \
1017 layer.name in udp_layers:
1019 delattr(temp.getlayer(counter), cf)
1020 checksums.append((counter, cf))
1023 counter = counter + 1
1024 if 0 == len(checksums):
1026 temp = temp.__class__(scapy.compat.raw(temp))
1027 for layer, cf in checksums:
1028 calc_sum = getattr(temp[layer], cf)
1030 getattr(received[layer], cf), calc_sum,
1031 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1033 "Checksum field `%s` on `%s` layer has correct value `%s`" %
1034 (cf, temp[layer].name, calc_sum))
1036 def assert_checksum_valid(self, received_packet, layer,
1037 field_name='chksum',
1038 ignore_zero_checksum=False):
1039 """ Check checksum of received packet on given layer """
1040 received_packet_checksum = getattr(received_packet[layer], field_name)
1041 if ignore_zero_checksum and 0 == received_packet_checksum:
1043 recalculated = received_packet.__class__(
1044 scapy.compat.raw(received_packet))
1045 delattr(recalculated[layer], field_name)
1046 recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1047 self.assert_equal(received_packet_checksum,
1048 getattr(recalculated[layer], field_name),
1049 "packet checksum on layer: %s" % layer)
1051 def assert_ip_checksum_valid(self, received_packet,
1052 ignore_zero_checksum=False):
1053 self.assert_checksum_valid(received_packet, 'IP',
1054 ignore_zero_checksum=ignore_zero_checksum)
1056 def assert_tcp_checksum_valid(self, received_packet,
1057 ignore_zero_checksum=False):
1058 self.assert_checksum_valid(received_packet, 'TCP',
1059 ignore_zero_checksum=ignore_zero_checksum)
1061 def assert_udp_checksum_valid(self, received_packet,
1062 ignore_zero_checksum=True):
1063 self.assert_checksum_valid(received_packet, 'UDP',
1064 ignore_zero_checksum=ignore_zero_checksum)
1066 def assert_embedded_icmp_checksum_valid(self, received_packet):
1067 if received_packet.haslayer(IPerror):
1068 self.assert_checksum_valid(received_packet, 'IPerror')
1069 if received_packet.haslayer(TCPerror):
1070 self.assert_checksum_valid(received_packet, 'TCPerror')
1071 if received_packet.haslayer(UDPerror):
1072 self.assert_checksum_valid(received_packet, 'UDPerror',
1073 ignore_zero_checksum=True)
1074 if received_packet.haslayer(ICMPerror):
1075 self.assert_checksum_valid(received_packet, 'ICMPerror')
1077 def assert_icmp_checksum_valid(self, received_packet):
1078 self.assert_checksum_valid(received_packet, 'ICMP')
1079 self.assert_embedded_icmp_checksum_valid(received_packet)
1081 def assert_icmpv6_checksum_valid(self, pkt):
1082 if pkt.haslayer(ICMPv6DestUnreach):
1083 self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1084 self.assert_embedded_icmp_checksum_valid(pkt)
1085 if pkt.haslayer(ICMPv6EchoRequest):
1086 self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1087 if pkt.haslayer(ICMPv6EchoReply):
1088 self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1090 def get_packet_counter(self, counter):
1091 if counter.startswith("/"):
1092 counter_value = self.statistics.get_counter(counter)
1094 counters = self.vapi.cli("sh errors").split('\n')
1096 for i in range(1, len(counters) - 1):
1097 results = counters[i].split()
1098 if results[1] == counter:
1099 counter_value = int(results[0])
1101 return counter_value
1103 def assert_packet_counter_equal(self, counter, expected_value):
1104 counter_value = self.get_packet_counter(counter)
1105 self.assert_equal(counter_value, expected_value,
1106 "packet counter `%s'" % counter)
1108 def assert_error_counter_equal(self, counter, expected_value):
1109 counter_value = self.statistics.get_err_counter(counter)
1110 self.assert_equal(counter_value, expected_value,
1111 "error counter `%s'" % counter)
1114 def sleep(cls, timeout, remark=None):
1116 # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1117 # * by Guido, only the main thread can be interrupted.
1119 # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892 # noqa
1122 if hasattr(os, 'sched_yield'):
1128 if hasattr(cls, 'logger'):
1129 cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1130 before = time.time()
1133 if hasattr(cls, 'logger') and after - before > 2 * timeout:
1134 cls.logger.error("unexpected self.sleep() result - "
1135 "slept for %es instead of ~%es!",
1136 after - before, timeout)
1137 if hasattr(cls, 'logger'):
1139 "Finished sleep (%s) - slept %es (wanted %es)",
1140 remark, after - before, timeout)
1142 def pg_send(self, intf, pkts):
1143 self.vapi.cli("clear trace")
1144 intf.add_stream(pkts)
1145 self.pg_enable_capture(self.pg_interfaces)
1148 def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1149 self.pg_send(intf, pkts)
1152 for i in self.pg_interfaces:
1153 i.get_capture(0, timeout=timeout)
1154 i.assert_nothing_captured(remark=remark)
1157 def send_and_expect(self, intf, pkts, output, n_rx=None):
1160 self.pg_send(intf, pkts)
1161 rx = output.get_capture(n_rx)
1164 def send_and_expect_only(self, intf, pkts, output, timeout=None):
1165 self.pg_send(intf, pkts)
1166 rx = output.get_capture(len(pkts))
1170 for i in self.pg_interfaces:
1171 if i not in outputs:
1172 i.get_capture(0, timeout=timeout)
1173 i.assert_nothing_captured()
1179 def get_testcase_doc_name(test):
1180 return getdoc(test.__class__).splitlines()[0]
1183 def get_test_description(descriptions, test):
1184 short_description = test.shortDescription()
1185 if descriptions and short_description:
1186 return short_description
1191 class TestCaseInfo(object):
1192 def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1193 self.logger = logger
1194 self.tempdir = tempdir
1195 self.vpp_pid = vpp_pid
1196 self.vpp_bin_path = vpp_bin_path
1197 self.core_crash_test = None
1200 class VppTestResult(unittest.TestResult):
1202 @property result_string
1203 String variable to store the test case result string.
1205 List variable containing 2-tuples of TestCase instances and strings
1206 holding formatted tracebacks. Each tuple represents a test which
1207 raised an unexpected exception.
1209 List variable containing 2-tuples of TestCase instances and strings
1210 holding formatted tracebacks. Each tuple represents a test where
1211 a failure was explicitly signalled using the TestCase.assert*()
1215 failed_test_cases_info = set()
1216 core_crash_test_cases_info = set()
1217 current_test_case_info = None
1219 def __init__(self, stream=None, descriptions=None, verbosity=None,
1222 :param stream File descriptor to store where to report test results.
1223 Set to the standard error stream by default.
1224 :param descriptions Boolean variable to store information if to use
1225 test case descriptions.
1226 :param verbosity Integer variable to store required verbosity level.
1228 super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1229 self.stream = stream
1230 self.descriptions = descriptions
1231 self.verbosity = verbosity
1232 self.result_string = None
1233 self.runner = runner
1235 def addSuccess(self, test):
1237 Record a test succeeded result
1242 if self.current_test_case_info:
1243 self.current_test_case_info.logger.debug(
1244 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1245 test._testMethodName,
1246 test._testMethodDoc))
1247 unittest.TestResult.addSuccess(self, test)
1248 self.result_string = colorize("OK", GREEN)
1250 self.send_result_through_pipe(test, PASS)
1252 def addSkip(self, test, reason):
1254 Record a test skipped.
1260 if self.current_test_case_info:
1261 self.current_test_case_info.logger.debug(
1262 "--- addSkip() %s.%s(%s) called, reason is %s" %
1263 (test.__class__.__name__, test._testMethodName,
1264 test._testMethodDoc, reason))
1265 unittest.TestResult.addSkip(self, test, reason)
1266 self.result_string = colorize("SKIP", YELLOW)
1268 self.send_result_through_pipe(test, SKIP)
1270 def symlink_failed(self):
1271 if self.current_test_case_info:
1273 failed_dir = os.getenv('FAILED_DIR')
1274 link_path = os.path.join(
1277 os.path.basename(self.current_test_case_info.tempdir))
1278 if self.current_test_case_info.logger:
1279 self.current_test_case_info.logger.debug(
1280 "creating a link to the failed test")
1281 self.current_test_case_info.logger.debug(
1282 "os.symlink(%s, %s)" %
1283 (self.current_test_case_info.tempdir, link_path))
1284 if os.path.exists(link_path):
1285 if self.current_test_case_info.logger:
1286 self.current_test_case_info.logger.debug(
1287 'symlink already exists')
1289 os.symlink(self.current_test_case_info.tempdir, link_path)
1291 except Exception as e:
1292 if self.current_test_case_info.logger:
1293 self.current_test_case_info.logger.error(e)
1295 def send_result_through_pipe(self, test, result):
1296 if hasattr(self, 'test_framework_result_pipe'):
1297 pipe = self.test_framework_result_pipe
1299 pipe.send((test.id(), result))
1301 def log_error(self, test, err, fn_name):
1302 if self.current_test_case_info:
1303 if isinstance(test, unittest.suite._ErrorHolder):
1304 test_name = test.description
1306 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1307 test._testMethodName,
1308 test._testMethodDoc)
1309 self.current_test_case_info.logger.debug(
1310 "--- %s() %s called, err is %s" %
1311 (fn_name, test_name, err))
1312 self.current_test_case_info.logger.debug(
1313 "formatted exception is:\n%s" %
1314 "".join(format_exception(*err)))
1316 def add_error(self, test, err, unittest_fn, error_type):
1317 if error_type == FAIL:
1318 self.log_error(test, err, 'addFailure')
1319 error_type_str = colorize("FAIL", RED)
1320 elif error_type == ERROR:
1321 self.log_error(test, err, 'addError')
1322 error_type_str = colorize("ERROR", RED)
1324 raise Exception('Error type %s cannot be used to record an '
1325 'error or a failure' % error_type)
1327 unittest_fn(self, test, err)
1328 if self.current_test_case_info:
1329 self.result_string = "%s [ temp dir used by test case: %s ]" % \
1331 self.current_test_case_info.tempdir)
1332 self.symlink_failed()
1333 self.failed_test_cases_info.add(self.current_test_case_info)
1334 if is_core_present(self.current_test_case_info.tempdir):
1335 if not self.current_test_case_info.core_crash_test:
1336 if isinstance(test, unittest.suite._ErrorHolder):
1337 test_name = str(test)
1339 test_name = "'{!s}' ({!s})".format(
1340 get_testcase_doc_name(test), test.id())
1341 self.current_test_case_info.core_crash_test = test_name
1342 self.core_crash_test_cases_info.add(
1343 self.current_test_case_info)
1345 self.result_string = '%s [no temp dir]' % error_type_str
1347 self.send_result_through_pipe(test, error_type)
1349 def addFailure(self, test, err):
1351 Record a test failed result
1354 :param err: error message
1357 self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1359 def addError(self, test, err):
1361 Record a test error result
1364 :param err: error message
1367 self.add_error(test, err, unittest.TestResult.addError, ERROR)
1369 def getDescription(self, test):
1371 Get test description
1374 :returns: test description
1377 return get_test_description(self.descriptions, test)
1379 def startTest(self, test):
1387 def print_header(test):
1388 if not hasattr(test.__class__, '_header_printed'):
1389 print(double_line_delim)
1390 print(colorize(getdoc(test).splitlines()[0], GREEN))
1391 print(double_line_delim)
1392 test.__class__._header_printed = True
1395 self.start_test = time.time()
1396 unittest.TestResult.startTest(self, test)
1397 if self.verbosity > 0:
1398 self.stream.writeln(
1399 "Starting " + self.getDescription(test) + " ...")
1400 self.stream.writeln(single_line_delim)
1402 def stopTest(self, test):
1404 Called when the given test has been run
1409 unittest.TestResult.stopTest(self, test)
1411 if self.verbosity > 0:
1412 self.stream.writeln(single_line_delim)
1413 self.stream.writeln("%-73s%s" % (self.getDescription(test),
1414 self.result_string))
1415 self.stream.writeln(single_line_delim)
1417 self.stream.writeln("%-68s %4.2f %s" %
1418 (self.getDescription(test),
1419 time.time() - self.start_test,
1420 self.result_string))
1422 self.send_result_through_pipe(test, TEST_RUN)
1424 def printErrors(self):
1426 Print errors from running the test case
1428 if len(self.errors) > 0 or len(self.failures) > 0:
1429 self.stream.writeln()
1430 self.printErrorList('ERROR', self.errors)
1431 self.printErrorList('FAIL', self.failures)
1433 # ^^ that is the last output from unittest before summary
1434 if not self.runner.print_summary:
1435 devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1436 self.stream = devnull
1437 self.runner.stream = devnull
1439 def printErrorList(self, flavour, errors):
1441 Print error list to the output stream together with error type
1442 and test case description.
1444 :param flavour: error type
1445 :param errors: iterable errors
1448 for test, err in errors:
1449 self.stream.writeln(double_line_delim)
1450 self.stream.writeln("%s: %s" %
1451 (flavour, self.getDescription(test)))
1452 self.stream.writeln(single_line_delim)
1453 self.stream.writeln("%s" % err)
1456 class VppTestRunner(unittest.TextTestRunner):
1458 A basic test runner implementation which prints results to standard error.
1462 def resultclass(self):
1463 """Class maintaining the results of the tests"""
1464 return VppTestResult
1466 def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1467 result_pipe=None, failfast=False, buffer=False,
1468 resultclass=None, print_summary=True, **kwargs):
1469 # ignore stream setting here, use hard-coded stdout to be in sync
1470 # with prints from VppTestCase methods ...
1471 super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1472 verbosity, failfast, buffer,
1473 resultclass, **kwargs)
1474 KeepAliveReporter.pipe = keep_alive_pipe
1476 self.orig_stream = self.stream
1477 self.resultclass.test_framework_result_pipe = result_pipe
1479 self.print_summary = print_summary
1481 def _makeResult(self):
1482 return self.resultclass(self.stream,
1487 def run(self, test):
1494 faulthandler.enable() # emit stack trace to stderr if killed by signal
1496 result = super(VppTestRunner, self).run(test)
1497 if not self.print_summary:
1498 self.stream = self.orig_stream
1499 result.stream = self.orig_stream
1503 class Worker(Thread):
1504 def __init__(self, args, logger, env=None):
1505 self.logger = logger
1507 if hasattr(self, 'testcase') and self.testcase.debug_all:
1508 if self.testcase.debug_gdbserver:
1509 self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1510 .format(port=self.testcase.gdbserver_port)] + args
1511 elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1512 self.args.append(self.wait_for_gdb)
1513 self.app_bin = args[0]
1514 self.app_name = os.path.basename(self.app_bin)
1515 if hasattr(self, 'role'):
1516 self.app_name += ' {role}'.format(role=self.role)
1519 env = {} if env is None else env
1520 self.env = copy.deepcopy(env)
1521 super(Worker, self).__init__()
1523 def wait_for_enter(self):
1524 if not hasattr(self, 'testcase'):
1526 if self.testcase.debug_all and self.testcase.debug_gdbserver:
1528 print(double_line_delim)
1529 print("Spawned GDB Server for '{app}' with PID: {pid}"
1530 .format(app=self.app_name, pid=self.process.pid))
1531 elif self.testcase.debug_all and self.testcase.debug_gdb:
1533 print(double_line_delim)
1534 print("Spawned '{app}' with PID: {pid}"
1535 .format(app=self.app_name, pid=self.process.pid))
1538 print(single_line_delim)
1539 print("You can debug '{app}' using:".format(app=self.app_name))
1540 if self.testcase.debug_gdbserver:
1541 print("sudo gdb " + self.app_bin +
1542 " -ex 'target remote localhost:{port}'"
1543 .format(port=self.testcase.gdbserver_port))
1544 print("Now is the time to attach gdb by running the above "
1545 "command, set up breakpoints etc., then resume from "
1546 "within gdb by issuing the 'continue' command")
1547 self.testcase.gdbserver_port += 1
1548 elif self.testcase.debug_gdb:
1549 print("sudo gdb " + self.app_bin +
1550 " -ex 'attach {pid}'".format(pid=self.process.pid))
1551 print("Now is the time to attach gdb by running the above "
1552 "command and set up breakpoints etc., then resume from"
1553 " within gdb by issuing the 'continue' command")
1554 print(single_line_delim)
1555 input("Press ENTER to continue running the testcase...")
1558 executable = self.args[0]
1559 if not os.path.exists(executable) or not os.access(
1560 executable, os.F_OK | os.X_OK):
1561 # Exit code that means some system file did not exist,
1562 # could not be opened, or had some other kind of error.
1563 self.result = os.EX_OSFILE
1564 raise EnvironmentError(
1565 "executable '%s' is not found or executable." % executable)
1566 self.logger.debug("Running executable: '{app}'"
1567 .format(app=' '.join(self.args)))
1568 env = os.environ.copy()
1569 env.update(self.env)
1570 env["CK_LOG_FILE_NAME"] = "-"
1571 self.process = subprocess.Popen(
1572 self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1573 stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1574 self.wait_for_enter()
1575 out, err = self.process.communicate()
1576 self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1577 self.logger.info("Return code is `%s'" % self.process.returncode)
1578 self.logger.info(single_line_delim)
1579 self.logger.info("Executable `{app}' wrote to stdout:"
1580 .format(app=self.app_name))
1581 self.logger.info(single_line_delim)
1582 self.logger.info(out.decode('utf-8'))
1583 self.logger.info(single_line_delim)
1584 self.logger.info("Executable `{app}' wrote to stderr:"
1585 .format(app=self.app_name))
1586 self.logger.info(single_line_delim)
1587 self.logger.info(err.decode('utf-8'))
1588 self.logger.info(single_line_delim)
1589 self.result = self.process.returncode
1592 if __name__ == '__main__':