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_gcov_tests():
221 return BoolEnvironmentVariable("GCOV_TESTS")
224 running_gcov_tests = _running_gcov_tests()
227 def _running_on_centos():
228 os_id = os.getenv("OS_ID", "")
229 return True if "centos" in os_id.lower() else False
232 running_on_centos = _running_on_centos()
235 class KeepAliveReporter(object):
237 Singleton object which reports test start to parent process
242 self.__dict__ = self._shared_state
250 def pipe(self, pipe):
251 if self._pipe is not None:
252 raise Exception("Internal error - pipe should only be set once.")
255 def send_keep_alive(self, test, desc=None):
257 Write current test tmpdir & desc to keep-alive pipe to signal liveness
259 if self.pipe is None:
260 # if not running forked..
264 desc = '%s (%s)' % (desc, unittest.util.strclass(test))
268 self.pipe.send((desc, test.vpp_bin, test.tempdir, test.vpp.pid))
271 class VppTestCase(unittest.TestCase):
272 """This subclass is a base class for VPP test cases that are implemented as
273 classes. It provides methods to create and run test case.
276 extra_vpp_punt_config = []
277 extra_vpp_plugin_config = []
278 vapi_response_timeout = 5
281 def packet_infos(self):
282 """List of packet infos"""
283 return self._packet_infos
286 def get_packet_count_for_if_idx(cls, dst_if_index):
287 """Get the number of packet info for specified destination if index"""
288 if dst_if_index in cls._packet_count_for_dst_if_idx:
289 return cls._packet_count_for_dst_if_idx[dst_if_index]
295 """Return the instance of this testcase"""
296 return cls.test_instance
299 def set_debug_flags(cls, d):
300 cls.gdbserver_port = 7777
301 cls.debug_core = False
302 cls.debug_gdb = False
303 cls.debug_gdbserver = False
304 cls.debug_all = False
309 cls.debug_core = True
310 elif dl == "gdb" or dl == "gdb-all":
312 elif dl == "gdbserver" or dl == "gdbserver-all":
313 cls.debug_gdbserver = True
315 raise Exception("Unrecognized DEBUG option: '%s'" % d)
316 if dl == "gdb-all" or dl == "gdbserver-all":
320 def get_least_used_cpu():
321 cpu_usage_list = [set(range(psutil.cpu_count()))]
322 vpp_processes = [p for p in psutil.process_iter(attrs=['pid', 'name'])
323 if 'vpp_main' == p.info['name']]
324 for vpp_process in vpp_processes:
325 for cpu_usage_set in cpu_usage_list:
327 cpu_num = vpp_process.cpu_num()
328 if cpu_num in cpu_usage_set:
329 cpu_usage_set_index = cpu_usage_list.index(
331 if cpu_usage_set_index == len(cpu_usage_list) - 1:
332 cpu_usage_list.append({cpu_num})
334 cpu_usage_list[cpu_usage_set_index + 1].add(
336 cpu_usage_set.remove(cpu_num)
338 except psutil.NoSuchProcess:
341 for cpu_usage_set in cpu_usage_list:
342 if len(cpu_usage_set) > 0:
343 min_usage_set = cpu_usage_set
346 return random.choice(tuple(min_usage_set))
349 def setUpConstants(cls):
350 """ Set-up the test case class based on environment variables """
351 cls.step = BoolEnvironmentVariable('STEP')
352 d = os.getenv("DEBUG", None)
353 # inverted case to handle '' == True
354 c = os.getenv("CACHE_OUTPUT", "1")
355 cls.cache_vpp_output = False if c.lower() in ("n", "no", "0") else True
356 cls.set_debug_flags(d)
357 cls.vpp_bin = os.getenv('VPP_BIN', "vpp")
358 cls.plugin_path = os.getenv('VPP_PLUGIN_PATH')
359 cls.test_plugin_path = os.getenv('VPP_TEST_PLUGIN_PATH')
360 cls.extern_plugin_path = os.getenv('EXTERN_PLUGINS')
362 if cls.plugin_path is not None:
363 if cls.extern_plugin_path is not None:
364 plugin_path = "%s:%s" % (
365 cls.plugin_path, cls.extern_plugin_path)
367 plugin_path = cls.plugin_path
368 elif cls.extern_plugin_path is not None:
369 plugin_path = cls.extern_plugin_path
371 if cls.step or cls.debug_gdb or cls.debug_gdbserver:
372 debug_cli = "cli-listen localhost:5002"
374 size = os.getenv("COREDUMP_SIZE")
376 coredump_size = "coredump-size %s" % size
377 if coredump_size is None:
378 coredump_size = "coredump-size unlimited"
380 cpu_core_number = cls.get_least_used_cpu()
381 if not hasattr(cls, "worker_config"):
382 cls.worker_config = ""
384 cls.vpp_cmdline = [cls.vpp_bin, "unix",
385 "{", "nodaemon", debug_cli, "full-coredump",
386 coredump_size, "runtime-dir", cls.tempdir, "}",
387 "api-trace", "{", "on", "}", "api-segment", "{",
388 "prefix", cls.shm_prefix, "}", "cpu", "{",
389 "main-core", str(cpu_core_number),
390 cls.worker_config, "}",
391 "physmem", "{", "max-size", "32m", "}",
392 "statseg", "{", "socket-name", cls.stats_sock, "}",
393 "socksvr", "{", "socket-name", cls.api_sock, "}",
395 "{", "plugin", "dpdk_plugin.so", "{", "disable",
396 "}", "plugin", "rdma_plugin.so", "{", "disable",
397 "}", "plugin", "unittest_plugin.so", "{", "enable",
398 "}"] + cls.extra_vpp_plugin_config + ["}", ]
399 if cls.extra_vpp_punt_config is not None:
400 cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
401 if plugin_path is not None:
402 cls.vpp_cmdline.extend(["plugin_path", plugin_path])
403 if cls.test_plugin_path is not None:
404 cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
406 cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
407 cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
410 def wait_for_enter(cls):
411 if cls.debug_gdbserver:
412 print(double_line_delim)
413 print("Spawned GDB server with PID: %d" % cls.vpp.pid)
415 print(double_line_delim)
416 print("Spawned VPP with PID: %d" % cls.vpp.pid)
418 cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
420 print(single_line_delim)
421 print("You can debug VPP using:")
422 if cls.debug_gdbserver:
423 print("sudo gdb " + cls.vpp_bin +
424 " -ex 'target remote localhost:{port}'"
425 .format(port=cls.gdbserver_port))
426 print("Now is the time to attach gdb by running the above "
427 "command, set up breakpoints etc., then resume VPP from "
428 "within gdb by issuing the 'continue' command")
429 cls.gdbserver_port += 1
431 print("sudo gdb " + cls.vpp_bin + " -ex 'attach %s'" % cls.vpp.pid)
432 print("Now is the time to attach gdb by running the above "
433 "command and set up breakpoints etc., then resume VPP from"
434 " within gdb by issuing the 'continue' command")
435 print(single_line_delim)
436 input("Press ENTER to continue running the testcase...")
440 cmdline = cls.vpp_cmdline
442 if cls.debug_gdbserver:
443 gdbserver = '/usr/bin/gdbserver'
444 if not os.path.isfile(gdbserver) or \
445 not os.access(gdbserver, os.X_OK):
446 raise Exception("gdbserver binary '%s' does not exist or is "
447 "not executable" % gdbserver)
449 cmdline = [gdbserver, 'localhost:{port}'
450 .format(port=cls.gdbserver_port)] + cls.vpp_cmdline
451 cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
454 cls.vpp = subprocess.Popen(cmdline,
455 stdout=subprocess.PIPE,
456 stderr=subprocess.PIPE)
457 except subprocess.CalledProcessError as e:
458 cls.logger.critical("Subprocess returned with non-0 return code: ("
462 cls.logger.critical("Subprocess returned with OS error: "
463 "(%s) %s", e.errno, e.strerror)
465 except Exception as e:
466 cls.logger.exception("Subprocess returned unexpected from "
473 def wait_for_coredump(cls):
474 corefile = cls.tempdir + "/core"
475 if os.path.isfile(corefile):
476 cls.logger.error("Waiting for coredump to complete: %s", corefile)
477 curr_size = os.path.getsize(corefile)
478 deadline = time.time() + 60
480 while time.time() < deadline:
483 curr_size = os.path.getsize(corefile)
484 if size == curr_size:
488 cls.logger.error("Timed out waiting for coredump to complete:"
491 cls.logger.error("Coredump complete: %s, size %d",
497 Perform class setup before running the testcase
498 Remove shared memory files, start vpp and connect the vpp-api
500 super(VppTestCase, cls).setUpClass()
501 gc.collect() # run garbage collection first
502 cls.logger = get_logger(cls.__name__)
503 seed = os.environ["RND_SEED"]
505 if hasattr(cls, 'parallel_handler'):
506 cls.logger.addHandler(cls.parallel_handler)
507 cls.logger.propagate = False
509 cls.tempdir = tempfile.mkdtemp(
510 prefix='vpp-unittest-%s-' % cls.__name__)
511 cls.stats_sock = "%s/stats.sock" % cls.tempdir
512 cls.api_sock = "%s/api.sock" % cls.tempdir
513 cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
514 cls.file_handler.setFormatter(
515 Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
517 cls.file_handler.setLevel(DEBUG)
518 cls.logger.addHandler(cls.file_handler)
519 cls.logger.debug("--- setUpClass() for %s called ---" %
521 cls.shm_prefix = os.path.basename(cls.tempdir)
522 os.chdir(cls.tempdir)
523 cls.logger.info("Temporary dir is %s, shm prefix is %s",
524 cls.tempdir, cls.shm_prefix)
525 cls.logger.debug("Random seed is %s" % seed)
527 cls.reset_packet_infos()
531 cls.registry = VppObjectRegistry()
532 cls.vpp_startup_failed = False
533 cls.reporter = KeepAliveReporter()
534 # need to catch exceptions here because if we raise, then the cleanup
535 # doesn't get called and we might end with a zombie vpp
538 cls.reporter.send_keep_alive(cls, 'setUpClass')
539 VppTestResult.current_test_case_info = TestCaseInfo(
540 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
541 cls.vpp_stdout_deque = deque()
542 cls.vpp_stderr_deque = deque()
543 cls.pump_thread_stop_flag = Event()
544 cls.pump_thread_wakeup_pipe = os.pipe()
545 cls.pump_thread = Thread(target=pump_output, args=(cls,))
546 cls.pump_thread.daemon = True
547 cls.pump_thread.start()
548 if cls.debug_gdb or cls.debug_gdbserver:
549 cls.vapi_response_timeout = 0
550 cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
551 cls.vapi_response_timeout)
553 hook = hookmodule.StepHook(cls)
555 hook = hookmodule.PollHook(cls)
556 cls.vapi.register_hook(hook)
557 cls.statistics = VPPStats(socketname=cls.stats_sock)
561 cls.vpp_startup_failed = True
563 "VPP died shortly after startup, check the"
564 " output to standard error for possible cause")
568 except vpp_papi.VPPIOError as e:
569 cls.logger.debug("Exception connecting to vapi: %s" % e)
570 cls.vapi.disconnect()
572 if cls.debug_gdbserver:
573 print(colorize("You're running VPP inside gdbserver but "
574 "VPP-API connection failed, did you forget "
575 "to 'continue' VPP from within gdb?", RED))
577 except Exception as e:
578 cls.logger.debug("Exception connecting to VPP: %s" % e)
584 def _debug_quit(cls):
585 if (cls.debug_gdbserver or cls.debug_gdb):
589 if cls.vpp.returncode is None:
591 print(double_line_delim)
592 print("VPP or GDB server is still running")
593 print(single_line_delim)
594 input("When done debugging, press ENTER to kill the "
595 "process and finish running the testcase...")
596 except AttributeError:
602 Disconnect vpp-api, kill vpp and cleanup shared memory files
606 # first signal that we want to stop the pump thread, then wake it up
607 if hasattr(cls, 'pump_thread_stop_flag'):
608 cls.pump_thread_stop_flag.set()
609 if hasattr(cls, 'pump_thread_wakeup_pipe'):
610 os.write(cls.pump_thread_wakeup_pipe[1], b'ding dong wake up')
611 if hasattr(cls, 'pump_thread'):
612 cls.logger.debug("Waiting for pump thread to stop")
613 cls.pump_thread.join()
614 if hasattr(cls, 'vpp_stderr_reader_thread'):
615 cls.logger.debug("Waiting for stderr pump to stop")
616 cls.vpp_stderr_reader_thread.join()
618 if hasattr(cls, 'vpp'):
619 if hasattr(cls, 'vapi'):
620 cls.logger.debug(cls.vapi.vpp.get_stats())
621 cls.logger.debug("Disconnecting class vapi client on %s",
623 cls.vapi.disconnect()
624 cls.logger.debug("Deleting class vapi attribute on %s",
628 if cls.vpp.returncode is None:
629 cls.wait_for_coredump()
630 cls.logger.debug("Sending TERM to vpp")
632 cls.logger.debug("Waiting for vpp to die")
633 cls.vpp.communicate()
634 cls.logger.debug("Deleting class vpp attribute on %s",
638 if cls.vpp_startup_failed:
639 stdout_log = cls.logger.info
640 stderr_log = cls.logger.critical
642 stdout_log = cls.logger.info
643 stderr_log = cls.logger.info
645 if hasattr(cls, 'vpp_stdout_deque'):
646 stdout_log(single_line_delim)
647 stdout_log('VPP output to stdout while running %s:', cls.__name__)
648 stdout_log(single_line_delim)
649 vpp_output = "".join(cls.vpp_stdout_deque)
650 with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
652 stdout_log('\n%s', vpp_output)
653 stdout_log(single_line_delim)
655 if hasattr(cls, 'vpp_stderr_deque'):
656 stderr_log(single_line_delim)
657 stderr_log('VPP output to stderr while running %s:', cls.__name__)
658 stderr_log(single_line_delim)
659 vpp_output = "".join(cls.vpp_stderr_deque)
660 with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
662 stderr_log('\n%s', vpp_output)
663 stderr_log(single_line_delim)
666 def tearDownClass(cls):
667 """ Perform final cleanup after running all tests in this test-case """
668 cls.logger.debug("--- tearDownClass() for %s called ---" %
670 cls.reporter.send_keep_alive(cls, 'tearDownClass')
672 cls.file_handler.close()
673 cls.reset_packet_infos()
675 debug_internal.on_tear_down_class(cls)
677 def show_commands_at_teardown(self):
678 """ Allow subclass specific teardown logging additions."""
679 self.logger.info("--- No test specific show commands provided. ---")
682 """ Show various debug prints after each test """
683 self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
684 (self.__class__.__name__, self._testMethodName,
685 self._testMethodDoc))
688 if not self.vpp_dead:
689 self.logger.debug(self.vapi.cli("show trace max 1000"))
690 self.logger.info(self.vapi.ppcli("show interface"))
691 self.logger.info(self.vapi.ppcli("show hardware"))
692 self.logger.info(self.statistics.set_errors_str())
693 self.logger.info(self.vapi.ppcli("show run"))
694 self.logger.info(self.vapi.ppcli("show log"))
695 self.logger.info(self.vapi.ppcli("show bihash"))
696 self.logger.info("Logging testcase specific show commands.")
697 self.show_commands_at_teardown()
698 self.registry.remove_vpp_config(self.logger)
699 # Save/Dump VPP api trace log
700 m = self._testMethodName
701 api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
702 tmp_api_trace = "/tmp/%s" % api_trace
703 vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
704 self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
705 self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
707 os.rename(tmp_api_trace, vpp_api_trace_log)
708 self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
710 except VppTransportShmemIOError:
711 self.logger.debug("VppTransportShmemIOError: Vpp dead. "
712 "Cannot log show commands.")
715 self.registry.unregister_all(self.logger)
718 """ Clear trace before running each test"""
719 super(VppTestCase, self).setUp()
720 self.reporter.send_keep_alive(self)
723 raise VppDiedError(rv=None, testcase=self.__class__.__name__,
724 method_name=self._testMethodName)
725 self.sleep(.1, "during setUp")
726 self.vpp_stdout_deque.append(
727 "--- test setUp() for %s.%s(%s) starts here ---\n" %
728 (self.__class__.__name__, self._testMethodName,
729 self._testMethodDoc))
730 self.vpp_stderr_deque.append(
731 "--- test setUp() for %s.%s(%s) starts here ---\n" %
732 (self.__class__.__name__, self._testMethodName,
733 self._testMethodDoc))
734 self.vapi.cli("clear trace")
735 # store the test instance inside the test class - so that objects
736 # holding the class can access instance methods (like assertEqual)
737 type(self).test_instance = self
740 def pg_enable_capture(cls, interfaces=None):
742 Enable capture on packet-generator interfaces
744 :param interfaces: iterable interface indexes (if None,
745 use self.pg_interfaces)
748 if interfaces is None:
749 interfaces = cls.pg_interfaces
754 def register_capture(cls, cap_name):
755 """ Register a capture in the testclass """
756 # add to the list of captures with current timestamp
757 cls._captures.append((time.time(), cap_name))
760 def get_vpp_time(cls):
761 return float(cls.vapi.cli('show clock').replace("Time now ", ""))
764 def sleep_on_vpp_time(cls, sec):
765 """ Sleep according to time in VPP world """
766 # On a busy system with many processes
767 # we might end up with VPP time being slower than real world
768 # So take that into account when waiting for VPP to do something
769 start_time = cls.get_vpp_time()
770 while cls.get_vpp_time() - start_time < sec:
775 """ Enable the PG, wait till it is done, then clean up """
776 cls.vapi.cli("trace add pg-input 1000")
777 cls.vapi.cli('packet-generator enable')
778 # PG, when starts, runs to completion -
779 # so let's avoid a race condition,
780 # and wait a little till it's done.
781 # Then clean it up - and then be gone.
782 deadline = time.time() + 300
783 while cls.vapi.cli('show packet-generator').find("Yes") != -1:
784 cls.sleep(0.01) # yield
785 if time.time() > deadline:
786 cls.logger.error("Timeout waiting for pg to stop")
788 for stamp, cap_name in cls._captures:
789 cls.vapi.cli('packet-generator delete %s' % cap_name)
793 def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
795 Create packet-generator interfaces.
797 :param interfaces: iterable indexes of the interfaces.
798 :returns: List of created interfaces.
803 intf = VppPGInterface(cls, i, gso, gso_size)
804 setattr(cls, intf.name, intf)
806 cls.pg_interfaces = result
810 def create_loopback_interfaces(cls, count):
812 Create loopback interfaces.
814 :param count: number of interfaces created.
815 :returns: List of created interfaces.
817 result = [VppLoInterface(cls) for i in range(count)]
819 setattr(cls, intf.name, intf)
820 cls.lo_interfaces = result
824 def create_bvi_interfaces(cls, count):
826 Create BVI interfaces.
828 :param count: number of interfaces created.
829 :returns: List of created interfaces.
831 result = [VppBviInterface(cls) for i in range(count)]
833 setattr(cls, intf.name, intf)
834 cls.bvi_interfaces = result
838 def extend_packet(packet, size, padding=' '):
840 Extend packet to given size by padding with spaces or custom padding
841 NOTE: Currently works only when Raw layer is present.
843 :param packet: packet
844 :param size: target size
845 :param padding: padding used to extend the payload
848 packet_len = len(packet) + 4
849 extend = size - packet_len
851 num = (extend // len(padding)) + 1
852 packet[Raw].load += (padding * num)[:extend].encode("ascii")
855 def reset_packet_infos(cls):
856 """ Reset the list of packet info objects and packet counts to zero """
857 cls._packet_infos = {}
858 cls._packet_count_for_dst_if_idx = {}
861 def create_packet_info(cls, src_if, dst_if):
863 Create packet info object containing the source and destination indexes
864 and add it to the testcase's packet info list
866 :param VppInterface src_if: source interface
867 :param VppInterface dst_if: destination interface
869 :returns: _PacketInfo object
873 info.index = len(cls._packet_infos)
874 info.src = src_if.sw_if_index
875 info.dst = dst_if.sw_if_index
876 if isinstance(dst_if, VppSubInterface):
877 dst_idx = dst_if.parent.sw_if_index
879 dst_idx = dst_if.sw_if_index
880 if dst_idx in cls._packet_count_for_dst_if_idx:
881 cls._packet_count_for_dst_if_idx[dst_idx] += 1
883 cls._packet_count_for_dst_if_idx[dst_idx] = 1
884 cls._packet_infos[info.index] = info
888 def info_to_payload(info):
890 Convert _PacketInfo object to packet payload
892 :param info: _PacketInfo object
894 :returns: string containing serialized data from packet info
896 return "%d %d %d %d %d" % (info.index, info.src, info.dst,
900 def payload_to_info(payload, payload_field='load'):
902 Convert packet payload to _PacketInfo object
904 :param payload: packet payload
905 :type payload: <class 'scapy.packet.Raw'>
906 :param payload_field: packet fieldname of payload "load" for
907 <class 'scapy.packet.Raw'>
908 :type payload_field: str
909 :returns: _PacketInfo object containing de-serialized data from payload
912 numbers = getattr(payload, payload_field).split()
914 info.index = int(numbers[0])
915 info.src = int(numbers[1])
916 info.dst = int(numbers[2])
917 info.ip = int(numbers[3])
918 info.proto = int(numbers[4])
921 def get_next_packet_info(self, info):
923 Iterate over the packet info list stored in the testcase
924 Start iteration with first element if info is None
925 Continue based on index in info if info is specified
927 :param info: info or None
928 :returns: next info in list or None if no more infos
933 next_index = info.index + 1
934 if next_index == len(self._packet_infos):
937 return self._packet_infos[next_index]
939 def get_next_packet_info_for_interface(self, src_index, info):
941 Search the packet info list for the next packet info with same source
944 :param src_index: source interface index to search for
945 :param info: packet info - where to start the search
946 :returns: packet info or None
950 info = self.get_next_packet_info(info)
953 if info.src == src_index:
956 def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
958 Search the packet info list for the next packet info with same source
959 and destination interface indexes
961 :param src_index: source interface index to search for
962 :param dst_index: destination interface index to search for
963 :param info: packet info - where to start the search
964 :returns: packet info or None
968 info = self.get_next_packet_info_for_interface(src_index, info)
971 if info.dst == dst_index:
974 def assert_equal(self, real_value, expected_value, name_or_class=None):
975 if name_or_class is None:
976 self.assertEqual(real_value, expected_value)
979 msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
980 msg = msg % (getdoc(name_or_class).strip(),
981 real_value, str(name_or_class(real_value)),
982 expected_value, str(name_or_class(expected_value)))
984 msg = "Invalid %s: %s does not match expected value %s" % (
985 name_or_class, real_value, expected_value)
987 self.assertEqual(real_value, expected_value, msg)
989 def assert_in_range(self,
997 msg = "Invalid %s: %s out of range <%s,%s>" % (
998 name, real_value, expected_min, expected_max)
999 self.assertTrue(expected_min <= real_value <= expected_max, msg)
1001 def assert_packet_checksums_valid(self, packet,
1002 ignore_zero_udp_checksums=True):
1003 received = packet.__class__(scapy.compat.raw(packet))
1004 udp_layers = ['UDP', 'UDPerror']
1005 checksum_fields = ['cksum', 'chksum']
1008 temp = received.__class__(scapy.compat.raw(received))
1010 layer = temp.getlayer(counter)
1012 layer = layer.copy()
1013 layer.remove_payload()
1014 for cf in checksum_fields:
1015 if hasattr(layer, cf):
1016 if ignore_zero_udp_checksums and \
1017 0 == getattr(layer, cf) and \
1018 layer.name in udp_layers:
1020 delattr(temp.getlayer(counter), cf)
1021 checksums.append((counter, cf))
1024 counter = counter + 1
1025 if 0 == len(checksums):
1027 temp = temp.__class__(scapy.compat.raw(temp))
1028 for layer, cf in checksums:
1029 calc_sum = getattr(temp[layer], cf)
1031 getattr(received[layer], cf), calc_sum,
1032 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1034 "Checksum field `%s` on `%s` layer has correct value `%s`" %
1035 (cf, temp[layer].name, calc_sum))
1037 def assert_checksum_valid(self, received_packet, layer,
1038 field_name='chksum',
1039 ignore_zero_checksum=False):
1040 """ Check checksum of received packet on given layer """
1041 received_packet_checksum = getattr(received_packet[layer], field_name)
1042 if ignore_zero_checksum and 0 == received_packet_checksum:
1044 recalculated = received_packet.__class__(
1045 scapy.compat.raw(received_packet))
1046 delattr(recalculated[layer], field_name)
1047 recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1048 self.assert_equal(received_packet_checksum,
1049 getattr(recalculated[layer], field_name),
1050 "packet checksum on layer: %s" % layer)
1052 def assert_ip_checksum_valid(self, received_packet,
1053 ignore_zero_checksum=False):
1054 self.assert_checksum_valid(received_packet, 'IP',
1055 ignore_zero_checksum=ignore_zero_checksum)
1057 def assert_tcp_checksum_valid(self, received_packet,
1058 ignore_zero_checksum=False):
1059 self.assert_checksum_valid(received_packet, 'TCP',
1060 ignore_zero_checksum=ignore_zero_checksum)
1062 def assert_udp_checksum_valid(self, received_packet,
1063 ignore_zero_checksum=True):
1064 self.assert_checksum_valid(received_packet, 'UDP',
1065 ignore_zero_checksum=ignore_zero_checksum)
1067 def assert_embedded_icmp_checksum_valid(self, received_packet):
1068 if received_packet.haslayer(IPerror):
1069 self.assert_checksum_valid(received_packet, 'IPerror')
1070 if received_packet.haslayer(TCPerror):
1071 self.assert_checksum_valid(received_packet, 'TCPerror')
1072 if received_packet.haslayer(UDPerror):
1073 self.assert_checksum_valid(received_packet, 'UDPerror',
1074 ignore_zero_checksum=True)
1075 if received_packet.haslayer(ICMPerror):
1076 self.assert_checksum_valid(received_packet, 'ICMPerror')
1078 def assert_icmp_checksum_valid(self, received_packet):
1079 self.assert_checksum_valid(received_packet, 'ICMP')
1080 self.assert_embedded_icmp_checksum_valid(received_packet)
1082 def assert_icmpv6_checksum_valid(self, pkt):
1083 if pkt.haslayer(ICMPv6DestUnreach):
1084 self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1085 self.assert_embedded_icmp_checksum_valid(pkt)
1086 if pkt.haslayer(ICMPv6EchoRequest):
1087 self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1088 if pkt.haslayer(ICMPv6EchoReply):
1089 self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1091 def get_packet_counter(self, counter):
1092 if counter.startswith("/"):
1093 counter_value = self.statistics.get_counter(counter)
1095 counters = self.vapi.cli("sh errors").split('\n')
1097 for i in range(1, len(counters) - 1):
1098 results = counters[i].split()
1099 if results[1] == counter:
1100 counter_value = int(results[0])
1102 return counter_value
1104 def assert_packet_counter_equal(self, counter, expected_value):
1105 counter_value = self.get_packet_counter(counter)
1106 self.assert_equal(counter_value, expected_value,
1107 "packet counter `%s'" % counter)
1109 def assert_error_counter_equal(self, counter, expected_value):
1110 counter_value = self.statistics.get_err_counter(counter)
1111 self.assert_equal(counter_value, expected_value,
1112 "error counter `%s'" % counter)
1115 def sleep(cls, timeout, remark=None):
1117 # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1118 # * by Guido, only the main thread can be interrupted.
1120 # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892 # noqa
1123 if hasattr(os, 'sched_yield'):
1129 if hasattr(cls, 'logger'):
1130 cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1131 before = time.time()
1134 if hasattr(cls, 'logger') and after - before > 2 * timeout:
1135 cls.logger.error("unexpected self.sleep() result - "
1136 "slept for %es instead of ~%es!",
1137 after - before, timeout)
1138 if hasattr(cls, 'logger'):
1140 "Finished sleep (%s) - slept %es (wanted %es)",
1141 remark, after - before, timeout)
1143 def pg_send(self, intf, pkts, worker=None):
1144 self.vapi.cli("clear trace")
1145 intf.add_stream(pkts, worker=worker)
1146 self.pg_enable_capture(self.pg_interfaces)
1149 def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1150 self.pg_send(intf, pkts)
1153 for i in self.pg_interfaces:
1154 i.get_capture(0, timeout=timeout)
1155 i.assert_nothing_captured(remark=remark)
1158 def send_and_expect(self, intf, pkts, output, n_rx=None, worker=None):
1161 self.pg_send(intf, pkts, worker=worker)
1162 rx = output.get_capture(n_rx)
1165 def send_and_expect_only(self, intf, pkts, output, timeout=None):
1166 self.pg_send(intf, pkts)
1167 rx = output.get_capture(len(pkts))
1171 for i in self.pg_interfaces:
1172 if i not in outputs:
1173 i.get_capture(0, timeout=timeout)
1174 i.assert_nothing_captured()
1180 def get_testcase_doc_name(test):
1181 return getdoc(test.__class__).splitlines()[0]
1184 def get_test_description(descriptions, test):
1185 short_description = test.shortDescription()
1186 if descriptions and short_description:
1187 return short_description
1192 class TestCaseInfo(object):
1193 def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1194 self.logger = logger
1195 self.tempdir = tempdir
1196 self.vpp_pid = vpp_pid
1197 self.vpp_bin_path = vpp_bin_path
1198 self.core_crash_test = None
1201 class VppTestResult(unittest.TestResult):
1203 @property result_string
1204 String variable to store the test case result string.
1206 List variable containing 2-tuples of TestCase instances and strings
1207 holding formatted tracebacks. Each tuple represents a test which
1208 raised an unexpected exception.
1210 List variable containing 2-tuples of TestCase instances and strings
1211 holding formatted tracebacks. Each tuple represents a test where
1212 a failure was explicitly signalled using the TestCase.assert*()
1216 failed_test_cases_info = set()
1217 core_crash_test_cases_info = set()
1218 current_test_case_info = None
1220 def __init__(self, stream=None, descriptions=None, verbosity=None,
1223 :param stream File descriptor to store where to report test results.
1224 Set to the standard error stream by default.
1225 :param descriptions Boolean variable to store information if to use
1226 test case descriptions.
1227 :param verbosity Integer variable to store required verbosity level.
1229 super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1230 self.stream = stream
1231 self.descriptions = descriptions
1232 self.verbosity = verbosity
1233 self.result_string = None
1234 self.runner = runner
1236 def addSuccess(self, test):
1238 Record a test succeeded result
1243 if self.current_test_case_info:
1244 self.current_test_case_info.logger.debug(
1245 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1246 test._testMethodName,
1247 test._testMethodDoc))
1248 unittest.TestResult.addSuccess(self, test)
1249 self.result_string = colorize("OK", GREEN)
1251 self.send_result_through_pipe(test, PASS)
1253 def addSkip(self, test, reason):
1255 Record a test skipped.
1261 if self.current_test_case_info:
1262 self.current_test_case_info.logger.debug(
1263 "--- addSkip() %s.%s(%s) called, reason is %s" %
1264 (test.__class__.__name__, test._testMethodName,
1265 test._testMethodDoc, reason))
1266 unittest.TestResult.addSkip(self, test, reason)
1267 self.result_string = colorize("SKIP", YELLOW)
1269 self.send_result_through_pipe(test, SKIP)
1271 def symlink_failed(self):
1272 if self.current_test_case_info:
1274 failed_dir = os.getenv('FAILED_DIR')
1275 link_path = os.path.join(
1278 os.path.basename(self.current_test_case_info.tempdir))
1279 if self.current_test_case_info.logger:
1280 self.current_test_case_info.logger.debug(
1281 "creating a link to the failed test")
1282 self.current_test_case_info.logger.debug(
1283 "os.symlink(%s, %s)" %
1284 (self.current_test_case_info.tempdir, link_path))
1285 if os.path.exists(link_path):
1286 if self.current_test_case_info.logger:
1287 self.current_test_case_info.logger.debug(
1288 'symlink already exists')
1290 os.symlink(self.current_test_case_info.tempdir, link_path)
1292 except Exception as e:
1293 if self.current_test_case_info.logger:
1294 self.current_test_case_info.logger.error(e)
1296 def send_result_through_pipe(self, test, result):
1297 if hasattr(self, 'test_framework_result_pipe'):
1298 pipe = self.test_framework_result_pipe
1300 pipe.send((test.id(), result))
1302 def log_error(self, test, err, fn_name):
1303 if self.current_test_case_info:
1304 if isinstance(test, unittest.suite._ErrorHolder):
1305 test_name = test.description
1307 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1308 test._testMethodName,
1309 test._testMethodDoc)
1310 self.current_test_case_info.logger.debug(
1311 "--- %s() %s called, err is %s" %
1312 (fn_name, test_name, err))
1313 self.current_test_case_info.logger.debug(
1314 "formatted exception is:\n%s" %
1315 "".join(format_exception(*err)))
1317 def add_error(self, test, err, unittest_fn, error_type):
1318 if error_type == FAIL:
1319 self.log_error(test, err, 'addFailure')
1320 error_type_str = colorize("FAIL", RED)
1321 elif error_type == ERROR:
1322 self.log_error(test, err, 'addError')
1323 error_type_str = colorize("ERROR", RED)
1325 raise Exception('Error type %s cannot be used to record an '
1326 'error or a failure' % error_type)
1328 unittest_fn(self, test, err)
1329 if self.current_test_case_info:
1330 self.result_string = "%s [ temp dir used by test case: %s ]" % \
1332 self.current_test_case_info.tempdir)
1333 self.symlink_failed()
1334 self.failed_test_cases_info.add(self.current_test_case_info)
1335 if is_core_present(self.current_test_case_info.tempdir):
1336 if not self.current_test_case_info.core_crash_test:
1337 if isinstance(test, unittest.suite._ErrorHolder):
1338 test_name = str(test)
1340 test_name = "'{!s}' ({!s})".format(
1341 get_testcase_doc_name(test), test.id())
1342 self.current_test_case_info.core_crash_test = test_name
1343 self.core_crash_test_cases_info.add(
1344 self.current_test_case_info)
1346 self.result_string = '%s [no temp dir]' % error_type_str
1348 self.send_result_through_pipe(test, error_type)
1350 def addFailure(self, test, err):
1352 Record a test failed result
1355 :param err: error message
1358 self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1360 def addError(self, test, err):
1362 Record a test error result
1365 :param err: error message
1368 self.add_error(test, err, unittest.TestResult.addError, ERROR)
1370 def getDescription(self, test):
1372 Get test description
1375 :returns: test description
1378 return get_test_description(self.descriptions, test)
1380 def startTest(self, test):
1388 def print_header(test):
1389 if not hasattr(test.__class__, '_header_printed'):
1390 print(double_line_delim)
1391 print(colorize(getdoc(test).splitlines()[0], GREEN))
1392 print(double_line_delim)
1393 test.__class__._header_printed = True
1396 self.start_test = time.time()
1397 unittest.TestResult.startTest(self, test)
1398 if self.verbosity > 0:
1399 self.stream.writeln(
1400 "Starting " + self.getDescription(test) + " ...")
1401 self.stream.writeln(single_line_delim)
1403 def stopTest(self, test):
1405 Called when the given test has been run
1410 unittest.TestResult.stopTest(self, test)
1412 if self.verbosity > 0:
1413 self.stream.writeln(single_line_delim)
1414 self.stream.writeln("%-73s%s" % (self.getDescription(test),
1415 self.result_string))
1416 self.stream.writeln(single_line_delim)
1418 self.stream.writeln("%-68s %4.2f %s" %
1419 (self.getDescription(test),
1420 time.time() - self.start_test,
1421 self.result_string))
1423 self.send_result_through_pipe(test, TEST_RUN)
1425 def printErrors(self):
1427 Print errors from running the test case
1429 if len(self.errors) > 0 or len(self.failures) > 0:
1430 self.stream.writeln()
1431 self.printErrorList('ERROR', self.errors)
1432 self.printErrorList('FAIL', self.failures)
1434 # ^^ that is the last output from unittest before summary
1435 if not self.runner.print_summary:
1436 devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1437 self.stream = devnull
1438 self.runner.stream = devnull
1440 def printErrorList(self, flavour, errors):
1442 Print error list to the output stream together with error type
1443 and test case description.
1445 :param flavour: error type
1446 :param errors: iterable errors
1449 for test, err in errors:
1450 self.stream.writeln(double_line_delim)
1451 self.stream.writeln("%s: %s" %
1452 (flavour, self.getDescription(test)))
1453 self.stream.writeln(single_line_delim)
1454 self.stream.writeln("%s" % err)
1457 class VppTestRunner(unittest.TextTestRunner):
1459 A basic test runner implementation which prints results to standard error.
1463 def resultclass(self):
1464 """Class maintaining the results of the tests"""
1465 return VppTestResult
1467 def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1468 result_pipe=None, failfast=False, buffer=False,
1469 resultclass=None, print_summary=True, **kwargs):
1470 # ignore stream setting here, use hard-coded stdout to be in sync
1471 # with prints from VppTestCase methods ...
1472 super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1473 verbosity, failfast, buffer,
1474 resultclass, **kwargs)
1475 KeepAliveReporter.pipe = keep_alive_pipe
1477 self.orig_stream = self.stream
1478 self.resultclass.test_framework_result_pipe = result_pipe
1480 self.print_summary = print_summary
1482 def _makeResult(self):
1483 return self.resultclass(self.stream,
1488 def run(self, test):
1495 faulthandler.enable() # emit stack trace to stderr if killed by signal
1497 result = super(VppTestRunner, self).run(test)
1498 if not self.print_summary:
1499 self.stream = self.orig_stream
1500 result.stream = self.orig_stream
1504 class Worker(Thread):
1505 def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1506 super(Worker, self).__init__(*args, **kwargs)
1507 self.logger = logger
1508 self.args = executable_args
1509 if hasattr(self, 'testcase') and self.testcase.debug_all:
1510 if self.testcase.debug_gdbserver:
1511 self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1512 .format(port=self.testcase.gdbserver_port)] + args
1513 elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1514 self.args.append(self.wait_for_gdb)
1515 self.app_bin = executable_args[0]
1516 self.app_name = os.path.basename(self.app_bin)
1517 if hasattr(self, 'role'):
1518 self.app_name += ' {role}'.format(role=self.role)
1521 env = {} if env is None else env
1522 self.env = copy.deepcopy(env)
1524 def wait_for_enter(self):
1525 if not hasattr(self, 'testcase'):
1527 if self.testcase.debug_all and self.testcase.debug_gdbserver:
1529 print(double_line_delim)
1530 print("Spawned GDB Server for '{app}' with PID: {pid}"
1531 .format(app=self.app_name, pid=self.process.pid))
1532 elif self.testcase.debug_all and self.testcase.debug_gdb:
1534 print(double_line_delim)
1535 print("Spawned '{app}' with PID: {pid}"
1536 .format(app=self.app_name, pid=self.process.pid))
1539 print(single_line_delim)
1540 print("You can debug '{app}' using:".format(app=self.app_name))
1541 if self.testcase.debug_gdbserver:
1542 print("sudo gdb " + self.app_bin +
1543 " -ex 'target remote localhost:{port}'"
1544 .format(port=self.testcase.gdbserver_port))
1545 print("Now is the time to attach gdb by running the above "
1546 "command, set up breakpoints etc., then resume from "
1547 "within gdb by issuing the 'continue' command")
1548 self.testcase.gdbserver_port += 1
1549 elif self.testcase.debug_gdb:
1550 print("sudo gdb " + self.app_bin +
1551 " -ex 'attach {pid}'".format(pid=self.process.pid))
1552 print("Now is the time to attach gdb by running the above "
1553 "command and set up breakpoints etc., then resume from"
1554 " within gdb by issuing the 'continue' command")
1555 print(single_line_delim)
1556 input("Press ENTER to continue running the testcase...")
1559 executable = self.args[0]
1560 if not os.path.exists(executable) or not os.access(
1561 executable, os.F_OK | os.X_OK):
1562 # Exit code that means some system file did not exist,
1563 # could not be opened, or had some other kind of error.
1564 self.result = os.EX_OSFILE
1565 raise EnvironmentError(
1566 "executable '%s' is not found or executable." % executable)
1567 self.logger.debug("Running executable: '{app}'"
1568 .format(app=' '.join(self.args)))
1569 env = os.environ.copy()
1570 env.update(self.env)
1571 env["CK_LOG_FILE_NAME"] = "-"
1572 self.process = subprocess.Popen(
1573 self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1574 stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1575 self.wait_for_enter()
1576 out, err = self.process.communicate()
1577 self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1578 self.logger.info("Return code is `%s'" % self.process.returncode)
1579 self.logger.info(single_line_delim)
1580 self.logger.info("Executable `{app}' wrote to stdout:"
1581 .format(app=self.app_name))
1582 self.logger.info(single_line_delim)
1583 self.logger.info(out.decode('utf-8'))
1584 self.logger.info(single_line_delim)
1585 self.logger.info("Executable `{app}' wrote to stderr:"
1586 .format(app=self.app_name))
1587 self.logger.info(single_line_delim)
1588 self.logger.info(err.decode('utf-8'))
1589 self.logger.info(single_line_delim)
1590 self.result = self.process.returncode
1593 if __name__ == '__main__':