X-Git-Url: https://gerrit.fd.io/r/gitweb?a=blobdiff_plain;f=test%2Fframework.py;h=fd493db36ded064bc1ee6724b867c67256c8392b;hb=15ac81c16fba83033090299413a3a2dbb848a0f9;hp=fe6a8a531f4dceb1be83a9cfe28cf8d6226fcb79;hpb=47e275bbe4327aabc641e917f738d72693eb2d81;p=vpp.git diff --git a/test/framework.py b/test/framework.py index fe6a8a531f4..fd493db36de 100644 --- a/test/framework.py +++ b/test/framework.py @@ -9,6 +9,7 @@ import unittest import tempfile import time import resource +import faulthandler from collections import deque from threading import Thread, Event from inspect import getdoc @@ -152,6 +153,8 @@ class VppTestCase(unittest.TestCase): if cls.extern_plugin_path is not None: plugin_path = "%s:%s" % ( cls.plugin_path, cls.extern_plugin_path) + else: + plugin_path = cls.plugin_path elif cls.extern_plugin_path is not None: plugin_path = cls.extern_plugin_path debug_cli = "" @@ -236,12 +239,12 @@ class VppTestCase(unittest.TestCase): cls.logger = getLogger(cls.__name__) cls.tempdir = tempfile.mkdtemp( prefix='vpp-unittest-' + cls.__name__ + '-') - file_handler = FileHandler("%s/log.txt" % cls.tempdir) - file_handler.setFormatter( + cls.file_handler = FileHandler("%s/log.txt" % cls.tempdir) + cls.file_handler.setFormatter( Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s', datefmt="%H:%M:%S")) - file_handler.setLevel(DEBUG) - cls.logger.addHandler(file_handler) + cls.file_handler.setLevel(DEBUG) + cls.logger.addHandler(cls.file_handler) cls.shm_prefix = cls.tempdir.split("/")[-1] os.chdir(cls.tempdir) cls.logger.info("Temporary dir is %s, shm prefix is %s", @@ -253,6 +256,7 @@ class VppTestCase(unittest.TestCase): cls.verbose = 0 cls.vpp_dead = False cls.registry = VppObjectRegistry() + cls.vpp_startup_failed = False # need to catch exceptions here because if we raise, then the cleanup # doesn't get called and we might end with a zombie vpp try: @@ -271,7 +275,14 @@ class VppTestCase(unittest.TestCase): hook = PollHook(cls) cls.vapi.register_hook(hook) cls.sleep(0.1, "after vpp startup, before initial poll") - hook.poll_vpp() + try: + hook.poll_vpp() + except: + cls.vpp_startup_failed = True + cls.logger.critical( + "VPP died shortly after startup, check the" + " output to standard error for possible cause") + raise try: cls.vapi.connect() except: @@ -323,32 +334,38 @@ class VppTestCase(unittest.TestCase): cls.vpp.communicate() del cls.vpp + if cls.vpp_startup_failed: + stdout_log = cls.logger.info + stderr_log = cls.logger.critical + else: + stdout_log = cls.logger.info + stderr_log = cls.logger.info + if hasattr(cls, 'vpp_stdout_deque'): - cls.logger.info(single_line_delim) - cls.logger.info('VPP output to stdout while running %s:', - cls.__name__) - cls.logger.info(single_line_delim) - f = open(cls.tempdir + '/vpp_stdout.txt', 'w') + stdout_log(single_line_delim) + stdout_log('VPP output to stdout while running %s:', cls.__name__) + stdout_log(single_line_delim) vpp_output = "".join(cls.vpp_stdout_deque) - f.write(vpp_output) - cls.logger.info('\n%s', vpp_output) - cls.logger.info(single_line_delim) + with open(cls.tempdir + '/vpp_stdout.txt', 'w') as f: + f.write(vpp_output) + stdout_log('\n%s', vpp_output) + stdout_log(single_line_delim) if hasattr(cls, 'vpp_stderr_deque'): - cls.logger.info(single_line_delim) - cls.logger.info('VPP output to stderr while running %s:', - cls.__name__) - cls.logger.info(single_line_delim) - f = open(cls.tempdir + '/vpp_stderr.txt', 'w') + stderr_log(single_line_delim) + stderr_log('VPP output to stderr while running %s:', cls.__name__) + stderr_log(single_line_delim) vpp_output = "".join(cls.vpp_stderr_deque) - f.write(vpp_output) - cls.logger.info('\n%s', vpp_output) - cls.logger.info(single_line_delim) + with open(cls.tempdir + '/vpp_stderr.txt', 'w') as f: + f.write(vpp_output) + stderr_log('\n%s', vpp_output) + stderr_log(single_line_delim) @classmethod def tearDownClass(cls): """ Perform final cleanup after running all tests in this test-case """ cls.quit() + cls.file_handler.close() def tearDown(self): """ Show various debug prints after each test """ @@ -357,7 +374,7 @@ class VppTestCase(unittest.TestCase): self._testMethodDoc)) if not self.vpp_dead: self.logger.debug(self.vapi.cli("show trace")) - self.logger.info(self.vapi.ppcli("show int")) + self.logger.info(self.vapi.ppcli("show interface")) self.logger.info(self.vapi.ppcli("show hardware")) self.logger.info(self.vapi.ppcli("show error")) self.logger.info(self.vapi.ppcli("show run")) @@ -632,8 +649,18 @@ class VppTestCase(unittest.TestCase): @classmethod def sleep(cls, timeout, remark=None): if hasattr(cls, 'logger'): - cls.logger.debug("Sleeping for %ss (%s)" % (timeout, remark)) + cls.logger.debug("Starting sleep for %ss (%s)" % (timeout, remark)) + before = time.time() time.sleep(timeout) + after = time.time() + if after - before > 2 * timeout: + cls.logger.error("unexpected time.sleep() result - " + "slept for %ss instead of ~%ss!" % ( + after - before, timeout)) + if hasattr(cls, 'logger'): + cls.logger.debug( + "Finished sleep (%s) - slept %ss (wanted %ss)" % ( + remark, after - before, timeout)) class TestCasePrinter(object): @@ -914,7 +941,7 @@ class VppTestRunner(unittest.TextTestRunner): :param test: """ - gc.disable() # disable garbage collection, we'll do that manually + faulthandler.enable() # emit stack trace to stderr if killed by signal print("Running tests using custom test runner") # debug message filter_file, filter_class, filter_func = self.parse_test_option() print("Active filters: file=%s, class=%s, function=%s" % ( @@ -923,4 +950,6 @@ class VppTestRunner(unittest.TextTestRunner): filter_func) print("%s out of %s tests match specified filters" % ( filtered.countTestCases(), test.countTestCases())) + if not running_extended_tests(): + print("Not running extended tests (some tests will be skipped)") return super(VppTestRunner, self).run(filtered)