From 735ee5487c7b312918f8a7ea46fd271c3c9957de Mon Sep 17 00:00:00 2001 From: Xavier-Do Date: Thu, 18 Jul 2019 15:10:57 +0000 Subject: [PATCH] [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) --- odoo/modules/loading.py | 2 +- odoo/modules/module.py | 114 +++++++++++++++++++++++++++++++++++----- odoo/service/server.py | 6 +-- odoo/tests/common.py | 35 +++++++----- 4 files changed, 126 insertions(+), 31 deletions(-) diff --git a/odoo/modules/loading.py b/odoo/modules/loading.py index e256711e06f..de6b07e01ca 100644 --- a/odoo/modules/loading.py +++ b/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) diff --git a/odoo/modules/module.py b/odoo/modules/module.py index 8036bff7dd9..f99c25ea11d 100644 --- a/odoo/modules/module.py +++ b/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(): diff --git a/odoo/service/server.py b/odoo/service/server.py index 7fd576ab6d5..cab3f75fe85 100644 --- a/odoo/service/server.py +++ b/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) diff --git a/odoo/tests/common.py b/odoo/tests/common.py index a8195359fe0..3bcc52b1aec 100644 --- a/odoo/tests/common.py +++ b/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