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)
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_coredump(cls):
467 corefile = cls.tempdir + "/core"
468 if os.path.isfile(corefile):
469 cls.logger.error("Waiting for coredump to complete: %s", corefile)
470 curr_size = os.path.getsize(corefile)
471 deadline = time.time() + 60
473 while time.time() < deadline:
476 curr_size = os.path.getsize(corefile)
477 if size == curr_size:
481 cls.logger.error("Timed out waiting for coredump to complete:"
484 cls.logger.error("Coredump complete: %s, size %d",
490 Perform class setup before running the testcase
491 Remove shared memory files, start vpp and connect the vpp-api
493 super(VppTestCase, cls).setUpClass()
494 gc.collect() # run garbage collection first
495 cls.logger = get_logger(cls.__name__)
496 seed = os.environ["RND_SEED"]
498 if hasattr(cls, 'parallel_handler'):
499 cls.logger.addHandler(cls.parallel_handler)
500 cls.logger.propagate = False
502 cls.tempdir = tempfile.mkdtemp(
503 prefix='vpp-unittest-%s-' % cls.__name__)
504 cls.stats_sock = "%s/stats.sock" % cls.tempdir
505 cls.api_sock = "%s/api.sock" % cls.tempdir
506 cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
507 cls.file_handler.setFormatter(
508 Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
510 cls.file_handler.setLevel(DEBUG)
511 cls.logger.addHandler(cls.file_handler)
512 cls.logger.debug("--- setUpClass() for %s called ---" %
514 cls.shm_prefix = os.path.basename(cls.tempdir)
515 os.chdir(cls.tempdir)
516 cls.logger.info("Temporary dir is %s, shm prefix is %s",
517 cls.tempdir, cls.shm_prefix)
518 cls.logger.debug("Random seed is %s" % seed)
520 cls.reset_packet_infos()
524 cls.registry = VppObjectRegistry()
525 cls.vpp_startup_failed = False
526 cls.reporter = KeepAliveReporter()
527 # need to catch exceptions here because if we raise, then the cleanup
528 # doesn't get called and we might end with a zombie vpp
531 cls.reporter.send_keep_alive(cls, 'setUpClass')
532 VppTestResult.current_test_case_info = TestCaseInfo(
533 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
534 cls.vpp_stdout_deque = deque()
535 cls.vpp_stderr_deque = deque()
536 cls.pump_thread_stop_flag = Event()
537 cls.pump_thread_wakeup_pipe = os.pipe()
538 cls.pump_thread = Thread(target=pump_output, args=(cls,))
539 cls.pump_thread.daemon = True
540 cls.pump_thread.start()
541 if cls.debug_gdb or cls.debug_gdbserver:
542 cls.vapi_response_timeout = 0
543 cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
544 cls.vapi_response_timeout)
546 hook = hookmodule.StepHook(cls)
548 hook = hookmodule.PollHook(cls)
549 cls.vapi.register_hook(hook)
550 cls.statistics = VPPStats(socketname=cls.stats_sock)
554 cls.vpp_startup_failed = True
556 "VPP died shortly after startup, check the"
557 " output to standard error for possible cause")
561 except vpp_papi.VPPIOError as e:
562 cls.logger.debug("Exception connecting to vapi: %s" % e)
563 cls.vapi.disconnect()
565 if cls.debug_gdbserver:
566 print(colorize("You're running VPP inside gdbserver but "
567 "VPP-API connection failed, did you forget "
568 "to 'continue' VPP from within gdb?", RED))
570 except Exception as e:
571 cls.logger.debug("Exception connecting to VPP: %s" % e)
577 def _debug_quit(cls):
578 if (cls.debug_gdbserver or cls.debug_gdb):
582 if cls.vpp.returncode is None:
584 print(double_line_delim)
585 print("VPP or GDB server is still running")
586 print(single_line_delim)
587 input("When done debugging, press ENTER to kill the "
588 "process and finish running the testcase...")
589 except AttributeError:
595 Disconnect vpp-api, kill vpp and cleanup shared memory files
599 # first signal that we want to stop the pump thread, then wake it up
600 if hasattr(cls, 'pump_thread_stop_flag'):
601 cls.pump_thread_stop_flag.set()
602 if hasattr(cls, 'pump_thread_wakeup_pipe'):
603 os.write(cls.pump_thread_wakeup_pipe[1], b'ding dong wake up')
604 if hasattr(cls, 'pump_thread'):
605 cls.logger.debug("Waiting for pump thread to stop")
606 cls.pump_thread.join()
607 if hasattr(cls, 'vpp_stderr_reader_thread'):
608 cls.logger.debug("Waiting for stderr pump to stop")
609 cls.vpp_stderr_reader_thread.join()
611 if hasattr(cls, 'vpp'):
612 if hasattr(cls, 'vapi'):
613 cls.logger.debug(cls.vapi.vpp.get_stats())
614 cls.logger.debug("Disconnecting class vapi client on %s",
616 cls.vapi.disconnect()
617 cls.logger.debug("Deleting class vapi attribute on %s",
621 if cls.vpp.returncode is None:
622 cls.wait_for_coredump()
623 cls.logger.debug("Sending TERM to vpp")
625 cls.logger.debug("Waiting for vpp to die")
626 cls.vpp.communicate()
627 cls.logger.debug("Deleting class vpp attribute on %s",
631 if cls.vpp_startup_failed:
632 stdout_log = cls.logger.info
633 stderr_log = cls.logger.critical
635 stdout_log = cls.logger.info
636 stderr_log = cls.logger.info
638 if hasattr(cls, 'vpp_stdout_deque'):
639 stdout_log(single_line_delim)
640 stdout_log('VPP output to stdout while running %s:', cls.__name__)
641 stdout_log(single_line_delim)
642 vpp_output = "".join(cls.vpp_stdout_deque)
643 with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
645 stdout_log('\n%s', vpp_output)
646 stdout_log(single_line_delim)
648 if hasattr(cls, 'vpp_stderr_deque'):
649 stderr_log(single_line_delim)
650 stderr_log('VPP output to stderr while running %s:', cls.__name__)
651 stderr_log(single_line_delim)
652 vpp_output = "".join(cls.vpp_stderr_deque)
653 with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
655 stderr_log('\n%s', vpp_output)
656 stderr_log(single_line_delim)
659 def tearDownClass(cls):
660 """ Perform final cleanup after running all tests in this test-case """
661 cls.logger.debug("--- tearDownClass() for %s called ---" %
663 cls.reporter.send_keep_alive(cls, 'tearDownClass')
665 cls.file_handler.close()
666 cls.reset_packet_infos()
668 debug_internal.on_tear_down_class(cls)
670 def show_commands_at_teardown(self):
671 """ Allow subclass specific teardown logging additions."""
672 self.logger.info("--- No test specific show commands provided. ---")
675 """ Show various debug prints after each test """
676 self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
677 (self.__class__.__name__, self._testMethodName,
678 self._testMethodDoc))
681 if not self.vpp_dead:
682 self.logger.debug(self.vapi.cli("show trace max 1000"))
683 self.logger.info(self.vapi.ppcli("show interface"))
684 self.logger.info(self.vapi.ppcli("show hardware"))
685 self.logger.info(self.statistics.set_errors_str())
686 self.logger.info(self.vapi.ppcli("show run"))
687 self.logger.info(self.vapi.ppcli("show log"))
688 self.logger.info(self.vapi.ppcli("show bihash"))
689 self.logger.info("Logging testcase specific show commands.")
690 self.show_commands_at_teardown()
691 self.registry.remove_vpp_config(self.logger)
692 # Save/Dump VPP api trace log
693 m = self._testMethodName
694 api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
695 tmp_api_trace = "/tmp/%s" % api_trace
696 vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
697 self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
698 self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
700 os.rename(tmp_api_trace, vpp_api_trace_log)
701 self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
703 except VppTransportShmemIOError:
704 self.logger.debug("VppTransportShmemIOError: Vpp dead. "
705 "Cannot log show commands.")
708 self.registry.unregister_all(self.logger)
711 """ Clear trace before running each test"""
712 super(VppTestCase, self).setUp()
713 self.reporter.send_keep_alive(self)
716 raise VppDiedError(rv=None, testcase=self.__class__.__name__,
717 method_name=self._testMethodName)
718 self.sleep(.1, "during setUp")
719 self.vpp_stdout_deque.append(
720 "--- test setUp() for %s.%s(%s) starts here ---\n" %
721 (self.__class__.__name__, self._testMethodName,
722 self._testMethodDoc))
723 self.vpp_stderr_deque.append(
724 "--- test setUp() for %s.%s(%s) starts here ---\n" %
725 (self.__class__.__name__, self._testMethodName,
726 self._testMethodDoc))
727 self.vapi.cli("clear trace")
728 # store the test instance inside the test class - so that objects
729 # holding the class can access instance methods (like assertEqual)
730 type(self).test_instance = self
733 def pg_enable_capture(cls, interfaces=None):
735 Enable capture on packet-generator interfaces
737 :param interfaces: iterable interface indexes (if None,
738 use self.pg_interfaces)
741 if interfaces is None:
742 interfaces = cls.pg_interfaces
747 def register_capture(cls, cap_name):
748 """ Register a capture in the testclass """
749 # add to the list of captures with current timestamp
750 cls._captures.append((time.time(), cap_name))
753 def get_vpp_time(cls):
754 return float(cls.vapi.cli('show clock').replace("Time now ", ""))
757 def sleep_on_vpp_time(cls, sec):
758 """ Sleep according to time in VPP world """
759 # On a busy system with many processes
760 # we might end up with VPP time being slower than real world
761 # So take that into account when waiting for VPP to do something
762 start_time = cls.get_vpp_time()
763 while cls.get_vpp_time() - start_time < sec:
768 """ Enable the PG, wait till it is done, then clean up """
769 cls.vapi.cli("trace add pg-input 1000")
770 cls.vapi.cli('packet-generator enable')
771 # PG, when starts, runs to completion -
772 # so let's avoid a race condition,
773 # and wait a little till it's done.
774 # Then clean it up - and then be gone.
775 deadline = time.time() + 300
776 while cls.vapi.cli('show packet-generator').find("Yes") != -1:
777 cls.sleep(0.01) # yield
778 if time.time() > deadline:
779 cls.logger.error("Timeout waiting for pg to stop")
781 for stamp, cap_name in cls._captures:
782 cls.vapi.cli('packet-generator delete %s' % cap_name)
786 def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
788 Create packet-generator interfaces.
790 :param interfaces: iterable indexes of the interfaces.
791 :returns: List of created interfaces.
796 intf = VppPGInterface(cls, i, gso, gso_size)
797 setattr(cls, intf.name, intf)
799 cls.pg_interfaces = result
803 def create_loopback_interfaces(cls, count):
805 Create loopback interfaces.
807 :param count: number of interfaces created.
808 :returns: List of created interfaces.
810 result = [VppLoInterface(cls) for i in range(count)]
812 setattr(cls, intf.name, intf)
813 cls.lo_interfaces = result
817 def create_bvi_interfaces(cls, count):
819 Create BVI interfaces.
821 :param count: number of interfaces created.
822 :returns: List of created interfaces.
824 result = [VppBviInterface(cls) for i in range(count)]
826 setattr(cls, intf.name, intf)
827 cls.bvi_interfaces = result
831 def extend_packet(packet, size, padding=' '):
833 Extend packet to given size by padding with spaces or custom padding
834 NOTE: Currently works only when Raw layer is present.
836 :param packet: packet
837 :param size: target size
838 :param padding: padding used to extend the payload
841 packet_len = len(packet) + 4
842 extend = size - packet_len
844 num = (extend // len(padding)) + 1
845 packet[Raw].load += (padding * num)[:extend].encode("ascii")
848 def reset_packet_infos(cls):
849 """ Reset the list of packet info objects and packet counts to zero """
850 cls._packet_infos = {}
851 cls._packet_count_for_dst_if_idx = {}
854 def create_packet_info(cls, src_if, dst_if):
856 Create packet info object containing the source and destination indexes
857 and add it to the testcase's packet info list
859 :param VppInterface src_if: source interface
860 :param VppInterface dst_if: destination interface
862 :returns: _PacketInfo object
866 info.index = len(cls._packet_infos)
867 info.src = src_if.sw_if_index
868 info.dst = dst_if.sw_if_index
869 if isinstance(dst_if, VppSubInterface):
870 dst_idx = dst_if.parent.sw_if_index
872 dst_idx = dst_if.sw_if_index
873 if dst_idx in cls._packet_count_for_dst_if_idx:
874 cls._packet_count_for_dst_if_idx[dst_idx] += 1
876 cls._packet_count_for_dst_if_idx[dst_idx] = 1
877 cls._packet_infos[info.index] = info
881 def info_to_payload(info):
883 Convert _PacketInfo object to packet payload
885 :param info: _PacketInfo object
887 :returns: string containing serialized data from packet info
889 return "%d %d %d %d %d" % (info.index, info.src, info.dst,
893 def payload_to_info(payload, payload_field='load'):
895 Convert packet payload to _PacketInfo object
897 :param payload: packet payload
898 :type payload: <class 'scapy.packet.Raw'>
899 :param payload_field: packet fieldname of payload "load" for
900 <class 'scapy.packet.Raw'>
901 :type payload_field: str
902 :returns: _PacketInfo object containing de-serialized data from payload
905 numbers = getattr(payload, payload_field).split()
907 info.index = int(numbers[0])
908 info.src = int(numbers[1])
909 info.dst = int(numbers[2])
910 info.ip = int(numbers[3])
911 info.proto = int(numbers[4])
914 def get_next_packet_info(self, info):
916 Iterate over the packet info list stored in the testcase
917 Start iteration with first element if info is None
918 Continue based on index in info if info is specified
920 :param info: info or None
921 :returns: next info in list or None if no more infos
926 next_index = info.index + 1
927 if next_index == len(self._packet_infos):
930 return self._packet_infos[next_index]
932 def get_next_packet_info_for_interface(self, src_index, info):
934 Search the packet info list for the next packet info with same source
937 :param src_index: source interface index to search for
938 :param info: packet info - where to start the search
939 :returns: packet info or None
943 info = self.get_next_packet_info(info)
946 if info.src == src_index:
949 def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
951 Search the packet info list for the next packet info with same source
952 and destination interface indexes
954 :param src_index: source interface index to search for
955 :param dst_index: destination interface index to search for
956 :param info: packet info - where to start the search
957 :returns: packet info or None
961 info = self.get_next_packet_info_for_interface(src_index, info)
964 if info.dst == dst_index:
967 def assert_equal(self, real_value, expected_value, name_or_class=None):
968 if name_or_class is None:
969 self.assertEqual(real_value, expected_value)
972 msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
973 msg = msg % (getdoc(name_or_class).strip(),
974 real_value, str(name_or_class(real_value)),
975 expected_value, str(name_or_class(expected_value)))
977 msg = "Invalid %s: %s does not match expected value %s" % (
978 name_or_class, real_value, expected_value)
980 self.assertEqual(real_value, expected_value, msg)
982 def assert_in_range(self,
990 msg = "Invalid %s: %s out of range <%s,%s>" % (
991 name, real_value, expected_min, expected_max)
992 self.assertTrue(expected_min <= real_value <= expected_max, msg)
994 def assert_packet_checksums_valid(self, packet,
995 ignore_zero_udp_checksums=True):
996 received = packet.__class__(scapy.compat.raw(packet))
997 udp_layers = ['UDP', 'UDPerror']
998 checksum_fields = ['cksum', 'chksum']
1001 temp = received.__class__(scapy.compat.raw(received))
1003 layer = temp.getlayer(counter)
1005 layer = layer.copy()
1006 layer.remove_payload()
1007 for cf in checksum_fields:
1008 if hasattr(layer, cf):
1009 if ignore_zero_udp_checksums and \
1010 0 == getattr(layer, cf) and \
1011 layer.name in udp_layers:
1013 delattr(temp.getlayer(counter), cf)
1014 checksums.append((counter, cf))
1017 counter = counter + 1
1018 if 0 == len(checksums):
1020 temp = temp.__class__(scapy.compat.raw(temp))
1021 for layer, cf in checksums:
1022 calc_sum = getattr(temp[layer], cf)
1024 getattr(received[layer], cf), calc_sum,
1025 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1027 "Checksum field `%s` on `%s` layer has correct value `%s`" %
1028 (cf, temp[layer].name, calc_sum))
1030 def assert_checksum_valid(self, received_packet, layer,
1031 field_name='chksum',
1032 ignore_zero_checksum=False):
1033 """ Check checksum of received packet on given layer """
1034 received_packet_checksum = getattr(received_packet[layer], field_name)
1035 if ignore_zero_checksum and 0 == received_packet_checksum:
1037 recalculated = received_packet.__class__(
1038 scapy.compat.raw(received_packet))
1039 delattr(recalculated[layer], field_name)
1040 recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1041 self.assert_equal(received_packet_checksum,
1042 getattr(recalculated[layer], field_name),
1043 "packet checksum on layer: %s" % layer)
1045 def assert_ip_checksum_valid(self, received_packet,
1046 ignore_zero_checksum=False):
1047 self.assert_checksum_valid(received_packet, 'IP',
1048 ignore_zero_checksum=ignore_zero_checksum)
1050 def assert_tcp_checksum_valid(self, received_packet,
1051 ignore_zero_checksum=False):
1052 self.assert_checksum_valid(received_packet, 'TCP',
1053 ignore_zero_checksum=ignore_zero_checksum)
1055 def assert_udp_checksum_valid(self, received_packet,
1056 ignore_zero_checksum=True):
1057 self.assert_checksum_valid(received_packet, 'UDP',
1058 ignore_zero_checksum=ignore_zero_checksum)
1060 def assert_embedded_icmp_checksum_valid(self, received_packet):
1061 if received_packet.haslayer(IPerror):
1062 self.assert_checksum_valid(received_packet, 'IPerror')
1063 if received_packet.haslayer(TCPerror):
1064 self.assert_checksum_valid(received_packet, 'TCPerror')
1065 if received_packet.haslayer(UDPerror):
1066 self.assert_checksum_valid(received_packet, 'UDPerror',
1067 ignore_zero_checksum=True)
1068 if received_packet.haslayer(ICMPerror):
1069 self.assert_checksum_valid(received_packet, 'ICMPerror')
1071 def assert_icmp_checksum_valid(self, received_packet):
1072 self.assert_checksum_valid(received_packet, 'ICMP')
1073 self.assert_embedded_icmp_checksum_valid(received_packet)
1075 def assert_icmpv6_checksum_valid(self, pkt):
1076 if pkt.haslayer(ICMPv6DestUnreach):
1077 self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1078 self.assert_embedded_icmp_checksum_valid(pkt)
1079 if pkt.haslayer(ICMPv6EchoRequest):
1080 self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1081 if pkt.haslayer(ICMPv6EchoReply):
1082 self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1084 def get_packet_counter(self, counter):
1085 if counter.startswith("/"):
1086 counter_value = self.statistics.get_counter(counter)
1088 counters = self.vapi.cli("sh errors").split('\n')
1090 for i in range(1, len(counters) - 1):
1091 results = counters[i].split()
1092 if results[1] == counter:
1093 counter_value = int(results[0])
1095 return counter_value
1097 def assert_packet_counter_equal(self, counter, expected_value):
1098 counter_value = self.get_packet_counter(counter)
1099 self.assert_equal(counter_value, expected_value,
1100 "packet counter `%s'" % counter)
1102 def assert_error_counter_equal(self, counter, expected_value):
1103 counter_value = self.statistics.get_err_counter(counter)
1104 self.assert_equal(counter_value, expected_value,
1105 "error counter `%s'" % counter)
1108 def sleep(cls, timeout, remark=None):
1110 # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1111 # * by Guido, only the main thread can be interrupted.
1113 # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892 # noqa
1116 if hasattr(os, 'sched_yield'):
1122 if hasattr(cls, 'logger'):
1123 cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1124 before = time.time()
1127 if hasattr(cls, 'logger') and after - before > 2 * timeout:
1128 cls.logger.error("unexpected self.sleep() result - "
1129 "slept for %es instead of ~%es!",
1130 after - before, timeout)
1131 if hasattr(cls, 'logger'):
1133 "Finished sleep (%s) - slept %es (wanted %es)",
1134 remark, after - before, timeout)
1136 def pg_send(self, intf, pkts, worker=None):
1137 self.vapi.cli("clear trace")
1138 intf.add_stream(pkts, worker=worker)
1139 self.pg_enable_capture(self.pg_interfaces)
1142 def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1143 self.pg_send(intf, pkts)
1146 for i in self.pg_interfaces:
1147 i.get_capture(0, timeout=timeout)
1148 i.assert_nothing_captured(remark=remark)
1151 def send_and_expect(self, intf, pkts, output, n_rx=None, worker=None):
1154 self.pg_send(intf, pkts, worker=worker)
1155 rx = output.get_capture(n_rx)
1158 def send_and_expect_only(self, intf, pkts, output, timeout=None):
1159 self.pg_send(intf, pkts)
1160 rx = output.get_capture(len(pkts))
1164 for i in self.pg_interfaces:
1165 if i not in outputs:
1166 i.get_capture(0, timeout=timeout)
1167 i.assert_nothing_captured()
1173 def get_testcase_doc_name(test):
1174 return getdoc(test.__class__).splitlines()[0]
1177 def get_test_description(descriptions, test):
1178 short_description = test.shortDescription()
1179 if descriptions and short_description:
1180 return short_description
1185 class TestCaseInfo(object):
1186 def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1187 self.logger = logger
1188 self.tempdir = tempdir
1189 self.vpp_pid = vpp_pid
1190 self.vpp_bin_path = vpp_bin_path
1191 self.core_crash_test = None
1194 class VppTestResult(unittest.TestResult):
1196 @property result_string
1197 String variable to store the test case result string.
1199 List variable containing 2-tuples of TestCase instances and strings
1200 holding formatted tracebacks. Each tuple represents a test which
1201 raised an unexpected exception.
1203 List variable containing 2-tuples of TestCase instances and strings
1204 holding formatted tracebacks. Each tuple represents a test where
1205 a failure was explicitly signalled using the TestCase.assert*()
1209 failed_test_cases_info = set()
1210 core_crash_test_cases_info = set()
1211 current_test_case_info = None
1213 def __init__(self, stream=None, descriptions=None, verbosity=None,
1216 :param stream File descriptor to store where to report test results.
1217 Set to the standard error stream by default.
1218 :param descriptions Boolean variable to store information if to use
1219 test case descriptions.
1220 :param verbosity Integer variable to store required verbosity level.
1222 super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1223 self.stream = stream
1224 self.descriptions = descriptions
1225 self.verbosity = verbosity
1226 self.result_string = None
1227 self.runner = runner
1229 def addSuccess(self, test):
1231 Record a test succeeded result
1236 if self.current_test_case_info:
1237 self.current_test_case_info.logger.debug(
1238 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1239 test._testMethodName,
1240 test._testMethodDoc))
1241 unittest.TestResult.addSuccess(self, test)
1242 self.result_string = colorize("OK", GREEN)
1244 self.send_result_through_pipe(test, PASS)
1246 def addSkip(self, test, reason):
1248 Record a test skipped.
1254 if self.current_test_case_info:
1255 self.current_test_case_info.logger.debug(
1256 "--- addSkip() %s.%s(%s) called, reason is %s" %
1257 (test.__class__.__name__, test._testMethodName,
1258 test._testMethodDoc, reason))
1259 unittest.TestResult.addSkip(self, test, reason)
1260 self.result_string = colorize("SKIP", YELLOW)
1262 self.send_result_through_pipe(test, SKIP)
1264 def symlink_failed(self):
1265 if self.current_test_case_info:
1267 failed_dir = os.getenv('FAILED_DIR')
1268 link_path = os.path.join(
1271 os.path.basename(self.current_test_case_info.tempdir))
1272 if self.current_test_case_info.logger:
1273 self.current_test_case_info.logger.debug(
1274 "creating a link to the failed test")
1275 self.current_test_case_info.logger.debug(
1276 "os.symlink(%s, %s)" %
1277 (self.current_test_case_info.tempdir, link_path))
1278 if os.path.exists(link_path):
1279 if self.current_test_case_info.logger:
1280 self.current_test_case_info.logger.debug(
1281 'symlink already exists')
1283 os.symlink(self.current_test_case_info.tempdir, link_path)
1285 except Exception as e:
1286 if self.current_test_case_info.logger:
1287 self.current_test_case_info.logger.error(e)
1289 def send_result_through_pipe(self, test, result):
1290 if hasattr(self, 'test_framework_result_pipe'):
1291 pipe = self.test_framework_result_pipe
1293 pipe.send((test.id(), result))
1295 def log_error(self, test, err, fn_name):
1296 if self.current_test_case_info:
1297 if isinstance(test, unittest.suite._ErrorHolder):
1298 test_name = test.description
1300 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1301 test._testMethodName,
1302 test._testMethodDoc)
1303 self.current_test_case_info.logger.debug(
1304 "--- %s() %s called, err is %s" %
1305 (fn_name, test_name, err))
1306 self.current_test_case_info.logger.debug(
1307 "formatted exception is:\n%s" %
1308 "".join(format_exception(*err)))
1310 def add_error(self, test, err, unittest_fn, error_type):
1311 if error_type == FAIL:
1312 self.log_error(test, err, 'addFailure')
1313 error_type_str = colorize("FAIL", RED)
1314 elif error_type == ERROR:
1315 self.log_error(test, err, 'addError')
1316 error_type_str = colorize("ERROR", RED)
1318 raise Exception('Error type %s cannot be used to record an '
1319 'error or a failure' % error_type)
1321 unittest_fn(self, test, err)
1322 if self.current_test_case_info:
1323 self.result_string = "%s [ temp dir used by test case: %s ]" % \
1325 self.current_test_case_info.tempdir)
1326 self.symlink_failed()
1327 self.failed_test_cases_info.add(self.current_test_case_info)
1328 if is_core_present(self.current_test_case_info.tempdir):
1329 if not self.current_test_case_info.core_crash_test:
1330 if isinstance(test, unittest.suite._ErrorHolder):
1331 test_name = str(test)
1333 test_name = "'{!s}' ({!s})".format(
1334 get_testcase_doc_name(test), test.id())
1335 self.current_test_case_info.core_crash_test = test_name
1336 self.core_crash_test_cases_info.add(
1337 self.current_test_case_info)
1339 self.result_string = '%s [no temp dir]' % error_type_str
1341 self.send_result_through_pipe(test, error_type)
1343 def addFailure(self, test, err):
1345 Record a test failed result
1348 :param err: error message
1351 self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1353 def addError(self, test, err):
1355 Record a test error result
1358 :param err: error message
1361 self.add_error(test, err, unittest.TestResult.addError, ERROR)
1363 def getDescription(self, test):
1365 Get test description
1368 :returns: test description
1371 return get_test_description(self.descriptions, test)
1373 def startTest(self, test):
1381 def print_header(test):
1382 if not hasattr(test.__class__, '_header_printed'):
1383 print(double_line_delim)
1384 print(colorize(getdoc(test).splitlines()[0], GREEN))
1385 print(double_line_delim)
1386 test.__class__._header_printed = True
1389 self.start_test = time.time()
1390 unittest.TestResult.startTest(self, test)
1391 if self.verbosity > 0:
1392 self.stream.writeln(
1393 "Starting " + self.getDescription(test) + " ...")
1394 self.stream.writeln(single_line_delim)
1396 def stopTest(self, test):
1398 Called when the given test has been run
1403 unittest.TestResult.stopTest(self, test)
1405 if self.verbosity > 0:
1406 self.stream.writeln(single_line_delim)
1407 self.stream.writeln("%-73s%s" % (self.getDescription(test),
1408 self.result_string))
1409 self.stream.writeln(single_line_delim)
1411 self.stream.writeln("%-68s %4.2f %s" %
1412 (self.getDescription(test),
1413 time.time() - self.start_test,
1414 self.result_string))
1416 self.send_result_through_pipe(test, TEST_RUN)
1418 def printErrors(self):
1420 Print errors from running the test case
1422 if len(self.errors) > 0 or len(self.failures) > 0:
1423 self.stream.writeln()
1424 self.printErrorList('ERROR', self.errors)
1425 self.printErrorList('FAIL', self.failures)
1427 # ^^ that is the last output from unittest before summary
1428 if not self.runner.print_summary:
1429 devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1430 self.stream = devnull
1431 self.runner.stream = devnull
1433 def printErrorList(self, flavour, errors):
1435 Print error list to the output stream together with error type
1436 and test case description.
1438 :param flavour: error type
1439 :param errors: iterable errors
1442 for test, err in errors:
1443 self.stream.writeln(double_line_delim)
1444 self.stream.writeln("%s: %s" %
1445 (flavour, self.getDescription(test)))
1446 self.stream.writeln(single_line_delim)
1447 self.stream.writeln("%s" % err)
1450 class VppTestRunner(unittest.TextTestRunner):
1452 A basic test runner implementation which prints results to standard error.
1456 def resultclass(self):
1457 """Class maintaining the results of the tests"""
1458 return VppTestResult
1460 def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1461 result_pipe=None, failfast=False, buffer=False,
1462 resultclass=None, print_summary=True, **kwargs):
1463 # ignore stream setting here, use hard-coded stdout to be in sync
1464 # with prints from VppTestCase methods ...
1465 super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1466 verbosity, failfast, buffer,
1467 resultclass, **kwargs)
1468 KeepAliveReporter.pipe = keep_alive_pipe
1470 self.orig_stream = self.stream
1471 self.resultclass.test_framework_result_pipe = result_pipe
1473 self.print_summary = print_summary
1475 def _makeResult(self):
1476 return self.resultclass(self.stream,
1481 def run(self, test):
1488 faulthandler.enable() # emit stack trace to stderr if killed by signal
1490 result = super(VppTestRunner, self).run(test)
1491 if not self.print_summary:
1492 self.stream = self.orig_stream
1493 result.stream = self.orig_stream
1497 class Worker(Thread):
1498 def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1499 super(Worker, self).__init__(*args, **kwargs)
1500 self.logger = logger
1501 self.args = executable_args
1502 if hasattr(self, 'testcase') and self.testcase.debug_all:
1503 if self.testcase.debug_gdbserver:
1504 self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1505 .format(port=self.testcase.gdbserver_port)] + args
1506 elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1507 self.args.append(self.wait_for_gdb)
1508 self.app_bin = executable_args[0]
1509 self.app_name = os.path.basename(self.app_bin)
1510 if hasattr(self, 'role'):
1511 self.app_name += ' {role}'.format(role=self.role)
1514 env = {} if env is None else env
1515 self.env = copy.deepcopy(env)
1517 def wait_for_enter(self):
1518 if not hasattr(self, 'testcase'):
1520 if self.testcase.debug_all and self.testcase.debug_gdbserver:
1522 print(double_line_delim)
1523 print("Spawned GDB Server for '{app}' with PID: {pid}"
1524 .format(app=self.app_name, pid=self.process.pid))
1525 elif self.testcase.debug_all and self.testcase.debug_gdb:
1527 print(double_line_delim)
1528 print("Spawned '{app}' with PID: {pid}"
1529 .format(app=self.app_name, pid=self.process.pid))
1532 print(single_line_delim)
1533 print("You can debug '{app}' using:".format(app=self.app_name))
1534 if self.testcase.debug_gdbserver:
1535 print("sudo gdb " + self.app_bin +
1536 " -ex 'target remote localhost:{port}'"
1537 .format(port=self.testcase.gdbserver_port))
1538 print("Now is the time to attach gdb by running the above "
1539 "command, set up breakpoints etc., then resume from "
1540 "within gdb by issuing the 'continue' command")
1541 self.testcase.gdbserver_port += 1
1542 elif self.testcase.debug_gdb:
1543 print("sudo gdb " + self.app_bin +
1544 " -ex 'attach {pid}'".format(pid=self.process.pid))
1545 print("Now is the time to attach gdb by running the above "
1546 "command and set up breakpoints etc., then resume from"
1547 " within gdb by issuing the 'continue' command")
1548 print(single_line_delim)
1549 input("Press ENTER to continue running the testcase...")
1552 executable = self.args[0]
1553 if not os.path.exists(executable) or not os.access(
1554 executable, os.F_OK | os.X_OK):
1555 # Exit code that means some system file did not exist,
1556 # could not be opened, or had some other kind of error.
1557 self.result = os.EX_OSFILE
1558 raise EnvironmentError(
1559 "executable '%s' is not found or executable." % executable)
1560 self.logger.debug("Running executable: '{app}'"
1561 .format(app=' '.join(self.args)))
1562 env = os.environ.copy()
1563 env.update(self.env)
1564 env["CK_LOG_FILE_NAME"] = "-"
1565 self.process = subprocess.Popen(
1566 self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1567 stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1568 self.wait_for_enter()
1569 out, err = self.process.communicate()
1570 self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1571 self.logger.info("Return code is `%s'" % self.process.returncode)
1572 self.logger.info(single_line_delim)
1573 self.logger.info("Executable `{app}' wrote to stdout:"
1574 .format(app=self.app_name))
1575 self.logger.info(single_line_delim)
1576 self.logger.info(out.decode('utf-8'))
1577 self.logger.info(single_line_delim)
1578 self.logger.info("Executable `{app}' wrote to stderr:"
1579 .format(app=self.app_name))
1580 self.logger.info(single_line_delim)
1581 self.logger.info(err.decode('utf-8'))
1582 self.logger.info(single_line_delim)
1583 self.result = self.process.returncode
1586 if __name__ == '__main__':