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