[IMP] core: tests reporting

* remove useless OdooTestRunner
* don't log results & time per-file, log a module-level tally instead
* add number of tests to post-test results
* generate a single test suite per module (see note)
* use the previous item to split out the at_install test-running in
  two steps: generating the suite for the module then running that
  suite, this way for modules which have no test, or for
  which all tests have been deselected by test tags, we can avoid some
  of the setup necessary to prepare for running tests but possibly
  quite expensive (e.g. `setup_models`)

Note: single test suite per module

I wanted to stop creating a test result for (essentially) every file
in the module, however because of the class-level ``addCleanup``, a
TestResult can't be reused by independent suites:

In order to run class-level cleanup, the test suite checks between
tests if the test it's *preparing* to run is in the same class as the
last test it ran, and if not applies the class-level cleanup.

The problem is that the "previous test class" is stored on the result
object, which is never cleaned up, and the "between tests" check is
really performed *before each test*.

This means when reusing results across suites it will run the
class-level cleanup at the end of one suite and immediately at the
start of the next, which will cause issues if class-level cleanups are
not idempotent (thankfully ``TestTestCursor`` has a non-idempotent
``tearDownClass` which let me discover the error).

Possible fixes are:

* don't reuse results
* clear the relevant states / attributes between suites
* put individual suites in a Big Suite for running

The latter seems simpler: just create a single suite for the entire
odoo-level module instead of creating one suite per test module.

Note to the note: the case of nested suite is taken in account, the
"end of suite" cleanup only runs at the end of the top-level suite, so
technically we don't have to unwrap suites for *that* purpose, we're
doing so in order to filter the test cases inside the suites. But
maybe we could integrate this feature to the suites themselves...

closes odoo/odoo#55185

Signed-off-by: Xavier Morel (xmo) <xmo@odoo.com>

4 files changed, 89 insertions, 70 deletions

diff --git a/odoo/modules/loading.py b/odoo/modules/loading.py
index dfe315c95d9..515cd4763bb 100644
--- a/odoo/modules/loading.py
+++ b/odoo/modules/loading.py
@@ -248,16 +248,27 @@ def load_module_graph(cr, graph, status=None, perform_checks=True,
             cr.commit()
 
         updating = tools.config.options['init'] or tools.config.options['update']
+        test_time = test_queries = 0
+        test_results = None
         if tools.config.options['test_enable'] and (needs_update or not updating):
             env = api.Environment(cr, SUPERUSER_ID, {})
-            if not needs_update:
-                registry.setup_models(cr)
-            # Python tests
-            env['ir.http']._clear_routing_map()     # force routing map to be rebuilt
-            report.update(odoo.tests.loader.run_unit_tests(module_name))
-            # tests may have reset the environment
-            env = api.Environment(cr, SUPERUSER_ID, {})
-            module = env['ir.module.module'].browse(module_id)
+            loader = odoo.tests.loader
+            suite = loader.make_suite(module_name, 'at_install')
+            if suite.countTestCases():
+                if not needs_update:
+                    registry.setup_models(cr)
+                # Python tests
+                env['ir.http']._clear_routing_map()     # force routing map to be rebuilt
+
+                tests_t0, tests_q0 = time.time(), odoo.sql_db.sql_counter
+                test_results = loader.run_suite(suite, module_name)
+                report.update(test_results)
+                test_time = time.time() - tests_t0
+                test_queries = odoo.sql_db.sql_counter - tests_q0
+
+                # tests may have reset the environment
+                env = api.Environment(cr, SUPERUSER_ID, {})
+                module = env['ir.module.module'].browse(module_id)
 
         if needs_update:
             processed_modules.append(package.name)
@@ -274,11 +285,25 @@ def load_module_graph(cr, graph, status=None, perform_checks=True,
                     delattr(package, kind)
             module.flush()
 
-        _logger.log(module_log_level, "Module %s loaded in %.2fs, %s queries (+%s extra)",
-                    module_name,
-                    time.time() - module_t0,
-                    cr.sql_log_count - module_cursor_query_count,
-                    odoo.sql_db.sql_counter - module_extra_query_count)  # extra queries: testes, notify, any other closed cursor
+        extra_queries = odoo.sql_db.sql_counter - module_extra_query_count - test_queries
+        extras = []
+        if test_queries:
+            extras.append(f'+{test_queries} test')
+        if extra_queries:
+            extras.append(f'+{extra_queries} other')
+        _logger.log(
+            module_log_level, "Module %s loaded in %.2fs%s, %s queries%s",
+            module_name, time.time() - module_t0,
+            f' (incl. {test_time:.2f}s test)' if test_time else '',
+            cr.sql_log_count - module_cursor_query_count,
+            f' ({", ".join(extras)})' if extras else ''
+        )
+        if test_results and not test_results.wasSuccessful():
+            _logger.error(
+                "Module %s: %d failures, %d errors of %d tests",
+                module_name, len(test_results.failures), len(test_results.errors),
+                test_results.testsRun
+            )
 
     _logger.runbot("%s modules loaded in %.2fs, %s queries (+%s extra)",
                    len(graph),
diff --git a/odoo/service/server.py b/odoo/service/server.py
index f6e0ee72b00..c57e1ba42a4 100644
--- a/odoo/service/server.py
+++ b/odoo/service/server.py
@@ -16,6 +16,7 @@ import sys
 import threading
 import time
 import unittest
+from itertools import chain
 
 import psutil
 import werkzeug.serving
@@ -511,13 +512,16 @@ class ThreadedServer(CommonServer):
 
         if stop:
             if config['test_enable']:
+                logger = odoo.tests.runner._logger
                 with Registry.registries._lock:
                     for db, registry in Registry.registries.d.items():
                         report = registry._assertion_report
-                        log = _logger.error if not report.wasSuccessful() \
-                         else _logger.warning if not report.testsRun \
-                         else _logger.info
-                        log("%s when loading %s", report, db)
+                        log = logger.error if not report.wasSuccessful() \
+                         else logger.warning if not report.testsRun \
+                         else logger.info
+                        log("%s when loading database %r", report, db)
+                        for test, traceback in chain(report.failures, report.errors):
+                            log("%s\n%s", report.getDescription(test), traceback)
             self.stop()
             return rc
 
@@ -1178,9 +1182,8 @@ def load_test_file_py(registry, test_file):
                         unittest.TestLoader().loadTestsFromModule(mod_mod))
                     suite = OdooSuite(tests)
                     _logger.log(logging.INFO, 'running tests %s.', mod_mod.__name__)
-                    result = runner.OdooTestRunner().run(suite)
-                    registry._assertion_report.update(result)
-                    if not result.wasSuccessful():
+                    suite(registry._assertion_report)
+                    if not registry._assertion_report.wasSuccessful():
                         _logger.error('%s: at least one error occurred in a test', test_file)
                     return
     finally:
@@ -1215,12 +1218,15 @@ def preload_registries(dbnames):
                 module_names = (registry.updated_modules if update_module else
                                 registry._init_modules)
                 _logger.info("Starting post tests")
+                tests_before = registry._assertion_report.testsRun
                 with odoo.api.Environment.manage():
                     for module_name in module_names:
-                        result = loader.run_unit_tests(module_name, position='post_install')
+                        result = loader.run_suite(loader.make_suite(module_name, 'post_install'), module_name)
                         registry._assertion_report.update(result)
-                _logger.info("All post-tested in %.2fs, %s queries",
-                             time.time() - t0, odoo.sql_db.sql_counter - t0_sql)
+                _logger.info("%d post-tests in %.2fs, %s queries",
+                             registry._assertion_report.testsRun - tests_before,
+                             time.time() - t0,
+                             odoo.sql_db.sql_counter - t0_sql)
 
             if not registry._assertion_report.wasSuccessful():
                 rc += 1
diff --git a/odoo/tests/loader.py b/odoo/tests/loader.py
index 99df113a82e..2d6c2d8275d 100644
--- a/odoo/tests/loader.py
+++ b/odoo/tests/loader.py
@@ -3,17 +3,14 @@ import inspect
 import itertools
 import logging
 import threading
-import time
 import unittest
 
-import odoo
 from .. import tools
 from .common import TagsSelector, OdooSuite
-from .runner import OdooTestRunner, OdooTestResult
+from .runner import OdooTestResult
 
-# backwards compatibility
-_logger = logging.getLogger('odoo.modules.module')
 
+_logger = logging.getLogger(__name__)
 def get_test_modules(module):
     """ Return a list of module for the addons potentially containing tests to
     feed unittest.TestLoader.loadTestsFromModule() """
@@ -53,45 +50,36 @@ def _get_tests_modules(path, module):
               if name.startswith('test_')]
     return result
 
+def make_suite(module_name, position='at_install'):
+    mods = get_test_modules(module_name)
+    """ Creates a test suite for all the tests in the specified module,
+    filtered by the provided ``position`` and the current test tags
 
-def run_unit_tests(module_name, position='at_install'):
-    """
-    :returns: ``True`` if all of ``module_name``'s tests succeeded, ``False``
-              if any of them failed, ``None`` if no tests were ran.
-    :rtype: bool | None
+    :param str module_name: module to load tests from
+    :param str position: "at_install" or "post_install"
     """
-    from ..modules import module
+    config_tags = TagsSelector(tools.config['test_tags'])
+    position_tag = TagsSelector(position)
+    return OdooSuite(
+        t
+        for m in mods
+        for t in unwrap_suite(unittest.TestLoader().loadTestsFromModule(m))
+        if position_tag.check(t) and config_tags.check(t)
+    )
+
+def run_suite(suite, module_name):
     # avoid dependency hell
+    from ..modules import module
     module.current_test = module_name
-    mods = get_test_modules(module_name)
     threading.currentThread().testing = True
-    config_tags = TagsSelector(tools.config['test_tags'])
-    position_tag = TagsSelector(position)
 
     results = OdooTestResult()
-    for m in mods:
-        tests = unwrap_suite(unittest.TestLoader().loadTestsFromModule(m))
-        suite = OdooSuite(t for t in tests if position_tag.check(t) and config_tags.check(t))
-
-        if suite.countTestCases():
-            t0 = time.time()
-            t0_sql = odoo.sql_db.sql_counter
-            _logger.info('%s running tests.', m.__name__)
-            result = OdooTestRunner().run(suite)
-            results.update(result)
-            log_level = logging.INFO
-            if time.time() - t0 > 5:
-                log_level = logging.RUNBOT
-            _logger.log(log_level, "%s ran %s tests in %.2fs, %s queries", m.__name__, result.testsRun, time.time() - t0, odoo.sql_db.sql_counter - t0_sql)
-            if not result.wasSuccessful():
-                _logger.error("Module %s: %d failures, %d errors", module_name, len(result.failures), len(result.errors))
+    suite(results)
 
-    module.current_test = None
     threading.currentThread().testing = False
-
+    module.current_test = None
     return results
 
-
 def unwrap_suite(test):
     """
     Attempts to unpack testsuites (holding suites or cases) in order to
diff --git a/odoo/tests/runner.py b/odoo/tests/runner.py
index 132124fe031..bf2680b90a7 100644
--- a/odoo/tests/runner.py
+++ b/odoo/tests/runner.py
@@ -1,8 +1,11 @@
 import logging
+import time
 import unittest
 
-# backwards compatibility
-_logger = logging.getLogger('odoo.modules.module')
+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)
@@ -10,8 +13,14 @@ class OdooTestResult(unittest.result.TestResult):
     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
+
     def __str__(self):
-        return f'{len(self.failures)} failed, {len(self.errors)} errors of {self.testsRun} tests'
+        return f'{len(self.failures)} failed, {len(self.errors)} error(s) of {self.testsRun} tests'
 
     def update(self, other):
         """ Merges an other test result into this one, only updates contents
@@ -60,6 +69,8 @@ class OdooTestResult(unittest.result.TestResult):
     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):
         super().addError(test, err)
@@ -118,14 +129,3 @@ class OdooTestResult(unittest.result.TestResult):
                 infos = (filename, lineno, method, None)
                 return infos
             error_traceback = error_traceback.tb_next
-
-
-class OdooTestRunner(object):
-    """A test runner class that displays results in in logger using OdooTestResult.
-    Simplified verison of TextTestRunner
-    """
-
-    def run(self, test):
-        result = OdooTestResult()
-        test(result)
-        return result