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 default_variant = os.getenv("VARIANT")
385 if default_variant is not None:
386 default_variant = "defaults { %s 100 }" % default_variant
390 cls.vpp_cmdline = [cls.vpp_bin, "unix",
391 "{", "nodaemon", debug_cli, "full-coredump",
392 coredump_size, "runtime-dir", cls.tempdir, "}",
393 "api-trace", "{", "on", "}", "api-segment", "{",
394 "prefix", cls.shm_prefix, "}", "cpu", "{",
395 "main-core", str(cpu_core_number),
396 cls.worker_config, "}",
397 "physmem", "{", "max-size", "32m", "}",
398 "statseg", "{", "socket-name", cls.stats_sock, "}",
399 "socksvr", "{", "socket-name", cls.api_sock, "}",
400 "node { ", default_variant, "}",
402 "{", "plugin", "dpdk_plugin.so", "{", "disable",
403 "}", "plugin", "rdma_plugin.so", "{", "disable",
404 "}", "plugin", "unittest_plugin.so", "{", "enable",
405 "}"] + cls.extra_vpp_plugin_config + ["}", ]
407 if cls.extra_vpp_punt_config is not None:
408 cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
409 if plugin_path is not None:
410 cls.vpp_cmdline.extend(["plugin_path", plugin_path])
411 if cls.test_plugin_path is not None:
412 cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
414 cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
415 cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
418 def wait_for_enter(cls):
419 if cls.debug_gdbserver:
420 print(double_line_delim)
421 print("Spawned GDB server with PID: %d" % cls.vpp.pid)
423 print(double_line_delim)
424 print("Spawned VPP with PID: %d" % cls.vpp.pid)
426 cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
428 print(single_line_delim)
429 print("You can debug VPP using:")
430 if cls.debug_gdbserver:
431 print("sudo gdb " + cls.vpp_bin +
432 " -ex 'target remote localhost:{port}'"
433 .format(port=cls.gdbserver_port))
434 print("Now is the time to attach gdb by running the above "
435 "command, set up breakpoints etc., then resume VPP from "
436 "within gdb by issuing the 'continue' command")
437 cls.gdbserver_port += 1
439 print("sudo gdb " + cls.vpp_bin + " -ex 'attach %s'" % cls.vpp.pid)
440 print("Now is the time to attach gdb by running the above "
441 "command and set up breakpoints etc., then resume VPP from"
442 " within gdb by issuing the 'continue' command")
443 print(single_line_delim)
444 input("Press ENTER to continue running the testcase...")
448 cmdline = cls.vpp_cmdline
450 if cls.debug_gdbserver:
451 gdbserver = '/usr/bin/gdbserver'
452 if not os.path.isfile(gdbserver) or \
453 not os.access(gdbserver, os.X_OK):
454 raise Exception("gdbserver binary '%s' does not exist or is "
455 "not executable" % gdbserver)
457 cmdline = [gdbserver, 'localhost:{port}'
458 .format(port=cls.gdbserver_port)] + cls.vpp_cmdline
459 cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
462 cls.vpp = subprocess.Popen(cmdline,
463 stdout=subprocess.PIPE,
464 stderr=subprocess.PIPE)
465 except subprocess.CalledProcessError as e:
466 cls.logger.critical("Subprocess returned with non-0 return code: ("
470 cls.logger.critical("Subprocess returned with OS error: "
471 "(%s) %s", e.errno, e.strerror)
473 except Exception as e:
474 cls.logger.exception("Subprocess returned unexpected from "
481 def wait_for_coredump(cls):
482 corefile = cls.tempdir + "/core"
483 if os.path.isfile(corefile):
484 cls.logger.error("Waiting for coredump to complete: %s", corefile)
485 curr_size = os.path.getsize(corefile)
486 deadline = time.time() + 60
488 while time.time() < deadline:
491 curr_size = os.path.getsize(corefile)
492 if size == curr_size:
496 cls.logger.error("Timed out waiting for coredump to complete:"
499 cls.logger.error("Coredump complete: %s, size %d",
505 Perform class setup before running the testcase
506 Remove shared memory files, start vpp and connect the vpp-api
508 super(VppTestCase, cls).setUpClass()
509 gc.collect() # run garbage collection first
510 cls.logger = get_logger(cls.__name__)
511 seed = os.environ["RND_SEED"]
513 if hasattr(cls, 'parallel_handler'):
514 cls.logger.addHandler(cls.parallel_handler)
515 cls.logger.propagate = False
517 cls.tempdir = tempfile.mkdtemp(
518 prefix='vpp-unittest-%s-' % cls.__name__)
519 cls.stats_sock = "%s/stats.sock" % cls.tempdir
520 cls.api_sock = "%s/api.sock" % cls.tempdir
521 cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
522 cls.file_handler.setFormatter(
523 Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
525 cls.file_handler.setLevel(DEBUG)
526 cls.logger.addHandler(cls.file_handler)
527 cls.logger.debug("--- setUpClass() for %s called ---" %
529 cls.shm_prefix = os.path.basename(cls.tempdir)
530 os.chdir(cls.tempdir)
531 cls.logger.info("Temporary dir is %s, shm prefix is %s",
532 cls.tempdir, cls.shm_prefix)
533 cls.logger.debug("Random seed is %s" % seed)
535 cls.reset_packet_infos()
539 cls.registry = VppObjectRegistry()
540 cls.vpp_startup_failed = False
541 cls.reporter = KeepAliveReporter()
542 # need to catch exceptions here because if we raise, then the cleanup
543 # doesn't get called and we might end with a zombie vpp
546 cls.reporter.send_keep_alive(cls, 'setUpClass')
547 VppTestResult.current_test_case_info = TestCaseInfo(
548 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
549 cls.vpp_stdout_deque = deque()
550 cls.vpp_stderr_deque = deque()
551 cls.pump_thread_stop_flag = Event()
552 cls.pump_thread_wakeup_pipe = os.pipe()
553 cls.pump_thread = Thread(target=pump_output, args=(cls,))
554 cls.pump_thread.daemon = True
555 cls.pump_thread.start()
556 if cls.debug_gdb or cls.debug_gdbserver:
557 cls.vapi_response_timeout = 0
558 cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
559 cls.vapi_response_timeout)
561 hook = hookmodule.StepHook(cls)
563 hook = hookmodule.PollHook(cls)
564 cls.vapi.register_hook(hook)
565 cls.statistics = VPPStats(socketname=cls.stats_sock)
569 cls.vpp_startup_failed = True
571 "VPP died shortly after startup, check the"
572 " output to standard error for possible cause")
576 except vpp_papi.VPPIOError as e:
577 cls.logger.debug("Exception connecting to vapi: %s" % e)
578 cls.vapi.disconnect()
580 if cls.debug_gdbserver:
581 print(colorize("You're running VPP inside gdbserver but "
582 "VPP-API connection failed, did you forget "
583 "to 'continue' VPP from within gdb?", RED))
585 except Exception as e:
586 cls.logger.debug("Exception connecting to VPP: %s" % e)
592 def _debug_quit(cls):
593 if (cls.debug_gdbserver or cls.debug_gdb):
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...")
604 except AttributeError:
610 Disconnect vpp-api, kill vpp and cleanup shared memory files
614 # first signal that we want to stop the pump thread, then wake it up
615 if hasattr(cls, 'pump_thread_stop_flag'):
616 cls.pump_thread_stop_flag.set()
617 if hasattr(cls, 'pump_thread_wakeup_pipe'):
618 os.write(cls.pump_thread_wakeup_pipe[1], b'ding dong wake up')
619 if hasattr(cls, 'pump_thread'):
620 cls.logger.debug("Waiting for pump thread to stop")
621 cls.pump_thread.join()
622 if hasattr(cls, 'vpp_stderr_reader_thread'):
623 cls.logger.debug("Waiting for stderr pump to stop")
624 cls.vpp_stderr_reader_thread.join()
626 if hasattr(cls, 'vpp'):
627 if hasattr(cls, 'vapi'):
628 cls.logger.debug(cls.vapi.vpp.get_stats())
629 cls.logger.debug("Disconnecting class vapi client on %s",
631 cls.vapi.disconnect()
632 cls.logger.debug("Deleting class vapi attribute on %s",
636 if cls.vpp.returncode is None:
637 cls.wait_for_coredump()
638 cls.logger.debug("Sending TERM to vpp")
640 cls.logger.debug("Waiting for vpp to die")
641 cls.vpp.communicate()
642 cls.logger.debug("Deleting class vpp attribute on %s",
646 if cls.vpp_startup_failed:
647 stdout_log = cls.logger.info
648 stderr_log = cls.logger.critical
650 stdout_log = cls.logger.info
651 stderr_log = cls.logger.info
653 if hasattr(cls, 'vpp_stdout_deque'):
654 stdout_log(single_line_delim)
655 stdout_log('VPP output to stdout while running %s:', cls.__name__)
656 stdout_log(single_line_delim)
657 vpp_output = "".join(cls.vpp_stdout_deque)
658 with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
660 stdout_log('\n%s', vpp_output)
661 stdout_log(single_line_delim)
663 if hasattr(cls, 'vpp_stderr_deque'):
664 stderr_log(single_line_delim)
665 stderr_log('VPP output to stderr while running %s:', cls.__name__)
666 stderr_log(single_line_delim)
667 vpp_output = "".join(cls.vpp_stderr_deque)
668 with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
670 stderr_log('\n%s', vpp_output)
671 stderr_log(single_line_delim)
674 def tearDownClass(cls):
675 """ Perform final cleanup after running all tests in this test-case """
676 cls.logger.debug("--- tearDownClass() for %s called ---" %
678 cls.reporter.send_keep_alive(cls, 'tearDownClass')
680 cls.file_handler.close()
681 cls.reset_packet_infos()
683 debug_internal.on_tear_down_class(cls)
685 def show_commands_at_teardown(self):
686 """ Allow subclass specific teardown logging additions."""
687 self.logger.info("--- No test specific show commands provided. ---")
690 """ Show various debug prints after each test """
691 self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
692 (self.__class__.__name__, self._testMethodName,
693 self._testMethodDoc))
696 if not self.vpp_dead:
697 self.logger.debug(self.vapi.cli("show trace max 1000"))
698 self.logger.info(self.vapi.ppcli("show interface"))
699 self.logger.info(self.vapi.ppcli("show hardware"))
700 self.logger.info(self.statistics.set_errors_str())
701 self.logger.info(self.vapi.ppcli("show run"))
702 self.logger.info(self.vapi.ppcli("show log"))
703 self.logger.info(self.vapi.ppcli("show bihash"))
704 self.logger.info("Logging testcase specific show commands.")
705 self.show_commands_at_teardown()
706 self.registry.remove_vpp_config(self.logger)
707 # Save/Dump VPP api trace log
708 m = self._testMethodName
709 api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
710 tmp_api_trace = "/tmp/%s" % api_trace
711 vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
712 self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
713 self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
715 os.rename(tmp_api_trace, vpp_api_trace_log)
716 self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
718 except VppTransportShmemIOError:
719 self.logger.debug("VppTransportShmemIOError: Vpp dead. "
720 "Cannot log show commands.")
723 self.registry.unregister_all(self.logger)
726 """ Clear trace before running each test"""
727 super(VppTestCase, self).setUp()
728 self.reporter.send_keep_alive(self)
731 raise VppDiedError(rv=None, testcase=self.__class__.__name__,
732 method_name=self._testMethodName)
733 self.sleep(.1, "during setUp")
734 self.vpp_stdout_deque.append(
735 "--- test setUp() for %s.%s(%s) starts here ---\n" %
736 (self.__class__.__name__, self._testMethodName,
737 self._testMethodDoc))
738 self.vpp_stderr_deque.append(
739 "--- test setUp() for %s.%s(%s) starts here ---\n" %
740 (self.__class__.__name__, self._testMethodName,
741 self._testMethodDoc))
742 self.vapi.cli("clear trace")
743 # store the test instance inside the test class - so that objects
744 # holding the class can access instance methods (like assertEqual)
745 type(self).test_instance = self
748 def pg_enable_capture(cls, interfaces=None):
750 Enable capture on packet-generator interfaces
752 :param interfaces: iterable interface indexes (if None,
753 use self.pg_interfaces)
756 if interfaces is None:
757 interfaces = cls.pg_interfaces
762 def register_capture(cls, cap_name):
763 """ Register a capture in the testclass """
764 # add to the list of captures with current timestamp
765 cls._captures.append((time.time(), cap_name))
768 def get_vpp_time(cls):
769 # processes e.g. "Time now 2.190522, Wed, 11 Mar 2020 17:29:54 GMT"
770 # returns float("2.190522")
771 timestr = cls.vapi.cli('show clock')
772 head, sep, tail = timestr.partition(',')
773 head, sep, tail = head.partition('Time now')
777 def sleep_on_vpp_time(cls, sec):
778 """ Sleep according to time in VPP world """
779 # On a busy system with many processes
780 # we might end up with VPP time being slower than real world
781 # So take that into account when waiting for VPP to do something
782 start_time = cls.get_vpp_time()
783 while cls.get_vpp_time() - start_time < sec:
788 """ Enable the PG, wait till it is done, then clean up """
789 cls.vapi.cli("trace add pg-input 1000")
790 cls.vapi.cli('packet-generator enable')
791 # PG, when starts, runs to completion -
792 # so let's avoid a race condition,
793 # and wait a little till it's done.
794 # Then clean it up - and then be gone.
795 deadline = time.time() + 300
796 while cls.vapi.cli('show packet-generator').find("Yes") != -1:
797 cls.sleep(0.01) # yield
798 if time.time() > deadline:
799 cls.logger.error("Timeout waiting for pg to stop")
801 for stamp, cap_name in cls._captures:
802 cls.vapi.cli('packet-generator delete %s' % cap_name)
806 def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
808 Create packet-generator interfaces.
810 :param interfaces: iterable indexes of the interfaces.
811 :returns: List of created interfaces.
816 intf = VppPGInterface(cls, i, gso, gso_size)
817 setattr(cls, intf.name, intf)
819 cls.pg_interfaces = result
823 def create_loopback_interfaces(cls, count):
825 Create loopback interfaces.
827 :param count: number of interfaces created.
828 :returns: List of created interfaces.
830 result = [VppLoInterface(cls) for i in range(count)]
832 setattr(cls, intf.name, intf)
833 cls.lo_interfaces = result
837 def create_bvi_interfaces(cls, count):
839 Create BVI interfaces.
841 :param count: number of interfaces created.
842 :returns: List of created interfaces.
844 result = [VppBviInterface(cls) for i in range(count)]
846 setattr(cls, intf.name, intf)
847 cls.bvi_interfaces = result
851 def extend_packet(packet, size, padding=' '):
853 Extend packet to given size by padding with spaces or custom padding
854 NOTE: Currently works only when Raw layer is present.
856 :param packet: packet
857 :param size: target size
858 :param padding: padding used to extend the payload
861 packet_len = len(packet) + 4
862 extend = size - packet_len
864 num = (extend // len(padding)) + 1
865 packet[Raw].load += (padding * num)[:extend].encode("ascii")
868 def reset_packet_infos(cls):
869 """ Reset the list of packet info objects and packet counts to zero """
870 cls._packet_infos = {}
871 cls._packet_count_for_dst_if_idx = {}
874 def create_packet_info(cls, src_if, dst_if):
876 Create packet info object containing the source and destination indexes
877 and add it to the testcase's packet info list
879 :param VppInterface src_if: source interface
880 :param VppInterface dst_if: destination interface
882 :returns: _PacketInfo object
886 info.index = len(cls._packet_infos)
887 info.src = src_if.sw_if_index
888 info.dst = dst_if.sw_if_index
889 if isinstance(dst_if, VppSubInterface):
890 dst_idx = dst_if.parent.sw_if_index
892 dst_idx = dst_if.sw_if_index
893 if dst_idx in cls._packet_count_for_dst_if_idx:
894 cls._packet_count_for_dst_if_idx[dst_idx] += 1
896 cls._packet_count_for_dst_if_idx[dst_idx] = 1
897 cls._packet_infos[info.index] = info
901 def info_to_payload(info):
903 Convert _PacketInfo object to packet payload
905 :param info: _PacketInfo object
907 :returns: string containing serialized data from packet info
909 return "%d %d %d %d %d" % (info.index, info.src, info.dst,
913 def payload_to_info(payload, payload_field='load'):
915 Convert packet payload to _PacketInfo object
917 :param payload: packet payload
918 :type payload: <class 'scapy.packet.Raw'>
919 :param payload_field: packet fieldname of payload "load" for
920 <class 'scapy.packet.Raw'>
921 :type payload_field: str
922 :returns: _PacketInfo object containing de-serialized data from payload
925 numbers = getattr(payload, payload_field).split()
927 info.index = int(numbers[0])
928 info.src = int(numbers[1])
929 info.dst = int(numbers[2])
930 info.ip = int(numbers[3])
931 info.proto = int(numbers[4])
934 def get_next_packet_info(self, info):
936 Iterate over the packet info list stored in the testcase
937 Start iteration with first element if info is None
938 Continue based on index in info if info is specified
940 :param info: info or None
941 :returns: next info in list or None if no more infos
946 next_index = info.index + 1
947 if next_index == len(self._packet_infos):
950 return self._packet_infos[next_index]
952 def get_next_packet_info_for_interface(self, src_index, info):
954 Search the packet info list for the next packet info with same source
957 :param src_index: source interface index to search for
958 :param info: packet info - where to start the search
959 :returns: packet info or None
963 info = self.get_next_packet_info(info)
966 if info.src == src_index:
969 def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
971 Search the packet info list for the next packet info with same source
972 and destination interface indexes
974 :param src_index: source interface index to search for
975 :param dst_index: destination interface index to search for
976 :param info: packet info - where to start the search
977 :returns: packet info or None
981 info = self.get_next_packet_info_for_interface(src_index, info)
984 if info.dst == dst_index:
987 def assert_equal(self, real_value, expected_value, name_or_class=None):
988 if name_or_class is None:
989 self.assertEqual(real_value, expected_value)
992 msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
993 msg = msg % (getdoc(name_or_class).strip(),
994 real_value, str(name_or_class(real_value)),
995 expected_value, str(name_or_class(expected_value)))
997 msg = "Invalid %s: %s does not match expected value %s" % (
998 name_or_class, real_value, expected_value)
1000 self.assertEqual(real_value, expected_value, msg)
1002 def assert_in_range(self,
1010 msg = "Invalid %s: %s out of range <%s,%s>" % (
1011 name, real_value, expected_min, expected_max)
1012 self.assertTrue(expected_min <= real_value <= expected_max, msg)
1014 def assert_packet_checksums_valid(self, packet,
1015 ignore_zero_udp_checksums=True):
1016 received = packet.__class__(scapy.compat.raw(packet))
1017 udp_layers = ['UDP', 'UDPerror']
1018 checksum_fields = ['cksum', 'chksum']
1021 temp = received.__class__(scapy.compat.raw(received))
1023 layer = temp.getlayer(counter)
1025 layer = layer.copy()
1026 layer.remove_payload()
1027 for cf in checksum_fields:
1028 if hasattr(layer, cf):
1029 if ignore_zero_udp_checksums and \
1030 0 == getattr(layer, cf) and \
1031 layer.name in udp_layers:
1033 delattr(temp.getlayer(counter), cf)
1034 checksums.append((counter, cf))
1037 counter = counter + 1
1038 if 0 == len(checksums):
1040 temp = temp.__class__(scapy.compat.raw(temp))
1041 for layer, cf in checksums:
1042 calc_sum = getattr(temp[layer], cf)
1044 getattr(received[layer], cf), calc_sum,
1045 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1047 "Checksum field `%s` on `%s` layer has correct value `%s`" %
1048 (cf, temp[layer].name, calc_sum))
1050 def assert_checksum_valid(self, received_packet, layer,
1051 field_name='chksum',
1052 ignore_zero_checksum=False):
1053 """ Check checksum of received packet on given layer """
1054 received_packet_checksum = getattr(received_packet[layer], field_name)
1055 if ignore_zero_checksum and 0 == received_packet_checksum:
1057 recalculated = received_packet.__class__(
1058 scapy.compat.raw(received_packet))
1059 delattr(recalculated[layer], field_name)
1060 recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1061 self.assert_equal(received_packet_checksum,
1062 getattr(recalculated[layer], field_name),
1063 "packet checksum on layer: %s" % layer)
1065 def assert_ip_checksum_valid(self, received_packet,
1066 ignore_zero_checksum=False):
1067 self.assert_checksum_valid(received_packet, 'IP',
1068 ignore_zero_checksum=ignore_zero_checksum)
1070 def assert_tcp_checksum_valid(self, received_packet,
1071 ignore_zero_checksum=False):
1072 self.assert_checksum_valid(received_packet, 'TCP',
1073 ignore_zero_checksum=ignore_zero_checksum)
1075 def assert_udp_checksum_valid(self, received_packet,
1076 ignore_zero_checksum=True):
1077 self.assert_checksum_valid(received_packet, 'UDP',
1078 ignore_zero_checksum=ignore_zero_checksum)
1080 def assert_embedded_icmp_checksum_valid(self, received_packet):
1081 if received_packet.haslayer(IPerror):
1082 self.assert_checksum_valid(received_packet, 'IPerror')
1083 if received_packet.haslayer(TCPerror):
1084 self.assert_checksum_valid(received_packet, 'TCPerror')
1085 if received_packet.haslayer(UDPerror):
1086 self.assert_checksum_valid(received_packet, 'UDPerror',
1087 ignore_zero_checksum=True)
1088 if received_packet.haslayer(ICMPerror):
1089 self.assert_checksum_valid(received_packet, 'ICMPerror')
1091 def assert_icmp_checksum_valid(self, received_packet):
1092 self.assert_checksum_valid(received_packet, 'ICMP')
1093 self.assert_embedded_icmp_checksum_valid(received_packet)
1095 def assert_icmpv6_checksum_valid(self, pkt):
1096 if pkt.haslayer(ICMPv6DestUnreach):
1097 self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1098 self.assert_embedded_icmp_checksum_valid(pkt)
1099 if pkt.haslayer(ICMPv6EchoRequest):
1100 self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1101 if pkt.haslayer(ICMPv6EchoReply):
1102 self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1104 def get_packet_counter(self, counter):
1105 if counter.startswith("/"):
1106 counter_value = self.statistics.get_counter(counter)
1108 counters = self.vapi.cli("sh errors").split('\n')
1110 for i in range(1, len(counters) - 1):
1111 results = counters[i].split()
1112 if results[1] == counter:
1113 counter_value = int(results[0])
1115 return counter_value
1117 def assert_packet_counter_equal(self, counter, expected_value):
1118 counter_value = self.get_packet_counter(counter)
1119 self.assert_equal(counter_value, expected_value,
1120 "packet counter `%s'" % counter)
1122 def assert_error_counter_equal(self, counter, expected_value):
1123 counter_value = self.statistics.get_err_counter(counter)
1124 self.assert_equal(counter_value, expected_value,
1125 "error counter `%s'" % counter)
1128 def sleep(cls, timeout, remark=None):
1130 # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1131 # * by Guido, only the main thread can be interrupted.
1133 # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892 # noqa
1136 if hasattr(os, 'sched_yield'):
1142 if hasattr(cls, 'logger'):
1143 cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1144 before = time.time()
1147 if hasattr(cls, 'logger') and after - before > 2 * timeout:
1148 cls.logger.error("unexpected self.sleep() result - "
1149 "slept for %es instead of ~%es!",
1150 after - before, timeout)
1151 if hasattr(cls, 'logger'):
1153 "Finished sleep (%s) - slept %es (wanted %es)",
1154 remark, after - before, timeout)
1156 def pg_send(self, intf, pkts, worker=None):
1157 self.vapi.cli("clear trace")
1158 intf.add_stream(pkts, worker=worker)
1159 self.pg_enable_capture(self.pg_interfaces)
1162 def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1163 self.pg_send(intf, pkts)
1166 for i in self.pg_interfaces:
1167 i.get_capture(0, timeout=timeout)
1168 i.assert_nothing_captured(remark=remark)
1171 def send_and_expect(self, intf, pkts, output, n_rx=None, worker=None):
1174 self.pg_send(intf, pkts, worker=worker)
1175 rx = output.get_capture(n_rx)
1178 def send_and_expect_only(self, intf, pkts, output, timeout=None):
1179 self.pg_send(intf, pkts)
1180 rx = output.get_capture(len(pkts))
1184 for i in self.pg_interfaces:
1185 if i not in outputs:
1186 i.get_capture(0, timeout=timeout)
1187 i.assert_nothing_captured()
1193 def get_testcase_doc_name(test):
1194 return getdoc(test.__class__).splitlines()[0]
1197 def get_test_description(descriptions, test):
1198 short_description = test.shortDescription()
1199 if descriptions and short_description:
1200 return short_description
1205 class TestCaseInfo(object):
1206 def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1207 self.logger = logger
1208 self.tempdir = tempdir
1209 self.vpp_pid = vpp_pid
1210 self.vpp_bin_path = vpp_bin_path
1211 self.core_crash_test = None
1214 class VppTestResult(unittest.TestResult):
1216 @property result_string
1217 String variable to store the test case result string.
1219 List variable containing 2-tuples of TestCase instances and strings
1220 holding formatted tracebacks. Each tuple represents a test which
1221 raised an unexpected exception.
1223 List variable containing 2-tuples of TestCase instances and strings
1224 holding formatted tracebacks. Each tuple represents a test where
1225 a failure was explicitly signalled using the TestCase.assert*()
1229 failed_test_cases_info = set()
1230 core_crash_test_cases_info = set()
1231 current_test_case_info = None
1233 def __init__(self, stream=None, descriptions=None, verbosity=None,
1236 :param stream File descriptor to store where to report test results.
1237 Set to the standard error stream by default.
1238 :param descriptions Boolean variable to store information if to use
1239 test case descriptions.
1240 :param verbosity Integer variable to store required verbosity level.
1242 super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1243 self.stream = stream
1244 self.descriptions = descriptions
1245 self.verbosity = verbosity
1246 self.result_string = None
1247 self.runner = runner
1249 def addSuccess(self, test):
1251 Record a test succeeded result
1256 if self.current_test_case_info:
1257 self.current_test_case_info.logger.debug(
1258 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1259 test._testMethodName,
1260 test._testMethodDoc))
1261 unittest.TestResult.addSuccess(self, test)
1262 self.result_string = colorize("OK", GREEN)
1264 self.send_result_through_pipe(test, PASS)
1266 def addSkip(self, test, reason):
1268 Record a test skipped.
1274 if self.current_test_case_info:
1275 self.current_test_case_info.logger.debug(
1276 "--- addSkip() %s.%s(%s) called, reason is %s" %
1277 (test.__class__.__name__, test._testMethodName,
1278 test._testMethodDoc, reason))
1279 unittest.TestResult.addSkip(self, test, reason)
1280 self.result_string = colorize("SKIP", YELLOW)
1282 self.send_result_through_pipe(test, SKIP)
1284 def symlink_failed(self):
1285 if self.current_test_case_info:
1287 failed_dir = os.getenv('FAILED_DIR')
1288 link_path = os.path.join(
1291 os.path.basename(self.current_test_case_info.tempdir))
1292 if self.current_test_case_info.logger:
1293 self.current_test_case_info.logger.debug(
1294 "creating a link to the failed test")
1295 self.current_test_case_info.logger.debug(
1296 "os.symlink(%s, %s)" %
1297 (self.current_test_case_info.tempdir, link_path))
1298 if os.path.exists(link_path):
1299 if self.current_test_case_info.logger:
1300 self.current_test_case_info.logger.debug(
1301 'symlink already exists')
1303 os.symlink(self.current_test_case_info.tempdir, link_path)
1305 except Exception as e:
1306 if self.current_test_case_info.logger:
1307 self.current_test_case_info.logger.error(e)
1309 def send_result_through_pipe(self, test, result):
1310 if hasattr(self, 'test_framework_result_pipe'):
1311 pipe = self.test_framework_result_pipe
1313 pipe.send((test.id(), result))
1315 def log_error(self, test, err, fn_name):
1316 if self.current_test_case_info:
1317 if isinstance(test, unittest.suite._ErrorHolder):
1318 test_name = test.description
1320 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1321 test._testMethodName,
1322 test._testMethodDoc)
1323 self.current_test_case_info.logger.debug(
1324 "--- %s() %s called, err is %s" %
1325 (fn_name, test_name, err))
1326 self.current_test_case_info.logger.debug(
1327 "formatted exception is:\n%s" %
1328 "".join(format_exception(*err)))
1330 def add_error(self, test, err, unittest_fn, error_type):
1331 if error_type == FAIL:
1332 self.log_error(test, err, 'addFailure')
1333 error_type_str = colorize("FAIL", RED)
1334 elif error_type == ERROR:
1335 self.log_error(test, err, 'addError')
1336 error_type_str = colorize("ERROR", RED)
1338 raise Exception('Error type %s cannot be used to record an '
1339 'error or a failure' % error_type)
1341 unittest_fn(self, test, err)
1342 if self.current_test_case_info:
1343 self.result_string = "%s [ temp dir used by test case: %s ]" % \
1345 self.current_test_case_info.tempdir)
1346 self.symlink_failed()
1347 self.failed_test_cases_info.add(self.current_test_case_info)
1348 if is_core_present(self.current_test_case_info.tempdir):
1349 if not self.current_test_case_info.core_crash_test:
1350 if isinstance(test, unittest.suite._ErrorHolder):
1351 test_name = str(test)
1353 test_name = "'{!s}' ({!s})".format(
1354 get_testcase_doc_name(test), test.id())
1355 self.current_test_case_info.core_crash_test = test_name
1356 self.core_crash_test_cases_info.add(
1357 self.current_test_case_info)
1359 self.result_string = '%s [no temp dir]' % error_type_str
1361 self.send_result_through_pipe(test, error_type)
1363 def addFailure(self, test, err):
1365 Record a test failed result
1368 :param err: error message
1371 self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1373 def addError(self, test, err):
1375 Record a test error result
1378 :param err: error message
1381 self.add_error(test, err, unittest.TestResult.addError, ERROR)
1383 def getDescription(self, test):
1385 Get test description
1388 :returns: test description
1391 return get_test_description(self.descriptions, test)
1393 def startTest(self, test):
1401 def print_header(test):
1402 if not hasattr(test.__class__, '_header_printed'):
1403 print(double_line_delim)
1404 print(colorize(getdoc(test).splitlines()[0], GREEN))
1405 print(double_line_delim)
1406 test.__class__._header_printed = True
1409 self.start_test = time.time()
1410 unittest.TestResult.startTest(self, test)
1411 if self.verbosity > 0:
1412 self.stream.writeln(
1413 "Starting " + self.getDescription(test) + " ...")
1414 self.stream.writeln(single_line_delim)
1416 def stopTest(self, test):
1418 Called when the given test has been run
1423 unittest.TestResult.stopTest(self, test)
1425 if self.verbosity > 0:
1426 self.stream.writeln(single_line_delim)
1427 self.stream.writeln("%-73s%s" % (self.getDescription(test),
1428 self.result_string))
1429 self.stream.writeln(single_line_delim)
1431 self.stream.writeln("%-68s %4.2f %s" %
1432 (self.getDescription(test),
1433 time.time() - self.start_test,
1434 self.result_string))
1436 self.send_result_through_pipe(test, TEST_RUN)
1438 def printErrors(self):
1440 Print errors from running the test case
1442 if len(self.errors) > 0 or len(self.failures) > 0:
1443 self.stream.writeln()
1444 self.printErrorList('ERROR', self.errors)
1445 self.printErrorList('FAIL', self.failures)
1447 # ^^ that is the last output from unittest before summary
1448 if not self.runner.print_summary:
1449 devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1450 self.stream = devnull
1451 self.runner.stream = devnull
1453 def printErrorList(self, flavour, errors):
1455 Print error list to the output stream together with error type
1456 and test case description.
1458 :param flavour: error type
1459 :param errors: iterable errors
1462 for test, err in errors:
1463 self.stream.writeln(double_line_delim)
1464 self.stream.writeln("%s: %s" %
1465 (flavour, self.getDescription(test)))
1466 self.stream.writeln(single_line_delim)
1467 self.stream.writeln("%s" % err)
1470 class VppTestRunner(unittest.TextTestRunner):
1472 A basic test runner implementation which prints results to standard error.
1476 def resultclass(self):
1477 """Class maintaining the results of the tests"""
1478 return VppTestResult
1480 def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1481 result_pipe=None, failfast=False, buffer=False,
1482 resultclass=None, print_summary=True, **kwargs):
1483 # ignore stream setting here, use hard-coded stdout to be in sync
1484 # with prints from VppTestCase methods ...
1485 super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1486 verbosity, failfast, buffer,
1487 resultclass, **kwargs)
1488 KeepAliveReporter.pipe = keep_alive_pipe
1490 self.orig_stream = self.stream
1491 self.resultclass.test_framework_result_pipe = result_pipe
1493 self.print_summary = print_summary
1495 def _makeResult(self):
1496 return self.resultclass(self.stream,
1501 def run(self, test):
1508 faulthandler.enable() # emit stack trace to stderr if killed by signal
1510 result = super(VppTestRunner, self).run(test)
1511 if not self.print_summary:
1512 self.stream = self.orig_stream
1513 result.stream = self.orig_stream
1517 class Worker(Thread):
1518 def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1519 super(Worker, self).__init__(*args, **kwargs)
1520 self.logger = logger
1521 self.args = executable_args
1522 if hasattr(self, 'testcase') and self.testcase.debug_all:
1523 if self.testcase.debug_gdbserver:
1524 self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1525 .format(port=self.testcase.gdbserver_port)] + args
1526 elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1527 self.args.append(self.wait_for_gdb)
1528 self.app_bin = executable_args[0]
1529 self.app_name = os.path.basename(self.app_bin)
1530 if hasattr(self, 'role'):
1531 self.app_name += ' {role}'.format(role=self.role)
1534 env = {} if env is None else env
1535 self.env = copy.deepcopy(env)
1537 def wait_for_enter(self):
1538 if not hasattr(self, 'testcase'):
1540 if self.testcase.debug_all and self.testcase.debug_gdbserver:
1542 print(double_line_delim)
1543 print("Spawned GDB Server for '{app}' with PID: {pid}"
1544 .format(app=self.app_name, pid=self.process.pid))
1545 elif self.testcase.debug_all and self.testcase.debug_gdb:
1547 print(double_line_delim)
1548 print("Spawned '{app}' with PID: {pid}"
1549 .format(app=self.app_name, pid=self.process.pid))
1552 print(single_line_delim)
1553 print("You can debug '{app}' using:".format(app=self.app_name))
1554 if self.testcase.debug_gdbserver:
1555 print("sudo gdb " + self.app_bin +
1556 " -ex 'target remote localhost:{port}'"
1557 .format(port=self.testcase.gdbserver_port))
1558 print("Now is the time to attach gdb by running the above "
1559 "command, set up breakpoints etc., then resume from "
1560 "within gdb by issuing the 'continue' command")
1561 self.testcase.gdbserver_port += 1
1562 elif self.testcase.debug_gdb:
1563 print("sudo gdb " + self.app_bin +
1564 " -ex 'attach {pid}'".format(pid=self.process.pid))
1565 print("Now is the time to attach gdb by running the above "
1566 "command and set up breakpoints etc., then resume from"
1567 " within gdb by issuing the 'continue' command")
1568 print(single_line_delim)
1569 input("Press ENTER to continue running the testcase...")
1572 executable = self.args[0]
1573 if not os.path.exists(executable) or not os.access(
1574 executable, os.F_OK | os.X_OK):
1575 # Exit code that means some system file did not exist,
1576 # could not be opened, or had some other kind of error.
1577 self.result = os.EX_OSFILE
1578 raise EnvironmentError(
1579 "executable '%s' is not found or executable." % executable)
1580 self.logger.debug("Running executable: '{app}'"
1581 .format(app=' '.join(self.args)))
1582 env = os.environ.copy()
1583 env.update(self.env)
1584 env["CK_LOG_FILE_NAME"] = "-"
1585 self.process = subprocess.Popen(
1586 self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1587 stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1588 self.wait_for_enter()
1589 out, err = self.process.communicate()
1590 self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1591 self.logger.info("Return code is `%s'" % self.process.returncode)
1592 self.logger.info(single_line_delim)
1593 self.logger.info("Executable `{app}' wrote to stdout:"
1594 .format(app=self.app_name))
1595 self.logger.info(single_line_delim)
1596 self.logger.info(out.decode('utf-8'))
1597 self.logger.info(single_line_delim)
1598 self.logger.info("Executable `{app}' wrote to stderr:"
1599 .format(app=self.app_name))
1600 self.logger.info(single_line_delim)
1601 self.logger.info(err.decode('utf-8'))
1602 self.logger.info(single_line_delim)
1603 self.result = self.process.returncode
1606 if __name__ == '__main__':