3 from __future__ import print_function
18 from collections import deque
19 from threading import Thread, Event
20 from inspect import getdoc, isclass
21 from traceback import format_exception
22 from logging import FileHandler, DEBUG, Formatter
25 from scapy.packet import Raw
26 import hook as hookmodule
27 from vpp_pg_interface import VppPGInterface
28 from vpp_sub_interface import VppSubInterface
29 from vpp_lo_interface import VppLoInterface
30 from vpp_bvi_interface import VppBviInterface
31 from vpp_papi_provider import VppPapiProvider
33 from vpp_papi.vpp_stats import VPPStats
34 from vpp_papi.vpp_transport_shmem import VppTransportShmemIOError
35 from log import RED, GREEN, YELLOW, double_line_delim, single_line_delim, \
37 from vpp_object import VppObjectRegistry
38 from util import ppp, is_core_present
39 from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
40 from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
41 from scapy.layers.inet6 import ICMPv6EchoReply
43 if os.name == 'posix' and sys.version_info[0] < 3:
44 # using subprocess32 is recommended by python official documentation
45 # @ https://docs.python.org/2/library/subprocess.html
46 import subprocess32 as subprocess
50 # Python2/3 compatible
56 logger = logging.getLogger(__name__)
58 # Set up an empty logger for the testcase that can be overridden as necessary
59 null_logger = logging.getLogger('VppTestCase')
60 null_logger.addHandler(logging.NullHandler())
69 class BoolEnvironmentVariable(object):
71 def __init__(self, env_var_name, default='n', true_values=None):
72 self.name = env_var_name
73 self.default = default
74 self.true_values = true_values if true_values is not None else \
78 return os.getenv(self.name, self.default).lower() in self.true_values
80 if sys.version_info[0] == 2:
81 __nonzero__ = __bool__
84 return 'BoolEnvironmentVariable(%r, default=%r, true_values=%r)' % \
85 (self.name, self.default, self.true_values)
88 debug_framework = BoolEnvironmentVariable('TEST_DEBUG')
93 Test framework module.
95 The module provides a set of tools for constructing and running tests and
96 representing the results.
100 class VppDiedError(Exception):
101 """ exception for reporting that the subprocess has died."""
103 signals_by_value = {v: k for k, v in signal.__dict__.items() if
104 k.startswith('SIG') and not k.startswith('SIG_')}
106 def __init__(self, rv=None, testcase=None, method_name=None):
108 self.signal_name = None
109 self.testcase = testcase
110 self.method_name = method_name
113 self.signal_name = VppDiedError.signals_by_value[-rv]
114 except (KeyError, TypeError):
117 if testcase is None and method_name is None:
120 in_msg = 'running %s.%s ' % (testcase, method_name)
122 msg = "VPP subprocess died %sunexpectedly with return code: %d%s." % (
125 ' [%s]' % (self.signal_name if
126 self.signal_name is not None else ''))
127 super(VppDiedError, self).__init__(msg)
130 class _PacketInfo(object):
131 """Private class to create packet info object.
133 Help process information about the next packet.
134 Set variables to default values.
136 #: Store the index of the packet.
138 #: Store the index of the source packet generator interface of the packet.
140 #: Store the index of the destination packet generator interface
143 #: Store expected ip version
145 #: Store expected upper protocol
147 #: Store the copy of the former packet.
150 def __eq__(self, other):
151 index = self.index == other.index
152 src = self.src == other.src
153 dst = self.dst == other.dst
154 data = self.data == other.data
155 return index and src and dst and data
158 def pump_output(testclass):
159 """ pump output from vpp stdout/stderr to proper queues """
162 while not testclass.pump_thread_stop_flag.is_set():
163 readable = select.select([testclass.vpp.stdout.fileno(),
164 testclass.vpp.stderr.fileno(),
165 testclass.pump_thread_wakeup_pipe[0]],
167 if testclass.vpp.stdout.fileno() in readable:
168 read = os.read(testclass.vpp.stdout.fileno(), 102400)
170 split = read.decode('ascii',
171 errors='backslashreplace').splitlines(True)
172 if len(stdout_fragment) > 0:
173 split[0] = "%s%s" % (stdout_fragment, split[0])
174 if len(split) > 0 and split[-1].endswith("\n"):
178 stdout_fragment = split[-1]
179 testclass.vpp_stdout_deque.extend(split[:limit])
180 if not testclass.cache_vpp_output:
181 for line in split[:limit]:
182 testclass.logger.info(
183 "VPP STDOUT: %s" % line.rstrip("\n"))
184 if testclass.vpp.stderr.fileno() in readable:
185 read = os.read(testclass.vpp.stderr.fileno(), 102400)
187 split = read.decode('ascii',
188 errors='backslashreplace').splitlines(True)
189 if len(stderr_fragment) > 0:
190 split[0] = "%s%s" % (stderr_fragment, split[0])
191 if len(split) > 0 and split[-1].endswith("\n"):
195 stderr_fragment = split[-1]
197 testclass.vpp_stderr_deque.extend(split[:limit])
198 if not testclass.cache_vpp_output:
199 for line in split[:limit]:
200 testclass.logger.error(
201 "VPP STDERR: %s" % line.rstrip("\n"))
202 # ignoring the dummy pipe here intentionally - the
203 # flag will take care of properly terminating the loop
206 def _is_skip_aarch64_set():
207 return BoolEnvironmentVariable('SKIP_AARCH64')
210 is_skip_aarch64_set = _is_skip_aarch64_set()
213 def _is_platform_aarch64():
214 return platform.machine() == 'aarch64'
217 is_platform_aarch64 = _is_platform_aarch64()
220 def _running_extended_tests():
221 return BoolEnvironmentVariable("EXTENDED_TESTS")
224 running_extended_tests = _running_extended_tests()
227 def _running_gcov_tests():
228 return BoolEnvironmentVariable("GCOV_TESTS")
231 running_gcov_tests = _running_gcov_tests()
234 def _running_on_centos():
235 os_id = os.getenv("OS_ID", "")
236 return True if "centos" in os_id.lower() else False
239 running_on_centos = _running_on_centos()
242 class KeepAliveReporter(object):
244 Singleton object which reports test start to parent process
249 self.__dict__ = self._shared_state
257 def pipe(self, pipe):
258 if self._pipe is not None:
259 raise Exception("Internal error - pipe should only be set once.")
262 def send_keep_alive(self, test, desc=None):
264 Write current test tmpdir & desc to keep-alive pipe to signal liveness
266 if self.pipe is None:
267 # if not running forked..
271 desc = '%s (%s)' % (desc, unittest.util.strclass(test))
275 self.pipe.send((desc, test.vpp_bin, test.tempdir, test.vpp.pid))
278 class VppTestCase(unittest.TestCase):
279 """This subclass is a base class for VPP test cases that are implemented as
280 classes. It provides methods to create and run test case.
283 extra_vpp_punt_config = []
284 extra_vpp_plugin_config = []
286 vapi_response_timeout = 5
289 def packet_infos(self):
290 """List of packet infos"""
291 return self._packet_infos
294 def get_packet_count_for_if_idx(cls, dst_if_index):
295 """Get the number of packet info for specified destination if index"""
296 if dst_if_index in cls._packet_count_for_dst_if_idx:
297 return cls._packet_count_for_dst_if_idx[dst_if_index]
303 """Return the instance of this testcase"""
304 return cls.test_instance
307 def set_debug_flags(cls, d):
308 cls.gdbserver_port = 7777
309 cls.debug_core = False
310 cls.debug_gdb = False
311 cls.debug_gdbserver = False
312 cls.debug_all = False
317 cls.debug_core = True
318 elif dl == "gdb" or dl == "gdb-all":
320 elif dl == "gdbserver" or dl == "gdbserver-all":
321 cls.debug_gdbserver = True
323 raise Exception("Unrecognized DEBUG option: '%s'" % d)
324 if dl == "gdb-all" or dl == "gdbserver-all":
328 def get_least_used_cpu():
329 cpu_usage_list = [set(range(psutil.cpu_count()))]
330 vpp_processes = [p for p in psutil.process_iter(attrs=['pid', 'name'])
331 if 'vpp_main' == p.info['name']]
332 for vpp_process in vpp_processes:
333 for cpu_usage_set in cpu_usage_list:
335 cpu_num = vpp_process.cpu_num()
336 if cpu_num in cpu_usage_set:
337 cpu_usage_set_index = cpu_usage_list.index(
339 if cpu_usage_set_index == len(cpu_usage_list) - 1:
340 cpu_usage_list.append({cpu_num})
342 cpu_usage_list[cpu_usage_set_index + 1].add(
344 cpu_usage_set.remove(cpu_num)
346 except psutil.NoSuchProcess:
349 for cpu_usage_set in cpu_usage_list:
350 if len(cpu_usage_set) > 0:
351 min_usage_set = cpu_usage_set
354 return random.choice(tuple(min_usage_set))
357 def setUpConstants(cls):
358 """ Set-up the test case class based on environment variables """
359 cls.step = BoolEnvironmentVariable('STEP')
360 d = os.getenv("DEBUG", None)
361 # inverted case to handle '' == True
362 c = os.getenv("CACHE_OUTPUT", "1")
363 cls.cache_vpp_output = False if c.lower() in ("n", "no", "0") else True
364 cls.set_debug_flags(d)
365 cls.vpp_bin = os.getenv('VPP_BIN', "vpp")
366 cls.plugin_path = os.getenv('VPP_PLUGIN_PATH')
367 cls.test_plugin_path = os.getenv('VPP_TEST_PLUGIN_PATH')
368 cls.extern_plugin_path = os.getenv('EXTERN_PLUGINS')
370 if cls.plugin_path is not None:
371 if cls.extern_plugin_path is not None:
372 plugin_path = "%s:%s" % (
373 cls.plugin_path, cls.extern_plugin_path)
375 plugin_path = cls.plugin_path
376 elif cls.extern_plugin_path is not None:
377 plugin_path = cls.extern_plugin_path
379 if cls.step or cls.debug_gdb or cls.debug_gdbserver:
380 debug_cli = "cli-listen localhost:5002"
382 size = os.getenv("COREDUMP_SIZE")
384 coredump_size = "coredump-size %s" % size
385 if coredump_size is None:
386 coredump_size = "coredump-size unlimited"
388 cpu_core_number = cls.get_least_used_cpu()
389 if not hasattr(cls, "worker_config"):
390 cls.worker_config = ""
392 default_variant = os.getenv("VARIANT")
393 if default_variant is not None:
394 default_variant = "defaults { %s 100 }" % default_variant
398 api_fuzzing = os.getenv("API_FUZZ")
399 if api_fuzzing is None:
402 cls.vpp_cmdline = [cls.vpp_bin, "unix",
403 "{", "nodaemon", debug_cli, "full-coredump",
404 coredump_size, "runtime-dir", cls.tempdir, "}",
405 "api-trace", "{", "on", "}", "api-segment", "{",
406 "prefix", cls.shm_prefix, "}", "cpu", "{",
407 "main-core", str(cpu_core_number),
408 cls.worker_config, "}",
409 "physmem", "{", "max-size", "32m", "}",
410 "statseg", "{", "socket-name", cls.stats_sock, "}",
411 "socksvr", "{", "socket-name", cls.api_sock, "}",
412 "node { ", default_variant, "}",
413 "api-fuzz {", api_fuzzing, "}",
415 "{", "plugin", "dpdk_plugin.so", "{", "disable",
416 "}", "plugin", "rdma_plugin.so", "{", "disable",
417 "}", "plugin", "unittest_plugin.so", "{", "enable",
418 "}"] + cls.extra_vpp_plugin_config + ["}", ]
420 if cls.extra_vpp_punt_config is not None:
421 cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
422 if plugin_path is not None:
423 cls.vpp_cmdline.extend(["plugin_path", plugin_path])
424 if cls.test_plugin_path is not None:
425 cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
427 cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
428 cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
431 def wait_for_enter(cls):
432 if cls.debug_gdbserver:
433 print(double_line_delim)
434 print("Spawned GDB server with PID: %d" % cls.vpp.pid)
436 print(double_line_delim)
437 print("Spawned VPP with PID: %d" % cls.vpp.pid)
439 cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
441 print(single_line_delim)
442 print("You can debug VPP using:")
443 if cls.debug_gdbserver:
444 print("sudo gdb " + cls.vpp_bin +
445 " -ex 'target remote localhost:{port}'"
446 .format(port=cls.gdbserver_port))
447 print("Now is the time to attach gdb by running the above "
448 "command, set up breakpoints etc., then resume VPP from "
449 "within gdb by issuing the 'continue' command")
450 cls.gdbserver_port += 1
452 print("sudo gdb " + cls.vpp_bin + " -ex 'attach %s'" % cls.vpp.pid)
453 print("Now is the time to attach gdb by running the above "
454 "command and set up breakpoints etc., then resume VPP from"
455 " within gdb by issuing the 'continue' command")
456 print(single_line_delim)
457 input("Press ENTER to continue running the testcase...")
461 cmdline = cls.vpp_cmdline
463 if cls.debug_gdbserver:
464 gdbserver = '/usr/bin/gdbserver'
465 if not os.path.isfile(gdbserver) or \
466 not os.access(gdbserver, os.X_OK):
467 raise Exception("gdbserver binary '%s' does not exist or is "
468 "not executable" % gdbserver)
470 cmdline = [gdbserver, 'localhost:{port}'
471 .format(port=cls.gdbserver_port)] + cls.vpp_cmdline
472 cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
475 cls.vpp = subprocess.Popen(cmdline,
476 stdout=subprocess.PIPE,
477 stderr=subprocess.PIPE)
478 except subprocess.CalledProcessError as e:
479 cls.logger.critical("Subprocess returned with non-0 return code: ("
483 cls.logger.critical("Subprocess returned with OS error: "
484 "(%s) %s", e.errno, e.strerror)
486 except Exception as e:
487 cls.logger.exception("Subprocess returned unexpected from "
494 def wait_for_coredump(cls):
495 corefile = cls.tempdir + "/core"
496 if os.path.isfile(corefile):
497 cls.logger.error("Waiting for coredump to complete: %s", corefile)
498 curr_size = os.path.getsize(corefile)
499 deadline = time.time() + 60
501 while time.time() < deadline:
504 curr_size = os.path.getsize(corefile)
505 if size == curr_size:
509 cls.logger.error("Timed out waiting for coredump to complete:"
512 cls.logger.error("Coredump complete: %s, size %d",
518 Perform class setup before running the testcase
519 Remove shared memory files, start vpp and connect the vpp-api
521 super(VppTestCase, cls).setUpClass()
522 gc.collect() # run garbage collection first
523 cls.logger = get_logger(cls.__name__)
524 seed = os.environ["RND_SEED"]
526 if hasattr(cls, 'parallel_handler'):
527 cls.logger.addHandler(cls.parallel_handler)
528 cls.logger.propagate = False
530 cls.tempdir = tempfile.mkdtemp(
531 prefix='vpp-unittest-%s-' % cls.__name__)
532 cls.stats_sock = "%s/stats.sock" % cls.tempdir
533 cls.api_sock = "%s/api.sock" % cls.tempdir
534 cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
535 cls.file_handler.setFormatter(
536 Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
538 cls.file_handler.setLevel(DEBUG)
539 cls.logger.addHandler(cls.file_handler)
540 cls.logger.debug("--- setUpClass() for %s called ---" %
542 cls.shm_prefix = os.path.basename(cls.tempdir)
543 os.chdir(cls.tempdir)
544 cls.logger.info("Temporary dir is %s, shm prefix is %s",
545 cls.tempdir, cls.shm_prefix)
546 cls.logger.debug("Random seed is %s" % seed)
548 cls.reset_packet_infos()
552 cls.registry = VppObjectRegistry()
553 cls.vpp_startup_failed = False
554 cls.reporter = KeepAliveReporter()
555 # need to catch exceptions here because if we raise, then the cleanup
556 # doesn't get called and we might end with a zombie vpp
559 cls.reporter.send_keep_alive(cls, 'setUpClass')
560 VppTestResult.current_test_case_info = TestCaseInfo(
561 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
562 cls.vpp_stdout_deque = deque()
563 cls.vpp_stderr_deque = deque()
564 cls.pump_thread_stop_flag = Event()
565 cls.pump_thread_wakeup_pipe = os.pipe()
566 cls.pump_thread = Thread(target=pump_output, args=(cls,))
567 cls.pump_thread.daemon = True
568 cls.pump_thread.start()
569 if cls.debug_gdb or cls.debug_gdbserver:
570 cls.vapi_response_timeout = 0
571 cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
572 cls.vapi_response_timeout)
574 hook = hookmodule.StepHook(cls)
576 hook = hookmodule.PollHook(cls)
577 cls.vapi.register_hook(hook)
578 cls.statistics = VPPStats(socketname=cls.stats_sock)
582 cls.vpp_startup_failed = True
584 "VPP died shortly after startup, check the"
585 " output to standard error for possible cause")
589 except vpp_papi.VPPIOError as e:
590 cls.logger.debug("Exception connecting to vapi: %s" % e)
591 cls.vapi.disconnect()
593 if cls.debug_gdbserver:
594 print(colorize("You're running VPP inside gdbserver but "
595 "VPP-API connection failed, did you forget "
596 "to 'continue' VPP from within gdb?", RED))
598 except vpp_papi.VPPRuntimeError as e:
599 cls.logger.debug("%s" % e)
602 except Exception as e:
603 cls.logger.debug("Exception connecting to VPP: %s" % e)
608 def _debug_quit(cls):
609 if (cls.debug_gdbserver or cls.debug_gdb):
613 if cls.vpp.returncode is None:
615 print(double_line_delim)
616 print("VPP or GDB server is still running")
617 print(single_line_delim)
618 input("When done debugging, press ENTER to kill the "
619 "process and finish running the testcase...")
620 except AttributeError:
626 Disconnect vpp-api, kill vpp and cleanup shared memory files
630 # first signal that we want to stop the pump thread, then wake it up
631 if hasattr(cls, 'pump_thread_stop_flag'):
632 cls.pump_thread_stop_flag.set()
633 if hasattr(cls, 'pump_thread_wakeup_pipe'):
634 os.write(cls.pump_thread_wakeup_pipe[1], b'ding dong wake up')
635 if hasattr(cls, 'pump_thread'):
636 cls.logger.debug("Waiting for pump thread to stop")
637 cls.pump_thread.join()
638 if hasattr(cls, 'vpp_stderr_reader_thread'):
639 cls.logger.debug("Waiting for stderr pump to stop")
640 cls.vpp_stderr_reader_thread.join()
642 if hasattr(cls, 'vpp'):
643 if hasattr(cls, 'vapi'):
644 cls.logger.debug(cls.vapi.vpp.get_stats())
645 cls.logger.debug("Disconnecting class vapi client on %s",
647 cls.vapi.disconnect()
648 cls.logger.debug("Deleting class vapi attribute on %s",
652 if cls.vpp.returncode is None:
653 cls.wait_for_coredump()
654 cls.logger.debug("Sending TERM to vpp")
656 cls.logger.debug("Waiting for vpp to die")
657 cls.vpp.communicate()
658 cls.logger.debug("Deleting class vpp attribute on %s",
662 if cls.vpp_startup_failed:
663 stdout_log = cls.logger.info
664 stderr_log = cls.logger.critical
666 stdout_log = cls.logger.info
667 stderr_log = cls.logger.info
669 if hasattr(cls, 'vpp_stdout_deque'):
670 stdout_log(single_line_delim)
671 stdout_log('VPP output to stdout while running %s:', cls.__name__)
672 stdout_log(single_line_delim)
673 vpp_output = "".join(cls.vpp_stdout_deque)
674 with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
676 stdout_log('\n%s', vpp_output)
677 stdout_log(single_line_delim)
679 if hasattr(cls, 'vpp_stderr_deque'):
680 stderr_log(single_line_delim)
681 stderr_log('VPP output to stderr while running %s:', cls.__name__)
682 stderr_log(single_line_delim)
683 vpp_output = "".join(cls.vpp_stderr_deque)
684 with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
686 stderr_log('\n%s', vpp_output)
687 stderr_log(single_line_delim)
690 def tearDownClass(cls):
691 """ Perform final cleanup after running all tests in this test-case """
692 cls.logger.debug("--- tearDownClass() for %s called ---" %
694 cls.reporter.send_keep_alive(cls, 'tearDownClass')
696 cls.file_handler.close()
697 cls.reset_packet_infos()
699 debug_internal.on_tear_down_class(cls)
701 def show_commands_at_teardown(self):
702 """ Allow subclass specific teardown logging additions."""
703 self.logger.info("--- No test specific show commands provided. ---")
706 """ Show various debug prints after each test """
707 self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
708 (self.__class__.__name__, self._testMethodName,
709 self._testMethodDoc))
712 if not self.vpp_dead:
713 self.logger.debug(self.vapi.cli("show trace max 1000"))
714 self.logger.info(self.vapi.ppcli("show interface"))
715 self.logger.info(self.vapi.ppcli("show hardware"))
716 self.logger.info(self.statistics.set_errors_str())
717 self.logger.info(self.vapi.ppcli("show run"))
718 self.logger.info(self.vapi.ppcli("show log"))
719 self.logger.info(self.vapi.ppcli("show bihash"))
720 self.logger.info("Logging testcase specific show commands.")
721 self.show_commands_at_teardown()
722 self.registry.remove_vpp_config(self.logger)
723 # Save/Dump VPP api trace log
724 m = self._testMethodName
725 api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
726 tmp_api_trace = "/tmp/%s" % api_trace
727 vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
728 self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
729 self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
731 os.rename(tmp_api_trace, vpp_api_trace_log)
732 self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
734 except VppTransportShmemIOError:
735 self.logger.debug("VppTransportShmemIOError: Vpp dead. "
736 "Cannot log show commands.")
739 self.registry.unregister_all(self.logger)
742 """ Clear trace before running each test"""
743 super(VppTestCase, self).setUp()
744 self.reporter.send_keep_alive(self)
747 raise VppDiedError(rv=None, testcase=self.__class__.__name__,
748 method_name=self._testMethodName)
749 self.sleep(.1, "during setUp")
750 self.vpp_stdout_deque.append(
751 "--- test setUp() for %s.%s(%s) starts here ---\n" %
752 (self.__class__.__name__, self._testMethodName,
753 self._testMethodDoc))
754 self.vpp_stderr_deque.append(
755 "--- test setUp() for %s.%s(%s) starts here ---\n" %
756 (self.__class__.__name__, self._testMethodName,
757 self._testMethodDoc))
758 self.vapi.cli("clear trace")
759 # store the test instance inside the test class - so that objects
760 # holding the class can access instance methods (like assertEqual)
761 type(self).test_instance = self
764 def pg_enable_capture(cls, interfaces=None):
766 Enable capture on packet-generator interfaces
768 :param interfaces: iterable interface indexes (if None,
769 use self.pg_interfaces)
772 if interfaces is None:
773 interfaces = cls.pg_interfaces
778 def register_capture(cls, cap_name):
779 """ Register a capture in the testclass """
780 # add to the list of captures with current timestamp
781 cls._captures.append((time.time(), cap_name))
784 def get_vpp_time(cls):
785 # processes e.g. "Time now 2.190522, Wed, 11 Mar 2020 17:29:54 GMT"
786 # returns float("2.190522")
787 timestr = cls.vapi.cli('show clock')
788 head, sep, tail = timestr.partition(',')
789 head, sep, tail = head.partition('Time now')
793 def sleep_on_vpp_time(cls, sec):
794 """ Sleep according to time in VPP world """
795 # On a busy system with many processes
796 # we might end up with VPP time being slower than real world
797 # So take that into account when waiting for VPP to do something
798 start_time = cls.get_vpp_time()
799 while cls.get_vpp_time() - start_time < sec:
804 """ Enable the PG, wait till it is done, then clean up """
805 cls.vapi.cli("trace add pg-input 1000")
806 cls.vapi.cli('packet-generator enable')
807 # PG, when starts, runs to completion -
808 # so let's avoid a race condition,
809 # and wait a little till it's done.
810 # Then clean it up - and then be gone.
811 deadline = time.time() + 300
812 while cls.vapi.cli('show packet-generator').find("Yes") != -1:
813 cls.sleep(0.01) # yield
814 if time.time() > deadline:
815 cls.logger.error("Timeout waiting for pg to stop")
817 for stamp, cap_name in cls._captures:
818 cls.vapi.cli('packet-generator delete %s' % cap_name)
822 def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
824 Create packet-generator interfaces.
826 :param interfaces: iterable indexes of the interfaces.
827 :returns: List of created interfaces.
832 intf = VppPGInterface(cls, i, gso, gso_size)
833 setattr(cls, intf.name, intf)
835 cls.pg_interfaces = result
839 def create_loopback_interfaces(cls, count):
841 Create loopback interfaces.
843 :param count: number of interfaces created.
844 :returns: List of created interfaces.
846 result = [VppLoInterface(cls) for i in range(count)]
848 setattr(cls, intf.name, intf)
849 cls.lo_interfaces = result
853 def create_bvi_interfaces(cls, count):
855 Create BVI interfaces.
857 :param count: number of interfaces created.
858 :returns: List of created interfaces.
860 result = [VppBviInterface(cls) for i in range(count)]
862 setattr(cls, intf.name, intf)
863 cls.bvi_interfaces = result
867 def extend_packet(packet, size, padding=' '):
869 Extend packet to given size by padding with spaces or custom padding
870 NOTE: Currently works only when Raw layer is present.
872 :param packet: packet
873 :param size: target size
874 :param padding: padding used to extend the payload
877 packet_len = len(packet) + 4
878 extend = size - packet_len
880 num = (extend // len(padding)) + 1
881 packet[Raw].load += (padding * num)[:extend].encode("ascii")
884 def reset_packet_infos(cls):
885 """ Reset the list of packet info objects and packet counts to zero """
886 cls._packet_infos = {}
887 cls._packet_count_for_dst_if_idx = {}
890 def create_packet_info(cls, src_if, dst_if):
892 Create packet info object containing the source and destination indexes
893 and add it to the testcase's packet info list
895 :param VppInterface src_if: source interface
896 :param VppInterface dst_if: destination interface
898 :returns: _PacketInfo object
902 info.index = len(cls._packet_infos)
903 info.src = src_if.sw_if_index
904 info.dst = dst_if.sw_if_index
905 if isinstance(dst_if, VppSubInterface):
906 dst_idx = dst_if.parent.sw_if_index
908 dst_idx = dst_if.sw_if_index
909 if dst_idx in cls._packet_count_for_dst_if_idx:
910 cls._packet_count_for_dst_if_idx[dst_idx] += 1
912 cls._packet_count_for_dst_if_idx[dst_idx] = 1
913 cls._packet_infos[info.index] = info
917 def info_to_payload(info):
919 Convert _PacketInfo object to packet payload
921 :param info: _PacketInfo object
923 :returns: string containing serialized data from packet info
925 return "%d %d %d %d %d" % (info.index, info.src, info.dst,
929 def payload_to_info(payload, payload_field='load'):
931 Convert packet payload to _PacketInfo object
933 :param payload: packet payload
934 :type payload: <class 'scapy.packet.Raw'>
935 :param payload_field: packet fieldname of payload "load" for
936 <class 'scapy.packet.Raw'>
937 :type payload_field: str
938 :returns: _PacketInfo object containing de-serialized data from payload
941 numbers = getattr(payload, payload_field).split()
943 info.index = int(numbers[0])
944 info.src = int(numbers[1])
945 info.dst = int(numbers[2])
946 info.ip = int(numbers[3])
947 info.proto = int(numbers[4])
950 def get_next_packet_info(self, info):
952 Iterate over the packet info list stored in the testcase
953 Start iteration with first element if info is None
954 Continue based on index in info if info is specified
956 :param info: info or None
957 :returns: next info in list or None if no more infos
962 next_index = info.index + 1
963 if next_index == len(self._packet_infos):
966 return self._packet_infos[next_index]
968 def get_next_packet_info_for_interface(self, src_index, info):
970 Search the packet info list for the next packet info with same source
973 :param src_index: source interface index to search for
974 :param info: packet info - where to start the search
975 :returns: packet info or None
979 info = self.get_next_packet_info(info)
982 if info.src == src_index:
985 def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
987 Search the packet info list for the next packet info with same source
988 and destination interface indexes
990 :param src_index: source interface index to search for
991 :param dst_index: destination interface index to search for
992 :param info: packet info - where to start the search
993 :returns: packet info or None
997 info = self.get_next_packet_info_for_interface(src_index, info)
1000 if info.dst == dst_index:
1003 def assert_equal(self, real_value, expected_value, name_or_class=None):
1004 if name_or_class is None:
1005 self.assertEqual(real_value, expected_value)
1008 msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
1009 msg = msg % (getdoc(name_or_class).strip(),
1010 real_value, str(name_or_class(real_value)),
1011 expected_value, str(name_or_class(expected_value)))
1013 msg = "Invalid %s: %s does not match expected value %s" % (
1014 name_or_class, real_value, expected_value)
1016 self.assertEqual(real_value, expected_value, msg)
1018 def assert_in_range(self,
1026 msg = "Invalid %s: %s out of range <%s,%s>" % (
1027 name, real_value, expected_min, expected_max)
1028 self.assertTrue(expected_min <= real_value <= expected_max, msg)
1030 def assert_packet_checksums_valid(self, packet,
1031 ignore_zero_udp_checksums=True):
1032 received = packet.__class__(scapy.compat.raw(packet))
1033 udp_layers = ['UDP', 'UDPerror']
1034 checksum_fields = ['cksum', 'chksum']
1037 temp = received.__class__(scapy.compat.raw(received))
1039 layer = temp.getlayer(counter)
1041 layer = layer.copy()
1042 layer.remove_payload()
1043 for cf in checksum_fields:
1044 if hasattr(layer, cf):
1045 if ignore_zero_udp_checksums and \
1046 0 == getattr(layer, cf) and \
1047 layer.name in udp_layers:
1049 delattr(temp.getlayer(counter), cf)
1050 checksums.append((counter, cf))
1053 counter = counter + 1
1054 if 0 == len(checksums):
1056 temp = temp.__class__(scapy.compat.raw(temp))
1057 for layer, cf in checksums:
1058 calc_sum = getattr(temp[layer], cf)
1060 getattr(received[layer], cf), calc_sum,
1061 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1063 "Checksum field `%s` on `%s` layer has correct value `%s`" %
1064 (cf, temp[layer].name, calc_sum))
1066 def assert_checksum_valid(self, received_packet, layer,
1067 field_name='chksum',
1068 ignore_zero_checksum=False):
1069 """ Check checksum of received packet on given layer """
1070 received_packet_checksum = getattr(received_packet[layer], field_name)
1071 if ignore_zero_checksum and 0 == received_packet_checksum:
1073 recalculated = received_packet.__class__(
1074 scapy.compat.raw(received_packet))
1075 delattr(recalculated[layer], field_name)
1076 recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1077 self.assert_equal(received_packet_checksum,
1078 getattr(recalculated[layer], field_name),
1079 "packet checksum on layer: %s" % layer)
1081 def assert_ip_checksum_valid(self, received_packet,
1082 ignore_zero_checksum=False):
1083 self.assert_checksum_valid(received_packet, 'IP',
1084 ignore_zero_checksum=ignore_zero_checksum)
1086 def assert_tcp_checksum_valid(self, received_packet,
1087 ignore_zero_checksum=False):
1088 self.assert_checksum_valid(received_packet, 'TCP',
1089 ignore_zero_checksum=ignore_zero_checksum)
1091 def assert_udp_checksum_valid(self, received_packet,
1092 ignore_zero_checksum=True):
1093 self.assert_checksum_valid(received_packet, 'UDP',
1094 ignore_zero_checksum=ignore_zero_checksum)
1096 def assert_embedded_icmp_checksum_valid(self, received_packet):
1097 if received_packet.haslayer(IPerror):
1098 self.assert_checksum_valid(received_packet, 'IPerror')
1099 if received_packet.haslayer(TCPerror):
1100 self.assert_checksum_valid(received_packet, 'TCPerror')
1101 if received_packet.haslayer(UDPerror):
1102 self.assert_checksum_valid(received_packet, 'UDPerror',
1103 ignore_zero_checksum=True)
1104 if received_packet.haslayer(ICMPerror):
1105 self.assert_checksum_valid(received_packet, 'ICMPerror')
1107 def assert_icmp_checksum_valid(self, received_packet):
1108 self.assert_checksum_valid(received_packet, 'ICMP')
1109 self.assert_embedded_icmp_checksum_valid(received_packet)
1111 def assert_icmpv6_checksum_valid(self, pkt):
1112 if pkt.haslayer(ICMPv6DestUnreach):
1113 self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1114 self.assert_embedded_icmp_checksum_valid(pkt)
1115 if pkt.haslayer(ICMPv6EchoRequest):
1116 self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1117 if pkt.haslayer(ICMPv6EchoReply):
1118 self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1120 def get_packet_counter(self, counter):
1121 if counter.startswith("/"):
1122 counter_value = self.statistics.get_counter(counter)
1124 counters = self.vapi.cli("sh errors").split('\n')
1126 for i in range(1, len(counters) - 1):
1127 results = counters[i].split()
1128 if results[1] == counter:
1129 counter_value = int(results[0])
1131 return counter_value
1133 def assert_packet_counter_equal(self, counter, expected_value):
1134 counter_value = self.get_packet_counter(counter)
1135 self.assert_equal(counter_value, expected_value,
1136 "packet counter `%s'" % counter)
1138 def assert_error_counter_equal(self, counter, expected_value):
1139 counter_value = self.statistics.get_err_counter(counter)
1140 self.assert_equal(counter_value, expected_value,
1141 "error counter `%s'" % counter)
1144 def sleep(cls, timeout, remark=None):
1146 # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1147 # * by Guido, only the main thread can be interrupted.
1149 # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892 # noqa
1152 if hasattr(os, 'sched_yield'):
1158 cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1159 before = time.time()
1162 if after - before > 2 * timeout:
1163 cls.logger.error("unexpected self.sleep() result - "
1164 "slept for %es instead of ~%es!",
1165 after - before, timeout)
1168 "Finished sleep (%s) - slept %es (wanted %es)",
1169 remark, after - before, timeout)
1171 def pg_send(self, intf, pkts, worker=None):
1172 self.vapi.cli("clear trace")
1173 intf.add_stream(pkts, worker=worker)
1174 self.pg_enable_capture(self.pg_interfaces)
1177 def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1178 self.pg_send(intf, pkts)
1181 for i in self.pg_interfaces:
1182 i.get_capture(0, timeout=timeout)
1183 i.assert_nothing_captured(remark=remark)
1186 def send_and_expect(self, intf, pkts, output, n_rx=None, worker=None):
1189 self.pg_send(intf, pkts, worker=worker)
1190 rx = output.get_capture(n_rx)
1193 def send_and_expect_only(self, intf, pkts, output, timeout=None):
1194 self.pg_send(intf, pkts)
1195 rx = output.get_capture(len(pkts))
1199 for i in self.pg_interfaces:
1200 if i not in outputs:
1201 i.get_capture(0, timeout=timeout)
1202 i.assert_nothing_captured()
1208 def get_testcase_doc_name(test):
1209 return getdoc(test.__class__).splitlines()[0]
1212 def get_test_description(descriptions, test):
1213 short_description = test.shortDescription()
1214 if descriptions and short_description:
1215 return short_description
1220 class TestCaseInfo(object):
1221 def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1222 self.logger = logger
1223 self.tempdir = tempdir
1224 self.vpp_pid = vpp_pid
1225 self.vpp_bin_path = vpp_bin_path
1226 self.core_crash_test = None
1229 class VppTestResult(unittest.TestResult):
1231 @property result_string
1232 String variable to store the test case result string.
1234 List variable containing 2-tuples of TestCase instances and strings
1235 holding formatted tracebacks. Each tuple represents a test which
1236 raised an unexpected exception.
1238 List variable containing 2-tuples of TestCase instances and strings
1239 holding formatted tracebacks. Each tuple represents a test where
1240 a failure was explicitly signalled using the TestCase.assert*()
1244 failed_test_cases_info = set()
1245 core_crash_test_cases_info = set()
1246 current_test_case_info = None
1248 def __init__(self, stream=None, descriptions=None, verbosity=None,
1251 :param stream File descriptor to store where to report test results.
1252 Set to the standard error stream by default.
1253 :param descriptions Boolean variable to store information if to use
1254 test case descriptions.
1255 :param verbosity Integer variable to store required verbosity level.
1257 super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1258 self.stream = stream
1259 self.descriptions = descriptions
1260 self.verbosity = verbosity
1261 self.result_string = None
1262 self.runner = runner
1264 def addSuccess(self, test):
1266 Record a test succeeded result
1271 if self.current_test_case_info:
1272 self.current_test_case_info.logger.debug(
1273 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1274 test._testMethodName,
1275 test._testMethodDoc))
1276 unittest.TestResult.addSuccess(self, test)
1277 self.result_string = colorize("OK", GREEN)
1279 self.send_result_through_pipe(test, PASS)
1281 def addSkip(self, test, reason):
1283 Record a test skipped.
1289 if self.current_test_case_info:
1290 self.current_test_case_info.logger.debug(
1291 "--- addSkip() %s.%s(%s) called, reason is %s" %
1292 (test.__class__.__name__, test._testMethodName,
1293 test._testMethodDoc, reason))
1294 unittest.TestResult.addSkip(self, test, reason)
1295 self.result_string = colorize("SKIP", YELLOW)
1297 self.send_result_through_pipe(test, SKIP)
1299 def symlink_failed(self):
1300 if self.current_test_case_info:
1302 failed_dir = os.getenv('FAILED_DIR')
1303 link_path = os.path.join(
1306 os.path.basename(self.current_test_case_info.tempdir))
1308 self.current_test_case_info.logger.debug(
1309 "creating a link to the failed test")
1310 self.current_test_case_info.logger.debug(
1311 "os.symlink(%s, %s)" %
1312 (self.current_test_case_info.tempdir, link_path))
1313 if os.path.exists(link_path):
1314 self.current_test_case_info.logger.debug(
1315 'symlink already exists')
1317 os.symlink(self.current_test_case_info.tempdir, link_path)
1319 except Exception as e:
1320 self.current_test_case_info.logger.error(e)
1322 def send_result_through_pipe(self, test, result):
1323 if hasattr(self, 'test_framework_result_pipe'):
1324 pipe = self.test_framework_result_pipe
1326 pipe.send((test.id(), result))
1328 def log_error(self, test, err, fn_name):
1329 if self.current_test_case_info:
1330 if isinstance(test, unittest.suite._ErrorHolder):
1331 test_name = test.description
1333 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1334 test._testMethodName,
1335 test._testMethodDoc)
1336 self.current_test_case_info.logger.debug(
1337 "--- %s() %s called, err is %s" %
1338 (fn_name, test_name, err))
1339 self.current_test_case_info.logger.debug(
1340 "formatted exception is:\n%s" %
1341 "".join(format_exception(*err)))
1343 def add_error(self, test, err, unittest_fn, error_type):
1344 if error_type == FAIL:
1345 self.log_error(test, err, 'addFailure')
1346 error_type_str = colorize("FAIL", RED)
1347 elif error_type == ERROR:
1348 self.log_error(test, err, 'addError')
1349 error_type_str = colorize("ERROR", RED)
1351 raise Exception('Error type %s cannot be used to record an '
1352 'error or a failure' % error_type)
1354 unittest_fn(self, test, err)
1355 if self.current_test_case_info:
1356 self.result_string = "%s [ temp dir used by test case: %s ]" % \
1358 self.current_test_case_info.tempdir)
1359 self.symlink_failed()
1360 self.failed_test_cases_info.add(self.current_test_case_info)
1361 if is_core_present(self.current_test_case_info.tempdir):
1362 if not self.current_test_case_info.core_crash_test:
1363 if isinstance(test, unittest.suite._ErrorHolder):
1364 test_name = str(test)
1366 test_name = "'{!s}' ({!s})".format(
1367 get_testcase_doc_name(test), test.id())
1368 self.current_test_case_info.core_crash_test = test_name
1369 self.core_crash_test_cases_info.add(
1370 self.current_test_case_info)
1372 self.result_string = '%s [no temp dir]' % error_type_str
1374 self.send_result_through_pipe(test, error_type)
1376 def addFailure(self, test, err):
1378 Record a test failed result
1381 :param err: error message
1384 self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1386 def addError(self, test, err):
1388 Record a test error result
1391 :param err: error message
1394 self.add_error(test, err, unittest.TestResult.addError, ERROR)
1396 def getDescription(self, test):
1398 Get test description
1401 :returns: test description
1404 return get_test_description(self.descriptions, test)
1406 def startTest(self, test):
1414 def print_header(test):
1415 if not hasattr(test.__class__, '_header_printed'):
1416 print(double_line_delim)
1417 print(colorize(getdoc(test).splitlines()[0], GREEN))
1418 print(double_line_delim)
1419 test.__class__._header_printed = True
1422 self.start_test = time.time()
1423 unittest.TestResult.startTest(self, test)
1424 if self.verbosity > 0:
1425 self.stream.writeln(
1426 "Starting " + self.getDescription(test) + " ...")
1427 self.stream.writeln(single_line_delim)
1429 def stopTest(self, test):
1431 Called when the given test has been run
1436 unittest.TestResult.stopTest(self, test)
1438 if self.verbosity > 0:
1439 self.stream.writeln(single_line_delim)
1440 self.stream.writeln("%-73s%s" % (self.getDescription(test),
1441 self.result_string))
1442 self.stream.writeln(single_line_delim)
1444 self.stream.writeln("%-68s %4.2f %s" %
1445 (self.getDescription(test),
1446 time.time() - self.start_test,
1447 self.result_string))
1449 self.send_result_through_pipe(test, TEST_RUN)
1451 def printErrors(self):
1453 Print errors from running the test case
1455 if len(self.errors) > 0 or len(self.failures) > 0:
1456 self.stream.writeln()
1457 self.printErrorList('ERROR', self.errors)
1458 self.printErrorList('FAIL', self.failures)
1460 # ^^ that is the last output from unittest before summary
1461 if not self.runner.print_summary:
1462 devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1463 self.stream = devnull
1464 self.runner.stream = devnull
1466 def printErrorList(self, flavour, errors):
1468 Print error list to the output stream together with error type
1469 and test case description.
1471 :param flavour: error type
1472 :param errors: iterable errors
1475 for test, err in errors:
1476 self.stream.writeln(double_line_delim)
1477 self.stream.writeln("%s: %s" %
1478 (flavour, self.getDescription(test)))
1479 self.stream.writeln(single_line_delim)
1480 self.stream.writeln("%s" % err)
1483 class VppTestRunner(unittest.TextTestRunner):
1485 A basic test runner implementation which prints results to standard error.
1489 def resultclass(self):
1490 """Class maintaining the results of the tests"""
1491 return VppTestResult
1493 def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1494 result_pipe=None, failfast=False, buffer=False,
1495 resultclass=None, print_summary=True, **kwargs):
1496 # ignore stream setting here, use hard-coded stdout to be in sync
1497 # with prints from VppTestCase methods ...
1498 super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1499 verbosity, failfast, buffer,
1500 resultclass, **kwargs)
1501 KeepAliveReporter.pipe = keep_alive_pipe
1503 self.orig_stream = self.stream
1504 self.resultclass.test_framework_result_pipe = result_pipe
1506 self.print_summary = print_summary
1508 def _makeResult(self):
1509 return self.resultclass(self.stream,
1514 def run(self, test):
1521 faulthandler.enable() # emit stack trace to stderr if killed by signal
1523 result = super(VppTestRunner, self).run(test)
1524 if not self.print_summary:
1525 self.stream = self.orig_stream
1526 result.stream = self.orig_stream
1530 class Worker(Thread):
1531 def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1532 super(Worker, self).__init__(*args, **kwargs)
1533 self.logger = logger
1534 self.args = executable_args
1535 if hasattr(self, 'testcase') and self.testcase.debug_all:
1536 if self.testcase.debug_gdbserver:
1537 self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1538 .format(port=self.testcase.gdbserver_port)] + args
1539 elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1540 self.args.append(self.wait_for_gdb)
1541 self.app_bin = executable_args[0]
1542 self.app_name = os.path.basename(self.app_bin)
1543 if hasattr(self, 'role'):
1544 self.app_name += ' {role}'.format(role=self.role)
1547 env = {} if env is None else env
1548 self.env = copy.deepcopy(env)
1550 def wait_for_enter(self):
1551 if not hasattr(self, 'testcase'):
1553 if self.testcase.debug_all and self.testcase.debug_gdbserver:
1555 print(double_line_delim)
1556 print("Spawned GDB Server for '{app}' with PID: {pid}"
1557 .format(app=self.app_name, pid=self.process.pid))
1558 elif self.testcase.debug_all and self.testcase.debug_gdb:
1560 print(double_line_delim)
1561 print("Spawned '{app}' with PID: {pid}"
1562 .format(app=self.app_name, pid=self.process.pid))
1565 print(single_line_delim)
1566 print("You can debug '{app}' using:".format(app=self.app_name))
1567 if self.testcase.debug_gdbserver:
1568 print("sudo gdb " + self.app_bin +
1569 " -ex 'target remote localhost:{port}'"
1570 .format(port=self.testcase.gdbserver_port))
1571 print("Now is the time to attach gdb by running the above "
1572 "command, set up breakpoints etc., then resume from "
1573 "within gdb by issuing the 'continue' command")
1574 self.testcase.gdbserver_port += 1
1575 elif self.testcase.debug_gdb:
1576 print("sudo gdb " + self.app_bin +
1577 " -ex 'attach {pid}'".format(pid=self.process.pid))
1578 print("Now is the time to attach gdb by running the above "
1579 "command and set up breakpoints etc., then resume from"
1580 " within gdb by issuing the 'continue' command")
1581 print(single_line_delim)
1582 input("Press ENTER to continue running the testcase...")
1585 executable = self.args[0]
1586 if not os.path.exists(executable) or not os.access(
1587 executable, os.F_OK | os.X_OK):
1588 # Exit code that means some system file did not exist,
1589 # could not be opened, or had some other kind of error.
1590 self.result = os.EX_OSFILE
1591 raise EnvironmentError(
1592 "executable '%s' is not found or executable." % executable)
1593 self.logger.debug("Running executable: '{app}'"
1594 .format(app=' '.join(self.args)))
1595 env = os.environ.copy()
1596 env.update(self.env)
1597 env["CK_LOG_FILE_NAME"] = "-"
1598 self.process = subprocess.Popen(
1599 self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1600 stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1601 self.wait_for_enter()
1602 out, err = self.process.communicate()
1603 self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1604 self.logger.info("Return code is `%s'" % self.process.returncode)
1605 self.logger.info(single_line_delim)
1606 self.logger.info("Executable `{app}' wrote to stdout:"
1607 .format(app=self.app_name))
1608 self.logger.info(single_line_delim)
1609 self.logger.info(out.decode('utf-8'))
1610 self.logger.info(single_line_delim)
1611 self.logger.info("Executable `{app}' wrote to stderr:"
1612 .format(app=self.app_name))
1613 self.logger.info(single_line_delim)
1614 self.logger.info(err.decode('utf-8'))
1615 self.logger.info(single_line_delim)
1616 self.result = self.process.returncode
1619 if __name__ == '__main__':