3 from __future__ import print_function
19 from collections import deque
20 from threading import Thread, Event
21 from inspect import getdoc, isclass
22 from traceback import format_exception
23 from logging import FileHandler, DEBUG, Formatter
26 from scapy.packet import Raw
27 import hook as hookmodule
28 from vpp_pg_interface import VppPGInterface
29 from vpp_sub_interface import VppSubInterface
30 from vpp_lo_interface import VppLoInterface
31 from vpp_bvi_interface import VppBviInterface
32 from vpp_papi_provider import VppPapiProvider
34 from vpp_papi.vpp_stats import VPPStats
35 from vpp_papi.vpp_transport_shmem import VppTransportShmemIOError
36 from log import RED, GREEN, YELLOW, double_line_delim, single_line_delim, \
38 from vpp_object import VppObjectRegistry
39 from util import ppp, is_core_present
40 from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
41 from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
42 from scapy.layers.inet6 import ICMPv6EchoReply
44 logger = logging.getLogger(__name__)
46 # Set up an empty logger for the testcase that can be overridden as necessary
47 null_logger = logging.getLogger('VppTestCase')
48 null_logger.addHandler(logging.NullHandler())
57 class BoolEnvironmentVariable(object):
59 def __init__(self, env_var_name, default='n', true_values=None):
60 self.name = env_var_name
61 self.default = default
62 self.true_values = true_values if true_values is not None else \
66 return os.getenv(self.name, self.default).lower() in self.true_values
68 if sys.version_info[0] == 2:
69 __nonzero__ = __bool__
72 return 'BoolEnvironmentVariable(%r, default=%r, true_values=%r)' % \
73 (self.name, self.default, self.true_values)
76 debug_framework = BoolEnvironmentVariable('TEST_DEBUG')
81 Test framework module.
83 The module provides a set of tools for constructing and running tests and
84 representing the results.
88 class VppDiedError(Exception):
89 """ exception for reporting that the subprocess has died."""
91 signals_by_value = {v: k for k, v in signal.__dict__.items() if
92 k.startswith('SIG') and not k.startswith('SIG_')}
94 def __init__(self, rv=None, testcase=None, method_name=None):
96 self.signal_name = None
97 self.testcase = testcase
98 self.method_name = method_name
101 self.signal_name = VppDiedError.signals_by_value[-rv]
102 except (KeyError, TypeError):
105 if testcase is None and method_name is None:
108 in_msg = 'running %s.%s ' % (testcase, method_name)
110 msg = "VPP subprocess died %sunexpectedly with return code: %d%s." % (
113 ' [%s]' % (self.signal_name if
114 self.signal_name is not None else ''))
115 super(VppDiedError, self).__init__(msg)
118 class _PacketInfo(object):
119 """Private class to create packet info object.
121 Help process information about the next packet.
122 Set variables to default values.
124 #: Store the index of the packet.
126 #: Store the index of the source packet generator interface of the packet.
128 #: Store the index of the destination packet generator interface
131 #: Store expected ip version
133 #: Store expected upper protocol
135 #: Store the copy of the former packet.
138 def __eq__(self, other):
139 index = self.index == other.index
140 src = self.src == other.src
141 dst = self.dst == other.dst
142 data = self.data == other.data
143 return index and src and dst and data
146 def pump_output(testclass):
147 """ pump output from vpp stdout/stderr to proper queues """
150 while not testclass.pump_thread_stop_flag.is_set():
151 readable = select.select([testclass.vpp.stdout.fileno(),
152 testclass.vpp.stderr.fileno(),
153 testclass.pump_thread_wakeup_pipe[0]],
155 if testclass.vpp.stdout.fileno() in readable:
156 read = os.read(testclass.vpp.stdout.fileno(), 102400)
158 split = read.decode('ascii',
159 errors='backslashreplace').splitlines(True)
160 if len(stdout_fragment) > 0:
161 split[0] = "%s%s" % (stdout_fragment, split[0])
162 if len(split) > 0 and split[-1].endswith("\n"):
166 stdout_fragment = split[-1]
167 testclass.vpp_stdout_deque.extend(split[:limit])
168 if not testclass.cache_vpp_output:
169 for line in split[:limit]:
170 testclass.logger.info(
171 "VPP STDOUT: %s" % line.rstrip("\n"))
172 if testclass.vpp.stderr.fileno() in readable:
173 read = os.read(testclass.vpp.stderr.fileno(), 102400)
175 split = read.decode('ascii',
176 errors='backslashreplace').splitlines(True)
177 if len(stderr_fragment) > 0:
178 split[0] = "%s%s" % (stderr_fragment, split[0])
179 if len(split) > 0 and split[-1].endswith("\n"):
183 stderr_fragment = split[-1]
185 testclass.vpp_stderr_deque.extend(split[:limit])
186 if not testclass.cache_vpp_output:
187 for line in split[:limit]:
188 testclass.logger.error(
189 "VPP STDERR: %s" % line.rstrip("\n"))
190 # ignoring the dummy pipe here intentionally - the
191 # flag will take care of properly terminating the loop
194 def _is_skip_aarch64_set():
195 return BoolEnvironmentVariable('SKIP_AARCH64')
198 is_skip_aarch64_set = _is_skip_aarch64_set()
201 def _is_platform_aarch64():
202 return platform.machine() == 'aarch64'
205 is_platform_aarch64 = _is_platform_aarch64()
208 def _running_extended_tests():
209 return BoolEnvironmentVariable("EXTENDED_TESTS")
212 running_extended_tests = _running_extended_tests()
215 def _running_gcov_tests():
216 return BoolEnvironmentVariable("GCOV_TESTS")
219 running_gcov_tests = _running_gcov_tests()
222 def _running_on_centos():
223 os_id = os.getenv("OS_ID", "")
224 return True if "centos" in os_id.lower() else False
227 running_on_centos = _running_on_centos()
230 class KeepAliveReporter(object):
232 Singleton object which reports test start to parent process
237 self.__dict__ = self._shared_state
245 def pipe(self, pipe):
246 if self._pipe is not None:
247 raise Exception("Internal error - pipe should only be set once.")
250 def send_keep_alive(self, test, desc=None):
252 Write current test tmpdir & desc to keep-alive pipe to signal liveness
254 if self.pipe is None:
255 # if not running forked..
259 desc = '%s (%s)' % (desc, unittest.util.strclass(test))
263 self.pipe.send((desc, test.vpp_bin, test.tempdir, test.vpp.pid))
266 class VppTestCase(unittest.TestCase):
267 """This subclass is a base class for VPP test cases that are implemented as
268 classes. It provides methods to create and run test case.
271 extra_vpp_punt_config = []
272 extra_vpp_plugin_config = []
274 vapi_response_timeout = 5
277 def packet_infos(self):
278 """List of packet infos"""
279 return self._packet_infos
282 def get_packet_count_for_if_idx(cls, dst_if_index):
283 """Get the number of packet info for specified destination if index"""
284 if dst_if_index in cls._packet_count_for_dst_if_idx:
285 return cls._packet_count_for_dst_if_idx[dst_if_index]
291 """ if the test case class is timing-sensitive - return true """
296 """Return the instance of this testcase"""
297 return cls.test_instance
300 def set_debug_flags(cls, d):
301 cls.gdbserver_port = 7777
302 cls.debug_core = False
303 cls.debug_gdb = False
304 cls.debug_gdbserver = False
305 cls.debug_all = False
310 cls.debug_core = True
311 elif dl == "gdb" or dl == "gdb-all":
313 elif dl == "gdbserver" or dl == "gdbserver-all":
314 cls.debug_gdbserver = True
316 raise Exception("Unrecognized DEBUG option: '%s'" % d)
317 if dl == "gdb-all" or dl == "gdbserver-all":
321 def get_least_used_cpu():
322 cpu_usage_list = [set(range(psutil.cpu_count()))]
323 vpp_processes = [p for p in psutil.process_iter(attrs=['pid', 'name'])
324 if 'vpp_main' == p.info['name']]
325 for vpp_process in vpp_processes:
326 for cpu_usage_set in cpu_usage_list:
328 cpu_num = vpp_process.cpu_num()
329 if cpu_num in cpu_usage_set:
330 cpu_usage_set_index = cpu_usage_list.index(
332 if cpu_usage_set_index == len(cpu_usage_list) - 1:
333 cpu_usage_list.append({cpu_num})
335 cpu_usage_list[cpu_usage_set_index + 1].add(
337 cpu_usage_set.remove(cpu_num)
339 except psutil.NoSuchProcess:
342 for cpu_usage_set in cpu_usage_list:
343 if len(cpu_usage_set) > 0:
344 min_usage_set = cpu_usage_set
347 return random.choice(tuple(min_usage_set))
350 def setUpConstants(cls):
351 """ Set-up the test case class based on environment variables """
352 cls.step = BoolEnvironmentVariable('STEP')
353 d = os.getenv("DEBUG", None)
354 # inverted case to handle '' == True
355 c = os.getenv("CACHE_OUTPUT", "1")
356 cls.cache_vpp_output = False if c.lower() in ("n", "no", "0") else True
357 cls.set_debug_flags(d)
358 cls.vpp_bin = os.getenv('VPP_BIN', "vpp")
359 cls.plugin_path = os.getenv('VPP_PLUGIN_PATH')
360 cls.test_plugin_path = os.getenv('VPP_TEST_PLUGIN_PATH')
361 cls.extern_plugin_path = os.getenv('EXTERN_PLUGINS')
363 if cls.plugin_path is not None:
364 if cls.extern_plugin_path is not None:
365 plugin_path = "%s:%s" % (
366 cls.plugin_path, cls.extern_plugin_path)
368 plugin_path = cls.plugin_path
369 elif cls.extern_plugin_path is not None:
370 plugin_path = cls.extern_plugin_path
372 if cls.step or cls.debug_gdb or cls.debug_gdbserver:
373 debug_cli = "cli-listen localhost:5002"
375 size = os.getenv("COREDUMP_SIZE")
377 coredump_size = "coredump-size %s" % size
378 if coredump_size is None:
379 coredump_size = "coredump-size unlimited"
381 cpu_core_number = cls.get_least_used_cpu()
382 if not hasattr(cls, "worker_config"):
383 cls.worker_config = ""
385 default_variant = os.getenv("VARIANT")
386 if default_variant is not None:
387 default_variant = "defaults { %s 100 }" % default_variant
391 api_fuzzing = os.getenv("API_FUZZ")
392 if api_fuzzing is None:
395 cls.vpp_cmdline = [cls.vpp_bin, "unix",
396 "{", "nodaemon", debug_cli, "full-coredump",
397 coredump_size, "runtime-dir", cls.tempdir, "}",
398 "api-trace", "{", "on", "}", "api-segment", "{",
399 "prefix", cls.shm_prefix, "}", "cpu", "{",
400 "main-core", str(cpu_core_number),
401 cls.worker_config, "}",
402 "physmem", "{", "max-size", "32m", "}",
403 "statseg", "{", "socket-name", cls.stats_sock, "}",
404 "socksvr", "{", "socket-name", cls.api_sock, "}",
405 "node { ", default_variant, "}",
406 "api-fuzz {", api_fuzzing, "}",
408 "{", "plugin", "dpdk_plugin.so", "{", "disable",
409 "}", "plugin", "rdma_plugin.so", "{", "disable",
410 "}", "plugin", "lisp_unittest_plugin.so", "{",
412 "}", "plugin", "unittest_plugin.so", "{", "enable",
413 "}"] + cls.extra_vpp_plugin_config + ["}", ]
415 if cls.extra_vpp_punt_config is not None:
416 cls.vpp_cmdline.extend(cls.extra_vpp_punt_config)
417 if plugin_path is not None:
418 cls.vpp_cmdline.extend(["plugin_path", plugin_path])
419 if cls.test_plugin_path is not None:
420 cls.vpp_cmdline.extend(["test_plugin_path", cls.test_plugin_path])
422 cls.logger.info("vpp_cmdline args: %s" % cls.vpp_cmdline)
423 cls.logger.info("vpp_cmdline: %s" % " ".join(cls.vpp_cmdline))
426 def wait_for_enter(cls):
427 if cls.debug_gdbserver:
428 print(double_line_delim)
429 print("Spawned GDB server with PID: %d" % cls.vpp.pid)
431 print(double_line_delim)
432 print("Spawned VPP with PID: %d" % cls.vpp.pid)
434 cls.logger.debug("Spawned VPP with PID: %d" % cls.vpp.pid)
436 print(single_line_delim)
437 print("You can debug VPP using:")
438 if cls.debug_gdbserver:
439 print("sudo gdb " + cls.vpp_bin +
440 " -ex 'target remote localhost:{port}'"
441 .format(port=cls.gdbserver_port))
442 print("Now is the time to attach gdb by running the above "
443 "command, set up breakpoints etc., then resume VPP from "
444 "within gdb by issuing the 'continue' command")
445 cls.gdbserver_port += 1
447 print("sudo gdb " + cls.vpp_bin + " -ex 'attach %s'" % cls.vpp.pid)
448 print("Now is the time to attach gdb by running the above "
449 "command and set up breakpoints etc., then resume VPP from"
450 " within gdb by issuing the 'continue' command")
451 print(single_line_delim)
452 input("Press ENTER to continue running the testcase...")
456 cmdline = cls.vpp_cmdline
458 if cls.debug_gdbserver:
459 gdbserver = '/usr/bin/gdbserver'
460 if not os.path.isfile(gdbserver) or \
461 not os.access(gdbserver, os.X_OK):
462 raise Exception("gdbserver binary '%s' does not exist or is "
463 "not executable" % gdbserver)
465 cmdline = [gdbserver, 'localhost:{port}'
466 .format(port=cls.gdbserver_port)] + cls.vpp_cmdline
467 cls.logger.info("Gdbserver cmdline is %s", " ".join(cmdline))
470 cls.vpp = subprocess.Popen(cmdline,
471 stdout=subprocess.PIPE,
472 stderr=subprocess.PIPE)
473 except subprocess.CalledProcessError as e:
474 cls.logger.critical("Subprocess returned with non-0 return code: ("
478 cls.logger.critical("Subprocess returned with OS error: "
479 "(%s) %s", e.errno, e.strerror)
481 except Exception as e:
482 cls.logger.exception("Subprocess returned unexpected from "
489 def wait_for_coredump(cls):
490 corefile = cls.tempdir + "/core"
491 if os.path.isfile(corefile):
492 cls.logger.error("Waiting for coredump to complete: %s", corefile)
493 curr_size = os.path.getsize(corefile)
494 deadline = time.time() + 60
496 while time.time() < deadline:
499 curr_size = os.path.getsize(corefile)
500 if size == curr_size:
504 cls.logger.error("Timed out waiting for coredump to complete:"
507 cls.logger.error("Coredump complete: %s, size %d",
513 Perform class setup before running the testcase
514 Remove shared memory files, start vpp and connect the vpp-api
516 super(VppTestCase, cls).setUpClass()
517 gc.collect() # run garbage collection first
518 cls.logger = get_logger(cls.__name__)
519 seed = os.environ["RND_SEED"]
521 if hasattr(cls, 'parallel_handler'):
522 cls.logger.addHandler(cls.parallel_handler)
523 cls.logger.propagate = False
525 cls.tempdir = tempfile.mkdtemp(
526 prefix='vpp-unittest-%s-' % cls.__name__)
527 cls.stats_sock = "%s/stats.sock" % cls.tempdir
528 cls.api_sock = "%s/api.sock" % cls.tempdir
529 cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir)
530 cls.file_handler.setFormatter(
531 Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
533 cls.file_handler.setLevel(DEBUG)
534 cls.logger.addHandler(cls.file_handler)
535 cls.logger.debug("--- setUpClass() for %s called ---" %
537 cls.shm_prefix = os.path.basename(cls.tempdir)
538 os.chdir(cls.tempdir)
539 cls.logger.info("Temporary dir is %s, shm prefix is %s",
540 cls.tempdir, cls.shm_prefix)
541 cls.logger.debug("Random seed is %s" % seed)
543 cls.reset_packet_infos()
547 cls.registry = VppObjectRegistry()
548 cls.vpp_startup_failed = False
549 cls.reporter = KeepAliveReporter()
550 # need to catch exceptions here because if we raise, then the cleanup
551 # doesn't get called and we might end with a zombie vpp
554 cls.reporter.send_keep_alive(cls, 'setUpClass')
555 VppTestResult.current_test_case_info = TestCaseInfo(
556 cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin)
557 cls.vpp_stdout_deque = deque()
558 cls.vpp_stderr_deque = deque()
559 cls.pump_thread_stop_flag = Event()
560 cls.pump_thread_wakeup_pipe = os.pipe()
561 cls.pump_thread = Thread(target=pump_output, args=(cls,))
562 cls.pump_thread.daemon = True
563 cls.pump_thread.start()
564 if cls.debug_gdb or cls.debug_gdbserver:
565 cls.vapi_response_timeout = 0
566 cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls,
567 cls.vapi_response_timeout)
569 hook = hookmodule.StepHook(cls)
571 hook = hookmodule.PollHook(cls)
572 cls.vapi.register_hook(hook)
573 cls.statistics = VPPStats(socketname=cls.stats_sock)
577 cls.vpp_startup_failed = True
579 "VPP died shortly after startup, check the"
580 " output to standard error for possible cause")
584 except vpp_papi.VPPIOError as e:
585 cls.logger.debug("Exception connecting to vapi: %s" % e)
586 cls.vapi.disconnect()
588 if cls.debug_gdbserver:
589 print(colorize("You're running VPP inside gdbserver but "
590 "VPP-API connection failed, did you forget "
591 "to 'continue' VPP from within gdb?", RED))
593 except vpp_papi.VPPRuntimeError as e:
594 cls.logger.debug("%s" % e)
597 except Exception as e:
598 cls.logger.debug("Exception connecting to VPP: %s" % e)
603 def _debug_quit(cls):
604 if (cls.debug_gdbserver or cls.debug_gdb):
608 if cls.vpp.returncode is None:
610 print(double_line_delim)
611 print("VPP or GDB server is still running")
612 print(single_line_delim)
613 input("When done debugging, press ENTER to kill the "
614 "process and finish running the testcase...")
615 except AttributeError:
621 Disconnect vpp-api, kill vpp and cleanup shared memory files
625 # first signal that we want to stop the pump thread, then wake it up
626 if hasattr(cls, 'pump_thread_stop_flag'):
627 cls.pump_thread_stop_flag.set()
628 if hasattr(cls, 'pump_thread_wakeup_pipe'):
629 os.write(cls.pump_thread_wakeup_pipe[1], b'ding dong wake up')
630 if hasattr(cls, 'pump_thread'):
631 cls.logger.debug("Waiting for pump thread to stop")
632 cls.pump_thread.join()
633 if hasattr(cls, 'vpp_stderr_reader_thread'):
634 cls.logger.debug("Waiting for stderr pump to stop")
635 cls.vpp_stderr_reader_thread.join()
637 if hasattr(cls, 'vpp'):
638 if hasattr(cls, 'vapi'):
639 cls.logger.debug(cls.vapi.vpp.get_stats())
640 cls.logger.debug("Disconnecting class vapi client on %s",
642 cls.vapi.disconnect()
643 cls.logger.debug("Deleting class vapi attribute on %s",
647 if cls.vpp.returncode is None:
648 cls.wait_for_coredump()
649 cls.logger.debug("Sending TERM to vpp")
651 cls.logger.debug("Waiting for vpp to die")
652 cls.vpp.communicate()
653 cls.logger.debug("Deleting class vpp attribute on %s",
657 if cls.vpp_startup_failed:
658 stdout_log = cls.logger.info
659 stderr_log = cls.logger.critical
661 stdout_log = cls.logger.info
662 stderr_log = cls.logger.info
664 if hasattr(cls, 'vpp_stdout_deque'):
665 stdout_log(single_line_delim)
666 stdout_log('VPP output to stdout while running %s:', cls.__name__)
667 stdout_log(single_line_delim)
668 vpp_output = "".join(cls.vpp_stdout_deque)
669 with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f:
671 stdout_log('\n%s', vpp_output)
672 stdout_log(single_line_delim)
674 if hasattr(cls, 'vpp_stderr_deque'):
675 stderr_log(single_line_delim)
676 stderr_log('VPP output to stderr while running %s:', cls.__name__)
677 stderr_log(single_line_delim)
678 vpp_output = "".join(cls.vpp_stderr_deque)
679 with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f:
681 stderr_log('\n%s', vpp_output)
682 stderr_log(single_line_delim)
685 def tearDownClass(cls):
686 """ Perform final cleanup after running all tests in this test-case """
687 cls.logger.debug("--- tearDownClass() for %s called ---" %
689 cls.reporter.send_keep_alive(cls, 'tearDownClass')
691 cls.file_handler.close()
692 cls.reset_packet_infos()
694 debug_internal.on_tear_down_class(cls)
696 def show_commands_at_teardown(self):
697 """ Allow subclass specific teardown logging additions."""
698 self.logger.info("--- No test specific show commands provided. ---")
701 """ Show various debug prints after each test """
702 self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
703 (self.__class__.__name__, self._testMethodName,
704 self._testMethodDoc))
707 if not self.vpp_dead:
708 self.logger.debug(self.vapi.cli("show trace max 1000"))
709 self.logger.info(self.vapi.ppcli("show interface"))
710 self.logger.info(self.vapi.ppcli("show hardware"))
711 self.logger.info(self.statistics.set_errors_str())
712 self.logger.info(self.vapi.ppcli("show run"))
713 self.logger.info(self.vapi.ppcli("show log"))
714 self.logger.info(self.vapi.ppcli("show bihash"))
715 self.logger.info("Logging testcase specific show commands.")
716 self.show_commands_at_teardown()
717 self.registry.remove_vpp_config(self.logger)
718 # Save/Dump VPP api trace log
719 m = self._testMethodName
720 api_trace = "vpp_api_trace.%s.%d.log" % (m, self.vpp.pid)
721 tmp_api_trace = "/tmp/%s" % api_trace
722 vpp_api_trace_log = "%s/%s" % (self.tempdir, api_trace)
723 self.logger.info(self.vapi.ppcli("api trace save %s" % api_trace))
724 self.logger.info("Moving %s to %s\n" % (tmp_api_trace,
726 os.rename(tmp_api_trace, vpp_api_trace_log)
727 self.logger.info(self.vapi.ppcli("api trace custom-dump %s" %
729 except VppTransportShmemIOError:
730 self.logger.debug("VppTransportShmemIOError: Vpp dead. "
731 "Cannot log show commands.")
734 self.registry.unregister_all(self.logger)
737 """ Clear trace before running each test"""
738 super(VppTestCase, self).setUp()
739 self.reporter.send_keep_alive(self)
742 raise VppDiedError(rv=None, testcase=self.__class__.__name__,
743 method_name=self._testMethodName)
744 self.sleep(.1, "during setUp")
745 self.vpp_stdout_deque.append(
746 "--- test setUp() for %s.%s(%s) starts here ---\n" %
747 (self.__class__.__name__, self._testMethodName,
748 self._testMethodDoc))
749 self.vpp_stderr_deque.append(
750 "--- test setUp() for %s.%s(%s) starts here ---\n" %
751 (self.__class__.__name__, self._testMethodName,
752 self._testMethodDoc))
753 self.vapi.cli("clear trace")
754 # store the test instance inside the test class - so that objects
755 # holding the class can access instance methods (like assertEqual)
756 type(self).test_instance = self
759 def pg_enable_capture(cls, interfaces=None):
761 Enable capture on packet-generator interfaces
763 :param interfaces: iterable interface indexes (if None,
764 use self.pg_interfaces)
767 if interfaces is None:
768 interfaces = cls.pg_interfaces
773 def register_capture(cls, cap_name):
774 """ Register a capture in the testclass """
775 # add to the list of captures with current timestamp
776 cls._captures.append((time.time(), cap_name))
779 def get_vpp_time(cls):
780 # processes e.g. "Time now 2.190522, Wed, 11 Mar 2020 17:29:54 GMT"
781 # returns float("2.190522")
782 timestr = cls.vapi.cli('show clock')
783 head, sep, tail = timestr.partition(',')
784 head, sep, tail = head.partition('Time now')
788 def sleep_on_vpp_time(cls, sec):
789 """ Sleep according to time in VPP world """
790 # On a busy system with many processes
791 # we might end up with VPP time being slower than real world
792 # So take that into account when waiting for VPP to do something
793 start_time = cls.get_vpp_time()
794 while cls.get_vpp_time() - start_time < sec:
799 """ Enable the PG, wait till it is done, then clean up """
800 cls.vapi.cli("trace add pg-input 1000")
801 cls.vapi.cli('packet-generator enable')
802 # PG, when starts, runs to completion -
803 # so let's avoid a race condition,
804 # and wait a little till it's done.
805 # Then clean it up - and then be gone.
806 deadline = time.time() + 300
807 while cls.vapi.cli('show packet-generator').find("Yes") != -1:
808 cls.sleep(0.01) # yield
809 if time.time() > deadline:
810 cls.logger.error("Timeout waiting for pg to stop")
812 for stamp, cap_name in cls._captures:
813 cls.vapi.cli('packet-generator delete %s' % cap_name)
817 def create_pg_interfaces(cls, interfaces, gso=0, gso_size=0):
819 Create packet-generator interfaces.
821 :param interfaces: iterable indexes of the interfaces.
822 :returns: List of created interfaces.
827 intf = VppPGInterface(cls, i, gso, gso_size)
828 setattr(cls, intf.name, intf)
830 cls.pg_interfaces = result
834 def create_loopback_interfaces(cls, count):
836 Create loopback interfaces.
838 :param count: number of interfaces created.
839 :returns: List of created interfaces.
841 result = [VppLoInterface(cls) for i in range(count)]
843 setattr(cls, intf.name, intf)
844 cls.lo_interfaces = result
848 def create_bvi_interfaces(cls, count):
850 Create BVI interfaces.
852 :param count: number of interfaces created.
853 :returns: List of created interfaces.
855 result = [VppBviInterface(cls) for i in range(count)]
857 setattr(cls, intf.name, intf)
858 cls.bvi_interfaces = result
862 def extend_packet(packet, size, padding=' '):
864 Extend packet to given size by padding with spaces or custom padding
865 NOTE: Currently works only when Raw layer is present.
867 :param packet: packet
868 :param size: target size
869 :param padding: padding used to extend the payload
872 packet_len = len(packet) + 4
873 extend = size - packet_len
875 num = (extend // len(padding)) + 1
876 packet[Raw].load += (padding * num)[:extend].encode("ascii")
879 def reset_packet_infos(cls):
880 """ Reset the list of packet info objects and packet counts to zero """
881 cls._packet_infos = {}
882 cls._packet_count_for_dst_if_idx = {}
885 def create_packet_info(cls, src_if, dst_if):
887 Create packet info object containing the source and destination indexes
888 and add it to the testcase's packet info list
890 :param VppInterface src_if: source interface
891 :param VppInterface dst_if: destination interface
893 :returns: _PacketInfo object
897 info.index = len(cls._packet_infos)
898 info.src = src_if.sw_if_index
899 info.dst = dst_if.sw_if_index
900 if isinstance(dst_if, VppSubInterface):
901 dst_idx = dst_if.parent.sw_if_index
903 dst_idx = dst_if.sw_if_index
904 if dst_idx in cls._packet_count_for_dst_if_idx:
905 cls._packet_count_for_dst_if_idx[dst_idx] += 1
907 cls._packet_count_for_dst_if_idx[dst_idx] = 1
908 cls._packet_infos[info.index] = info
912 def info_to_payload(info):
914 Convert _PacketInfo object to packet payload
916 :param info: _PacketInfo object
918 :returns: string containing serialized data from packet info
920 return "%d %d %d %d %d" % (info.index, info.src, info.dst,
924 def payload_to_info(payload, payload_field='load'):
926 Convert packet payload to _PacketInfo object
928 :param payload: packet payload
929 :type payload: <class 'scapy.packet.Raw'>
930 :param payload_field: packet fieldname of payload "load" for
931 <class 'scapy.packet.Raw'>
932 :type payload_field: str
933 :returns: _PacketInfo object containing de-serialized data from payload
936 numbers = getattr(payload, payload_field).split()
938 info.index = int(numbers[0])
939 info.src = int(numbers[1])
940 info.dst = int(numbers[2])
941 info.ip = int(numbers[3])
942 info.proto = int(numbers[4])
945 def get_next_packet_info(self, info):
947 Iterate over the packet info list stored in the testcase
948 Start iteration with first element if info is None
949 Continue based on index in info if info is specified
951 :param info: info or None
952 :returns: next info in list or None if no more infos
957 next_index = info.index + 1
958 if next_index == len(self._packet_infos):
961 return self._packet_infos[next_index]
963 def get_next_packet_info_for_interface(self, src_index, info):
965 Search the packet info list for the next packet info with same source
968 :param src_index: source interface index to search for
969 :param info: packet info - where to start the search
970 :returns: packet info or None
974 info = self.get_next_packet_info(info)
977 if info.src == src_index:
980 def get_next_packet_info_for_interface2(self, src_index, dst_index, info):
982 Search the packet info list for the next packet info with same source
983 and destination interface indexes
985 :param src_index: source interface index to search for
986 :param dst_index: destination interface index to search for
987 :param info: packet info - where to start the search
988 :returns: packet info or None
992 info = self.get_next_packet_info_for_interface(src_index, info)
995 if info.dst == dst_index:
998 def assert_equal(self, real_value, expected_value, name_or_class=None):
999 if name_or_class is None:
1000 self.assertEqual(real_value, expected_value)
1003 msg = "Invalid %s: %d('%s') does not match expected value %d('%s')"
1004 msg = msg % (getdoc(name_or_class).strip(),
1005 real_value, str(name_or_class(real_value)),
1006 expected_value, str(name_or_class(expected_value)))
1008 msg = "Invalid %s: %s does not match expected value %s" % (
1009 name_or_class, real_value, expected_value)
1011 self.assertEqual(real_value, expected_value, msg)
1013 def assert_in_range(self,
1021 msg = "Invalid %s: %s out of range <%s,%s>" % (
1022 name, real_value, expected_min, expected_max)
1023 self.assertTrue(expected_min <= real_value <= expected_max, msg)
1025 def assert_packet_checksums_valid(self, packet,
1026 ignore_zero_udp_checksums=True):
1027 received = packet.__class__(scapy.compat.raw(packet))
1028 udp_layers = ['UDP', 'UDPerror']
1029 checksum_fields = ['cksum', 'chksum']
1032 temp = received.__class__(scapy.compat.raw(received))
1034 layer = temp.getlayer(counter)
1036 layer = layer.copy()
1037 layer.remove_payload()
1038 for cf in checksum_fields:
1039 if hasattr(layer, cf):
1040 if ignore_zero_udp_checksums and \
1041 0 == getattr(layer, cf) and \
1042 layer.name in udp_layers:
1044 delattr(temp.getlayer(counter), cf)
1045 checksums.append((counter, cf))
1048 counter = counter + 1
1049 if 0 == len(checksums):
1051 temp = temp.__class__(scapy.compat.raw(temp))
1052 for layer, cf in checksums:
1053 calc_sum = getattr(temp[layer], cf)
1055 getattr(received[layer], cf), calc_sum,
1056 "packet checksum on layer #%d: %s" % (layer, temp[layer].name))
1058 "Checksum field `%s` on `%s` layer has correct value `%s`" %
1059 (cf, temp[layer].name, calc_sum))
1061 def assert_checksum_valid(self, received_packet, layer,
1062 field_name='chksum',
1063 ignore_zero_checksum=False):
1064 """ Check checksum of received packet on given layer """
1065 received_packet_checksum = getattr(received_packet[layer], field_name)
1066 if ignore_zero_checksum and 0 == received_packet_checksum:
1068 recalculated = received_packet.__class__(
1069 scapy.compat.raw(received_packet))
1070 delattr(recalculated[layer], field_name)
1071 recalculated = recalculated.__class__(scapy.compat.raw(recalculated))
1072 self.assert_equal(received_packet_checksum,
1073 getattr(recalculated[layer], field_name),
1074 "packet checksum on layer: %s" % layer)
1076 def assert_ip_checksum_valid(self, received_packet,
1077 ignore_zero_checksum=False):
1078 self.assert_checksum_valid(received_packet, 'IP',
1079 ignore_zero_checksum=ignore_zero_checksum)
1081 def assert_tcp_checksum_valid(self, received_packet,
1082 ignore_zero_checksum=False):
1083 self.assert_checksum_valid(received_packet, 'TCP',
1084 ignore_zero_checksum=ignore_zero_checksum)
1086 def assert_udp_checksum_valid(self, received_packet,
1087 ignore_zero_checksum=True):
1088 self.assert_checksum_valid(received_packet, 'UDP',
1089 ignore_zero_checksum=ignore_zero_checksum)
1091 def assert_embedded_icmp_checksum_valid(self, received_packet):
1092 if received_packet.haslayer(IPerror):
1093 self.assert_checksum_valid(received_packet, 'IPerror')
1094 if received_packet.haslayer(TCPerror):
1095 self.assert_checksum_valid(received_packet, 'TCPerror')
1096 if received_packet.haslayer(UDPerror):
1097 self.assert_checksum_valid(received_packet, 'UDPerror',
1098 ignore_zero_checksum=True)
1099 if received_packet.haslayer(ICMPerror):
1100 self.assert_checksum_valid(received_packet, 'ICMPerror')
1102 def assert_icmp_checksum_valid(self, received_packet):
1103 self.assert_checksum_valid(received_packet, 'ICMP')
1104 self.assert_embedded_icmp_checksum_valid(received_packet)
1106 def assert_icmpv6_checksum_valid(self, pkt):
1107 if pkt.haslayer(ICMPv6DestUnreach):
1108 self.assert_checksum_valid(pkt, 'ICMPv6DestUnreach', 'cksum')
1109 self.assert_embedded_icmp_checksum_valid(pkt)
1110 if pkt.haslayer(ICMPv6EchoRequest):
1111 self.assert_checksum_valid(pkt, 'ICMPv6EchoRequest', 'cksum')
1112 if pkt.haslayer(ICMPv6EchoReply):
1113 self.assert_checksum_valid(pkt, 'ICMPv6EchoReply', 'cksum')
1115 def get_packet_counter(self, counter):
1116 if counter.startswith("/"):
1117 counter_value = self.statistics.get_counter(counter)
1119 counters = self.vapi.cli("sh errors").split('\n')
1121 for i in range(1, len(counters) - 1):
1122 results = counters[i].split()
1123 if results[1] == counter:
1124 counter_value = int(results[0])
1126 return counter_value
1128 def assert_packet_counter_equal(self, counter, expected_value):
1129 counter_value = self.get_packet_counter(counter)
1130 self.assert_equal(counter_value, expected_value,
1131 "packet counter `%s'" % counter)
1133 def assert_error_counter_equal(self, counter, expected_value):
1134 counter_value = self.statistics.get_err_counter(counter)
1135 self.assert_equal(counter_value, expected_value,
1136 "error counter `%s'" % counter)
1139 def sleep(cls, timeout, remark=None):
1141 # /* Allow sleep(0) to maintain win32 semantics, and as decreed
1142 # * by Guido, only the main thread can be interrupted.
1144 # https://github.com/python/cpython/blob/6673decfa0fb078f60587f5cb5e98460eea137c2/Modules/timemodule.c#L1892 # noqa
1147 if hasattr(os, 'sched_yield'):
1153 cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
1154 before = time.time()
1157 if after - before > 2 * timeout:
1158 cls.logger.error("unexpected self.sleep() result - "
1159 "slept for %es instead of ~%es!",
1160 after - before, timeout)
1163 "Finished sleep (%s) - slept %es (wanted %es)",
1164 remark, after - before, timeout)
1166 def pg_send(self, intf, pkts, worker=None):
1167 self.vapi.cli("clear trace")
1168 intf.add_stream(pkts, worker=worker)
1169 self.pg_enable_capture(self.pg_interfaces)
1172 def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
1173 self.pg_send(intf, pkts)
1176 for i in self.pg_interfaces:
1177 i.get_capture(0, timeout=timeout)
1178 i.assert_nothing_captured(remark=remark)
1181 def send_and_expect(self, intf, pkts, output, n_rx=None, worker=None):
1184 self.pg_send(intf, pkts, worker=worker)
1185 rx = output.get_capture(n_rx)
1188 def send_and_expect_only(self, intf, pkts, output, timeout=None):
1189 self.pg_send(intf, pkts)
1190 rx = output.get_capture(len(pkts))
1194 for i in self.pg_interfaces:
1195 if i not in outputs:
1196 i.get_capture(0, timeout=timeout)
1197 i.assert_nothing_captured()
1203 def get_testcase_doc_name(test):
1204 return getdoc(test.__class__).splitlines()[0]
1207 def get_test_description(descriptions, test):
1208 short_description = test.shortDescription()
1209 if descriptions and short_description:
1210 return short_description
1215 class TestCaseInfo(object):
1216 def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path):
1217 self.logger = logger
1218 self.tempdir = tempdir
1219 self.vpp_pid = vpp_pid
1220 self.vpp_bin_path = vpp_bin_path
1221 self.core_crash_test = None
1224 class VppTestResult(unittest.TestResult):
1226 @property result_string
1227 String variable to store the test case result string.
1229 List variable containing 2-tuples of TestCase instances and strings
1230 holding formatted tracebacks. Each tuple represents a test which
1231 raised an unexpected exception.
1233 List variable containing 2-tuples of TestCase instances and strings
1234 holding formatted tracebacks. Each tuple represents a test where
1235 a failure was explicitly signalled using the TestCase.assert*()
1239 failed_test_cases_info = set()
1240 core_crash_test_cases_info = set()
1241 current_test_case_info = None
1243 def __init__(self, stream=None, descriptions=None, verbosity=None,
1246 :param stream File descriptor to store where to report test results.
1247 Set to the standard error stream by default.
1248 :param descriptions Boolean variable to store information if to use
1249 test case descriptions.
1250 :param verbosity Integer variable to store required verbosity level.
1252 super(VppTestResult, self).__init__(stream, descriptions, verbosity)
1253 self.stream = stream
1254 self.descriptions = descriptions
1255 self.verbosity = verbosity
1256 self.result_string = None
1257 self.runner = runner
1259 def addSuccess(self, test):
1261 Record a test succeeded result
1266 if self.current_test_case_info:
1267 self.current_test_case_info.logger.debug(
1268 "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__,
1269 test._testMethodName,
1270 test._testMethodDoc))
1271 unittest.TestResult.addSuccess(self, test)
1272 self.result_string = colorize("OK", GREEN)
1274 self.send_result_through_pipe(test, PASS)
1276 def addSkip(self, test, reason):
1278 Record a test skipped.
1284 if self.current_test_case_info:
1285 self.current_test_case_info.logger.debug(
1286 "--- addSkip() %s.%s(%s) called, reason is %s" %
1287 (test.__class__.__name__, test._testMethodName,
1288 test._testMethodDoc, reason))
1289 unittest.TestResult.addSkip(self, test, reason)
1290 self.result_string = colorize("SKIP", YELLOW)
1292 self.send_result_through_pipe(test, SKIP)
1294 def symlink_failed(self):
1295 if self.current_test_case_info:
1297 failed_dir = os.getenv('FAILED_DIR')
1298 link_path = os.path.join(
1301 os.path.basename(self.current_test_case_info.tempdir))
1303 self.current_test_case_info.logger.debug(
1304 "creating a link to the failed test")
1305 self.current_test_case_info.logger.debug(
1306 "os.symlink(%s, %s)" %
1307 (self.current_test_case_info.tempdir, link_path))
1308 if os.path.exists(link_path):
1309 self.current_test_case_info.logger.debug(
1310 'symlink already exists')
1312 os.symlink(self.current_test_case_info.tempdir, link_path)
1314 except Exception as e:
1315 self.current_test_case_info.logger.error(e)
1317 def send_result_through_pipe(self, test, result):
1318 if hasattr(self, 'test_framework_result_pipe'):
1319 pipe = self.test_framework_result_pipe
1321 pipe.send((test.id(), result))
1323 def log_error(self, test, err, fn_name):
1324 if self.current_test_case_info:
1325 if isinstance(test, unittest.suite._ErrorHolder):
1326 test_name = test.description
1328 test_name = '%s.%s(%s)' % (test.__class__.__name__,
1329 test._testMethodName,
1330 test._testMethodDoc)
1331 self.current_test_case_info.logger.debug(
1332 "--- %s() %s called, err is %s" %
1333 (fn_name, test_name, err))
1334 self.current_test_case_info.logger.debug(
1335 "formatted exception is:\n%s" %
1336 "".join(format_exception(*err)))
1338 def add_error(self, test, err, unittest_fn, error_type):
1339 if error_type == FAIL:
1340 self.log_error(test, err, 'addFailure')
1341 error_type_str = colorize("FAIL", RED)
1342 elif error_type == ERROR:
1343 self.log_error(test, err, 'addError')
1344 error_type_str = colorize("ERROR", RED)
1346 raise Exception('Error type %s cannot be used to record an '
1347 'error or a failure' % error_type)
1349 unittest_fn(self, test, err)
1350 if self.current_test_case_info:
1351 self.result_string = "%s [ temp dir used by test case: %s ]" % \
1353 self.current_test_case_info.tempdir)
1354 self.symlink_failed()
1355 self.failed_test_cases_info.add(self.current_test_case_info)
1356 if is_core_present(self.current_test_case_info.tempdir):
1357 if not self.current_test_case_info.core_crash_test:
1358 if isinstance(test, unittest.suite._ErrorHolder):
1359 test_name = str(test)
1361 test_name = "'{!s}' ({!s})".format(
1362 get_testcase_doc_name(test), test.id())
1363 self.current_test_case_info.core_crash_test = test_name
1364 self.core_crash_test_cases_info.add(
1365 self.current_test_case_info)
1367 self.result_string = '%s [no temp dir]' % error_type_str
1369 self.send_result_through_pipe(test, error_type)
1371 def addFailure(self, test, err):
1373 Record a test failed result
1376 :param err: error message
1379 self.add_error(test, err, unittest.TestResult.addFailure, FAIL)
1381 def addError(self, test, err):
1383 Record a test error result
1386 :param err: error message
1389 self.add_error(test, err, unittest.TestResult.addError, ERROR)
1391 def getDescription(self, test):
1393 Get test description
1396 :returns: test description
1399 return get_test_description(self.descriptions, test)
1401 def startTest(self, test):
1409 def print_header(test):
1410 test_doc = getdoc(test)
1412 raise Exception("No doc string for test '%s'" % test.id())
1413 test_title = test_doc.splitlines()[0]
1414 test_title_colored = colorize(test_title, GREEN)
1415 if test.force_solo():
1416 # long live PEP-8 and 80 char width limitation...
1418 test_title_colored = colorize("SOLO RUN: " + test_title, c)
1420 if not hasattr(test.__class__, '_header_printed'):
1421 print(double_line_delim)
1422 print(test_title_colored)
1423 print(double_line_delim)
1424 test.__class__._header_printed = True
1427 self.start_test = time.time()
1428 unittest.TestResult.startTest(self, test)
1429 if self.verbosity > 0:
1430 self.stream.writeln(
1431 "Starting " + self.getDescription(test) + " ...")
1432 self.stream.writeln(single_line_delim)
1434 def stopTest(self, test):
1436 Called when the given test has been run
1441 unittest.TestResult.stopTest(self, test)
1443 if self.verbosity > 0:
1444 self.stream.writeln(single_line_delim)
1445 self.stream.writeln("%-73s%s" % (self.getDescription(test),
1446 self.result_string))
1447 self.stream.writeln(single_line_delim)
1449 self.stream.writeln("%-68s %4.2f %s" %
1450 (self.getDescription(test),
1451 time.time() - self.start_test,
1452 self.result_string))
1454 self.send_result_through_pipe(test, TEST_RUN)
1456 def printErrors(self):
1458 Print errors from running the test case
1460 if len(self.errors) > 0 or len(self.failures) > 0:
1461 self.stream.writeln()
1462 self.printErrorList('ERROR', self.errors)
1463 self.printErrorList('FAIL', self.failures)
1465 # ^^ that is the last output from unittest before summary
1466 if not self.runner.print_summary:
1467 devnull = unittest.runner._WritelnDecorator(open(os.devnull, 'w'))
1468 self.stream = devnull
1469 self.runner.stream = devnull
1471 def printErrorList(self, flavour, errors):
1473 Print error list to the output stream together with error type
1474 and test case description.
1476 :param flavour: error type
1477 :param errors: iterable errors
1480 for test, err in errors:
1481 self.stream.writeln(double_line_delim)
1482 self.stream.writeln("%s: %s" %
1483 (flavour, self.getDescription(test)))
1484 self.stream.writeln(single_line_delim)
1485 self.stream.writeln("%s" % err)
1488 class VppTestRunner(unittest.TextTestRunner):
1490 A basic test runner implementation which prints results to standard error.
1494 def resultclass(self):
1495 """Class maintaining the results of the tests"""
1496 return VppTestResult
1498 def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
1499 result_pipe=None, failfast=False, buffer=False,
1500 resultclass=None, print_summary=True, **kwargs):
1501 # ignore stream setting here, use hard-coded stdout to be in sync
1502 # with prints from VppTestCase methods ...
1503 super(VppTestRunner, self).__init__(sys.stdout, descriptions,
1504 verbosity, failfast, buffer,
1505 resultclass, **kwargs)
1506 KeepAliveReporter.pipe = keep_alive_pipe
1508 self.orig_stream = self.stream
1509 self.resultclass.test_framework_result_pipe = result_pipe
1511 self.print_summary = print_summary
1513 def _makeResult(self):
1514 return self.resultclass(self.stream,
1519 def run(self, test):
1526 faulthandler.enable() # emit stack trace to stderr if killed by signal
1528 result = super(VppTestRunner, self).run(test)
1529 if not self.print_summary:
1530 self.stream = self.orig_stream
1531 result.stream = self.orig_stream
1535 class Worker(Thread):
1536 def __init__(self, executable_args, logger, env=None, *args, **kwargs):
1537 super(Worker, self).__init__(*args, **kwargs)
1538 self.logger = logger
1539 self.args = executable_args
1540 if hasattr(self, 'testcase') and self.testcase.debug_all:
1541 if self.testcase.debug_gdbserver:
1542 self.args = ['/usr/bin/gdbserver', 'localhost:{port}'
1543 .format(port=self.testcase.gdbserver_port)] + args
1544 elif self.testcase.debug_gdb and hasattr(self, 'wait_for_gdb'):
1545 self.args.append(self.wait_for_gdb)
1546 self.app_bin = executable_args[0]
1547 self.app_name = os.path.basename(self.app_bin)
1548 if hasattr(self, 'role'):
1549 self.app_name += ' {role}'.format(role=self.role)
1552 env = {} if env is None else env
1553 self.env = copy.deepcopy(env)
1555 def wait_for_enter(self):
1556 if not hasattr(self, 'testcase'):
1558 if self.testcase.debug_all and self.testcase.debug_gdbserver:
1560 print(double_line_delim)
1561 print("Spawned GDB Server for '{app}' with PID: {pid}"
1562 .format(app=self.app_name, pid=self.process.pid))
1563 elif self.testcase.debug_all and self.testcase.debug_gdb:
1565 print(double_line_delim)
1566 print("Spawned '{app}' with PID: {pid}"
1567 .format(app=self.app_name, pid=self.process.pid))
1570 print(single_line_delim)
1571 print("You can debug '{app}' using:".format(app=self.app_name))
1572 if self.testcase.debug_gdbserver:
1573 print("sudo gdb " + self.app_bin +
1574 " -ex 'target remote localhost:{port}'"
1575 .format(port=self.testcase.gdbserver_port))
1576 print("Now is the time to attach gdb by running the above "
1577 "command, set up breakpoints etc., then resume from "
1578 "within gdb by issuing the 'continue' command")
1579 self.testcase.gdbserver_port += 1
1580 elif self.testcase.debug_gdb:
1581 print("sudo gdb " + self.app_bin +
1582 " -ex 'attach {pid}'".format(pid=self.process.pid))
1583 print("Now is the time to attach gdb by running the above "
1584 "command and set up breakpoints etc., then resume from"
1585 " within gdb by issuing the 'continue' command")
1586 print(single_line_delim)
1587 input("Press ENTER to continue running the testcase...")
1590 executable = self.args[0]
1591 if not os.path.exists(executable) or not os.access(
1592 executable, os.F_OK | os.X_OK):
1593 # Exit code that means some system file did not exist,
1594 # could not be opened, or had some other kind of error.
1595 self.result = os.EX_OSFILE
1596 raise EnvironmentError(
1597 "executable '%s' is not found or executable." % executable)
1598 self.logger.debug("Running executable: '{app}'"
1599 .format(app=' '.join(self.args)))
1600 env = os.environ.copy()
1601 env.update(self.env)
1602 env["CK_LOG_FILE_NAME"] = "-"
1603 self.process = subprocess.Popen(
1604 self.args, shell=False, env=env, preexec_fn=os.setpgrp,
1605 stdout=subprocess.PIPE, stderr=subprocess.PIPE)
1606 self.wait_for_enter()
1607 out, err = self.process.communicate()
1608 self.logger.debug("Finished running `{app}'".format(app=self.app_name))
1609 self.logger.info("Return code is `%s'" % self.process.returncode)
1610 self.logger.info(single_line_delim)
1611 self.logger.info("Executable `{app}' wrote to stdout:"
1612 .format(app=self.app_name))
1613 self.logger.info(single_line_delim)
1614 self.logger.info(out.decode('utf-8'))
1615 self.logger.info(single_line_delim)
1616 self.logger.info("Executable `{app}' wrote to stderr:"
1617 .format(app=self.app_name))
1618 self.logger.info(single_line_delim)
1619 self.logger.info(err.decode('utf-8'))
1620 self.logger.info(single_line_delim)
1621 self.result = self.process.returncode
1624 if __name__ == '__main__':