Files
odoo_source/odoo/tests/runner.py
T
Xavier-Do 8a7990735d [IMP] tests: autoretry mechanism for staging
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>
2021-09-24 13:59:56 +00:00

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