3 from __future__ import print_function
17 from collections import deque
18 from threading import Thread, Event
19 from inspect import getdoc, isclass
20 from traceback import format_exception
21 from logging import FileHandler, DEBUG, Formatter
24 from scapy.packet import Raw
25 import hook as hookmodule
26 from vpp_pg_interface import VppPGInterface
27 from vpp_sub_interface import VppSubInterface
28 from vpp_lo_interface import VppLoInterface
29 from vpp_bvi_interface import VppBviInterface
30 from vpp_papi_provider import VppPapiProvider
32 from vpp_papi.vpp_stats import VPPStats
33 from vpp_papi.vpp_transport_shmem import VppTransportShmemIOError
34 from log import RED, GREEN, YELLOW, double_line_delim, single_line_delim, \
36 from vpp_object import VppObjectRegistry
37 from util import ppp, is_core_present
38 from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
39 from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
40 from scapy.layers.inet6 import ICMPv6EchoReply
42 if os.name == 'posix' and sys.version_info[0] < 3:
43 # using subprocess32 is recommended by python official documentation
44 # @ https://docs.python.org/2/library/subprocess.html
45 import subprocess32 as subprocess
49 # Python2/3 compatible
62 class BoolEnvironmentVariable(object):
64 def __init__(self, env_var_name, default='n', true_values=None):
65 self.name = env_var_name
66 self.default = default
67 self.true_values = true_values if true_values is not None else \
71 return os.getenv(self.name, self.default).lower() in self.true_values
73 if sys.version_info[0] == 2:
74 __nonzero__ = __bool__
77 return 'BoolEnvironmentVariable(%r, default=%r, true_values=%r)' % \
78 (self.name, self.default, self.true_values)
81 debug_framework = BoolEnvironmentVariable('TEST_DEBUG')
86 Test framework module.
88 The module provides a set of tools for constructing and running tests and
89 representing the results.
93 class VppDiedError(Exception):
94 """ exception for reporting that the subprocess has died."""
96 signals_by_value = {v: k for k, v in signal.__dict__.items() if
97 k.startswith('SIG') and not k.startswith('SIG_')}
99 def __init__(self, rv=None, testcase=None, method_name=None):
101 self.signal_name = None
102 self.testcase = testcase
103 self.method_name = method_name
106 self.signal_name = VppDiedError.signals_by_value[-rv]
107 except (KeyError, TypeError):
110 if testcase is None and method_name is None:
113 in_msg = 'running %s.%s ' % (testcase, method_name)
115 msg = "VPP subprocess died %sunexpectedly with return code: %d%s." % (
118 ' [%s]' % (self.signal_name if
119 self.signal_name is not None else ''))
120 super(VppDiedError, self).__init__(msg)
123 class _PacketInfo(object):
124 """Private class to create packet info object.
126 Help process information about the next packet.
127 Set variables to default values.
129 #: Store the index of the packet.
131 #: Store the index of the source packet generator interface of the packet.
133 #: Store the index of the destination packet generator interface
136 #: Store expected ip version
138 #: Store expected upper protocol
140 #: Store the copy of the former packet.
143 def __eq__(self, other):
144 index = self.index == other.index
145 src = self.src == other.src
146 dst = self.dst == other.dst
147 data = self.data == other.data
148 return index and src and dst and data
151 def pump_output(testclass):
152 """ pump output from vpp stdout/stderr to proper queues """
155 while not testclass.pump_thread_stop_flag.is_set():
156 readable = select.select([testclass.vpp.stdout.fileno(),
157 testclass.vpp.stderr.fileno(),
158 testclass.pump_thread_wakeup_pipe[0]],
160 if testclass.vpp.stdout.fileno() in readable:
161 read = os.read(testclass.vpp.stdout.fileno(), 102400)
163 split = read.decode('ascii',
164 errors='backslashreplace').splitlines(True)
165 if len(stdout_fragment) > 0:
166 split[0] = "%s%s" % (stdout_fragment, split[0])
167 if len(split) > 0 and split[-1].endswith("\n"):
171 stdout_fragment = split[-1]
172 testclass.vpp_stdout_deque.extend(split[:limit])
173 if not testclass.cache_vpp_output:
174 for line in split[:limit]:
175 testclass.logger.info(
176 "VPP STDOUT: %s" % line.rstrip("\n"))
177 if testclass.vpp.stderr.fileno() in readable:
178 read = os.read(testclass.vpp.stderr.fileno(), 102400)
180 split = read.decode('ascii',
181 errors='backslashreplace').splitlines(True)
182 if len(stderr_fragment) > 0:
183 split[0] = "%s%s" % (stderr_fragment, split[0])
184 if len(split) > 0 and split[-1].endswith("\n"):
188 stderr_fragment = split[-1]
190 testclass.vpp_stderr_deque.extend(split[:limit])
191 if not testclass.cache_vpp_output:
192 for line in split[:limit]:
193 testclass.logger.error(
194 "VPP STDERR: %s" % line.rstrip("\n"))
195 # ignoring the dummy pipe here intentionally - the
196 # flag will take care of properly terminating the loop
199 def _is_skip_aarch64_set():
200 return BoolEnvironmentVariable('SKIP_AARCH64')
203 is_skip_aarch64_set = _is_skip_aarch64_set()
206 def _is_platform_aarch64():
207 return platform.machine() == 'aarch64'
210 is_platform_aarch64 = _is_platform_aarch64()
213 def _running_extended_tests():
214 return BoolEnvironmentVariable("EXTENDED_TESTS")
217 running_extended_tests = _running_extended_tests()
220 def _running_gcov_tests():
221 return BoolEnvironmentVariable("GCOV_TESTS")
224 running_gcov_tests = _running_gcov_tests()
227 def _running_on_centos():
228 os_id = os.getenv("OS_ID", "")
229 return True if "centos" in os_id.lower() else False
232 running_on_centos = _running_on_centos()
235 class KeepAliveReporter(object):
237 Singleton object which reports test start to parent process
242 self.__dict__ = self._shared_state
250 def pipe(self, pipe):
251 if self._pipe is not None:
252 raise Exception("Internal error - pipe should only be set once.")
255 def send_keep_alive(self, test, desc=None):
257 Write current test tmpdir & desc to keep-alive pipe to signal liveness
259 if self.pipe is None:
260 # if not running forked..
264 desc = '%s (%s)' % (desc, unittest.util.strclass(test))
268 self.pipe.send((desc, test.vpp_bin, test.tempdir, test.vpp.pid))
271 class VppTestCase(unittest.TestCase):
272 """This subclass is a base class for VPP test cases that are implemented as
273 classes. It provides methods to create and run test case.
276 extra_vpp_punt_config = []
277 extra_vpp_plugin_config = []
278 vapi_response_timeout = 5
281 def packet_infos(self):
282 """List of packet infos"""
283 return self._packet_infos
286 def get_packet_count_for_if_idx(cls, dst_if_index):
287 """Get the number of packet info for specified destination if index"""
288 if dst_if_index in cls._packet_count_for_dst_if_idx:
289 return cls._packet_count_for_dst_if_idx[dst_if_index]
295 """Return the instance of this testcase"""
296 return cls.test_instance
299 def set_debug_flags(cls, d):
300 cls.gdbserver_port = 7777
301 cls.debug_core = False
302 cls.debug_gdb = False
303 cls.debug_gdbserver = False
304 cls.debug_all = False
309 cls.debug_core = True
310 elif dl == "gdb" or dl == "gdb-all":
312 elif dl == "gdbserver" or dl == "gdbserver-all":
313 cls.debug_gdbserver = True
315 raise Exception("Unrecognized DEBUG option: '%s'" % d)
316 if dl == "gdb-all" or dl == "gdbserver-all":
320 def get_least_used_cpu():
321 cpu_usage_list = [set(range(psutil.cpu_count()))]
322 vpp_processes = [p for p in psutil.process_iter(attrs=['pid', 'name'])
323 if 'vpp_main' == p.info['name']]
324 for vpp_process in vpp_processes:
325 for cpu_usage_set in cpu_usage_list:
327 cpu_num = vpp_process.cpu_num()
328 if cpu_num in cpu_usage_set:
329 cpu_usage_set_index = cpu_usage_list.index(
331 if cpu_usage_set_index == len(cpu_usage_list) - 1:
332 cpu_usage_list.append({cpu_num})
334 cpu_usage_list[cpu_usage_set_index + 1].add(
336 cpu_usage_set.remove(cpu_num)
338 except psutil.NoSuchProcess:
341 for cpu_usage_set in cpu_usage_list:
342 if len(cpu_usage_set) > 0:
343 min_usage_set = cpu_usage_set
346 return random.choice(tuple(min_usage_set))
349 def setUpConstants(cls):
350 """ Set-up the test case class based on environment variables """
351 cls.step = BoolEnvironmentVariable('STEP')
352 d = os.getenv("DEBUG", None)
353 # inverted case to handle '' == True
354 c = os.getenv("CACHE_OUTPUT", "1")
355 cls.cache_vpp_output = False if c.lower() in ("n", "no", "0") else True
356 cls.set_debug_flags(d)
357 cls.vpp_bin = os.getenv('VPP_BIN', "vpp")
358 cls.plugin_path = os.getenv('VPP_PLUGIN_PATH')
359 cls.test_plugin_path = os.getenv('VPP_TEST_PLUGIN_PATH')
360 cls.extern_plugin_path = os.getenv('EXTERN_PLUGINS')
362 if cls.plugin_path is not None:
363 if cls.extern_plugin_path is not None:
364 plugin_path = "%s:%s" % (
365 cls.plugin_path, cls.extern_plugin_path)
367 plugin_path = cls.plugin_path
368 elif cls.extern_plugin_path is not None:
369 plugin_path = cls.extern_plugin_path
371 if cls.step or cls.debug_gdb or cls.debug_gdbserver:
372 debug_cli = "cli-listen localhost:5002"
374 size = os.getenv("COREDUMP_SIZE")
376 coredump_size = "coredump-size %s" % size
377 if coredump_size is None:
378 coredump_size = "coredump-size unlimited"
380 cpu_core_number = cls.get_least_used_cpu()
381 if not hasattr(cls, "worker_config"):
382 cls.worker_config = ""
384 cls.vpp_cmdline = [cls.vpp_bin, "unix",
385 "{", "nodaemon", debug_cli, "full-coredump",
386 coredump_size, "runtime-dir", cls.tempdir, "}",
387 "api-trace", "{", "on", "}", "api-segment", "{",
388 "prefix", cls.shm_prefix, "}", "cpu", "{",
389 "main-core", str(cpu_core_number),
390 cls.worker_config, "}",
391 "physmem", "{", "max-size", "32m", "}",
392 "statseg", "{", "socket-name", cls.stats_sock, "}",
393 "socksvr", "{", "socket-name", cls.api_sock, "}",
395 "{", "plugin", "dpdk_plugin.so", "{", "disable",
396 "}", "plugin", "rdma_plugin.so", "{", "disable",
397 "}", "plugin", "unittest_plugin.so", "{", "enable",
398 "}"] + cls.extra_vpp_plugin_config + ["}", ]
399 if cls.extra_vpp_punt_config is not None:
400 cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
401 if plugin_path is not None:
402 cls.vpp_cmdline.extend(["plugin_path", plugin_path])
403 if cls.test_plugin_path is not None:
404 cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
406 cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
407 cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
410 def wait_for_enter(cls):
411 if cls.debug_gdbserver:
412 print(double_line_delim)
413 print("Spawned GDB server with PID: %d" % cls.vpp.pid)
415 print(double_line_delim)
416 print("Spawned VPP with PID: %d" % cls.vpp.pid)
418 cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
420 print(single_line_delim)
421 print("You can debug VPP using:")
422 if cls.debug_gdbserver:
423 print("sudo gdb " + cls.vpp_bin +
424 " -ex 'target remote localhost:{port}'"
425 .format(port=cls.gdbserver_port))
426 print("Now is the time to attach gdb by running the above "
427 "command, set up breakpoints etc., then resume VPP from "
428 "within gdb by issuing the 'continue' command")
429 cls.gdbserver_port += 1
431 print("sudo gdb " + cls.vpp_bin + " -ex 'attach %s'" % cls.vpp.pid)
432 print("Now is the time to attach gdb by running the above "
433 "command and set up breakpoints etc., then resume VPP from"
434 " within gdb by issuing the 'continue' command")
435 print(single_line_delim)
436 input("Press ENTER to continue running the testcase...")
440 cmdline = cls.vpp_cmdline
442 if cls.debug_gdbserver:
443 gdbserver = '/usr/bin/gdbserver'
444 if not os.path.isfile(gdbserver) or \
445 not os.access(gdbserver, os.X_OK):
446 raise Exception("gdbserver binary '%s' does not exist or is "
447 "not executable" % gdbserver)
449 cmdline = [gdbserver, 'localhost:{port}'
450 .format(port=cls.gdbserver_port)] + cls.vpp_cmdline
451 cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
454 cls.vpp = subprocess.Popen(cmdline,
455 stdout=subprocess.PIPE,
456 stderr=subprocess.PIPE)
457 except subprocess.CalledProcessError as e:
458 cls.logger.critical("Subprocess returned with non-0 return code: ("
462 cls.logger.critical("Subprocess returned with OS error: "
463 "(%s) %s", e.errno, e.strerror)
465 except Exception as e:
466 cls.logger.exception("Subprocess returned unexpected from "
473 def wait_for_coredump(cls):
474 corefile = cls.tempdir + "/core"
475 if os.path.isfile(corefile):
476 cls.logger.error("Waiting for coredump to complete: %s", corefile)
477 curr_size = os.path.getsize(corefile)
478 deadline = time.time() + 60
480 while time.time() < deadline:
483 curr_size = os.path.getsize(corefile)
484 if size == curr_size:
488 cls.logger.error("Timed out waiting for coredump to complete:"
491 cls.logger.error("Coredump complete: %s, size %d",
497 Perform class setup before running the testcase
498 Remove shared memory files, start vpp and connect the vpp-api
500 super(VppTestCase, cls).setUpClass()
501 gc.collect() # run garbage collection first
502 cls.logger = get_logger(cls.__name__)
503 seed = os.environ["RND_SEED"]
505 if hasattr(cls, 'parallel_handler'):
506 cls.logger.addHandler(cls.parallel_handler)
507 cls.logger.propagate = False
509 cls.tempdir = tempfile.mkdtemp(
510 prefix='vpp-unittest-%s-' % cls.__name__)
511 cls.stats_sock = "%s/stats.sock" % cls.tempdir
512 cls.api_sock = "%s/api.sock" % cls.tempdir
513 cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
514 cls.file_handler.setFormatter(
515 Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
517 cls.file_handler.setLevel(DEBUG)
518 cls.logger.addHandler(cls.file_handler)
519 cls.logger.debug("--- setUpClass() for %s called ---" %
521 cls.shm_prefix = os.path.basename(cls.tempdir)
522 os.chdir(cls.tempdir)
523 cls.logger.info("Temporary dir is %s, shm prefix is %s",
524 cls.tempdir, cls.shm_prefix)
525 cls.logger.debug("Random seed is %s" % seed)
527 cls.reset_packet_infos()
531 cls.registry = VppObjectRegistry()
532 cls.vpp_startup_failed = False
533 cls.reporter = KeepAliveReporter()
534 # need to catch exceptions here because if we raise, then the cleanup
535 # doesn't get called and we might end with a zombie vpp
538 cls.reporter.send_keep_alive(cls, 'setUpClass')
539 VppTestResult.current_test_case_info = TestCaseInfo(
540 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
541 cls.vpp_stdout_deque = deque()
542 cls.vpp_stderr_deque = deque()
543 cls.pump_thread_stop_flag = Event()
544 cls.pump_thread_wakeup_pipe = os.pipe()
545 cls.pump_thread = Thread(target=pump_output, args=(cls,))
546 cls.pump_thread.daemon = True
547 cls.pump_thread.start()
548 if cls.debug_gdb or cls.debug_gdbserver:
549 cls.vapi_response_timeout = 0
550 cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
551 cls.vapi_response_timeout)
553 hook = hookmodule.StepHook(cls)
555 hook = hookmodule.PollHook(cls)
556 cls.vapi.register_hook(hook)
557 cls.statistics = VPPStats(socketname=cls.stats_sock)
561 cls.vpp_startup_failed = True
563 "VPP died shortly after startup, check the"
564 " output to standard error for possible cause")
568 except vpp_papi.VPPIOError as e:
569 cls.logger.debug("Exception connecting to vapi: %s" % e)
570 cls.vapi.disconnect()
572 if cls.debug_gdbserver:
573 print(colorize("You're running VPP inside gdbserver but "
574 "VPP-API connection failed, did you forget "
575 "to 'continue' VPP from within gdb?", RED))
577 except Exception as e:
578 cls.logger.debug("Exception connecting to VPP: %s" % e)
584 def _debug_quit(cls):
585 if (cls.debug_gdbserver or cls.debug_gdb):
589 if cls.vpp.returncode is None:
591 print(double_line_delim)
592 print("VPP or GDB server is still running")
593 print(single_line_delim)
594 input("When done debugging, press ENTER to kill the "
595 "process and finish running the testcase...")
596 except AttributeError:
602 Disconnect vpp-api, kill vpp and cleanup shared memory files
606 # first signal that we want to stop the pump thread, then wake it up
607 if hasattr(cls, 'pump_thread_stop_flag'):
608 cls.pump_thread_stop_flag.set()
609 if hasattr(cls, 'pump_thread_wakeup_pipe'):
610 os.write(cls.pump_thread_wakeup_pipe[1], b'ding dong wake up')
611 if hasattr(cls, 'pump_thread'):
612 cls.logger.debug("Waiting for pump thread to stop")
613 cls.pump_thread.join()
614 if hasattr(cls, 'vpp_stderr_reader_thread'):
615 cls.logger.debug("Waiting for stderr pump to stop")
616 cls.vpp_stderr_reader_thread.join()
618 if hasattr(cls, 'vpp'):
619 if hasattr(cls, 'vapi'):
620 cls.logger.debug(cls.vapi.vpp.get_stats())
621 cls.logger.debug("Disconnecting class vapi client on %s",
623 cls.vapi.disconnect()
624 cls.logger.debug("Deleting class vapi attribute on %s",
628 if cls.vpp.returncode is None:
629 cls.wait_for_coredump()
630 cls.logger.debug("Sending TERM to vpp")
632 cls.logger.debug("Waiting for vpp to die")
633 cls.vpp.communicate()
634 cls.logger.debug("Deleting class vpp attribute on %s",
638 if cls.vpp_startup_failed:
639 stdout_log = cls.logger.info
640 stderr_log = cls.logger.critical
642 stdout_log = cls.logger.info
643 stderr_log = cls.logger.info
645 if hasattr(cls, 'vpp_stdout_deque'):
646 stdout_log(single_line_delim)
647 stdout_log('VPP output to stdout while running %s:', cls.__name__)
648 stdout_log(single_line_delim)
649 vpp_output = "".join(cls.vpp_stdout_deque)
650 with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
652 stdout_log('\n%s', vpp_output)
653 stdout_log(single_line_delim)
655 if hasattr(cls, 'vpp_stderr_deque'):
656 stderr_log(single_line_delim)
657 stderr_log('VPP output to stderr while running %s:', cls.__name__)
658 stderr_log(single_line_delim)
659 vpp_output = "".join(cls.vpp_stderr_deque)
660 with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
662 stderr_log('\n%s', vpp_output)
663 stderr_log(single_line_delim)
666 def tearDownClass(cls):
667 """ Perform final cleanup after running all tests in this test-case """
668 cls.logger.debug("--- tearDownClass() for %s called ---" %
670 cls.reporter.send_keep_alive(cls, 'tearDownClass')
672 cls.file_handler.close()
673 cls.reset_packet_infos()
675 debug_internal.on_tear_down_class(cls)
677 def show_commands_at_teardown(self):
678 """ Allow subclass specific teardown logging additions."""
679 self.logger.info("--- No test specific show commands provided. ---")
682 """ Show various debug prints after each test """
683 self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
684 (self.__class__.__name__, self._testMethodName,
685 self._testMethodDoc))
688 if not self.vpp_dead:
689 self.logger.debug(self.vapi.cli("show trace max 1000"))
690 self.logger.info(self.vapi.ppcli("show interface"))
691 self.logger.info(self.vapi.ppcli("show hardware"))
692 self.logger.info(self.statistics.set_errors_str())
693 self.logger.info(self.vapi.ppcli("show run"))
694 self.logger.info(self.vapi.ppcli("show log"))
695 self.logger.info(self.vapi.ppcli("show bihash"))
696 self.logger.info("Logging testcase specific show commands.")
697 self.show_commands_at_teardown()
698 self.registry.remove_vpp_config(self.logger)
699 # Save/Dump VPP api trace log
700 m = self._testMethodName
701 api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
702 tmp_api_trace = "/tmp/%s" % api_trace
703 vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
704 self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
705 self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
707 os.rename(tmp_api_trace, vpp_api_trace_log)
708 self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
710 except VppTransportShmemIOError:
711 self.logger.debug("VppTransportShmemIOError: Vpp dead. "
712 "Cannot log show commands.")
715 self.registry.unregister_all(self.logger)
718 """ Clear trace before running each test"""
719 super(VppTestCase, self).setUp()
720 self.reporter.send_keep_alive(self)
723 raise VppDiedError(rv=None, testcase=self.__class__.__name__,
724 method_name=self._testMethodName)
725 self.sleep(.1, "during setUp")
726 self.vpp_stdout_deque.append(
727 "--- test setUp() for %s.%s(%s) starts here ---\n" %
728 (self.__class__.__name__, self._testMethodName,
729 self._testMethodDoc))
730 self.vpp_stderr_deque.append(
731 "--- test setUp() for %s.%s(%s) starts here ---\n" %
732 (self.__class__.__name__, self._testMethodName,
733 self._testMethodDoc))
734 self.vapi.cli("clear trace")
735 # store the test instance inside the test class - so that objects
736 # holding the class can access instance methods (like assertEqual)
737 type(self).test_instance = self
740 def pg_enable_capture(cls, interfaces=None):
742 Enable capture on packet-generator interfaces
744 :param interfaces: iterable interface indexes (if None,
745 use self.pg_interfaces)
748 if interfaces is None:
749 interfaces = cls.pg_interfaces
754 def register_capture(cls, cap_name):
755 """ Register a capture in the testclass """
756 # add to the list of captures with current timestamp
757 cls._captures.append((time.time(), cap_name))
760 def get_vpp_time(cls):
761 # processes e.g. "Time now 2.190522, Wed, 11 Mar 2020 17:29:54 GMT"
762 # returns float("2.190522")
763 timestr = cls.vapi.cli('show clock')
764 head, sep, tail = timestr.partition(',')
765 head, sep, tail = head.partition('Time now')
769 def sleep_on_vpp_time(cls, sec):
770 """ Sleep according to time in VPP world """
771 # On a busy system with many processes
772 # we might end up with VPP time being slower than real world
773 # So take that into account when waiting for VPP to do something
774 start_time = cls.get_vpp_time()
775 while cls.get_vpp_time() - start_time < sec:
780 """ Enable the PG, wait till it is done, then clean up """
781 cls.vapi.cli("trace add pg-input 1000")
782 cls.vapi.cli('packet-generator enable')
783 # PG, when starts, runs to completion -
784 # so let's avoid a race condition,
785 # and wait a little till it's done.
786 # Then clean it up - and then be gone.
787 deadline = time.time() + 300
788 while cls.vapi.cli('show packet-generator').find("Yes") != -1:
789 cls.sleep(0.01) # yield
790 if time.time() > deadline:
791 cls.logger.error("Timeout waiting for pg to stop")
793 for stamp, cap_name in cls._captures:
794 cls.vapi.cli('packet-generator delete %s' % cap_name)
798 def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
800 Create packet-generator interfaces.
802 :param interfaces: iterable indexes of the interfaces.
803 :returns: List of created interfaces.
808 intf = VppPGInterface(cls, i, gso, gso_size)
809 setattr(cls, intf.name, intf)
811 cls.pg_interfaces = result
815 def create_loopback_interfaces(cls, count):
817 Create loopback interfaces.
819 :param count: number of interfaces created.
820 :returns: List of created interfaces.
822 result = [VppLoInterface(cls) for i in range(count)]
824 setattr(cls, intf.name, intf)
825 cls.lo_interfaces = result
829 def create_bvi_interfaces(cls, count):
831 Create BVI interfaces.
833 :param count: number of interfaces created.
834 :returns: List of created interfaces.
836 result = [VppBviInterface(cls) for i in range(count)]
838 setattr(cls, intf.name, intf)
839 cls.bvi_interfaces = result
843 def extend_packet(packet, size, padding=' '):
845 Extend packet to given size by padding with spaces or custom padding
846 NOTE: Currently works only when Raw layer is present.
848 :param packet: packet
849 :param size: target size
850 :param padding: padding used to extend the payload
853 packet_len = len(packet) + 4
854 extend = size - packet_len
856 num = (extend // len(padding)) + 1
857 packet[Raw].load += (padding * num)[:extend].encode("ascii")
860 def reset_packet_infos(cls):
861 """ Reset the list of packet info objects and packet counts to zero """
862 cls._packet_infos = {}
863 cls._packet_count_for_dst_if_idx = {}
866 def create_packet_info(cls, src_if, dst_if):
868 Create packet info object containing the source and destination indexes
869 and add it to the testcase's packet info list
871 :param VppInterface src_if: source interface
872 :param VppInterface dst_if: destination interface
874 :returns: _PacketInfo object
878 info.index = len(cls._packet_infos)
879 info.src = src_if.sw_if_index
880 info.dst = dst_if.sw_if_index
881 if isinstance(dst_if, VppSubInterface):
882 dst_idx = dst_if.parent.sw_if_index
884 dst_idx = dst_if.sw_if_index
885 if dst_idx in cls._packet_count_for_dst_if_idx:
886 cls._packet_count_for_dst_if_idx[dst_idx] += 1
888 cls._packet_count_for_dst_if_idx[dst_idx] = 1
889 cls._packet_infos[info.index] = info
893 def info_to_payload(info):
895 Convert _PacketInfo object to packet payload
897 :param info: _PacketInfo object
899 :returns: string containing serialized data from packet info
901 return "%d %d %d %d %d" % (info.index, info.src, info.dst,
905 def payload_to_info(payload, payload_field='load'):
907 Convert packet payload to _PacketInfo object
909 :param payload: packet payload
910 :type payload: <class 'scapy.packet.Raw'>
911 :param payload_field: packet fieldname of payload "load" for
912 <class 'scapy.packet.Raw'>
913 :type payload_field: str
914 :returns: _PacketInfo object containing de-serialized data from payload
917 numbers = getattr(payload, payload_field).split()
919 info.index = int(numbers[0])
920 info.src = int(numbers[1])
921 info.dst = int(numbers[2])
922 info.ip = int(numbers[3])
923 info.proto = int(numbers[4])
926 def get_next_packet_info(self, info):
928 Iterate over the packet info list stored in the testcase
929 Start iteration with first element if info is None
930 Continue based on index in info if info is specified
932 :param info: info or None
933 :returns: next info in list or None if no more infos
938 next_index = info.index + 1
939 if next_index == len(self._packet_infos):
942 return self._packet_infos[next_index]
944 def get_next_packet_info_for_interface(self, src_index, info):
946 Search the packet info list for the next packet info with same source
949 :param src_index: source interface index to search for
950 :param info: packet info - where to start the search
951 :returns: packet info or None
955 info = self.get_next_packet_info(info)
958 if info.src == src_index:
961 def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
963 Search the packet info list for the next packet info with same source
964 and destination interface indexes
966 :param src_index: source interface index to search for
967 :param dst_index: destination interface index to search for
968 :param info: packet info - where to start the search
969 :returns: packet info or None
973 info = self.get_next_packet_info_for_interface(src_index, info)
976 if info.dst == dst_index:
979 def assert_equal(self, real_value, expected_value, name_or_class=None):
980 if name_or_class is None:
981 self.assertEqual(real_value, expected_value)
984 msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
985 msg = msg % (getdoc(name_or_class).strip(),
986 real_value, str(name_or_class(real_value)),
987 expected_value, str(name_or_class(expected_value)))
989 msg = "Invalid %s: %s does not match expected value %s" % (
990 name_or_class, real_value, expected_value)
992 self.assertEqual(real_value, expected_value, msg)
994 def assert_in_range(self,
1002 msg = "Invalid %s: %s out of range <%s,%s>" % (
1003 name, real_value, expected_min, expected_max)
1004 self.assertTrue(expected_min <= real_value <= expected_max, msg)
1006 def assert_packet_checksums_valid(self, packet,
1007 ignore_zero_udp_checksums=True):
1008 received = packet.__class__(scapy.compat.raw(packet))
1009 udp_layers = ['UDP', 'UDPerror']
1010 checksum_fields = ['cksum', 'chksum']
1013 temp = received.__class__(scapy.compat.raw(received))
1015 layer = temp.getlayer(counter)
1017 layer = layer.copy()
1018 layer.remove_payload()
1019 for cf in checksum_fields:
1020 if hasattr(layer, cf):
1021 if ignore_zero_udp_checksums and \
1022 0 == getattr(layer, cf) and \
1023 layer.name in udp_layers:
1025 delattr(temp.getlayer(counter), cf)
1026 checksums.append((counter, cf))
1029 counter = counter + 1
1030 if 0 == len(checksums):
1032 temp = temp.__class__(scapy.compat.raw(temp))
1033 for layer, cf in checksums:
1034 calc_sum = getattr(temp[layer], cf)
1036 getattr(received[layer], cf), calc_sum,
1037 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1039 "Checksum field `%s` on `%s` layer has correct value `%s`" %
1040 (cf, temp[layer].name, calc_sum))
1042 def assert_checksum_valid(self, received_packet, layer,
1043 field_name='chksum',
1044 ignore_zero_checksum=False):
1045 """ Check checksum of received packet on given layer """
1046 received_packet_checksum = getattr(received_packet[layer], field_name)
1047 if ignore_zero_checksum and 0 == received_packet_checksum:
1049 recalculated = received_packet.__class__(
1050 scapy.compat.raw(received_packet))
1051 delattr(recalculated[layer], field_name)
1052 recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1053 self.assert_equal(received_packet_checksum,
1054 getattr(recalculated[layer], field_name),
1055 "packet checksum on layer: %s" % layer)
1057 def assert_ip_checksum_valid(self, received_packet,
1058 ignore_zero_checksum=False):
1059 self.assert_checksum_valid(received_packet, 'IP',
1060 ignore_zero_checksum=ignore_zero_checksum)
1062 def assert_tcp_checksum_valid(self, received_packet,
1063 ignore_zero_checksum=False):
1064 self.assert_checksum_valid(received_packet, 'TCP',
1065 ignore_zero_checksum=ignore_zero_checksum)
1067 def assert_udp_checksum_valid(self, received_packet,
1068 ignore_zero_checksum=True):
1069 self.assert_checksum_valid(received_packet, 'UDP',
1070 ignore_zero_checksum=ignore_zero_checksum)
1072 def assert_embedded_icmp_checksum_valid(self, received_packet):
1073 if received_packet.haslayer(IPerror):
1074 self.assert_checksum_valid(received_packet, 'IPerror')
1075 if received_packet.haslayer(TCPerror):
1076 self.assert_checksum_valid(received_packet, 'TCPerror')
1077 if received_packet.haslayer(UDPerror):
1078 self.assert_checksum_valid(received_packet, 'UDPerror',
1079 ignore_zero_checksum=True)
1080 if received_packet.haslayer(ICMPerror):
1081 self.assert_checksum_valid(received_packet, 'ICMPerror')
1083 def assert_icmp_checksum_valid(self, received_packet):
1084 self.assert_checksum_valid(received_packet, 'ICMP')
1085 self.assert_embedded_icmp_checksum_valid(received_packet)
1087 def assert_icmpv6_checksum_valid(self, pkt):
1088 if pkt.haslayer(ICMPv6DestUnreach):
1089 self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1090 self.assert_embedded_icmp_checksum_valid(pkt)
1091 if pkt.haslayer(ICMPv6EchoRequest):
1092 self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1093 if pkt.haslayer(ICMPv6EchoReply):
1094 self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1096 def get_packet_counter(self, counter):
1097 if counter.startswith("/"):
1098 counter_value = self.statistics.get_counter(counter)
1100 counters = self.vapi.cli("sh errors").split('\n')
1102 for i in range(1, len(counters) - 1):
1103 results = counters[i].split()
1104 if results[1] == counter:
1105 counter_value = int(results[0])
1107 return counter_value
1109 def assert_packet_counter_equal(self, counter, expected_value):
1110 counter_value = self.get_packet_counter(counter)
1111 self.assert_equal(counter_value, expected_value,
1112 "packet counter `%s'" % counter)
1114 def assert_error_counter_equal(self, counter, expected_value):
1115 counter_value = self.statistics.get_err_counter(counter)
1116 self.assert_equal(counter_value, expected_value,
1117 "error counter `%s'" % counter)
1120 def sleep(cls, timeout, remark=None):
1122 # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1123 # * by Guido, only the main thread can be interrupted.
1125 # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892 # noqa
1128 if hasattr(os, 'sched_yield'):
1134 if hasattr(cls, 'logger'):
1135 cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1136 before = time.time()
1139 if hasattr(cls, 'logger') and after - before > 2 * timeout:
1140 cls.logger.error("unexpected self.sleep() result - "
1141 "slept for %es instead of ~%es!",
1142 after - before, timeout)
1143 if hasattr(cls, 'logger'):
1145 "Finished sleep (%s) - slept %es (wanted %es)",
1146 remark, after - before, timeout)
1148 def pg_send(self, intf, pkts, worker=None):
1149 self.vapi.cli("clear trace")
1150 intf.add_stream(pkts, worker=worker)
1151 self.pg_enable_capture(self.pg_interfaces)
1154 def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1155 self.pg_send(intf, pkts)
1158 for i in self.pg_interfaces:
1159 i.get_capture(0, timeout=timeout)
1160 i.assert_nothing_captured(remark=remark)
1163 def send_and_expect(self, intf, pkts, output, n_rx=None, worker=None):
1166 self.pg_send(intf, pkts, worker=worker)
1167 rx = output.get_capture(n_rx)
1170 def send_and_expect_only(self, intf, pkts, output, timeout=None):
1171 self.pg_send(intf, pkts)
1172 rx = output.get_capture(len(pkts))
1176 for i in self.pg_interfaces:
1177 if i not in outputs:
1178 i.get_capture(0, timeout=timeout)
1179 i.assert_nothing_captured()
1185 def get_testcase_doc_name(test):
1186 return getdoc(test.__class__).splitlines()[0]
1189 def get_test_description(descriptions, test):
1190 short_description = test.shortDescription()
1191 if descriptions and short_description:
1192 return short_description
1197 class TestCaseInfo(object):
1198 def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1199 self.logger = logger
1200 self.tempdir = tempdir
1201 self.vpp_pid = vpp_pid
1202 self.vpp_bin_path = vpp_bin_path
1203 self.core_crash_test = None
1206 class VppTestResult(unittest.TestResult):
1208 @property result_string
1209 String variable to store the test case result string.
1211 List variable containing 2-tuples of TestCase instances and strings
1212 holding formatted tracebacks. Each tuple represents a test which
1213 raised an unexpected exception.
1215 List variable containing 2-tuples of TestCase instances and strings
1216 holding formatted tracebacks. Each tuple represents a test where
1217 a failure was explicitly signalled using the TestCase.assert*()
1221 failed_test_cases_info = set()
1222 core_crash_test_cases_info = set()
1223 current_test_case_info = None
1225 def __init__(self, stream=None, descriptions=None, verbosity=None,
1228 :param stream File descriptor to store where to report test results.
1229 Set to the standard error stream by default.
1230 :param descriptions Boolean variable to store information if to use
1231 test case descriptions.
1232 :param verbosity Integer variable to store required verbosity level.
1234 super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1235 self.stream = stream
1236 self.descriptions = descriptions
1237 self.verbosity = verbosity
1238 self.result_string = None
1239 self.runner = runner
1241 def addSuccess(self, test):
1243 Record a test succeeded result
1248 if self.current_test_case_info:
1249 self.current_test_case_info.logger.debug(
1250 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1251 test._testMethodName,
1252 test._testMethodDoc))
1253 unittest.TestResult.addSuccess(self, test)
1254 self.result_string = colorize("OK", GREEN)
1256 self.send_result_through_pipe(test, PASS)
1258 def addSkip(self, test, reason):
1260 Record a test skipped.
1266 if self.current_test_case_info:
1267 self.current_test_case_info.logger.debug(
1268 "--- addSkip() %s.%s(%s) called, reason is %s" %
1269 (test.__class__.__name__, test._testMethodName,
1270 test._testMethodDoc, reason))
1271 unittest.TestResult.addSkip(self, test, reason)
1272 self.result_string = colorize("SKIP", YELLOW)
1274 self.send_result_through_pipe(test, SKIP)
1276 def symlink_failed(self):
1277 if self.current_test_case_info:
1279 failed_dir = os.getenv('FAILED_DIR')
1280 link_path = os.path.join(
1283 os.path.basename(self.current_test_case_info.tempdir))
1284 if self.current_test_case_info.logger:
1285 self.current_test_case_info.logger.debug(
1286 "creating a link to the failed test")
1287 self.current_test_case_info.logger.debug(
1288 "os.symlink(%s, %s)" %
1289 (self.current_test_case_info.tempdir, link_path))
1290 if os.path.exists(link_path):
1291 if self.current_test_case_info.logger:
1292 self.current_test_case_info.logger.debug(
1293 'symlink already exists')
1295 os.symlink(self.current_test_case_info.tempdir, link_path)
1297 except Exception as e:
1298 if self.current_test_case_info.logger:
1299 self.current_test_case_info.logger.error(e)
1301 def send_result_through_pipe(self, test, result):
1302 if hasattr(self, 'test_framework_result_pipe'):
1303 pipe = self.test_framework_result_pipe
1305 pipe.send((test.id(), result))
1307 def log_error(self, test, err, fn_name):
1308 if self.current_test_case_info:
1309 if isinstance(test, unittest.suite._ErrorHolder):
1310 test_name = test.description
1312 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1313 test._testMethodName,
1314 test._testMethodDoc)
1315 self.current_test_case_info.logger.debug(
1316 "--- %s() %s called, err is %s" %
1317 (fn_name, test_name, err))
1318 self.current_test_case_info.logger.debug(
1319 "formatted exception is:\n%s" %
1320 "".join(format_exception(*err)))
1322 def add_error(self, test, err, unittest_fn, error_type):
1323 if error_type == FAIL:
1324 self.log_error(test, err, 'addFailure')
1325 error_type_str = colorize("FAIL", RED)
1326 elif error_type == ERROR:
1327 self.log_error(test, err, 'addError')
1328 error_type_str = colorize("ERROR", RED)
1330 raise Exception('Error type %s cannot be used to record an '
1331 'error or a failure' % error_type)
1333 unittest_fn(self, test, err)
1334 if self.current_test_case_info:
1335 self.result_string = "%s [ temp dir used by test case: %s ]" % \
1337 self.current_test_case_info.tempdir)
1338 self.symlink_failed()
1339 self.failed_test_cases_info.add(self.current_test_case_info)
1340 if is_core_present(self.current_test_case_info.tempdir):
1341 if not self.current_test_case_info.core_crash_test:
1342 if isinstance(test, unittest.suite._ErrorHolder):
1343 test_name = str(test)
1345 test_name = "'{!s}' ({!s})".format(
1346 get_testcase_doc_name(test), test.id())
1347 self.current_test_case_info.core_crash_test = test_name
1348 self.core_crash_test_cases_info.add(
1349 self.current_test_case_info)
1351 self.result_string = '%s [no temp dir]' % error_type_str
1353 self.send_result_through_pipe(test, error_type)
1355 def addFailure(self, test, err):
1357 Record a test failed result
1360 :param err: error message
1363 self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1365 def addError(self, test, err):
1367 Record a test error result
1370 :param err: error message
1373 self.add_error(test, err, unittest.TestResult.addError, ERROR)
1375 def getDescription(self, test):
1377 Get test description
1380 :returns: test description
1383 return get_test_description(self.descriptions, test)
1385 def startTest(self, test):
1393 def print_header(test):
1394 if not hasattr(test.__class__, '_header_printed'):
1395 print(double_line_delim)
1396 print(colorize(getdoc(test).splitlines()[0], GREEN))
1397 print(double_line_delim)
1398 test.__class__._header_printed = True
1401 self.start_test = time.time()
1402 unittest.TestResult.startTest(self, test)
1403 if self.verbosity > 0:
1404 self.stream.writeln(
1405 "Starting " + self.getDescription(test) + " ...")
1406 self.stream.writeln(single_line_delim)
1408 def stopTest(self, test):
1410 Called when the given test has been run
1415 unittest.TestResult.stopTest(self, test)
1417 if self.verbosity > 0:
1418 self.stream.writeln(single_line_delim)
1419 self.stream.writeln("%-73s%s" % (self.getDescription(test),
1420 self.result_string))
1421 self.stream.writeln(single_line_delim)
1423 self.stream.writeln("%-68s %4.2f %s" %
1424 (self.getDescription(test),
1425 time.time() - self.start_test,
1426 self.result_string))
1428 self.send_result_through_pipe(test, TEST_RUN)
1430 def printErrors(self):
1432 Print errors from running the test case
1434 if len(self.errors) > 0 or len(self.failures) > 0:
1435 self.stream.writeln()
1436 self.printErrorList('ERROR', self.errors)
1437 self.printErrorList('FAIL', self.failures)
1439 # ^^ that is the last output from unittest before summary
1440 if not self.runner.print_summary:
1441 devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1442 self.stream = devnull
1443 self.runner.stream = devnull
1445 def printErrorList(self, flavour, errors):
1447 Print error list to the output stream together with error type
1448 and test case description.
1450 :param flavour: error type
1451 :param errors: iterable errors
1454 for test, err in errors:
1455 self.stream.writeln(double_line_delim)
1456 self.stream.writeln("%s: %s" %
1457 (flavour, self.getDescription(test)))
1458 self.stream.writeln(single_line_delim)
1459 self.stream.writeln("%s" % err)
1462 class VppTestRunner(unittest.TextTestRunner):
1464 A basic test runner implementation which prints results to standard error.
1468 def resultclass(self):
1469 """Class maintaining the results of the tests"""
1470 return VppTestResult
1472 def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1473 result_pipe=None, failfast=False, buffer=False,
1474 resultclass=None, print_summary=True, **kwargs):
1475 # ignore stream setting here, use hard-coded stdout to be in sync
1476 # with prints from VppTestCase methods ...
1477 super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1478 verbosity, failfast, buffer,
1479 resultclass, **kwargs)
1480 KeepAliveReporter.pipe = keep_alive_pipe
1482 self.orig_stream = self.stream
1483 self.resultclass.test_framework_result_pipe = result_pipe
1485 self.print_summary = print_summary
1487 def _makeResult(self):
1488 return self.resultclass(self.stream,
1493 def run(self, test):
1500 faulthandler.enable() # emit stack trace to stderr if killed by signal
1502 result = super(VppTestRunner, self).run(test)
1503 if not self.print_summary:
1504 self.stream = self.orig_stream
1505 result.stream = self.orig_stream
1509 class Worker(Thread):
1510 def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1511 super(Worker, self).__init__(*args, **kwargs)
1512 self.logger = logger
1513 self.args = executable_args
1514 if hasattr(self, 'testcase') and self.testcase.debug_all:
1515 if self.testcase.debug_gdbserver:
1516 self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1517 .format(port=self.testcase.gdbserver_port)] + args
1518 elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1519 self.args.append(self.wait_for_gdb)
1520 self.app_bin = executable_args[0]
1521 self.app_name = os.path.basename(self.app_bin)
1522 if hasattr(self, 'role'):
1523 self.app_name += ' {role}'.format(role=self.role)
1526 env = {} if env is None else env
1527 self.env = copy.deepcopy(env)
1529 def wait_for_enter(self):
1530 if not hasattr(self, 'testcase'):
1532 if self.testcase.debug_all and self.testcase.debug_gdbserver:
1534 print(double_line_delim)
1535 print("Spawned GDB Server for '{app}' with PID: {pid}"
1536 .format(app=self.app_name, pid=self.process.pid))
1537 elif self.testcase.debug_all and self.testcase.debug_gdb:
1539 print(double_line_delim)
1540 print("Spawned '{app}' with PID: {pid}"
1541 .format(app=self.app_name, pid=self.process.pid))
1544 print(single_line_delim)
1545 print("You can debug '{app}' using:".format(app=self.app_name))
1546 if self.testcase.debug_gdbserver:
1547 print("sudo gdb " + self.app_bin +
1548 " -ex 'target remote localhost:{port}'"
1549 .format(port=self.testcase.gdbserver_port))
1550 print("Now is the time to attach gdb by running the above "
1551 "command, set up breakpoints etc., then resume from "
1552 "within gdb by issuing the 'continue' command")
1553 self.testcase.gdbserver_port += 1
1554 elif self.testcase.debug_gdb:
1555 print("sudo gdb " + self.app_bin +
1556 " -ex 'attach {pid}'".format(pid=self.process.pid))
1557 print("Now is the time to attach gdb by running the above "
1558 "command and set up breakpoints etc., then resume from"
1559 " within gdb by issuing the 'continue' command")
1560 print(single_line_delim)
1561 input("Press ENTER to continue running the testcase...")
1564 executable = self.args[0]
1565 if not os.path.exists(executable) or not os.access(
1566 executable, os.F_OK | os.X_OK):
1567 # Exit code that means some system file did not exist,
1568 # could not be opened, or had some other kind of error.
1569 self.result = os.EX_OSFILE
1570 raise EnvironmentError(
1571 "executable '%s' is not found or executable." % executable)
1572 self.logger.debug("Running executable: '{app}'"
1573 .format(app=' '.join(self.args)))
1574 env = os.environ.copy()
1575 env.update(self.env)
1576 env["CK_LOG_FILE_NAME"] = "-"
1577 self.process = subprocess.Popen(
1578 self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1579 stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1580 self.wait_for_enter()
1581 out, err = self.process.communicate()
1582 self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1583 self.logger.info("Return code is `%s'" % self.process.returncode)
1584 self.logger.info(single_line_delim)
1585 self.logger.info("Executable `{app}' wrote to stdout:"
1586 .format(app=self.app_name))
1587 self.logger.info(single_line_delim)
1588 self.logger.info(out.decode('utf-8'))
1589 self.logger.info(single_line_delim)
1590 self.logger.info("Executable `{app}' wrote to stderr:"
1591 .format(app=self.app_name))
1592 self.logger.info(single_line_delim)
1593 self.logger.info(err.decode('utf-8'))
1594 self.logger.info(single_line_delim)
1595 self.result = self.process.returncode
1598 if __name__ == '__main__':