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 "physmem", "{", "max-size", "32m", "}",
385 "statseg", "{", "socket-name", cls.stats_sock, "}",
386 "socksvr", "{", "socket-name", cls.api_sock, "}",
388 "{", "plugin", "dpdk_plugin.so", "{", "disable",
389 "}", "plugin", "rdma_plugin.so", "{", "disable",
390 "}", "plugin", "unittest_plugin.so", "{", "enable",
391 "}"] + cls.extra_vpp_plugin_config + ["}", ]
392 if cls.extra_vpp_punt_config is not None:
393 cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
394 if plugin_path is not None:
395 cls.vpp_cmdline.extend(["plugin_path", plugin_path])
396 if cls.test_plugin_path is not None:
397 cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
399 cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
400 cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
403 def wait_for_enter(cls):
404 if cls.debug_gdbserver:
405 print(double_line_delim)
406 print("Spawned GDB server with PID: %d" % cls.vpp.pid)
408 print(double_line_delim)
409 print("Spawned VPP with PID: %d" % cls.vpp.pid)
411 cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
413 print(single_line_delim)
414 print("You can debug VPP using:")
415 if cls.debug_gdbserver:
416 print("sudo gdb " + cls.vpp_bin +
417 " -ex 'target remote localhost:{port}'"
418 .format(port=cls.gdbserver_port))
419 print("Now is the time to attach gdb by running the above "
420 "command, set up breakpoints etc., then resume VPP from "
421 "within gdb by issuing the 'continue' command")
422 cls.gdbserver_port += 1
424 print("sudo gdb " + cls.vpp_bin + " -ex 'attach %s'" % cls.vpp.pid)
425 print("Now is the time to attach gdb by running the above "
426 "command and set up breakpoints etc., then resume VPP from"
427 " within gdb by issuing the 'continue' command")
428 print(single_line_delim)
429 input("Press ENTER to continue running the testcase...")
433 cmdline = cls.vpp_cmdline
435 if cls.debug_gdbserver:
436 gdbserver = '/usr/bin/gdbserver'
437 if not os.path.isfile(gdbserver) or \
438 not os.access(gdbserver, os.X_OK):
439 raise Exception("gdbserver binary '%s' does not exist or is "
440 "not executable" % gdbserver)
442 cmdline = [gdbserver, 'localhost:{port}'
443 .format(port=cls.gdbserver_port)] + cls.vpp_cmdline
444 cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
447 cls.vpp = subprocess.Popen(cmdline,
448 stdout=subprocess.PIPE,
449 stderr=subprocess.PIPE,
451 except subprocess.CalledProcessError as e:
452 cls.logger.critical("Subprocess returned with non-0 return code: ("
456 cls.logger.critical("Subprocess returned with OS error: "
457 "(%s) %s", e.errno, e.strerror)
459 except Exception as e:
460 cls.logger.exception("Subprocess returned unexpected from "
467 def wait_for_coredump(cls):
468 corefile = cls.tempdir + "/core"
469 if os.path.isfile(corefile):
470 cls.logger.error("Waiting for coredump to complete: %s", corefile)
471 curr_size = os.path.getsize(corefile)
472 deadline = time.time() + 60
474 while time.time() < deadline:
477 curr_size = os.path.getsize(corefile)
478 if size == curr_size:
482 cls.logger.error("Timed out waiting for coredump to complete:"
485 cls.logger.error("Coredump complete: %s, size %d",
491 Perform class setup before running the testcase
492 Remove shared memory files, start vpp and connect the vpp-api
494 super(VppTestCase, cls).setUpClass()
495 gc.collect() # run garbage collection first
496 cls.logger = get_logger(cls.__name__)
497 seed = os.environ["RND_SEED"]
499 if hasattr(cls, 'parallel_handler'):
500 cls.logger.addHandler(cls.parallel_handler)
501 cls.logger.propagate = False
503 cls.tempdir = tempfile.mkdtemp(
504 prefix='vpp-unittest-%s-' % cls.__name__)
505 cls.stats_sock = "%s/stats.sock" % cls.tempdir
506 cls.api_sock = "%s/api.sock" % cls.tempdir
507 cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
508 cls.file_handler.setFormatter(
509 Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
511 cls.file_handler.setLevel(DEBUG)
512 cls.logger.addHandler(cls.file_handler)
513 cls.logger.debug("--- setUpClass() for %s called ---" %
515 cls.shm_prefix = os.path.basename(cls.tempdir)
516 os.chdir(cls.tempdir)
517 cls.logger.info("Temporary dir is %s, shm prefix is %s",
518 cls.tempdir, cls.shm_prefix)
519 cls.logger.debug("Random seed is %s" % seed)
521 cls.reset_packet_infos()
525 cls.registry = VppObjectRegistry()
526 cls.vpp_startup_failed = False
527 cls.reporter = KeepAliveReporter()
528 # need to catch exceptions here because if we raise, then the cleanup
529 # doesn't get called and we might end with a zombie vpp
532 cls.reporter.send_keep_alive(cls, 'setUpClass')
533 VppTestResult.current_test_case_info = TestCaseInfo(
534 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
535 cls.vpp_stdout_deque = deque()
536 cls.vpp_stderr_deque = deque()
537 cls.pump_thread_stop_flag = Event()
538 cls.pump_thread_wakeup_pipe = os.pipe()
539 cls.pump_thread = Thread(target=pump_output, args=(cls,))
540 cls.pump_thread.daemon = True
541 cls.pump_thread.start()
542 if cls.debug_gdb or cls.debug_gdbserver:
543 cls.vapi_response_timeout = 0
544 cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
545 cls.vapi_response_timeout)
547 hook = hookmodule.StepHook(cls)
549 hook = hookmodule.PollHook(cls)
550 cls.vapi.register_hook(hook)
551 cls.statistics = VPPStats(socketname=cls.stats_sock)
555 cls.vpp_startup_failed = True
557 "VPP died shortly after startup, check the"
558 " output to standard error for possible cause")
562 except vpp_papi.VPPIOError as e:
563 cls.logger.debug("Exception connecting to vapi: %s" % e)
564 cls.vapi.disconnect()
566 if cls.debug_gdbserver:
567 print(colorize("You're running VPP inside gdbserver but "
568 "VPP-API connection failed, did you forget "
569 "to 'continue' VPP from within gdb?", RED))
571 except Exception as e:
572 cls.logger.debug("Exception connecting to VPP: %s" % e)
578 def _debug_quit(cls):
579 if (cls.debug_gdbserver or cls.debug_gdb):
583 if cls.vpp.returncode is None:
585 print(double_line_delim)
586 print("VPP or GDB server is still running")
587 print(single_line_delim)
588 input("When done debugging, press ENTER to kill the "
589 "process and finish running the testcase...")
590 except AttributeError:
596 Disconnect vpp-api, kill vpp and cleanup shared memory files
600 # first signal that we want to stop the pump thread, then wake it up
601 if hasattr(cls, 'pump_thread_stop_flag'):
602 cls.pump_thread_stop_flag.set()
603 if hasattr(cls, 'pump_thread_wakeup_pipe'):
604 os.write(cls.pump_thread_wakeup_pipe[1], b'ding dong wake up')
605 if hasattr(cls, 'pump_thread'):
606 cls.logger.debug("Waiting for pump thread to stop")
607 cls.pump_thread.join()
608 if hasattr(cls, 'vpp_stderr_reader_thread'):
609 cls.logger.debug("Waiting for stderr pump to stop")
610 cls.vpp_stderr_reader_thread.join()
612 if hasattr(cls, 'vpp'):
613 if hasattr(cls, 'vapi'):
614 cls.logger.debug(cls.vapi.vpp.get_stats())
615 cls.logger.debug("Disconnecting class vapi client on %s",
617 cls.vapi.disconnect()
618 cls.logger.debug("Deleting class vapi attribute on %s",
622 if cls.vpp.returncode is None:
623 cls.wait_for_coredump()
624 cls.logger.debug("Sending TERM to vpp")
626 cls.logger.debug("Waiting for vpp to die")
627 cls.vpp.communicate()
628 cls.logger.debug("Deleting class vpp attribute on %s",
632 if cls.vpp_startup_failed:
633 stdout_log = cls.logger.info
634 stderr_log = cls.logger.critical
636 stdout_log = cls.logger.info
637 stderr_log = cls.logger.info
639 if hasattr(cls, 'vpp_stdout_deque'):
640 stdout_log(single_line_delim)
641 stdout_log('VPP output to stdout while running %s:', cls.__name__)
642 stdout_log(single_line_delim)
643 vpp_output = "".join(cls.vpp_stdout_deque)
644 with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
646 stdout_log('\n%s', vpp_output)
647 stdout_log(single_line_delim)
649 if hasattr(cls, 'vpp_stderr_deque'):
650 stderr_log(single_line_delim)
651 stderr_log('VPP output to stderr while running %s:', cls.__name__)
652 stderr_log(single_line_delim)
653 vpp_output = "".join(cls.vpp_stderr_deque)
654 with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
656 stderr_log('\n%s', vpp_output)
657 stderr_log(single_line_delim)
660 def tearDownClass(cls):
661 """ Perform final cleanup after running all tests in this test-case """
662 cls.logger.debug("--- tearDownClass() for %s called ---" %
664 cls.reporter.send_keep_alive(cls, 'tearDownClass')
666 cls.file_handler.close()
667 cls.reset_packet_infos()
669 debug_internal.on_tear_down_class(cls)
671 def show_commands_at_teardown(self):
672 """ Allow subclass specific teardown logging additions."""
673 self.logger.info("--- No test specific show commands provided. ---")
676 """ Show various debug prints after each test """
677 self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
678 (self.__class__.__name__, self._testMethodName,
679 self._testMethodDoc))
682 if not self.vpp_dead:
683 self.logger.debug(self.vapi.cli("show trace max 1000"))
684 self.logger.info(self.vapi.ppcli("show interface"))
685 self.logger.info(self.vapi.ppcli("show hardware"))
686 self.logger.info(self.statistics.set_errors_str())
687 self.logger.info(self.vapi.ppcli("show run"))
688 self.logger.info(self.vapi.ppcli("show log"))
689 self.logger.info(self.vapi.ppcli("show bihash"))
690 self.logger.info("Logging testcase specific show commands.")
691 self.show_commands_at_teardown()
692 self.registry.remove_vpp_config(self.logger)
693 # Save/Dump VPP api trace log
694 m = self._testMethodName
695 api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
696 tmp_api_trace = "/tmp/%s" % api_trace
697 vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
698 self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
699 self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
701 os.rename(tmp_api_trace, vpp_api_trace_log)
702 self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
704 except VppTransportShmemIOError:
705 self.logger.debug("VppTransportShmemIOError: Vpp dead. "
706 "Cannot log show commands.")
709 self.registry.unregister_all(self.logger)
712 """ Clear trace before running each test"""
713 super(VppTestCase, self).setUp()
714 self.reporter.send_keep_alive(self)
717 raise VppDiedError(rv=None, testcase=self.__class__.__name__,
718 method_name=self._testMethodName)
719 self.sleep(.1, "during setUp")
720 self.vpp_stdout_deque.append(
721 "--- test setUp() for %s.%s(%s) starts here ---\n" %
722 (self.__class__.__name__, self._testMethodName,
723 self._testMethodDoc))
724 self.vpp_stderr_deque.append(
725 "--- test setUp() for %s.%s(%s) starts here ---\n" %
726 (self.__class__.__name__, self._testMethodName,
727 self._testMethodDoc))
728 self.vapi.cli("clear trace")
729 # store the test instance inside the test class - so that objects
730 # holding the class can access instance methods (like assertEqual)
731 type(self).test_instance = self
734 def pg_enable_capture(cls, interfaces=None):
736 Enable capture on packet-generator interfaces
738 :param interfaces: iterable interface indexes (if None,
739 use self.pg_interfaces)
742 if interfaces is None:
743 interfaces = cls.pg_interfaces
748 def register_capture(cls, cap_name):
749 """ Register a capture in the testclass """
750 # add to the list of captures with current timestamp
751 cls._captures.append((time.time(), cap_name))
754 def get_vpp_time(cls):
755 return float(cls.vapi.cli('show clock').replace("Time now ", ""))
758 def sleep_on_vpp_time(cls, sec):
759 """ Sleep according to time in VPP world """
760 # On a busy system with many processes
761 # we might end up with VPP time being slower than real world
762 # So take that into account when waiting for VPP to do something
763 start_time = cls.get_vpp_time()
764 while cls.get_vpp_time() - start_time < sec:
769 """ Enable the PG, wait till it is done, then clean up """
770 cls.vapi.cli("trace add pg-input 1000")
771 cls.vapi.cli('packet-generator enable')
772 # PG, when starts, runs to completion -
773 # so let's avoid a race condition,
774 # and wait a little till it's done.
775 # Then clean it up - and then be gone.
776 deadline = time.time() + 300
777 while cls.vapi.cli('show packet-generator').find("Yes") != -1:
778 cls.sleep(0.01) # yield
779 if time.time() > deadline:
780 cls.logger.error("Timeout waiting for pg to stop")
782 for stamp, cap_name in cls._captures:
783 cls.vapi.cli('packet-generator delete %s' % cap_name)
787 def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
789 Create packet-generator interfaces.
791 :param interfaces: iterable indexes of the interfaces.
792 :returns: List of created interfaces.
797 intf = VppPGInterface(cls, i, gso, gso_size)
798 setattr(cls, intf.name, intf)
800 cls.pg_interfaces = result
804 def create_loopback_interfaces(cls, count):
806 Create loopback interfaces.
808 :param count: number of interfaces created.
809 :returns: List of created interfaces.
811 result = [VppLoInterface(cls) for i in range(count)]
813 setattr(cls, intf.name, intf)
814 cls.lo_interfaces = result
818 def create_bvi_interfaces(cls, count):
820 Create BVI interfaces.
822 :param count: number of interfaces created.
823 :returns: List of created interfaces.
825 result = [VppBviInterface(cls) for i in range(count)]
827 setattr(cls, intf.name, intf)
828 cls.bvi_interfaces = result
832 def extend_packet(packet, size, padding=' '):
834 Extend packet to given size by padding with spaces or custom padding
835 NOTE: Currently works only when Raw layer is present.
837 :param packet: packet
838 :param size: target size
839 :param padding: padding used to extend the payload
842 packet_len = len(packet) + 4
843 extend = size - packet_len
845 num = (extend // len(padding)) + 1
846 packet[Raw].load += (padding * num)[:extend].encode("ascii")
849 def reset_packet_infos(cls):
850 """ Reset the list of packet info objects and packet counts to zero """
851 cls._packet_infos = {}
852 cls._packet_count_for_dst_if_idx = {}
855 def create_packet_info(cls, src_if, dst_if):
857 Create packet info object containing the source and destination indexes
858 and add it to the testcase's packet info list
860 :param VppInterface src_if: source interface
861 :param VppInterface dst_if: destination interface
863 :returns: _PacketInfo object
867 info.index = len(cls._packet_infos)
868 info.src = src_if.sw_if_index
869 info.dst = dst_if.sw_if_index
870 if isinstance(dst_if, VppSubInterface):
871 dst_idx = dst_if.parent.sw_if_index
873 dst_idx = dst_if.sw_if_index
874 if dst_idx in cls._packet_count_for_dst_if_idx:
875 cls._packet_count_for_dst_if_idx[dst_idx] += 1
877 cls._packet_count_for_dst_if_idx[dst_idx] = 1
878 cls._packet_infos[info.index] = info
882 def info_to_payload(info):
884 Convert _PacketInfo object to packet payload
886 :param info: _PacketInfo object
888 :returns: string containing serialized data from packet info
890 return "%d %d %d %d %d" % (info.index, info.src, info.dst,
894 def payload_to_info(payload, payload_field='load'):
896 Convert packet payload to _PacketInfo object
898 :param payload: packet payload
899 :type payload: <class 'scapy.packet.Raw'>
900 :param payload_field: packet fieldname of payload "load" for
901 <class 'scapy.packet.Raw'>
902 :type payload_field: str
903 :returns: _PacketInfo object containing de-serialized data from payload
906 numbers = getattr(payload, payload_field).split()
908 info.index = int(numbers[0])
909 info.src = int(numbers[1])
910 info.dst = int(numbers[2])
911 info.ip = int(numbers[3])
912 info.proto = int(numbers[4])
915 def get_next_packet_info(self, info):
917 Iterate over the packet info list stored in the testcase
918 Start iteration with first element if info is None
919 Continue based on index in info if info is specified
921 :param info: info or None
922 :returns: next info in list or None if no more infos
927 next_index = info.index + 1
928 if next_index == len(self._packet_infos):
931 return self._packet_infos[next_index]
933 def get_next_packet_info_for_interface(self, src_index, info):
935 Search the packet info list for the next packet info with same source
938 :param src_index: source interface index to search for
939 :param info: packet info - where to start the search
940 :returns: packet info or None
944 info = self.get_next_packet_info(info)
947 if info.src == src_index:
950 def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
952 Search the packet info list for the next packet info with same source
953 and destination interface indexes
955 :param src_index: source interface index to search for
956 :param dst_index: destination interface index to search for
957 :param info: packet info - where to start the search
958 :returns: packet info or None
962 info = self.get_next_packet_info_for_interface(src_index, info)
965 if info.dst == dst_index:
968 def assert_equal(self, real_value, expected_value, name_or_class=None):
969 if name_or_class is None:
970 self.assertEqual(real_value, expected_value)
973 msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
974 msg = msg % (getdoc(name_or_class).strip(),
975 real_value, str(name_or_class(real_value)),
976 expected_value, str(name_or_class(expected_value)))
978 msg = "Invalid %s: %s does not match expected value %s" % (
979 name_or_class, real_value, expected_value)
981 self.assertEqual(real_value, expected_value, msg)
983 def assert_in_range(self,
991 msg = "Invalid %s: %s out of range <%s,%s>" % (
992 name, real_value, expected_min, expected_max)
993 self.assertTrue(expected_min <= real_value <= expected_max, msg)
995 def assert_packet_checksums_valid(self, packet,
996 ignore_zero_udp_checksums=True):
997 received = packet.__class__(scapy.compat.raw(packet))
998 udp_layers = ['UDP', 'UDPerror']
999 checksum_fields = ['cksum', 'chksum']
1002 temp = received.__class__(scapy.compat.raw(received))
1004 layer = temp.getlayer(counter)
1006 layer = layer.copy()
1007 layer.remove_payload()
1008 for cf in checksum_fields:
1009 if hasattr(layer, cf):
1010 if ignore_zero_udp_checksums and \
1011 0 == getattr(layer, cf) and \
1012 layer.name in udp_layers:
1014 delattr(temp.getlayer(counter), cf)
1015 checksums.append((counter, cf))
1018 counter = counter + 1
1019 if 0 == len(checksums):
1021 temp = temp.__class__(scapy.compat.raw(temp))
1022 for layer, cf in checksums:
1023 calc_sum = getattr(temp[layer], cf)
1025 getattr(received[layer], cf), calc_sum,
1026 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1028 "Checksum field `%s` on `%s` layer has correct value `%s`" %
1029 (cf, temp[layer].name, calc_sum))
1031 def assert_checksum_valid(self, received_packet, layer,
1032 field_name='chksum',
1033 ignore_zero_checksum=False):
1034 """ Check checksum of received packet on given layer """
1035 received_packet_checksum = getattr(received_packet[layer], field_name)
1036 if ignore_zero_checksum and 0 == received_packet_checksum:
1038 recalculated = received_packet.__class__(
1039 scapy.compat.raw(received_packet))
1040 delattr(recalculated[layer], field_name)
1041 recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1042 self.assert_equal(received_packet_checksum,
1043 getattr(recalculated[layer], field_name),
1044 "packet checksum on layer: %s" % layer)
1046 def assert_ip_checksum_valid(self, received_packet,
1047 ignore_zero_checksum=False):
1048 self.assert_checksum_valid(received_packet, 'IP',
1049 ignore_zero_checksum=ignore_zero_checksum)
1051 def assert_tcp_checksum_valid(self, received_packet,
1052 ignore_zero_checksum=False):
1053 self.assert_checksum_valid(received_packet, 'TCP',
1054 ignore_zero_checksum=ignore_zero_checksum)
1056 def assert_udp_checksum_valid(self, received_packet,
1057 ignore_zero_checksum=True):
1058 self.assert_checksum_valid(received_packet, 'UDP',
1059 ignore_zero_checksum=ignore_zero_checksum)
1061 def assert_embedded_icmp_checksum_valid(self, received_packet):
1062 if received_packet.haslayer(IPerror):
1063 self.assert_checksum_valid(received_packet, 'IPerror')
1064 if received_packet.haslayer(TCPerror):
1065 self.assert_checksum_valid(received_packet, 'TCPerror')
1066 if received_packet.haslayer(UDPerror):
1067 self.assert_checksum_valid(received_packet, 'UDPerror',
1068 ignore_zero_checksum=True)
1069 if received_packet.haslayer(ICMPerror):
1070 self.assert_checksum_valid(received_packet, 'ICMPerror')
1072 def assert_icmp_checksum_valid(self, received_packet):
1073 self.assert_checksum_valid(received_packet, 'ICMP')
1074 self.assert_embedded_icmp_checksum_valid(received_packet)
1076 def assert_icmpv6_checksum_valid(self, pkt):
1077 if pkt.haslayer(ICMPv6DestUnreach):
1078 self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1079 self.assert_embedded_icmp_checksum_valid(pkt)
1080 if pkt.haslayer(ICMPv6EchoRequest):
1081 self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1082 if pkt.haslayer(ICMPv6EchoReply):
1083 self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1085 def get_packet_counter(self, counter):
1086 if counter.startswith("/"):
1087 counter_value = self.statistics.get_counter(counter)
1089 counters = self.vapi.cli("sh errors").split('\n')
1091 for i in range(1, len(counters) - 1):
1092 results = counters[i].split()
1093 if results[1] == counter:
1094 counter_value = int(results[0])
1096 return counter_value
1098 def assert_packet_counter_equal(self, counter, expected_value):
1099 counter_value = self.get_packet_counter(counter)
1100 self.assert_equal(counter_value, expected_value,
1101 "packet counter `%s'" % counter)
1103 def assert_error_counter_equal(self, counter, expected_value):
1104 counter_value = self.statistics.get_err_counter(counter)
1105 self.assert_equal(counter_value, expected_value,
1106 "error counter `%s'" % counter)
1109 def sleep(cls, timeout, remark=None):
1111 # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1112 # * by Guido, only the main thread can be interrupted.
1114 # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892 # noqa
1117 if hasattr(os, 'sched_yield'):
1123 if hasattr(cls, 'logger'):
1124 cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1125 before = time.time()
1128 if hasattr(cls, 'logger') and after - before > 2 * timeout:
1129 cls.logger.error("unexpected self.sleep() result - "
1130 "slept for %es instead of ~%es!",
1131 after - before, timeout)
1132 if hasattr(cls, 'logger'):
1134 "Finished sleep (%s) - slept %es (wanted %es)",
1135 remark, after - before, timeout)
1137 def pg_send(self, intf, pkts, worker=None):
1138 self.vapi.cli("clear trace")
1139 intf.add_stream(pkts, worker=worker)
1140 self.pg_enable_capture(self.pg_interfaces)
1143 def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1144 self.pg_send(intf, pkts)
1147 for i in self.pg_interfaces:
1148 i.get_capture(0, timeout=timeout)
1149 i.assert_nothing_captured(remark=remark)
1152 def send_and_expect(self, intf, pkts, output, n_rx=None, worker=None):
1155 self.pg_send(intf, pkts, worker=worker)
1156 rx = output.get_capture(n_rx)
1159 def send_and_expect_only(self, intf, pkts, output, timeout=None):
1160 self.pg_send(intf, pkts)
1161 rx = output.get_capture(len(pkts))
1165 for i in self.pg_interfaces:
1166 if i not in outputs:
1167 i.get_capture(0, timeout=timeout)
1168 i.assert_nothing_captured()
1174 def get_testcase_doc_name(test):
1175 return getdoc(test.__class__).splitlines()[0]
1178 def get_test_description(descriptions, test):
1179 short_description = test.shortDescription()
1180 if descriptions and short_description:
1181 return short_description
1186 class TestCaseInfo(object):
1187 def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1188 self.logger = logger
1189 self.tempdir = tempdir
1190 self.vpp_pid = vpp_pid
1191 self.vpp_bin_path = vpp_bin_path
1192 self.core_crash_test = None
1195 class VppTestResult(unittest.TestResult):
1197 @property result_string
1198 String variable to store the test case result string.
1200 List variable containing 2-tuples of TestCase instances and strings
1201 holding formatted tracebacks. Each tuple represents a test which
1202 raised an unexpected exception.
1204 List variable containing 2-tuples of TestCase instances and strings
1205 holding formatted tracebacks. Each tuple represents a test where
1206 a failure was explicitly signalled using the TestCase.assert*()
1210 failed_test_cases_info = set()
1211 core_crash_test_cases_info = set()
1212 current_test_case_info = None
1214 def __init__(self, stream=None, descriptions=None, verbosity=None,
1217 :param stream File descriptor to store where to report test results.
1218 Set to the standard error stream by default.
1219 :param descriptions Boolean variable to store information if to use
1220 test case descriptions.
1221 :param verbosity Integer variable to store required verbosity level.
1223 super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1224 self.stream = stream
1225 self.descriptions = descriptions
1226 self.verbosity = verbosity
1227 self.result_string = None
1228 self.runner = runner
1230 def addSuccess(self, test):
1232 Record a test succeeded result
1237 if self.current_test_case_info:
1238 self.current_test_case_info.logger.debug(
1239 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1240 test._testMethodName,
1241 test._testMethodDoc))
1242 unittest.TestResult.addSuccess(self, test)
1243 self.result_string = colorize("OK", GREEN)
1245 self.send_result_through_pipe(test, PASS)
1247 def addSkip(self, test, reason):
1249 Record a test skipped.
1255 if self.current_test_case_info:
1256 self.current_test_case_info.logger.debug(
1257 "--- addSkip() %s.%s(%s) called, reason is %s" %
1258 (test.__class__.__name__, test._testMethodName,
1259 test._testMethodDoc, reason))
1260 unittest.TestResult.addSkip(self, test, reason)
1261 self.result_string = colorize("SKIP", YELLOW)
1263 self.send_result_through_pipe(test, SKIP)
1265 def symlink_failed(self):
1266 if self.current_test_case_info:
1268 failed_dir = os.getenv('FAILED_DIR')
1269 link_path = os.path.join(
1272 os.path.basename(self.current_test_case_info.tempdir))
1273 if self.current_test_case_info.logger:
1274 self.current_test_case_info.logger.debug(
1275 "creating a link to the failed test")
1276 self.current_test_case_info.logger.debug(
1277 "os.symlink(%s, %s)" %
1278 (self.current_test_case_info.tempdir, link_path))
1279 if os.path.exists(link_path):
1280 if self.current_test_case_info.logger:
1281 self.current_test_case_info.logger.debug(
1282 'symlink already exists')
1284 os.symlink(self.current_test_case_info.tempdir, link_path)
1286 except Exception as e:
1287 if self.current_test_case_info.logger:
1288 self.current_test_case_info.logger.error(e)
1290 def send_result_through_pipe(self, test, result):
1291 if hasattr(self, 'test_framework_result_pipe'):
1292 pipe = self.test_framework_result_pipe
1294 pipe.send((test.id(), result))
1296 def log_error(self, test, err, fn_name):
1297 if self.current_test_case_info:
1298 if isinstance(test, unittest.suite._ErrorHolder):
1299 test_name = test.description
1301 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1302 test._testMethodName,
1303 test._testMethodDoc)
1304 self.current_test_case_info.logger.debug(
1305 "--- %s() %s called, err is %s" %
1306 (fn_name, test_name, err))
1307 self.current_test_case_info.logger.debug(
1308 "formatted exception is:\n%s" %
1309 "".join(format_exception(*err)))
1311 def add_error(self, test, err, unittest_fn, error_type):
1312 if error_type == FAIL:
1313 self.log_error(test, err, 'addFailure')
1314 error_type_str = colorize("FAIL", RED)
1315 elif error_type == ERROR:
1316 self.log_error(test, err, 'addError')
1317 error_type_str = colorize("ERROR", RED)
1319 raise Exception('Error type %s cannot be used to record an '
1320 'error or a failure' % error_type)
1322 unittest_fn(self, test, err)
1323 if self.current_test_case_info:
1324 self.result_string = "%s [ temp dir used by test case: %s ]" % \
1326 self.current_test_case_info.tempdir)
1327 self.symlink_failed()
1328 self.failed_test_cases_info.add(self.current_test_case_info)
1329 if is_core_present(self.current_test_case_info.tempdir):
1330 if not self.current_test_case_info.core_crash_test:
1331 if isinstance(test, unittest.suite._ErrorHolder):
1332 test_name = str(test)
1334 test_name = "'{!s}' ({!s})".format(
1335 get_testcase_doc_name(test), test.id())
1336 self.current_test_case_info.core_crash_test = test_name
1337 self.core_crash_test_cases_info.add(
1338 self.current_test_case_info)
1340 self.result_string = '%s [no temp dir]' % error_type_str
1342 self.send_result_through_pipe(test, error_type)
1344 def addFailure(self, test, err):
1346 Record a test failed result
1349 :param err: error message
1352 self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1354 def addError(self, test, err):
1356 Record a test error result
1359 :param err: error message
1362 self.add_error(test, err, unittest.TestResult.addError, ERROR)
1364 def getDescription(self, test):
1366 Get test description
1369 :returns: test description
1372 return get_test_description(self.descriptions, test)
1374 def startTest(self, test):
1382 def print_header(test):
1383 if not hasattr(test.__class__, '_header_printed'):
1384 print(double_line_delim)
1385 print(colorize(getdoc(test).splitlines()[0], GREEN))
1386 print(double_line_delim)
1387 test.__class__._header_printed = True
1390 self.start_test = time.time()
1391 unittest.TestResult.startTest(self, test)
1392 if self.verbosity > 0:
1393 self.stream.writeln(
1394 "Starting " + self.getDescription(test) + " ...")
1395 self.stream.writeln(single_line_delim)
1397 def stopTest(self, test):
1399 Called when the given test has been run
1404 unittest.TestResult.stopTest(self, test)
1406 if self.verbosity > 0:
1407 self.stream.writeln(single_line_delim)
1408 self.stream.writeln("%-73s%s" % (self.getDescription(test),
1409 self.result_string))
1410 self.stream.writeln(single_line_delim)
1412 self.stream.writeln("%-68s %4.2f %s" %
1413 (self.getDescription(test),
1414 time.time() - self.start_test,
1415 self.result_string))
1417 self.send_result_through_pipe(test, TEST_RUN)
1419 def printErrors(self):
1421 Print errors from running the test case
1423 if len(self.errors) > 0 or len(self.failures) > 0:
1424 self.stream.writeln()
1425 self.printErrorList('ERROR', self.errors)
1426 self.printErrorList('FAIL', self.failures)
1428 # ^^ that is the last output from unittest before summary
1429 if not self.runner.print_summary:
1430 devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1431 self.stream = devnull
1432 self.runner.stream = devnull
1434 def printErrorList(self, flavour, errors):
1436 Print error list to the output stream together with error type
1437 and test case description.
1439 :param flavour: error type
1440 :param errors: iterable errors
1443 for test, err in errors:
1444 self.stream.writeln(double_line_delim)
1445 self.stream.writeln("%s: %s" %
1446 (flavour, self.getDescription(test)))
1447 self.stream.writeln(single_line_delim)
1448 self.stream.writeln("%s" % err)
1451 class VppTestRunner(unittest.TextTestRunner):
1453 A basic test runner implementation which prints results to standard error.
1457 def resultclass(self):
1458 """Class maintaining the results of the tests"""
1459 return VppTestResult
1461 def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1462 result_pipe=None, failfast=False, buffer=False,
1463 resultclass=None, print_summary=True, **kwargs):
1464 # ignore stream setting here, use hard-coded stdout to be in sync
1465 # with prints from VppTestCase methods ...
1466 super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1467 verbosity, failfast, buffer,
1468 resultclass, **kwargs)
1469 KeepAliveReporter.pipe = keep_alive_pipe
1471 self.orig_stream = self.stream
1472 self.resultclass.test_framework_result_pipe = result_pipe
1474 self.print_summary = print_summary
1476 def _makeResult(self):
1477 return self.resultclass(self.stream,
1482 def run(self, test):
1489 faulthandler.enable() # emit stack trace to stderr if killed by signal
1491 result = super(VppTestRunner, self).run(test)
1492 if not self.print_summary:
1493 self.stream = self.orig_stream
1494 result.stream = self.orig_stream
1498 class Worker(Thread):
1499 def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1500 super(Worker, self).__init__(*args, **kwargs)
1501 self.logger = logger
1502 self.args = executable_args
1503 if hasattr(self, 'testcase') and self.testcase.debug_all:
1504 if self.testcase.debug_gdbserver:
1505 self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1506 .format(port=self.testcase.gdbserver_port)] + args
1507 elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1508 self.args.append(self.wait_for_gdb)
1509 self.app_bin = executable_args[0]
1510 self.app_name = os.path.basename(self.app_bin)
1511 if hasattr(self, 'role'):
1512 self.app_name += ' {role}'.format(role=self.role)
1515 env = {} if env is None else env
1516 self.env = copy.deepcopy(env)
1518 def wait_for_enter(self):
1519 if not hasattr(self, 'testcase'):
1521 if self.testcase.debug_all and self.testcase.debug_gdbserver:
1523 print(double_line_delim)
1524 print("Spawned GDB Server for '{app}' with PID: {pid}"
1525 .format(app=self.app_name, pid=self.process.pid))
1526 elif self.testcase.debug_all and self.testcase.debug_gdb:
1528 print(double_line_delim)
1529 print("Spawned '{app}' with PID: {pid}"
1530 .format(app=self.app_name, pid=self.process.pid))
1533 print(single_line_delim)
1534 print("You can debug '{app}' using:".format(app=self.app_name))
1535 if self.testcase.debug_gdbserver:
1536 print("sudo gdb " + self.app_bin +
1537 " -ex 'target remote localhost:{port}'"
1538 .format(port=self.testcase.gdbserver_port))
1539 print("Now is the time to attach gdb by running the above "
1540 "command, set up breakpoints etc., then resume from "
1541 "within gdb by issuing the 'continue' command")
1542 self.testcase.gdbserver_port += 1
1543 elif self.testcase.debug_gdb:
1544 print("sudo gdb " + self.app_bin +
1545 " -ex 'attach {pid}'".format(pid=self.process.pid))
1546 print("Now is the time to attach gdb by running the above "
1547 "command and set up breakpoints etc., then resume from"
1548 " within gdb by issuing the 'continue' command")
1549 print(single_line_delim)
1550 input("Press ENTER to continue running the testcase...")
1553 executable = self.args[0]
1554 if not os.path.exists(executable) or not os.access(
1555 executable, os.F_OK | os.X_OK):
1556 # Exit code that means some system file did not exist,
1557 # could not be opened, or had some other kind of error.
1558 self.result = os.EX_OSFILE
1559 raise EnvironmentError(
1560 "executable '%s' is not found or executable." % executable)
1561 self.logger.debug("Running executable: '{app}'"
1562 .format(app=' '.join(self.args)))
1563 env = os.environ.copy()
1564 env.update(self.env)
1565 env["CK_LOG_FILE_NAME"] = "-"
1566 self.process = subprocess.Popen(
1567 self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1568 stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1569 self.wait_for_enter()
1570 out, err = self.process.communicate()
1571 self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1572 self.logger.info("Return code is `%s'" % self.process.returncode)
1573 self.logger.info(single_line_delim)
1574 self.logger.info("Executable `{app}' wrote to stdout:"
1575 .format(app=self.app_name))
1576 self.logger.info(single_line_delim)
1577 self.logger.info(out.decode('utf-8'))
1578 self.logger.info(single_line_delim)
1579 self.logger.info("Executable `{app}' wrote to stderr:"
1580 .format(app=self.app_name))
1581 self.logger.info(single_line_delim)
1582 self.logger.info(err.decode('utf-8'))
1583 self.logger.info(single_line_delim)
1584 self.result = self.process.returncode
1587 if __name__ == '__main__':