[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
This commit is contained in:
Xavier-Do
2022-12-16 19:37:52 +01:00
parent 5c69db2220
commit e583a1f8f4
3 changed files with 572 additions and 12 deletions
+439
View File
@@ -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 (<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 "<decorator-gen-xxx>", line $line, in test_with_decorators
File "/root_path/odoo/odoo/tests/common.py", line $line, in _users
func(*args, **kwargs)
File "<decorator-gen-xxx>", 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 (<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 (<subtest>)
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')
+101 -5
View File
@@ -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
+32 -7
View File
@@ -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)