diff options
| -rw-r--r-- | odoo/modules/loading.py | 2 | ||||
| -rw-r--r-- | odoo/modules/module.py | 114 | ||||
| -rw-r--r-- | odoo/service/server.py | 6 | ||||
| -rw-r--r-- | 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 |