diff options
| -rw-r--r-- | test/debug.py | 7 | ||||
| -rw-r--r-- | test/framework.py | 192 | ||||
| -rw-r--r-- | test/hook.py | 35 | ||||
| -rw-r--r-- | test/run_tests.py | 357 | ||||
| -rw-r--r-- | test/util.py | 38 |
5 files changed, 380 insertions, 249 deletions
diff --git a/test/debug.py b/test/debug.py index 4516b8c150b..d1c89c66f3c 100644 --- a/test/debug.py +++ b/test/debug.py @@ -2,11 +2,12 @@ import os import pexpect +import sys gdb_path = '/usr/bin/gdb' -def spawn_gdb(binary_path, core_path, logger): +def spawn_gdb(binary_path, core_path): if os.path.isfile(gdb_path) and os.access(gdb_path, os.X_OK): # automatically attach gdb gdb_cmdline = "%s %s %s" % (gdb_path, binary_path, core_path) @@ -19,5 +20,5 @@ def spawn_gdb(binary_path, core_path, logger): if gdb.isalive(): raise Exception("GDB refused to die...") else: - logger.error("Debugger '%s' does not exist or is not an " - "executable.." % gdb_path) + sys.stderr.write("Debugger '%s' does not exist or is not " + "an executable..\n" % gdb_path) diff --git a/test/framework.py b/test/framework.py index a7f4fc774b4..fbe6c370a3f 100644 --- a/test/framework.py +++ b/test/framework.py @@ -27,7 +27,7 @@ from vpp_papi.vpp_stats import VPPStats from log import RED, GREEN, YELLOW, double_line_delim, single_line_delim, \ getLogger, colorize from vpp_object import VppObjectRegistry -from util import ppp +from util import ppp, is_core_present from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest from scapy.layers.inet6 import ICMPv6EchoReply @@ -162,7 +162,7 @@ class KeepAliveReporter(object): raise Exception("Internal error - pipe should only be set once.") self._pipe = pipe - def send_keep_alive(self, test): + def send_keep_alive(self, test, desc=None): """ Write current test tmpdir & desc to keep-alive pipe to signal liveness """ @@ -171,11 +171,9 @@ class KeepAliveReporter(object): return if isclass(test): - desc = test.__name__ + desc = '%s (%s)' % (desc, unittest.util.strclass(test)) else: - desc = test.shortDescription() - if not desc: - desc = str(test) + desc = test.id() self.pipe.send((desc, test.vpp_bin, test.tempdir, test.vpp.pid)) @@ -249,6 +247,14 @@ class VppTestCase(unittest.TestCase): return random.choice(tuple(min_usage_set)) + @staticmethod + def print_header(cls): + if not hasattr(cls, '_header_printed'): + print(double_line_delim) + print(colorize(getdoc(cls).splitlines()[0], GREEN)) + print(double_line_delim) + cls._header_printed = True + @classmethod def setUpConstants(cls): """ Set-up the test case class based on environment variables """ @@ -361,6 +367,7 @@ class VppTestCase(unittest.TestCase): """ gc.collect() # run garbage collection first random.seed() + cls.print_header(cls) if not hasattr(cls, 'logger'): cls.logger = getLogger(cls.__name__) else: @@ -391,7 +398,9 @@ class VppTestCase(unittest.TestCase): # doesn't get called and we might end with a zombie vpp try: cls.run_vpp() - cls.reporter.send_keep_alive(cls) + cls.reporter.send_keep_alive(cls, 'setUpClass') + VppTestResult.current_test_case_info = TestCaseInfo( + cls.logger, cls.tempdir, cls.vpp.pid, cls.vpp_bin) cls.vpp_stdout_deque = deque() cls.vpp_stderr_deque = deque() cls.pump_thread_stop_flag = Event() @@ -507,6 +516,7 @@ class VppTestCase(unittest.TestCase): @classmethod def tearDownClass(cls): """ Perform final cleanup after running all tests in this test-case """ + cls.reporter.send_keep_alive(cls, 'tearDownClass') cls.quit() cls.file_handler.close() cls.reset_packet_infos() @@ -928,7 +938,6 @@ def get_testcase_doc_name(test): def get_test_description(descriptions, test): - # TODO: if none print warning not raise exception short_description = test.shortDescription() if descriptions and short_description: return short_description @@ -936,20 +945,13 @@ def get_test_description(descriptions, test): return str(test) -class TestCasePrinter(object): - _shared_state = {} - - def __init__(self): - self.__dict__ = self._shared_state - if not hasattr(self, "_test_case_set"): - self._test_case_set = set() - - def print_test_case_heading_if_first_time(self, case): - if case.__class__ not in self._test_case_set: - print(double_line_delim) - print(colorize(get_testcase_doc_name(case), GREEN)) - print(double_line_delim) - self._test_case_set.add(case.__class__) +class TestCaseInfo(object): + def __init__(self, logger, tempdir, vpp_pid, vpp_bin_path): + self.logger = logger + self.tempdir = tempdir + self.vpp_pid = vpp_pid + self.vpp_bin_path = vpp_bin_path + self.core_crash_test = None class VppTestResult(unittest.TestResult): @@ -967,6 +969,10 @@ class VppTestResult(unittest.TestResult): methods. """ + failed_test_cases_info = set() + core_crash_test_cases_info = set() + current_test_case_info = None + def __init__(self, stream, descriptions, verbosity): """ :param stream File descriptor to store where to report test results. @@ -980,7 +986,6 @@ class VppTestResult(unittest.TestResult): self.descriptions = descriptions self.verbosity = verbosity self.result_string = None - self.printer = TestCasePrinter() def addSuccess(self, test): """ @@ -989,11 +994,11 @@ class VppTestResult(unittest.TestResult): :param test: """ - if hasattr(test, 'logger'): - test.logger.debug("--- addSuccess() %s.%s(%s) called" - % (test.__class__.__name__, - test._testMethodName, - test._testMethodDoc)) + if self.current_test_case_info: + self.current_test_case_info.logger.debug( + "--- addSuccess() %s.%s(%s) called" % (test.__class__.__name__, + test._testMethodName, + test._testMethodDoc)) unittest.TestResult.addSuccess(self, test) self.result_string = colorize("OK", GREEN) @@ -1007,39 +1012,40 @@ class VppTestResult(unittest.TestResult): :param reason: """ - if hasattr(test, 'logger'): - test.logger.debug("--- addSkip() %s.%s(%s) called, reason is %s" - % (test.__class__.__name__, - test._testMethodName, - test._testMethodDoc, - reason)) + if self.current_test_case_info: + self.current_test_case_info.logger.debug( + "--- addSkip() %s.%s(%s) called, reason is %s" % + (test.__class__.__name__, test._testMethodName, + test._testMethodDoc, reason)) unittest.TestResult.addSkip(self, test, reason) self.result_string = colorize("SKIP", YELLOW) self.send_result_through_pipe(test, SKIP) - def symlink_failed(self, test): - logger = None - if hasattr(test, 'logger'): - logger = test.logger - if hasattr(test, 'tempdir'): + def symlink_failed(self): + if self.current_test_case_info: try: failed_dir = os.getenv('VPP_TEST_FAILED_DIR') - link_path = os.path.join(failed_dir, '%s-FAILED' % - os.path.basename(test.tempdir)) - if logger: - logger.debug("creating a link to the failed test") - logger.debug("os.symlink(%s, %s)" % - (test.tempdir, link_path)) + link_path = os.path.join( + failed_dir, + '%s-FAILED' % + os.path.basename(self.current_test_case_info.tempdir)) + if self.current_test_case_info.logger: + self.current_test_case_info.logger.debug( + "creating a link to the failed test") + self.current_test_case_info.logger.debug( + "os.symlink(%s, %s)" % + (self.current_test_case_info.tempdir, link_path)) if os.path.exists(link_path): - if logger: - logger.debug('symlink already exists') + if self.current_test_case_info.logger: + self.current_test_case_info.logger.debug( + 'symlink already exists') else: - os.symlink(test.tempdir, link_path) + os.symlink(self.current_test_case_info.tempdir, link_path) except Exception as e: - if logger: - logger.error(e) + if self.current_test_case_info.logger: + self.current_test_case_info.logger.error(e) def send_result_through_pipe(self, test, result): if hasattr(self, 'test_framework_result_pipe'): @@ -1047,6 +1053,54 @@ class VppTestResult(unittest.TestResult): if pipe: pipe.send((test.id(), result)) + def log_error(self, test, err, fn_name): + if self.current_test_case_info: + if isinstance(test, unittest.suite._ErrorHolder): + test_name = test.description + else: + test_name = '%s.%s(%s)' % (test.__class__.__name__, + test._testMethodName, + test._testMethodDoc) + self.current_test_case_info.logger.debug( + "--- %s() %s called, err is %s" % + (fn_name, test_name, err)) + self.current_test_case_info.logger.debug( + "formatted exception is:\n%s" % + "".join(format_exception(*err))) + + def add_error(self, test, err, unittest_fn, error_type): + if error_type == FAIL: + self.log_error(test, err, 'addFailure') + error_type_str = colorize("FAIL", RED) + elif error_type == ERROR: + self.log_error(test, err, 'addError') + error_type_str = colorize("ERROR", RED) + else: + raise Exception('Error type %s cannot be used to record an ' + 'error or a failure' % error_type) + + unittest_fn(self, test, err) + if self.current_test_case_info: + self.result_string = "%s [ temp dir used by test case: %s ]" % \ + (error_type_str, + self.current_test_case_info.tempdir) + self.symlink_failed() + self.failed_test_cases_info.add(self.current_test_case_info) + if is_core_present(self.current_test_case_info.tempdir): + if not self.current_test_case_info.core_crash_test: + if isinstance(test, unittest.suite._ErrorHolder): + test_name = str(test) + else: + test_name = "'{}' ({})".format( + get_testcase_doc_name(test), test.id()) + self.current_test_case_info.core_crash_test = test_name + self.core_crash_test_cases_info.add( + self.current_test_case_info) + else: + self.result_string = '%s [no temp dir]' % error_type_str + + self.send_result_through_pipe(test, error_type) + def addFailure(self, test, err): """ Record a test failed result @@ -1055,22 +1109,7 @@ class VppTestResult(unittest.TestResult): :param err: error message """ - if hasattr(test, 'logger'): - test.logger.debug("--- addFailure() %s.%s(%s) called, err is %s" - % (test.__class__.__name__, - test._testMethodName, - test._testMethodDoc, err)) - test.logger.debug("formatted exception is:\n%s" % - "".join(format_exception(*err))) - unittest.TestResult.addFailure(self, test, err) - if hasattr(test, 'tempdir'): - self.result_string = colorize("FAIL", RED) + \ - ' [ temp dir used by test case: ' + test.tempdir + ' ]' - self.symlink_failed(test) - else: - self.result_string = colorize("FAIL", RED) + ' [no temp dir]' - - self.send_result_through_pipe(test, FAIL) + self.add_error(test, err, unittest.TestResult.addFailure, FAIL) def addError(self, test, err): """ @@ -1080,22 +1119,7 @@ class VppTestResult(unittest.TestResult): :param err: error message """ - if hasattr(test, 'logger'): - test.logger.debug("--- addError() %s.%s(%s) called, err is %s" - % (test.__class__.__name__, - test._testMethodName, - test._testMethodDoc, err)) - test.logger.debug("formatted exception is:\n%s" % - "".join(format_exception(*err))) - unittest.TestResult.addError(self, test, err) - if hasattr(test, 'tempdir'): - self.result_string = colorize("ERROR", RED) + \ - ' [ temp dir used by test case: ' + test.tempdir + ' ]' - self.symlink_failed(test) - else: - self.result_string = colorize("ERROR", RED) + ' [no temp dir]' - - self.send_result_through_pipe(test, ERROR) + self.add_error(test, err, unittest.TestResult.addError, ERROR) def getDescription(self, test): """ @@ -1114,7 +1138,8 @@ class VppTestResult(unittest.TestResult): :param test: """ - self.printer.print_test_case_heading_if_first_time(test) + test.print_header(test.__class__) + unittest.TestResult.startTest(self, test) if self.verbosity > 0: self.stream.writeln( @@ -1177,6 +1202,7 @@ class VppTestRunner(unittest.TextTestRunner): def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1, result_pipe=None, failfast=False, buffer=False, resultclass=None): + # ignore stream setting here, use hard-coded stdout to be in sync # with prints from VppTestCase methods ... super(VppTestRunner, self).__init__(sys.stdout, descriptions, diff --git a/test/hook.py b/test/hook.py index 7287aaa1920..29c4cd9435c 100644 --- a/test/hook.py +++ b/test/hook.py @@ -3,9 +3,8 @@ import os import sys import traceback from log import RED, single_line_delim, double_line_delim -from debug import spawn_gdb from subprocess import check_output, CalledProcessError -from util import check_core_path +from util import check_core_path, get_core_path class Hook(object): @@ -60,27 +59,21 @@ class PollHook(Hook): """ Hook which checks if the vpp subprocess is alive """ def __init__(self, testcase): + super(PollHook, self).__init__(testcase.logger) self.testcase = testcase - self.logger = testcase.logger def on_crash(self, core_path): - if self.testcase.debug_core: - # notify parent process that we're handling a core file - open('%s/_core_handled' % self.testcase.tempdir, 'a').close() - spawn_gdb(self.testcase.vpp_bin, core_path, self.logger) - else: - self.logger.error("Core file present, debug with: gdb %s %s" % - (self.testcase.vpp_bin, core_path)) - check_core_path(self.logger, core_path) - self.logger.error("Running `file %s':" % core_path) - try: - info = check_output(["file", core_path]) - self.logger.error(info) - except CalledProcessError as e: - self.logger.error( - "Could not run `file' utility on core-file, " - "rc=%s" % e.returncode) - pass + self.logger.error("Core file present, debug with: gdb %s %s" % + (self.testcase.vpp_bin, core_path)) + check_core_path(self.logger, core_path) + self.logger.error("Running `file %s':" % core_path) + try: + info = check_output(["file", core_path]) + self.logger.error(info) + except CalledProcessError as e: + self.logger.error( + "Could not run `file' utility on core-file, " + "rc=%s" % e.returncode) def poll_vpp(self): """ @@ -104,7 +97,7 @@ class PollHook(Hook): msg = "VPP subprocess died unexpectedly with returncode %d [%s]" %\ (self.testcase.vpp.returncode, s) self.logger.critical(msg) - core_path = self.testcase.tempdir + '/core' + core_path = get_core_path(self.testcase.tempdir) if os.path.isfile(core_path): self.on_crash(core_path) self.testcase.vpp_dead = True diff --git a/test/run_tests.py b/test/run_tests.py index 6836466373e..c42c6a820dc 100644 --- a/test/run_tests.py +++ b/test/run_tests.py @@ -4,13 +4,13 @@ import sys import shutil import os import fnmatch -import select import unittest import argparse import time import threading import signal import psutil +import re from multiprocessing import Process, Pipe, cpu_count from multiprocessing.queues import Queue from multiprocessing.managers import BaseManager @@ -19,10 +19,10 @@ from framework import VppTestRunner, running_extended_tests, VppTestCase, \ TEST_RUN from debug import spawn_gdb from log import get_parallel_logger, double_line_delim, RED, YELLOW, GREEN, \ - colorize + colorize, single_line_delim from discover_tests import discover_tests from subprocess import check_output, CalledProcessError -from util import check_core_path +from util import check_core_path, get_core_path, is_core_present # timeout which controls how long the child has to finish after seeing # a core dump in test temporary directory. If this is exceeded, parent assumes @@ -54,31 +54,28 @@ StreamQueueManager.register('StreamQueue', StreamQueue) class TestResult(dict): - def __init__(self, testcase_suite): + def __init__(self, testcase_suite, testcases_by_id=None): super(TestResult, self).__init__() self[PASS] = [] self[FAIL] = [] self[ERROR] = [] self[SKIP] = [] self[TEST_RUN] = [] + self.crashed = False self.testcase_suite = testcase_suite self.testcases = [testcase for testcase in testcase_suite] - self.testcases_by_id = {} + self.testcases_by_id = testcases_by_id def was_successful(self): - return len(self[PASS] + self[SKIP]) \ - == self.testcase_suite.countTestCases() + return 0 == len(self[FAIL]) == len(self[ERROR]) \ + and len(self[PASS] + self[SKIP]) \ + == self.testcase_suite.countTestCases() == len(self[TEST_RUN]) def no_tests_run(self): return 0 == len(self[TEST_RUN]) def process_result(self, test_id, result): self[result].append(test_id) - for testcase in self.testcases: - if testcase.id() == test_id: - self.testcases_by_id[test_id] = testcase - self.testcases.remove(testcase) - break def suite_from_failed(self): rerun_ids = set([]) @@ -90,21 +87,33 @@ class TestResult(dict): return suite_from_failed(self.testcase_suite, rerun_ids) def get_testcase_names(self, test_id): - return self._get_testcase_class(test_id), \ - self._get_test_description(test_id) + if re.match(r'.+\..+\..+', test_id): + test_name = self._get_test_description(test_id) + testcase_name = self._get_testcase_doc_name(test_id) + else: + # could be tearDownClass (test_ipsec_esp.TestIpsecEsp1) + setup_teardown_match = re.match( + r'((tearDownClass)|(setUpClass)) \((.+\..+)\)', test_id) + if setup_teardown_match: + test_name, _, _, testcase_name = setup_teardown_match.groups() + if len(testcase_name.split('.')) == 2: + for key in self.testcases_by_id.keys(): + if key.startswith(testcase_name): + testcase_name = key + break + testcase_name = self._get_testcase_doc_name(testcase_name) + else: + test_name = test_id + testcase_name = test_id + + return testcase_name, test_name def _get_test_description(self, test_id): - if test_id in self.testcases_by_id: - return get_test_description(descriptions, - self.testcases_by_id[test_id]) - else: - return test_id + return get_test_description(descriptions, + self.testcases_by_id[test_id]) - def _get_testcase_class(self, test_id): - if test_id in self.testcases_by_id: - return get_testcase_doc_name(self.testcases_by_id[test_id]) - else: - return test_id + def _get_testcase_doc_name(self, test_id): + return get_testcase_doc_name(self.testcases_by_id[test_id]) def test_runner_wrapper(suite, keep_alive_pipe, stdouterr_queue, @@ -142,12 +151,48 @@ class TestCaseWrapper(object): self.child.start() self.last_test_temp_dir = None self.last_test_vpp_binary = None - self.last_test = None - self.result = None + self._last_test = None + self.last_test_id = None self.vpp_pid = None self.last_heard = time.time() self.core_detected_at = None - self.result = TestResult(testcase_suite) + self.testcases_by_id = {} + self.testclasess_with_core = {} + for testcase in self.testcase_suite: + self.testcases_by_id[testcase.id()] = testcase + self.result = TestResult(testcase_suite, self.testcases_by_id) + + @property + def last_test(self): + return self._last_test + + @last_test.setter + def last_test(self, test_id): + self.last_test_id = test_id + if test_id in self.testcases_by_id: + testcase = self.testcases_by_id[test_id] + self._last_test = testcase.shortDescription() + if not self._last_test: + self._last_test = str(testcase) + else: + self._last_test = test_id + + def add_testclass_with_core(self): + if self.last_test_id in self.testcases_by_id: + test = self.testcases_by_id[self.last_test_id] + class_name = unittest.util.strclass(test.__class__) + test_name = "'{}' ({})".format(get_test_description(descriptions, + test), + self.last_test_id) + else: + test_name = self.last_test_id + class_name = re.match(r'((tearDownClass)|(setUpClass)) ' + r'\((.+\..+)\)', test_name).groups()[3] + if class_name not in self.testclasess_with_core: + self.testclasess_with_core[class_name] = ( + test_name, + self.last_test_vpp_binary, + self.last_test_temp_dir) def close_pipes(self): self.keep_alive_child_end.close() @@ -157,6 +202,9 @@ class TestCaseWrapper(object): self.finished_parent_end.close() self.result_parent_end.close() + def was_successful(self): + return self.result.was_successful() + def stdouterr_reader_wrapper(unread_testcases, finished_unread_testcases, read_testcases): @@ -179,12 +227,86 @@ def stdouterr_reader_wrapper(unread_testcases, finished_unread_testcases, read_testcase = None +def handle_failed_suite(logger, last_test_temp_dir, vpp_pid): + if last_test_temp_dir: + # Need to create link in case of a timeout or core dump without failure + lttd = os.path.basename(last_test_temp_dir) + failed_dir = os.getenv('VPP_TEST_FAILED_DIR') + link_path = '%s%s-FAILED' % (failed_dir, lttd) + if not os.path.exists(link_path): + logger.error("Creating a link to the failed test: %s -> %s" % + (link_path, lttd)) + os.symlink(last_test_temp_dir, link_path) + else: + logger.error("Link to the failed test already exists: %s -> %s" % + (link_path, lttd)) + + # Report core existence + core_path = get_core_path(last_test_temp_dir) + if os.path.exists(core_path): + logger.error( + "Core-file exists in test temporary directory: %s!" % + core_path) + check_core_path(logger, core_path) + logger.debug("Running `file %s':" % core_path) + try: + info = check_output(["file", core_path]) + logger.debug(info) + except CalledProcessError as e: + logger.error("Could not run `file' utility on core-file, " + "rc=%s" % e.returncode) + + if vpp_pid: + # Copy api post mortem + api_post_mortem_path = "/tmp/api_post_mortem.%d" % vpp_pid + if os.path.isfile(api_post_mortem_path): + logger.error("Copying api_post_mortem.%d to %s" % + (vpp_pid, last_test_temp_dir)) + shutil.copy2(api_post_mortem_path, last_test_temp_dir) + + +def check_and_handle_core(vpp_binary, tempdir, core_crash_test): + if is_core_present(tempdir): + print('VPP core detected in %s. Last test running was %s' % + (tempdir, core_crash_test)) + print(single_line_delim) + spawn_gdb(vpp_binary, get_core_path(tempdir)) + print(single_line_delim) + + +def handle_cores(failed_testcases): + if debug_core: + for failed_testcase in failed_testcases: + tcs_with_core = failed_testcase.testclasess_with_core + if len(tcs_with_core) > 0: + for test, vpp_binary, tempdir in tcs_with_core.values(): + check_and_handle_core(vpp_binary, tempdir, test) + + +def process_finished_testsuite(wrapped_testcase_suite, + finished_testcase_suites, + failed_wrapped_testcases, + results): + results.append(wrapped_testcase_suite.result) + finished_testcase_suites.add(wrapped_testcase_suite) + stop_run = False + if failfast and not wrapped_testcase_suite.was_successful(): + stop_run = True + + if not wrapped_testcase_suite.was_successful(): + failed_wrapped_testcases.add(wrapped_testcase_suite) + handle_failed_suite(wrapped_testcase_suite.logger, + wrapped_testcase_suite.last_test_temp_dir, + wrapped_testcase_suite.vpp_pid) + + return stop_run + + def run_forked(testcase_suites): wrapped_testcase_suites = set() # suites are unhashable, need to use list results = [] - debug_core = os.getenv("DEBUG", "").lower() == "core" unread_testcases = set() finished_unread_testcases = set() manager = StreamQueueManager() @@ -195,7 +317,6 @@ def run_forked(testcase_suites): manager) wrapped_testcase_suites.add(wrapped_testcase_suite) unread_testcases.add(wrapped_testcase_suite) - # time.sleep(1) else: break @@ -207,6 +328,8 @@ def run_forked(testcase_suites): read_from_testcases)) stdouterr_thread.start() + failed_wrapped_testcases = set() + stop_run = False while len(wrapped_testcase_suites) > 0: finished_testcase_suites = set() for wrapped_testcase_suite in wrapped_testcase_suites: @@ -215,12 +338,6 @@ def run_forked(testcase_suites): *wrapped_testcase_suite.result_parent_end.recv()) wrapped_testcase_suite.last_heard = time.time() - if wrapped_testcase_suite.finished_parent_end.poll(): - wrapped_testcase_suite.finished_parent_end.recv() - results.append(wrapped_testcase_suite.result) - finished_testcase_suites.add(wrapped_testcase_suite) - continue - while wrapped_testcase_suite.keep_alive_parent_end.poll(): wrapped_testcase_suite.last_test, \ wrapped_testcase_suite.last_test_vpp_binary, \ @@ -229,101 +346,65 @@ def run_forked(testcase_suites): wrapped_testcase_suite.keep_alive_parent_end.recv() wrapped_testcase_suite.last_heard = time.time() + if wrapped_testcase_suite.finished_parent_end.poll(): + wrapped_testcase_suite.finished_parent_end.recv() + wrapped_testcase_suite.last_heard = time.time() + stop_run = process_finished_testsuite( + wrapped_testcase_suite, + finished_testcase_suites, + failed_wrapped_testcases, + results) or stop_run + continue + fail = False - if wrapped_testcase_suite.last_heard + test_timeout < time.time() \ - and not os.path.isfile( - "%s/_core_handled" % - wrapped_testcase_suite.last_test_temp_dir): + if wrapped_testcase_suite.last_heard + test_timeout < time.time(): fail = True wrapped_testcase_suite.logger.critical( - "Timeout while waiting for child test " - "runner process (last test running was " - "`%s' in `%s')!" % + "Child test runner process timed out " + "(last test running was `%s' in `%s')!" % (wrapped_testcase_suite.last_test, wrapped_testcase_suite.last_test_temp_dir)) elif not wrapped_testcase_suite.child.is_alive(): fail = True wrapped_testcase_suite.logger.critical( - "Child python process unexpectedly died " + "Child test runner process unexpectedly died " "(last test running was `%s' in `%s')!" % (wrapped_testcase_suite.last_test, wrapped_testcase_suite.last_test_temp_dir)) elif wrapped_testcase_suite.last_test_temp_dir and \ wrapped_testcase_suite.last_test_vpp_binary: - core_path = "%s/core" % \ - wrapped_testcase_suite.last_test_temp_dir - if os.path.isfile(core_path): + if is_core_present(wrapped_testcase_suite.last_test_temp_dir): + wrapped_testcase_suite.add_testclass_with_core() if wrapped_testcase_suite.core_detected_at is None: wrapped_testcase_suite.core_detected_at = time.time() elif wrapped_testcase_suite.core_detected_at + \ core_timeout < time.time(): - if not os.path.isfile( - "%s/_core_handled" % - wrapped_testcase_suite. - last_test_temp_dir): - wrapped_testcase_suite.logger.critical( - "Child python process unresponsive and core-" - "file exists in test temporary directory!") - fail = True + wrapped_testcase_suite.logger.critical( + "Child test runner process unresponsive and core-" + "file exists in test temporary directory " + "(last test running was `%s' in `%s')!" % + (wrapped_testcase_suite.last_test, + wrapped_testcase_suite.last_test_temp_dir)) + fail = True if fail: - failed_dir = os.getenv('VPP_TEST_FAILED_DIR') - if wrapped_testcase_suite.last_test_temp_dir: - lttd = os.path.basename( - wrapped_testcase_suite.last_test_temp_dir) - else: - lttd = None - link_path = '%s%s-FAILED' % (failed_dir, lttd) - wrapped_testcase_suite.logger.error( - "Creating a link to the failed test: %s -> %s" % - (link_path, lttd)) - if not os.path.exists(link_path) \ - and wrapped_testcase_suite.last_test_temp_dir: - os.symlink(wrapped_testcase_suite.last_test_temp_dir, - link_path) - api_post_mortem_path = "/tmp/api_post_mortem.%d" % \ - wrapped_testcase_suite.vpp_pid - if os.path.isfile(api_post_mortem_path): - wrapped_testcase_suite.logger.error( - "Copying api_post_mortem.%d to %s" % - (wrapped_testcase_suite.vpp_pid, - wrapped_testcase_suite.last_test_temp_dir)) - shutil.copy2(api_post_mortem_path, - wrapped_testcase_suite.last_test_temp_dir) - if wrapped_testcase_suite.last_test_temp_dir and \ - wrapped_testcase_suite.last_test_vpp_binary: - core_path = "%s/core" % \ - wrapped_testcase_suite.last_test_temp_dir - if os.path.isfile(core_path): - wrapped_testcase_suite.logger.error( - "Core-file exists in test temporary directory: %s!" - % core_path) - check_core_path(wrapped_testcase_suite.logger, - core_path) - wrapped_testcase_suite.logger.debug( - "Running `file %s':" % core_path) - try: - info = check_output(["file", core_path]) - wrapped_testcase_suite.logger.debug(info) - except CalledProcessError as e: - wrapped_testcase_suite.logger.error( - "Could not run `file' utility on core-file, " - "rc=%s" % e.returncode) - pass - if debug_core: - spawn_gdb( - wrapped_testcase_suite.last_test_vpp_binary, - core_path, wrapped_testcase_suite.logger) wrapped_testcase_suite.child.terminate() try: # terminating the child process tends to leave orphan # VPP process around - os.kill(wrapped_testcase_suite.vpp_pid, signal.SIGTERM) + if wrapped_testcase_suite.vpp_pid: + os.kill(wrapped_testcase_suite.vpp_pid, signal.SIGTERM) except OSError: # already dead pass - results.append(wrapped_testcase_suite.result) - finished_testcase_suites.add(wrapped_testcase_suite) + wrapped_testcase_suite.result.crashed = True + wrapped_testcase_suite.result.process_result( + wrapped_testcase_suite.last_test_id, ERROR) + stop_run = process_finished_testsuite( + wrapped_testcase_suite, + finished_testcase_suites, + failed_wrapped_testcases, + results) or stop_run for finished_testcase in finished_testcase_suites: finished_testcase.child.join() @@ -331,14 +412,22 @@ def run_forked(testcase_suites): wrapped_testcase_suites.remove(finished_testcase) finished_unread_testcases.add(finished_testcase) finished_testcase.stdouterr_queue.put(None) - if len(testcase_suites) > 0: + if stop_run: + while len(testcase_suites) > 0: + results.append(TestResult(testcase_suites.pop(0))) + elif len(testcase_suites) > 0: new_testcase = TestCaseWrapper(testcase_suites.pop(0), manager) wrapped_testcase_suites.add(new_testcase) unread_testcases.add(new_testcase) + while len(unread_testcases) > 0: + # wait for reader thread to read everything in all loggers + pass + read_from_testcases.clear() stdouterr_thread.join(test_timeout) manager.shutdown() + handle_cores(failed_wrapped_testcases) return results @@ -474,21 +563,20 @@ class AllResults(dict): def add_result(self, result): retval = 0 self.all_testcases += result.testcase_suite.countTestCases() - if not result.no_tests_run(): - if not result.was_successful(): - retval = 1 + self.add_results(result) - self.add_results(result) - else: + if result.no_tests_run(): self.testsuites_no_tests_run.append(result.testcase_suite) - retval = -1 + if result.crashed: + retval = -1 + else: + retval = 1 + elif not result.was_successful(): + retval = 1 if retval != 0: if concurrent_tests == 1: - if not result.no_tests_run(): - self.rerun.append(result.suite_from_failed()) - else: - self.rerun.append(result.testcase_suite) + self.rerun.append(result.suite_from_failed()) else: self.rerun.append(result.testcase_suite) @@ -516,7 +604,7 @@ class AllResults(dict): colorize(str(self[ERROR]), RED))) if self.all_failed > 0: - print('FAILED TESTS:') + print('FAILURES AND ERRORS IN TESTS:') for result in self.results_per_suite: failed_testcase_ids = result[FAIL] errored_testcase_ids = result[ERROR] @@ -529,7 +617,7 @@ class AllResults(dict): print(' Testcase name: {}'.format( colorize(new_testcase_name, RED))) old_testcase_name = new_testcase_name - print(' FAILED: {}'.format( + print(' FAILURE: {}'.format( colorize(test_name, RED))) for failed_test_id in errored_testcase_ids: new_testcase_name, test_name = \ @@ -538,11 +626,11 @@ class AllResults(dict): print(' Testcase name: {}'.format( colorize(new_testcase_name, RED))) old_testcase_name = new_testcase_name - print(' ERRORED: {}'.format( + print(' ERROR: {}'.format( colorize(test_name, RED))) if len(self.testsuites_no_tests_run) > 0: print('TESTCASES WHERE NO TESTS WERE SUCCESSFULLY EXECUTED:') - tc_classes = set([]) + tc_classes = set() for testsuite in self.testsuites_no_tests_run: for testcase in testsuite: tc_classes.add(get_testcase_doc_name(testcase)) @@ -615,12 +703,11 @@ if __name__ == '__main__': debug = os.getenv("DEBUG", "n").lower() in ["gdb", "gdbserver"] - step = os.getenv("STEP", "n").lower() in ("y", "yes", "1") + debug_core = os.getenv("DEBUG", "").lower() == "core" - force_foreground = \ - os.getenv("FORCE_FOREGROUND", "n").lower() in ("y", "yes", "1") + step = os.getenv("STEP", "n").lower() in ("y", "yes", "1") - run_interactive = debug or step or force_foreground + run_interactive = debug or step test_jobs = os.getenv("TEST_JOBS", "1").lower() # default = 1 process if test_jobs == 'auto': @@ -647,9 +734,8 @@ if __name__ == '__main__': if run_interactive and concurrent_tests > 1: raise NotImplementedError( - 'Running tests interactively (DEBUG, STEP or FORCE_FOREGROUND is ' - 'set) in parallel (TEST_JOBS is more than 1) is not ' - 'supported') + 'Running tests interactively (DEBUG is gdb or gdbserver or STEP ' + 'is set) in parallel (TEST_JOBS is more than 1) is not supported') parser = argparse.ArgumentParser(description="VPP unit tests") parser.add_argument("-f", "--failfast", action='store_true', @@ -700,13 +786,24 @@ if __name__ == '__main__': if run_interactive: # don't fork if requiring interactive terminal - sys.exit(not VppTestRunner( - verbosity=verbose, failfast=failfast) - .run(suites[0]).wasSuccessful()) + result = VppTestRunner(verbosity=verbose, failfast=failfast)\ + .run(suites[0]) + was_successful = result.wasSuccessful() + if not was_successful: + for test_case_info in result.failed_test_cases_info: + handle_failed_suite(test_case_info.logger, + test_case_info.tempdir, + test_case_info.vpp_pid) + if debug_core and \ + test_case_info in result.core_crash_test_cases_info: + check_and_handle_core(test_case_info.vpp_bin_path, + test_case_info.tempdir, + test_case_info.core_crash_test) + + sys.exit(not was_successful) else: exit_code = 0 while len(suites) > 0 and attempts > 0: - tests_amount = sum([x.countTestCases() for x in suites]) results = run_forked(suites) exit_code, suites = parse_results(results) attempts -= 1 diff --git a/test/util.py b/test/util.py index d8ecf270f67..1ab5c1f2350 100644 --- a/test/util.py +++ b/test/util.py @@ -2,6 +2,7 @@ import socket import sys +import os.path from abc import abstractmethod, ABCMeta from cStringIO import StringIO from scapy.utils6 import in6_mactoifaceid @@ -73,19 +74,32 @@ def ip6_normalize(ip6): socket.inet_pton(socket.AF_INET6, ip6)) -def check_core_path(logger, core_path): +def get_core_path(tempdir): + return "%s/%s" % (tempdir, get_core_pattern()) + + +def is_core_present(tempdir): + return os.path.isfile(get_core_path(tempdir)) + + +def get_core_pattern(): with open("/proc/sys/kernel/core_pattern", "r") as f: - corefmt = f.read() - if corefmt.startswith("|"): - logger.error( - "WARNING: redirecting the core dump through a" - " filter may result in truncated dumps.") - logger.error( - " You may want to check the filter settings" - " or uninstall it and edit the" - " /proc/sys/kernel/core_pattern accordingly.") - logger.error( - " current core pattern is: %s" % corefmt) + corefmt = f.read().strip() + return corefmt + + +def check_core_path(logger, core_path): + corefmt = get_core_pattern() + if corefmt.startswith("|"): + logger.error( + "WARNING: redirecting the core dump through a" + " filter may result in truncated dumps.") + logger.error( + " You may want to check the filter settings" + " or uninstall it and edit the" + " /proc/sys/kernel/core_pattern accordingly.") + logger.error( + " current core pattern is: %s" % corefmt) class NumericConstant(object): |