[IMP] core: improve test logs

1. Make test logs clearer & remove redundancies

Instead of having an ERROR log right when the test fails then print
the useful / relevant information at the end of the test suite,
immediately print the traceback. Keep the final summary. Also avoids
having to wait for the entire test suite to end before a dev' can know
the failure details of a specific test.

Done by working at a lower level and replacing the custom
test stream mess by a custom Result class which prints and formats the
information we want. Replace TextTestRunner by a bare-bones custom
Runner object to tie it in.

2. Provide useful location information on test failure

Leverage the work above to log the test function's failure location:
previously logging would point to within TestStream which is not
useful.

Here, on failure the traceback is used to discover the caller info and
point to the test line which fails instead. similar to unittest's
_exc_info_to_string (https://github.com/python/cpython/blob/93e8aa62cfd0a61efed4a61a2ffc2283ae986ef2/Lib/unittest/result.py#L173).

3. Replace direct logging in browser_js by raising errors

Properly marks the test as in error, and the error traceback points to
the tour definition / launcher (python side) rather than common.py
and/or module.py.

Also removes unused dbname parameter that was added in
/278ed718e9805edf088642ba10d3b7c4e5716c31/openerp/modules/module.py#L361
for nor visible reason

closes odoo/odoo#34996

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

odoo/modules/loading.py

@@ -251,7 +251,7 @@ def load_module_graph(cr, graph, status=None, perform_checks=True,
                 report.record_result(load_test(idref, mode))
                 # Python tests
                 env['ir.http']._clear_routing_map()     # force routing map to be rebuilt
-                report.record_result(odoo.modules.module.run_unit_tests(module_name, cr.dbname))
+                report.record_result(odoo.modules.module.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)

odoo/modules/module.py

@@ -465,22 +465,110 @@ def get_test_modules(module):
               if name.startswith('test_')]
     return result
 
-# Use a custom stream object to log the test executions.
-class TestStream(object):
-    def __init__(self, logger_name='odoo.tests'):
-        self.logger = logging.getLogger(logger_name)
-        self.r = re.compile(r'^-*$|^ *... *$|^ok$')
-    def flush(self):
-        pass
-    def write(self, s):
-        if self.r.match(s):
+
+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 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.
+        """
+        logger = logging.getLogger((test or self).__module__)  # test should be always set
+        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
+        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.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)
+
+    def addError(self, test, err):
+        super().addError(test, err)
+        self.logError("ERROR", test, err)
+
+    def addFailure(self, test, err):
+        super().addFailure(test, err)
+        self.logError("FAIL", test, 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 not isinstance(test, unittest.TestCase):
+            _logger.warning('%r is not a TestCase' % test)
             return
-        level = logging.ERROR if s.startswith(('ERROR', 'FAIL', 'Traceback')) else logging.INFO
-        self.logger.log(level, s)
+        _, _, 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
+
+
+class OdooTestRunner(object):
+    """A test runner class that displays results in in logger.
+    Simplified verison of TextTestRunner(
+    """
+
+    def run(self, test):
+        result = OdooTestResult()
+
+        start_time = time.perf_counter()
+        test(result)
+        time_taken = time.perf_counter() - start_time
+
+        logger = logging.getLogger(test.__module__)
+        run = result.testsRun
+        logger.info("Ran %d test%s in %.3fs", run, run != 1 and "s" or "", time_taken)
+        return result
 
 current_test = None
 
-def run_unit_tests(module_name, dbname, position='at_install'):
+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.
@@ -502,7 +590,7 @@ def run_unit_tests(module_name, dbname, position='at_install'):
             t0 = time.time()
             t0_sql = odoo.sql_db.sql_counter
             _logger.info('%s running tests.', m.__name__)
-            result = unittest.TextTestRunner(verbosity=2, stream=TestStream(m.__name__)).run(suite)
+            result = OdooTestRunner().run(suite)
             if time.time() - t0 > 5:
                 _logger.log(25, "%s tested in %.2fs, %s queries", m.__name__, time.time() - t0, odoo.sql_db.sql_counter - t0_sql)
             if not result.wasSuccessful():

odoo/service/server.py

@@ -1099,8 +1099,7 @@ def load_test_file_py(registry, test_file):
                     for t in unittest.TestLoader().loadTestsFromModule(mod_mod):
                         suite.addTest(t)
                     _logger.log(logging.INFO, 'running tests %s.', mod_mod.__name__)
-                    stream = odoo.modules.module.TestStream()
-                    result = unittest.TextTestRunner(verbosity=2, stream=stream).run(suite)
+                    result = odoo.modules.module.OdooTestRunner().run(suite)
                     success = result.wasSuccessful()
                     if hasattr(registry._assertion_report,'report_result'):
                         registry._assertion_report.report_result(success)
@@ -1141,8 +1140,7 @@ def preload_registries(dbnames):
                 _logger.info("Starting post tests")
                 with odoo.api.Environment.manage():
                     for module_name in module_names:
-                        result = run_unit_tests(module_name, registry.db_name,
-                                                position='post_install')
+                        result = run_unit_tests(module_name, position='post_install')
                         registry._assertion_report.record_result(result)
                 _logger.info("All post-tested in %.2fs, %s queries",
                              time.time() - t0, odoo.sql_db.sql_counter - t0_sql)

odoo/tests/common.py

@@ -459,6 +459,10 @@ class SavepointCase(SingleTransactionCase):
         super(SavepointCase, self).tearDown()
 
 
+class ChromeBrowserException(Exception):
+    pass
+
+
 class ChromeBrowser():
     """ Helper object to control a Chrome headless process. """
 
@@ -775,23 +779,20 @@ class ChromeBrowser():
             if res and res.get('id', -1) == code_id:
                 self._logger.info('Code start result: %s', res)
                 if res.get('result', {}).get('result').get('subtype', '') == 'error':
-                    self._logger.error("Running code returned an error")
-                    return False
+                    raise ChromeBrowserException("Running code returned an error: %s" % res)
             elif res and res.get('method') == 'Runtime.exceptionThrown':
                 exception_details = res.get('params', {}).get('exceptionDetails', {})
-                self._logger.error(exception_details)
                 self.take_screenshot()
                 self._save_screencast()
-                return False
+                raise ChromeBrowserException(exception_details)
             elif res and res.get('method') == 'Runtime.consoleAPICalled' and res.get('params', {}).get('type') in ('log', 'error', 'trace'):
                 logs = res.get('params', {}).get('args')
                 log_type = res.get('params', {}).get('type')
                 content = " ".join([str(log.get('value', '')) for log in logs])
                 if log_type == 'error':
-                    self._logger.error(content)
                     self.take_screenshot()
                     self._save_screencast()
-                    return False
+                    raise ChromeBrowserException(content)
                 else:
                     self._logger.info('console log: %s', content)
                     if 'test successful' in content:
@@ -810,9 +811,9 @@ class ChromeBrowser():
                     })
             elif res:
                 self._logger.debug('chrome devtools protocol event: %s', res)
-        self._logger.error('Script timeout exceeded : %s', (time.time() - start_time))
         self.take_screenshot()
-        return False
+        raise ChromeBrowserException('Script timeout exceeded : %s' % (time.time() - start_time))
+
 
     def navigate_to(self, url, wait_stop=False):
         self._logger.info('Navigating to: "%s"', url)
@@ -976,11 +977,19 @@ class HttpCase(TransactionCase):
             # code = ""
             ready = ready or "document.readyState === 'complete'"
             self.assertTrue(self.browser._wait_ready(ready), 'The ready "%s" code was always falsy' % ready)
-            if code:
-                message = 'The test code "%s" failed' % code
-            else:
-                message = "Some js test failed"
-            self.assertTrue(self.browser._wait_code_ok(code, timeout), message)
+
+            error = False
+            try:
+                self.browser._wait_code_ok(code, timeout)
+            except ChromeBrowserException as chrome_browser_exception:
+                error = chrome_browser_exception
+            if error:  # dont keep initial traceback, keep that outside of except
+                if code:
+                    message = 'The test code "%s" failed' % code
+                else:
+                    message = "Some js test failed"
+                self.fail('%s\n%s' % (message, error))
+
         finally:
             # clear browser to make it stop sending requests, in case we call
             # the method several times in a test method