Setup, teardown, DEBUG=core, FAILFAST fixes

- Fixed a bug when an error occuring in tearDownClass would not result in
test being marked as failed
- Improved test results reporting in cases when an error occurs in setUpClass
and tearDownClass
- Fixed DEBUG=core when the core is produced in setUpClass or
tearDownClass
- Reworked DEBUG=core to always be handled after all tests have been
executed
- Fixed FAILFAST=1 for parallel test runs

Change-Id: I3e9cd3b97ba6fa802fa0aa2dd7678ff82eee09ec
Signed-off-by: juraj.linkes <juraj.linkes@pantheon.tech>

1 files changed, 227 insertions, 130 deletions

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