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