From e583a1f8f411efe7a0e4ec2ed89c075a8af7de51 Mon Sep 17 00:00:00 2001 From: Xavier-Do Date: Tue, 6 Dec 2022 16:27:57 +0000 Subject: [PATCH] [FIX] tests: better test traceback The motivation of this commit is to get a correct pathname on an ir_logging when a test fail . The main issue comes from subtest since an exception inside a subtest will have only a partial traceback, not containing the line triggering the error in the test method. This can also affect debugging since a part of the stack is missing. See pull request for more informations X-original-commit: 2b6a8bc79529578ecd21bbb0fd4fe452f28d7cd7 Part-of: odoo/odoo#108202 --- odoo/addons/base/tests/test_test_suite.py | 439 ++++++++++++++++++++++ odoo/tests/common.py | 106 +++++- odoo/tests/runner.py | 39 +- 3 files changed, 572 insertions(+), 12 deletions(-) diff --git a/odoo/addons/base/tests/test_test_suite.py b/odoo/addons/base/tests/test_test_suite.py index 893d94a04f8..ae8f2e6b814 100644 --- a/odoo/addons/base/tests/test_test_suite.py +++ b/odoo/addons/base/tests/test_test_suite.py @@ -1,7 +1,19 @@ # -*- coding: utf-8 -*- # Part of Odoo. See LICENSE file for full copyright and licensing details. +import difflib +import logging +import re +import sys +from contextlib import contextmanager from unittest import TestCase +from unittest.mock import patch + +from odoo.tests.common import TransactionCase +from odoo.tests.common import users, warmup +from odoo.tests.runner import OdooTestResult + +_logger = logging.getLogger(__name__) from odoo.tests import MetaCase @@ -10,3 +22,430 @@ class TestTestSuite(TestCase, metaclass=MetaCase): def test_test_suite(self): """ Check that OdooSuite handles unittest.TestCase correctly. """ + + +class TestRunnerLoggingCommon(TransactionCase): + """ + The purpose of this class is to do some "metatesting": it actually checks + that on error, the runner logged the error with the right file reference. + This is mainly to avoid having errors in test/common.py or test/runner.py`. + This kind of metatesting is tricky; in this case the logs are made outside + of the test method, after the teardown actually. + """ + + def setUp(self): + self.expected_logs = None + self.expected_first_frame_methods = None + return super().setUp() + + def _feedErrorsToResult(self, result, errors): + # We use this hook to catch the logged error. It is initially called + # post tearDown, and logs the actual errors. Because of our hack + # tests.common._ErrorCatcher, the errors are logged directly. This is + # still useful to test errors raised from tests. We cannot assert what + # was logged after the test inside the test, though. This method can be + # temporary renamed to test the real failure. + try: + self.test_result = result + # while we are here, let's check that the first frame of the stack + # is always inside the test method + for error in errors: + _, exc_info = error + if exc_info: + tb = exc_info[2] + self._check_first_frame(tb) + + # intercept all ir_logging. We cannot use log catchers or other + # fancy stuff because makeRecord is too low level. + log_records = [] + + def makeRecord(logger, name, level, fn, lno, msg, args, exc_info, func=None, extra=None, sinfo=None): + log_records.append({ + 'logger': logger, 'name': name, 'level': level, 'fn': fn, 'lno': lno, + 'msg': msg % args, 'exc_info': exc_info, 'func': func, 'extra': extra, 'sinfo': sinfo, + }) + + def handle(logger, record): + # disable error logging + return + + fake_result = OdooTestResult() + with patch('logging.Logger.makeRecord', makeRecord), patch('logging.Logger.handle', handle): + super()._feedErrorsToResult(fake_result, errors) + + self._check_log_records(log_records) + + except Exception as e: + # we don't expect _feedErrorsToResult() to raise any exception, this + # will make it more robust to future changes and eventual mistakes + _logger.exception(e) + + def _check_first_frame(self, tb): + """ Check that the first frame of the given traceback is the expected method name. """ + # the list expected_first_frame_methods allow to define a list of first + # expected frame (useful for setup/teardown tests) + if self.expected_first_frame_methods is None: + expected_first_frame_method = self._testMethodName + else: + expected_first_frame_method = self.expected_first_frame_methods.pop(0) + first_frame_method = tb.tb_frame.f_code.co_name + if first_frame_method != expected_first_frame_method: + self._log_error(f"Checking first tb frame: {first_frame_method} is not equal to {expected_first_frame_method}") + + def _check_log_records(self, log_records): + """ Check that what was logged is what was expected. """ + for log_record in log_records: + self._assert_log_equal(log_record, 'logger', _logger) + self._assert_log_equal(log_record, 'name', 'odoo.addons.base.tests.test_test_suite') + self._assert_log_equal(log_record, 'fn', __file__) + self._assert_log_equal(log_record, 'func', self._testMethodName) + + if self.expected_logs is not None: + for log_record in log_records: + level, msg = self.expected_logs.pop(0) + self._assert_log_equal(log_record, 'level', level) + self._assert_log_equal(log_record, 'msg', msg) + + def _assert_log_equal(self, log_record, key, expected): + """ Check the content of a log record. """ + value = log_record[key] + if key == 'msg': + value = self._clean_message(value) + if value != expected: + if key != 'msg': + self._log_error(f"Key `{key}` => `{value}` is not equal to `{expected}` \n {log_record['str']}") + else: + diff = '\n'.join(difflib.ndiff(value.splitlines(), expected.splitlines())) + self._log_error(f"Key `{key}` did not matched expected:\n{diff}") + + def _log_error(self, message): + """ Log an actual error (about a log in a test that doesn't match expectations) """ + # we would just log, but using the test_result will help keeping the tests counters correct + self.test_result.addError(self, (AssertionError, AssertionError(message), None)) + + def _clean_message(self, message): + root_path = __file__.replace('/odoo/odoo/addons/base/tests/test_test_suite.py', '') + message = re.sub(r'line \d+', 'line $line', message) + message = re.sub(r'py:\d+', 'py:$line', message) + message = re.sub(r'decorator-gen-\d+', 'decorator-gen-xxx', message) + message = re.sub(r'python[\d\.]+', 'python', message) + message = message.replace(f'{root_path}', '/root_path') + return message + + +class TestRunnerLogging(TestRunnerLoggingCommon): + + def test_raise(self): + raise Exception('This is an error') + + def test_raise_subtest(self): + """ + with subtest, we expect to have multiple errors, one per subtest + """ + def make_message(message): + return ( +f'''ERROR: Subtest TestRunnerLogging.test_raise_subtest () +Traceback (most recent call last): + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in test_raise_subtest + raise Exception('{message}') +Exception: {message} +''') + self.expected_logs = [ + (logging.INFO, '=' * 70), + (logging.ERROR, make_message('This is an error')), + ] + with self.subTest(): + raise Exception('This is an error') + + self.assertFalse(self.expected_logs, "Error should have been logged immediatly") + + self.expected_logs = [ + (logging.INFO, '=' * 70), + (logging.ERROR, make_message('This is an error2')), + ] + + with self.subTest(): + raise Exception('This is an error2') + + self.assertFalse(self.expected_logs, "Error should have been logged immediatly") + + @users('__system__') + @warmup + def test_with_decorators(self): + message = ( +'''ERROR: Subtest TestRunnerLogging.test_with_decorators (login='__system__') +Traceback (most recent call last): + File "", line $line, in test_with_decorators + File "/root_path/odoo/odoo/tests/common.py", line $line, in _users + func(*args, **kwargs) + File "", line $line, in test_with_decorators + File "/root_path/odoo/odoo/tests/common.py", line $line, in warmup + func(*args, **kwargs) + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in test_with_decorators + raise Exception('This is an error') +Exception: This is an error +''') + self.expected_logs = [ + (logging.INFO, '=' * 70), + (logging.ERROR, message), + ] + raise Exception('This is an error') + + def test_traverse_contextmanager(self): + @contextmanager + def assertSomething(): + yield + raise Exception('This is an error') + + with assertSomething(): + pass + + def test_subtest_sub_call(self): + def func(): + with self.subTest(): + raise Exception('This is an error') + + func() + + def test_call_stack(self): + message = ( +'''ERROR: TestRunnerLogging.test_call_stack +Traceback (most recent call last): + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in test_call_stack + alpha() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in alpha + beta() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in beta + gamma() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in gamma + raise Exception('This is an error') +Exception: This is an error +''') + self.expected_logs = [ + (logging.INFO, '=' * 70), + (logging.ERROR, message), + ] + + def alpha(): + beta() + + def beta(): + gamma() + + def gamma(): + raise Exception('This is an error') + + alpha() + + def test_call_stack_context_manager(self): + message = ( +'''ERROR: TestRunnerLogging.test_call_stack_context_manager +Traceback (most recent call last): + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in test_call_stack_context_manager + alpha() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in alpha + beta() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in beta + gamma() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in gamma + raise Exception('This is an error') +Exception: This is an error +''') + self.expected_logs = [ + (logging.INFO, '=' * 70), + (logging.ERROR, message), + ] + + def alpha(): + beta() + + def beta(): + with self.with_user('admin'): + gamma() + return 0 + + def gamma(): + raise Exception('This is an error') + + alpha() + + def test_call_stack_subtest(self): + message = ( +'''ERROR: Subtest TestRunnerLogging.test_call_stack_subtest () +Traceback (most recent call last): + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in test_call_stack_subtest + alpha() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in alpha + beta() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in beta + gamma() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in gamma + raise Exception('This is an error') +Exception: This is an error +''') + self.expected_logs = [ + (logging.INFO, '=' * 70), + (logging.ERROR, message), + ] + + def alpha(): + beta() + + def beta(): + with self.subTest(): + gamma() + + def gamma(): + raise Exception('This is an error') + + alpha() + + def test_assertQueryCount(self): + message = ( +'''FAIL: Subtest TestRunnerLogging.test_assertQueryCount () +Traceback (most recent call last): + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in test_assertQueryCount + with self.assertQueryCount(system=0): + File "/usr/lib/python/contextlib.py", line $line, in __exit__ + next(self.gen) + File "/root_path/odoo/odoo/tests/common.py", line $line, in assertQueryCount + self.fail(msg % (login, count, expected, funcname, filename, linenum)) +AssertionError: Query count more than expected for user __system__: 1 > 0 in test_assertQueryCount at base/tests/test_test_suite.py:$line +''') + if sys.version_info < (3, 10, 0): + message = message.replace("with self.assertQueryCount(system=0):", "self.env.cr.execute('SELECT 1')") + + self.expected_logs = [ + (logging.INFO, '=' * 70), + (logging.ERROR, message), + ] + with self.assertQueryCount(system=0): + self.env.cr.execute('SELECT 1') + + @users('__system__') + @warmup + def test_assertQueryCount_with_decorators(self): + with self.assertQueryCount(system=0): + self.env.cr.execute('SELECT 1') + + def test_reraise(self): + message = ( +'''ERROR: TestRunnerLogging.test_reraise +Traceback (most recent call last): + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in test_reraise + alpha() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in alpha + beta() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in beta + raise Exception('This is an error') +Exception: This is an error +''') + self.expected_logs = [ + (logging.INFO, '=' * 70), + (logging.ERROR, message), + ] + + def alpha(): + # pylint: disable=try-except-raise + try: + beta() + except Exception: + raise + + def beta(): + raise Exception('This is an error') + + alpha() + + def test_handle_error(self): + message = ( +'''ERROR: TestRunnerLogging.test_handle_error +Traceback (most recent call last): + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in alpha + beta() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in beta + raise Exception('This is an error') +Exception: This is an error + +During handling of the above exception, another exception occurred: + +Traceback (most recent call last): + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in test_handle_error + alpha() + File "/root_path/odoo/odoo/addons/base/tests/test_test_suite.py", line $line, in alpha + raise Exception('This is an error2') +Exception: This is an error2 +''') + self.expected_logs = [ + (logging.INFO, '=' * 70), + (logging.ERROR, message), + ] + + def alpha(): + try: + beta() + except Exception: + raise Exception('This is an error2') + + def beta(): + raise Exception('This is an error') + + alpha() + + +class TestRunnerLoggingSetup(TestRunnerLoggingCommon): + + def setUp(self): + super().setUp() + self.expected_first_frame_methods = [ + 'setUp', + 'cleanupError2', + 'cleanupError', + ] + + def cleanupError(): + raise Exception("This is a cleanup error") + self.addCleanup(cleanupError) + + def cleanupError2(): + raise Exception("This is a second cleanup error") + self.addCleanup(cleanupError2) + + raise Exception('This is a setup error') + + def test_raises_setup(self): + _logger.error("This shouldn't be executed") + + def tearDown(self): + _logger.error("This shouldn't be executed since setup failed") + + +class TestRunnerLoggingTeardown(TestRunnerLoggingCommon): + def setUp(self): + super().setUp() + self.expected_first_frame_methods = [ + 'test_raises_teardown', + 'test_raises_teardown', + 'test_raises_teardown', + 'tearDown', + 'cleanupError2', + 'cleanupError', + ] + + def cleanupError(): + raise Exception("This is a cleanup error") + self.addCleanup(cleanupError) + + def cleanupError2(): + raise Exception("This is a second cleanup error") + self.addCleanup(cleanupError2) + + def tearDown(self): + raise Exception('This is a tearDown error') + + def test_raises_teardown(self): + with self.subTest(): + raise Exception('This is a subTest error') + with self.subTest(): + raise Exception('This is a second subTest error') + raise Exception('This is a test error') diff --git a/odoo/tests/common.py b/odoo/tests/common.py index eee5facd318..e16892c552e 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -611,7 +611,7 @@ class BaseCase(unittest.TestCase, metaclass=MetaCase): """ if self.warm: # mock random in order to avoid random bus gc - with self.subTest(), patch('random.random', lambda: 1): + with patch('random.random', lambda: 1): login = self.env.user.login expected = counters.get(login, default) if flush: @@ -630,7 +630,9 @@ class BaseCase(unittest.TestCase, metaclass=MetaCase): filename = filename.rsplit("/odoo/addons/", 1)[1] if count > expected: msg = "Query count more than expected for user %s: %d > %d in %s at %s:%s" - self.fail(msg % (login, count, expected, funcname, filename, linenum)) + # add a subtest in order to continue the test_method in case of failures + with self.subTest(): + self.fail(msg % (login, count, expected, funcname, filename, linenum)) else: logger = logging.getLogger(type(self).__module__) msg = "Query count less than expected for user %s: %d < %d in %s at %s:%s" @@ -762,7 +764,6 @@ class BaseCase(unittest.TestCase, metaclass=MetaCase): # Because lxml.attrib is an ordereddict for which order is important # to equality, even though *we* don't care self.assertEqual(dict(n1.attrib), dict(n2.attrib), msg) - self.assertEqual((n1.text or u'').strip(), (n2.text or u'').strip(), msg) self.assertEqual((n1.tail or u'').strip(), (n2.tail or u'').strip(), msg) @@ -802,6 +803,101 @@ class BaseCase(unittest.TestCase, metaclass=MetaCase): profile_session=self.profile_session, **kwargs) + def _callSetUp(self): + # This override is aimed at providing better error logs inside tests. + # First, we want errors to be logged whenever they appear instead of + # after the test, as the latter makes debugging harder and can even be + # confusing in the case of subtests. + # + # When a subtest is used inside a test, (1) the recovered traceback is + # not complete, and (2) the error is delayed to the end of the test + # method. There is unfortunately no simple way to hook inside a subtest + # to fix this issue. The method TestCase.subTest uses the context + # manager _Outcome.testPartExecutor as follows: + # + # with self._outcome.testPartExecutor(self._subtest, isTest=True): + # yield + # + # This context manager is actually also used for the setup, test method, + # teardown, cleanups. If an error occurs during any one of those, it is + # simply appended in TestCase._outcome.errors, and the latter is + # consumed at the end calling _feedErrorsToResult. + # + # The TestCase._outcome is set just before calling _callSetUp. This + # method is actually executed inside a testPartExecutor. Replacing it + # here ensures that all errors will be caught. + # See https://github.com/odoo/odoo/pull/107572 for more info. + self._outcome.errors = _ErrorCatcher(self) + super()._callSetUp() + + +class _ErrorCatcher(list): + """ This extends a list where errors are appended whenever they occur. The + purpose of this class is to feed the errors directly to the output, instead + of letting them accumulate until the test is over. It also improves the + traceback to make it easier to debug. + """ + __slots__ = ['test'] + + def __init__(self, test): + super().__init__() + self.test = test + + def append(self, error): + exc_info = error[1] + if exc_info is not None: + exception_type, exception, tb = exc_info + tb = self._complete_traceback(tb) + exc_info = (exception_type, exception, tb) + self.test._feedErrorsToResult(self.test._outcome.result, [(error[0], exc_info)]) + + def _complete_traceback(self, initial_tb): + Traceback = type(initial_tb) + + # make the set of frames in the traceback + tb_frames = set() + tb = initial_tb + while tb: + tb_frames.add(tb.tb_frame) + tb = tb.tb_next + tb = initial_tb + + # find the common frame by searching the last frame of the current_stack present in the traceback. + current_frame = inspect.currentframe() + common_frame = None + while current_frame: + if current_frame in tb_frames: + common_frame = current_frame # we want to find the last frame in common + current_frame = current_frame.f_back + + if not common_frame: # not really useful but safer + _logger.warning('No common frame found with current stack, displaying full stack') + tb = initial_tb + else: + # remove the tb_frames untile the common_frame is reached (keep the current_frame tb since the line is more accurate) + while tb and tb.tb_frame != common_frame: + tb = tb.tb_next + + # add all current frame elements under the common_frame to tb + current_frame = common_frame.f_back + while current_frame: + tb = Traceback(tb, current_frame, current_frame.f_lasti, current_frame.f_lineno) + current_frame = current_frame.f_back + + # remove traceback root part (odoo_bin, main, loading, ...), as + # everything under the testCase is not useful. Using '_callTestMethod', + # '_callSetUp', '_callTearDown', '_callCleanup' instead of the test + # method since the error does not comme especially from the test method. + while tb: + code = tb.tb_frame.f_code + if code.co_filename.endswith('/unittest/case.py') and code.co_name in ('_callTestMethod', '_callSetUp', '_callTearDown', '_callCleanup'): + return tb.tb_next + tb = tb.tb_next + + _logger.warning('No root frame found, displaying full stacks') + return initial_tb # this shouldn't be reached + + savepoint_seq = itertools.count() @@ -1908,7 +2004,7 @@ def no_retry(arg): def users(*logins): """ Decorate a method to execute it once for each given user. """ @decorator - def wrapper(func, *args, **kwargs): + def _users(func, *args, **kwargs): self = args[0] old_uid = self.uid try: @@ -1929,7 +2025,7 @@ def users(*logins): finally: self.uid = old_uid - return wrapper + return _users @decorator diff --git a/odoo/tests/runner.py b/odoo/tests/runner.py index f2431f0b830..c16f728c635 100644 --- a/odoo/tests/runner.py +++ b/odoo/tests/runner.py @@ -1,5 +1,6 @@ import collections import contextlib +import inspect import logging import re import time @@ -87,7 +88,7 @@ class OdooTestResult(unittest.result.TestResult): the other parameters. """ test = test or self - if isinstance(test, unittest.case._SubTest) and test.test_case: + while isinstance(test, unittest.case._SubTest) and test.test_case: test = test.test_case logger = logging.getLogger(test.__module__) try: @@ -223,14 +224,38 @@ class OdooTestResult(unittest.result.TestResult): if not isinstance(test, unittest.TestCase): _logger.warning('%r is not a TestCase' % test) return + _, _, error_traceback = error + # move upwards the subtest hierarchy to find the real test + while isinstance(test, unittest.case._SubTest) and test.test_case: + test = test.test_case + + method_tb = None + file_tb = None + filename = inspect.getfile(type(test)) + + # Note: since _ErrorCatcher was introduced, we could always take the + # last frame, keeping the check on the test method for safety. + # Fallbacking on file for cleanup file shoud always be correct to a + # minimal working version would be + # + # infos_tb = error_traceback + # while infos_tb.tb_next() + # infos_tb = infos_tb.tb_next() + # while error_traceback: code = error_traceback.tb_frame.f_code - if code.co_name == test._testMethodName: - lineno = error_traceback.tb_lineno - filename = code.co_filename - method = test._testMethodName - infos = (filename, lineno, method, None) - return infos + if code.co_name in (test._testMethodName, 'setUp', 'tearDown'): + method_tb = error_traceback + if code.co_filename == filename: + file_tb = error_traceback error_traceback = error_traceback.tb_next + + infos_tb = method_tb or file_tb + if infos_tb: + code = infos_tb.tb_frame.f_code + lineno = infos_tb.tb_lineno + filename = code.co_filename + method = test._testMethodName + return (filename, lineno, method, None)