This pr proposes an auto retry mechanism for tests. This shouldn't impact normal testing: tests are not supposed to fail, but the growing number of tests and pull requests can lead to some bottleneck when a staging fails because of a random error. This mechanism should help to reduce splits/the need to retry a failed pr. This branch have been tested with the nightly multi build, creating 40 identical build without test-tags to disable know random errors. This multi build is used to detect test failing randomly, this is an excellent candidate to detect the effect of the retry. On average, with the current base of this pull request, there is between 10 en 15 failures over 40 build. With the auto retry mechanism, only 1 build failed over 40 builds since the same error was triggered twice. This is simply because with the retry mechanism, an error that has a probability of p to fail randomly will still have a probability of p² to fail with the retry mechanism. A error that occurs 10% of the time should only appear 1% of the time with one retry. In most of the case, the retry is sucessfull: https://runbot.odoo.com/runbot/build/10053257 The current solution to allow to enable this mechanism only in some cases (staging) is to check an environment variable "ODOO_TEST_FAILURE_RETRIES" that defines a number of retry. This will allow to retry more than once if an error still occurs to ofen with the autoretry. The mechanism will run multiple time the same test on the same test_case, meaning that some modification on self may impact the second execution. The following code is an example of how this could be problematic, but also a good example to test the auto-retry mechanism. ```python class TestRetry(HttpCase): def test_fail(self): self.t = getattr(self, 't', 0) + 1 if True or self.t == 1: import logging _logger = logging.getLogger('test_a') with self.assertLogs(level="ERROR"): _logger.error("This shouldn't be log at all") with mute_logger('test_a'): _logger.error("This shouldn't be logged (mute)") _logger.error("This should be log") ``` As we can see here the error logs are also managed, and emit at a lower level the first time, butany log higher than 25 will make the test "failed" and the autoretry mechanism will be triggered. The second time, everything is logged normally. We also need to replace Traceback by _Traceback to avoid being catched by runbot Traceback detection regexes. The inspiration here commes from the assertLogs, that replace all handlers. The mute_logger had to be adapted to use the same strategy, so that quite_logger won't detect logs catched by mute_logger or assertLogs. closes odoo/odoo#76336 Signed-off-by: Xavier Dollé (xdo) <xdo@odoo.com>
151 lines
6.0 KiB
Python
151 lines
6.0 KiB
Python
import contextlib
|
|
import logging
|
|
import time
|
|
import unittest
|
|
|
|
from .. import sql_db
|
|
|
|
|
|
_logger = logging.getLogger(__name__)
|
|
class OdooTestResult(unittest.result.TestResult):
|
|
"""
|
|
This class in inspired from TextTestResult (https://github.com/python/cpython/blob/master/Lib/unittest/runner.py)
|
|
Instead of using a stream, we are using the logger,
|
|
but replacing the "findCaller" in order to give the information we
|
|
have based on the test object that is running.
|
|
"""
|
|
|
|
def __init__(self):
|
|
super().__init__()
|
|
self.time_start = None
|
|
self.queries_start = None
|
|
self._soft_fail = False
|
|
self.had_failure = False
|
|
|
|
def __str__(self):
|
|
return f'{len(self.failures)} failed, {len(self.errors)} error(s) of {self.testsRun} tests'
|
|
|
|
@contextlib.contextmanager
|
|
def soft_fail(self):
|
|
self.had_failure = False
|
|
self._soft_fail = True
|
|
try:
|
|
yield
|
|
finally:
|
|
self._soft_fail = False
|
|
self.had_failure = False
|
|
|
|
def update(self, other):
|
|
""" Merges an other test result into this one, only updates contents
|
|
|
|
:type other: OdooTestResult
|
|
"""
|
|
self.failures.extend(other.failures)
|
|
self.errors.extend(other.errors)
|
|
self.testsRun += other.testsRun
|
|
self.skipped.extend(other.skipped)
|
|
self.expectedFailures.extend(other.expectedFailures)
|
|
self.unexpectedSuccesses.extend(other.unexpectedSuccesses)
|
|
self.shouldStop = self.shouldStop or other.shouldStop
|
|
|
|
def log(self, level, msg, *args, test=None, exc_info=None, extra=None, stack_info=False, caller_infos=None):
|
|
"""
|
|
``test`` is the running test case, ``caller_infos`` is
|
|
(fn, lno, func, sinfo) (logger.findCaller format), see logger.log for
|
|
the other parameters.
|
|
"""
|
|
test = test or self
|
|
if isinstance(test, unittest.case._SubTest) and test.test_case:
|
|
test = test.test_case
|
|
logger = logging.getLogger(test.__module__)
|
|
try:
|
|
caller_infos = caller_infos or logger.findCaller(stack_info)
|
|
except ValueError:
|
|
caller_infos = "(unknown file)", 0, "(unknown function)", None
|
|
(fn, lno, func, sinfo) = caller_infos
|
|
# using logger.log makes it difficult to spot-replace findCaller in
|
|
# order to provide useful location information (the problematic spot
|
|
# inside the test function), so use lower-level functions instead
|
|
if logger.isEnabledFor(level):
|
|
record = logger.makeRecord(logger.name, level, fn, lno, msg, args, exc_info, func, extra, sinfo)
|
|
logger.handle(record)
|
|
|
|
def getDescription(self, test):
|
|
if isinstance(test, unittest.case._SubTest):
|
|
return 'Subtest %s.%s %s' % (test.test_case.__class__.__qualname__, test.test_case._testMethodName, test._subDescription())
|
|
if isinstance(test, unittest.TestCase):
|
|
# since we have the module name in the logger, this will avoid to duplicate module info in log line
|
|
# we only apply this for TestCase since we can receive error handler or other special case
|
|
return "%s.%s" % (test.__class__.__qualname__, test._testMethodName)
|
|
return str(test)
|
|
|
|
def startTest(self, test):
|
|
super().startTest(test)
|
|
self.log(logging.INFO, 'Starting %s ...', self.getDescription(test), test=test)
|
|
self.time_start = time.time()
|
|
self.queries_start = sql_db.sql_counter
|
|
|
|
def addError(self, test, err):
|
|
if self._soft_fail:
|
|
self.had_failure = True
|
|
else:
|
|
super().addError(test, err)
|
|
self.logError("ERROR", test, err)
|
|
|
|
def addFailure(self, test, err):
|
|
if self._soft_fail:
|
|
self.had_failure = True
|
|
else:
|
|
super().addFailure(test, err)
|
|
self.logError("FAIL", test, err)
|
|
|
|
def addSubTest(self, test, subtest, err):
|
|
# since addSubTest is not making a call to addFailure or addError we need to manage it too
|
|
# https://github.com/python/cpython/blob/3.7/Lib/unittest/result.py#L136
|
|
if err is not None:
|
|
if issubclass(err[0], test.failureException):
|
|
flavour = "FAIL"
|
|
else:
|
|
flavour = "ERROR"
|
|
self.logError(flavour, subtest, err)
|
|
super().addSubTest(test, subtest, err)
|
|
|
|
def addSkip(self, test, reason):
|
|
super().addSkip(test, reason)
|
|
self.log(logging.INFO, 'skipped %s', self.getDescription(test), test=test)
|
|
|
|
def addUnexpectedSuccess(self, test):
|
|
super().addUnexpectedSuccess(test)
|
|
self.log(logging.ERROR, 'unexpected success for %s', self.getDescription(test), test=test)
|
|
|
|
def logError(self, flavour, test, error):
|
|
err = self._exc_info_to_string(error, test)
|
|
caller_infos = self.getErrorCallerInfo(error, test)
|
|
self.log(logging.INFO, '=' * 70, test=test, caller_infos=caller_infos) # keep this as info !!!!!!
|
|
self.log(logging.ERROR, "%s: %s\n%s", flavour, self.getDescription(test), err, test=test, caller_infos=caller_infos)
|
|
|
|
def getErrorCallerInfo(self, error, test):
|
|
"""
|
|
:param error: A tuple (exctype, value, tb) as returned by sys.exc_info().
|
|
:param test: A TestCase that created this error.
|
|
:returns: a tuple (fn, lno, func, sinfo) matching the logger findCaller format or None
|
|
"""
|
|
|
|
# only test case should be executed in odoo, this is only a safe guard
|
|
if isinstance(test, unittest.suite._ErrorHolder):
|
|
return
|
|
if not isinstance(test, unittest.TestCase):
|
|
_logger.warning('%r is not a TestCase' % test)
|
|
return
|
|
_, _, error_traceback = error
|
|
|
|
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
|
|
error_traceback = error_traceback.tb_next
|