diff --git a/addons/l10n_ar/models/res_partner.py b/addons/l10n_ar/models/res_partner.py index d79552f3583..dd4d7aee514 100644 --- a/addons/l10n_ar/models/res_partner.py +++ b/addons/l10n_ar/models/res_partner.py @@ -41,7 +41,7 @@ class ResPartner(models.Model): rec.l10n_ar_formatted_vat = stdnum.ar.cuit.format(rec.l10n_ar_vat) except Exception as error: rec.l10n_ar_formatted_vat = rec.l10n_ar_vat - _logger.log(25, "Argentinian VAT was not formatted: %s", repr(error)) + _logger.runbot("Argentinian VAT was not formatted: %s", repr(error)) remaining = self - recs_ar_vat remaining.l10n_ar_formatted_vat = False @@ -96,7 +96,7 @@ class ResPartner(models.Model): module = rec._get_validation_module() except Exception as error: module = False - _logger.log(25, "Argentinian document was not validated: %s", repr(error)) + _logger.runbot("Argentinian document was not validated: %s", repr(error)) if not module: continue diff --git a/addons/web/tests/test_click_everywhere.py b/addons/web/tests/test_click_everywhere.py index 7f2d16d75d6..18c7431339e 100644 --- a/addons/web/tests/test_click_everywhere.py +++ b/addons/web/tests/test_click_everywhere.py @@ -13,7 +13,7 @@ class TestMenusAdmin(odoo.tests.HttpCase): menus = self.env['ir.ui.menu'].load_menus(False) for app in menus['children']: with self.subTest(app=app['name']): - _logger.log(25, 'Testing %s', app['name']) + _logger.runbot('Testing %s', app['name']) self.browser_js("/web", "odoo.__DEBUG__.services['web.clickEverywhere'](%d);" % app['id'], "odoo.isReady === true", login="admin", timeout=300) self.terminate_browser() @@ -25,7 +25,7 @@ class TestMenusDemo(odoo.tests.HttpCase): menus = self.env['ir.ui.menu'].load_menus(False) for app in menus['children']: with self.subTest(app=app['name']): - _logger.log(25, 'Testing %s', app['name']) + _logger.runbot('Testing %s', app['name']) self.browser_js("/web", "odoo.__DEBUG__.services['web.clickEverywhere'](%d);" % app['id'], "odoo.isReady === true", login="demo", timeout=300) self.terminate_browser() diff --git a/addons/web/tests/test_serving_base.py b/addons/web/tests/test_serving_base.py index 09c52df3471..267388bda85 100644 --- a/addons/web/tests/test_serving_base.py +++ b/addons/web/tests/test_serving_base.py @@ -982,7 +982,7 @@ class TestStaticInheritancePerformance(TestStaticInheritanceCommon): contents = HomeStaticTemplateHelpers.get_qweb_templates(addons=self._get_module_names(), debug=True) after = datetime.now() delta2500 = after - before - _logger.log(25, 'Static Templates Inheritance: 2500 templates treated in %s seconds' % delta2500.total_seconds()) + _logger.runbot('Static Templates Inheritance: 2500 templates treated in %s seconds' % delta2500.total_seconds()) whole_tree = etree.fromstring(contents) self.assertEqual(len(whole_tree), nMod * nFilePerMod * nTemplatePerFile) @@ -997,6 +997,6 @@ class TestStaticInheritancePerformance(TestStaticInheritanceCommon): delta25000 = after - before time_ratio = delta25000.total_seconds() / delta2500.total_seconds() - _logger.log(25, 'Static Templates Inheritance: 25000 templates treated in %s seconds' % delta25000.total_seconds()) - _logger.log(25, 'Static Templates Inheritance: Computed linearity ratio: %s' % time_ratio) + _logger.runbot('Static Templates Inheritance: 25000 templates treated in %s seconds' % delta25000.total_seconds()) + _logger.runbot('Static Templates Inheritance: Computed linearity ratio: %s' % time_ratio) self.assertLessEqual(time_ratio, 10) diff --git a/addons/website/tests/test_crawl.py b/addons/website/tests/test_crawl.py index 62df28c0f38..648fa258ec2 100644 --- a/addons/website/tests/test_crawl.py +++ b/addons/website/tests/test_crawl.py @@ -85,7 +85,7 @@ class Crawler(HttpCaseWithUserDemo): count = len(seen) duration = time.time() - t0 sql = self.registry.test_cr.sql_log_count - t0_sql - _logger.log(25, "public crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request, ", count, duration, sql, duration / count, float(sql) / count) + _logger.runbot("public crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request, ", count, duration, sql, duration / count, float(sql) / count) def test_20_crawl_demo(self): t0 = time.time() @@ -95,7 +95,7 @@ class Crawler(HttpCaseWithUserDemo): count = len(seen) duration = time.time() - t0 sql = self.registry.test_cr.sql_log_count - t0_sql - _logger.log(25, "demo crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request", count, duration, sql, duration / count, float(sql) / count) + _logger.runbot("demo crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request", count, duration, sql, duration / count, float(sql) / count) def test_30_crawl_admin(self): t0 = time.time() @@ -105,4 +105,4 @@ class Crawler(HttpCaseWithUserDemo): count = len(seen) duration = time.time() - t0 sql = self.registry.test_cr.sql_log_count - t0_sql - _logger.log(25, "admin crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request", count, duration, sql, duration / count, float(sql) / count) + _logger.runbot("admin crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request", count, duration, sql, duration / count, float(sql) / count) diff --git a/odoo/modules/loading.py b/odoo/modules/loading.py index 117bd0a4f90..8cb50e68438 100644 --- a/odoo/modules/loading.py +++ b/odoo/modules/loading.py @@ -153,7 +153,8 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, # register, instantiate and initialize models for each modules t0 = time.time() - t0_sql = odoo.sql_db.sql_counter + loading_extra_query_count = odoo.sql_db.sql_counter + loading_cursor_query_count = cr.sql_log_count models_updated = set() @@ -164,13 +165,20 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, if skip_modules and module_name in skip_modules: continue - _logger.debug('loading module %s (%d/%d)', module_name, index, module_count) + module_t0 = time.time() + module_cursor_query_count = cr.sql_log_count + module_extra_query_count = odoo.sql_db.sql_counter needs_update = ( hasattr(package, "init") or hasattr(package, "update") or package.state in ("to install", "to upgrade") ) + module_log_level = logging.DEBUG + if needs_update: + module_log_level = logging.INFO + _logger.log(module_log_level, 'Loading module %s (%d/%d)', module_name, index, module_count) + if needs_update: if package.name != 'base': registry.setup_models(cr) @@ -276,7 +284,17 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, if package.name is not None: registry._init_modules.add(package.name) - _logger.log(25, "%s modules loaded in %.2fs, %s queries", len(graph), time.time() - t0, odoo.sql_db.sql_counter - t0_sql) + _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 + + _logger.runbot("%s modules loaded in %.2fs, %s queries (+%s extra)", + len(graph), + time.time() - t0, + cr.sql_log_count - loading_cursor_query_count, + odoo.sql_db.sql_counter - loading_extra_query_count) # extra queries: testes, notify, any other closed cursor return loaded_modules, processed_modules @@ -459,7 +477,7 @@ def load_modules(db, force_demo=False, status=None, update_module=False): if model in registry: env[model]._check_removed_columns(log=True) elif _logger.isEnabledFor(logging.INFO): # more an info that a warning... - _logger.log(25, "Model %s is declared but cannot be loaded! (Perhaps a module was partially removed or renamed)", model) + _logger.runbot("Model %s is declared but cannot be loaded! (Perhaps a module was partially removed or renamed)", model) # Cleanup orphan records env['ir.model.data']._process_end(processed_modules) diff --git a/odoo/modules/module.py b/odoo/modules/module.py index b5a513e19fc..88d96949b74 100644 --- a/odoo/modules/module.py +++ b/odoo/modules/module.py @@ -495,18 +495,13 @@ class OdooTestResult(unittest.result.TestResult): class OdooTestRunner(object): - """A test runner class that displays results in in logger. - Simplified verison of TextTestRunner( + """A test runner class that displays results in in logger using OdooTestResult. + Simplified verison of TextTestRunner """ def run(self, test): result = OdooTestResult() - - start_time = time.perf_counter() test(result) - time_taken = time.perf_counter() - start_time - run = result.testsRun - _logger.info("Ran %d test%s in %.3fs", run, run != 1 and "s" or "", time_taken) return result current_test = None @@ -535,8 +530,10 @@ def run_unit_tests(module_name, position='at_install'): t0_sql = odoo.sql_db.sql_counter _logger.info('%s running tests.', m.__name__) result = OdooTestRunner().run(suite) + log_level = logging.INFO 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) + 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(): r = False _logger.error("Module %s: %d failures, %d errors", module_name, len(result.failures), len(result.errors)) diff --git a/odoo/netsvc.py b/odoo/netsvc.py index a9c1a365986..8257dccdbcb 100644 --- a/odoo/netsvc.py +++ b/odoo/netsvc.py @@ -125,9 +125,14 @@ def init_logger(): return record logging.setLogRecordFactory(record_factory) - logging.addLevelName(25, "INFO") + logging.RUNBOT = 25 + logging.addLevelName(logging.RUNBOT, "INFO") # displayed as info in log logging.captureWarnings(True) + def runbot(self, message, *args, **kws): + self.log(logging.RUNBOT, message, *args, **kws) + logging.Logger.runbot = runbot + # enable deprecation warnings (disabled by default) warnings.filterwarnings('once', category=DeprecationWarning) # ignore deprecation warnings from invalid escape (there's a ton and it's @@ -228,6 +233,7 @@ PSEUDOCONFIG_MAPPER = { 'debug': ['odoo:DEBUG', 'odoo.sql_db:INFO'], 'debug_sql': ['odoo.sql_db:DEBUG'], 'info': [], + 'runbot': ['odoo:RUNBOT', 'werkzeug:WARNING'], 'warn': ['odoo:WARNING', 'werkzeug:WARNING'], 'error': ['odoo:ERROR', 'werkzeug:ERROR'], 'critical': ['odoo:CRITICAL', 'werkzeug:CRITICAL'], diff --git a/odoo/tests/common.py b/odoo/tests/common.py index a86f0cc8bcf..15bc0ce1cec 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -964,7 +964,7 @@ class ChromeBrowser(): full_path = os.path.join(self.screenshots_dir, fname) with open(full_path, 'wb') as f: f.write(decoded) - self._logger.log(25, 'Screenshot in: %s', full_path) + self._logger.runbot('Screenshot in: %s', full_path) def _save_screencast(self, prefix='failed'): # could be encododed with something like that @@ -993,11 +993,11 @@ class ChromeBrowser(): if ffmpeg_path: framerate = int(len(self.screencast_frames) / (self.screencast_frames[-1].get('timestamp') - self.screencast_frames[0].get('timestamp'))) r = subprocess.run([ffmpeg_path, '-framerate', str(framerate), '-i', '%s/frame_%%05d.png' % self.screencasts_dir, outfile]) - self._logger.log(25, 'Screencast in: %s', outfile) + self._logger.runbot('Screencast in: %s', outfile) else: outfile = outfile.strip('.mp4') shutil.move(self.screencasts_frames_dir, outfile) - self._logger.log(25, 'Screencast frames in: %s', outfile) + self._logger.runbot('Screencast frames in: %s', outfile) def start_screencast(self): if self.screencasts_dir: diff --git a/odoo/tools/config.py b/odoo/tools/config.py index 0ac8c40e31b..efcd71ccf57 100644 --- a/odoo/tools/config.py +++ b/odoo/tools/config.py @@ -198,7 +198,7 @@ class configmanager(object): # For backward-compatibility, map the old log levels to something # quite close. levels = [ - 'info', 'debug_rpc', 'warn', 'test', 'critical', + 'info', 'debug_rpc', 'warn', 'test', 'critical', 'runbot', 'debug_sql', 'error', 'debug', 'debug_rpc_answer', 'notset' ] group.add_option('--log-level', dest='log_level', type='choice',