[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>

odoo/tests/common.py

@@ -48,7 +48,7 @@ from odoo.exceptions import AccessError
 from odoo.osv.expression import normalize_domain, TRUE_LEAF, FALSE_LEAF
 from odoo.service import security
 from odoo.sql_db import Cursor
-from odoo.tools import float_compare, single_email_re, profiler
+from odoo.tools import float_compare, single_email_re, profiler, lower_logging
 from odoo.tools.misc import find_in_path
 from odoo.tools.safe_eval import safe_eval
 
@@ -348,6 +348,21 @@ class BaseCase(unittest.TestCase, metaclass=MetaCase):
         self.addTypeEqualityFunc(etree._Element, self.assertTreesEqual)
         self.addTypeEqualityFunc(html.HtmlElement, self.assertTreesEqual)
 
+    def run(self, result):
+        tests_run_count = int(os.environ.get('ODOO_TEST_FAILURE_RETRIES', 0)) + 1
+        failure = False
+        for retry in range(tests_run_count):
+            if retry:
+                _logger.runbot(f'Retrying a failed test: {self}')
+            if retry < tests_run_count-1:
+                with result.soft_fail(), lower_logging(25) as quiet_log:
+                    super().run(result)
+                    failure = result.had_failure or quiet_log.had_error_log
+            else:  # last try
+                super().run(result)
+            if not failure:
+                break
+
     def shortDescription(self):
         return None
 

odoo/tests/runner.py

@@ -1,3 +1,4 @@
+import contextlib
 import logging
 import time
 import unittest
@@ -18,10 +19,22 @@ class OdooTestResult(unittest.result.TestResult):
         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
 
@@ -73,11 +86,17 @@ class OdooTestResult(unittest.result.TestResult):
         self.queries_start = sql_db.sql_counter
 
     def addError(self, test, err):
-        super().addError(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):
-        super().addFailure(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):

odoo/tools/misc.py

@@ -767,7 +767,7 @@ class UnquoteEvalContext(defaultdict):
         return unquote(key)
 
 
-class mute_logger(object):
+class mute_logger(logging.Handler):
     """Temporary suppress the logging.
     Can be used as context manager or decorator.
 
@@ -780,20 +780,21 @@ class mute_logger(object):
 
     """
     def __init__(self, *loggers):
+        super().__init__()
         self.loggers = loggers
-
-    def filter(self, record):
-        return 0
+        self.old_params = {}
 
     def __enter__(self):
-        for logger in self.loggers:
-            assert isinstance(logger, str),\
-                "A logger name must be a string, got %s" % type(logger)
-            logging.getLogger(logger).addFilter(self)
+        for logger_name in self.loggers:
+            logger = logging.getLogger(logger_name)
+            self.old_params[logger_name] = (logger.handlers, logger.propagate)
+            logger.propagate = False
+            logger.handlers = [self]
 
     def __exit__(self, exc_type=None, exc_val=None, exc_tb=None):
-        for logger in self.loggers:
-            logging.getLogger(logger).removeFilter(self)
+        for logger_name in self.loggers:
+            logger = logging.getLogger(logger_name)
+            logger.handlers, logger.propagate = self.old_params[logger_name]
 
     def __call__(self, func):
         @wraps(func)
@@ -802,6 +803,46 @@ class mute_logger(object):
                 return func(*args, **kwargs)
         return deco
 
+    def emit(self, record):
+        pass
+
+
+class lower_logging(logging.Handler):
+    """Temporary lower the max logging level.
+    """
+    def __init__(self, max_level):
+        super().__init__()
+        self.old_handlers = None
+        self.old_propagate = None
+        self.had_error_log = False
+        self.max_level = max_level
+
+    def __enter__(self):
+        logger = logging.getLogger()
+        self.old_handlers = logger.handlers[:]
+        self.old_propagate = logger.propagate
+        logger.propagate = False
+        logger.handlers = [self]
+        self.had_error_log = False
+        return self
+
+    def __exit__(self, exc_type=None, exc_val=None, exc_tb=None):
+        logger = logging.getLogger()
+        logger.handlers = self.old_handlers
+        logger.propagate = self.old_propagate
+
+    def emit(self, record):
+        if record.levelno > self.max_level:
+            record.levelname = f'_{record.levelname}'
+            record.levelno = self.max_level
+            self.had_error_log = True
+            record.args = tuple(arg.replace('Traceback (most recent call last):', '_Traceback_ (most recent call last):') for arg in record.args)
+
+        for handler in self.old_handlers:
+            if handler.level <= record.levelno:
+                handler.emit(record)
+
+
 _ph = object()
 class CountingStream(object):
     """ Stream wrapper counting the number of element it has yielded. Similar