From 58da816c873382c32230aa3203dce1a1cd522805 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ga=C3=ABtan=20Trellu?= Date: Fri, 7 Aug 2026 21:10:18 -0400 Subject: [PATCH 1/3] perf: skip disabled debug call-site resolution --- ovos_utils/log.py | 27 ++++++++++++++++++++++++--- test/unittests/test_log.py | 32 +++++++++++++++++++++++++++++++- 2 files changed, 55 insertions(+), 4 deletions(-) diff --git a/ovos_utils/log.py b/ovos_utils/log.py index df389929..e49ff3fd 100644 --- a/ovos_utils/log.py +++ b/ovos_utils/log.py @@ -131,8 +131,25 @@ def create_logger(cls, name, tostdout=True): @classmethod def set_level(cls, level): cls.level = level - for l in cls._loggers: - cls._loggers[l].setLevel(level) + for logger_name in cls._loggers: + cls._loggers[logger_name].setLevel(level) + + @classmethod + def is_enabled_for(cls, level: int) -> bool: + """Return whether a record at ``level`` would be emitted. + + ``LOG.level`` accepts the same integer and named levels as the stdlib + logger. Unknown names deliberately fall through as enabled so the + existing logger configuration path still raises its normal error. + """ + configured = cls.level + if isinstance(configured, int): + threshold = configured + else: + threshold = logging.getLevelName(str(configured).upper()) + if not isinstance(threshold, int): + return True + return level >= threshold @classmethod def _get_real_logger(cls): @@ -174,6 +191,11 @@ def info(cls, *args, **kwargs): @classmethod def debug(cls, *args, **kwargs): + # Resolving the call-site logger uses inspect.stack(), which is much + # more expensive than the disabled DEBUG record itself. Match stdlib + # logging's cheap level gate before doing that work. + if not cls.is_enabled_for(logging.DEBUG): + return cls._get_real_logger().debug(*args, **kwargs) @classmethod @@ -358,7 +380,6 @@ def get_log_path(service: str, directories: Optional[List[str]] = None) \ from ovos_utils.xdg_utils import xdg_state_home try: - from ovos_config import Configuration from ovos_config.meta import get_xdg_base except ImportError: xdg_base = os.environ.get("OVOS_CONFIG_BASE_FOLDER", "mycroft") diff --git a/test/unittests/test_log.py b/test/unittests/test_log.py index 15419dc9..b7d1ee59 100644 --- a/test/unittests/test_log.py +++ b/test/unittests/test_log.py @@ -2,6 +2,7 @@ import shutil import unittest import importlib +import logging from os.path import join, dirname, isdir, isfile from unittest.mock import patch, Mock @@ -106,6 +107,35 @@ def test_log(self): self.assertEqual(len(lines), 1) self.assertTrue(lines[0].endswith("99\n")) + def test_disabled_debug_skips_call_site_resolution(self): + from ovos_utils.log import LOG + + with patch.object(LOG, "level", "INFO"), \ + patch.object(LOG, "_get_real_logger") as get_logger: + LOG.debug("not emitted") + get_logger.assert_not_called() + + def test_enabled_debug_keeps_existing_logger_path(self): + from ovos_utils.log import LOG + + logger = Mock() + with patch.object(LOG, "level", logging.DEBUG), \ + patch.object(LOG, "_get_real_logger", return_value=logger): + LOG.debug("emitted: %s", "value") + logger.debug.assert_called_once_with("emitted: %s", "value") + + def test_is_enabled_for_accepts_named_and_numeric_levels(self): + from ovos_utils.log import LOG + + with patch.object(LOG, "level", "DEBUG"): + self.assertTrue(LOG.is_enabled_for(logging.DEBUG)) + with patch.object(LOG, "level", "INFO"): + self.assertFalse(LOG.is_enabled_for(logging.DEBUG)) + self.assertTrue(LOG.is_enabled_for(logging.WARNING)) + with patch.object(LOG, "level", logging.ERROR): + self.assertFalse(LOG.is_enabled_for(logging.WARNING)) + self.assertTrue(LOG.is_enabled_for(logging.ERROR)) + @patch("ovos_utils.log.get_logs_config") @patch("ovos_config.Configuration.set_config_watcher") def test_init_service_logger(self, set_config_watcher, log_config): @@ -166,7 +196,7 @@ def test_deprecated_decorator(self, create_logger): self.assertIn('test_log', log_msg, log_msg) self.assertIn('imported deprecation', log_msg, log_msg) - test_class = Deprecated() + Deprecated() log_msg = log_warning.call_args[0][0] self.assertIn('version=0.2.0', log_msg, log_msg) self.assertIn('Class Deprecated', log_msg, log_msg) From 9fb6be2a413a2cec5702ad0ae62c03b5a5dcffc9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ga=C3=ABtan=20Trellu?= Date: Fri, 7 Aug 2026 21:38:23 -0400 Subject: [PATCH 2/3] fix: mirror stdlib logging suppression --- ovos_utils/log.py | 4 ++++ test/unittests/test_log.py | 20 ++++++++++++++++++++ 2 files changed, 24 insertions(+) diff --git a/ovos_utils/log.py b/ovos_utils/log.py index e49ff3fd..482299ed 100644 --- a/ovos_utils/log.py +++ b/ovos_utils/log.py @@ -142,6 +142,8 @@ def is_enabled_for(cls, level: int) -> bool: logger. Unknown names deliberately fall through as enabled so the existing logger configuration path still raises its normal error. """ + if logging.root.manager.disable >= level: + return False configured = cls.level if isinstance(configured, int): threshold = configured @@ -149,6 +151,8 @@ def is_enabled_for(cls, level: int) -> bool: threshold = logging.getLevelName(str(configured).upper()) if not isinstance(threshold, int): return True + if threshold == logging.NOTSET: + threshold = logging.root.getEffectiveLevel() return level >= threshold @classmethod diff --git a/test/unittests/test_log.py b/test/unittests/test_log.py index b7d1ee59..9030a449 100644 --- a/test/unittests/test_log.py +++ b/test/unittests/test_log.py @@ -136,6 +136,26 @@ def test_is_enabled_for_accepts_named_and_numeric_levels(self): self.assertFalse(LOG.is_enabled_for(logging.WARNING)) self.assertTrue(LOG.is_enabled_for(logging.ERROR)) + def test_is_enabled_for_honors_global_disable(self): + from ovos_utils.log import LOG + + original_disable = logging.root.manager.disable + try: + logging.disable(logging.CRITICAL) + with patch.object(LOG, "level", "DEBUG"): + self.assertFalse(LOG.is_enabled_for(logging.DEBUG)) + finally: + logging.disable(original_disable) + + def test_is_enabled_for_uses_effective_root_level_for_notset(self): + from ovos_utils.log import LOG + + with patch.object(LOG, "level", logging.NOTSET), \ + patch.object(logging.root, "getEffectiveLevel", + return_value=logging.INFO): + self.assertFalse(LOG.is_enabled_for(logging.DEBUG)) + self.assertTrue(LOG.is_enabled_for(logging.WARNING)) + @patch("ovos_utils.log.get_logs_config") @patch("ovos_config.Configuration.set_config_watcher") def test_init_service_logger(self, set_config_watcher, log_config): From 4b67071b391b8e1a09d33f6beecbacdbac898c90 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ga=C3=ABtan=20Trellu?= Date: Sun, 9 Aug 2026 18:05:14 -0400 Subject: [PATCH 3/3] perf: gate all disabled log levels --- ovos_utils/log.py | 11 ++++++--- test/unittests/test_log.py | 47 +++++++++++++++++++++++++++----------- 2 files changed, 42 insertions(+), 16 deletions(-) diff --git a/ovos_utils/log.py b/ovos_utils/log.py index 482299ed..0fd55a5d 100644 --- a/ovos_utils/log.py +++ b/ovos_utils/log.py @@ -191,27 +191,32 @@ def _get_real_logger(cls): @classmethod def info(cls, *args, **kwargs): + if not cls.is_enabled_for(logging.INFO): + return cls._get_real_logger().info(*args, **kwargs) @classmethod def debug(cls, *args, **kwargs): - # Resolving the call-site logger uses inspect.stack(), which is much - # more expensive than the disabled DEBUG record itself. Match stdlib - # logging's cheap level gate before doing that work. if not cls.is_enabled_for(logging.DEBUG): return cls._get_real_logger().debug(*args, **kwargs) @classmethod def warning(cls, *args, **kwargs): + if not cls.is_enabled_for(logging.WARNING): + return cls._get_real_logger().warning(*args, **kwargs) @classmethod def error(cls, *args, **kwargs): + if not cls.is_enabled_for(logging.ERROR): + return cls._get_real_logger().error(*args, **kwargs) @classmethod def exception(cls, *args, **kwargs): + if not cls.is_enabled_for(logging.ERROR): + return cls._get_real_logger().exception(*args, **kwargs) diff --git a/test/unittests/test_log.py b/test/unittests/test_log.py index 9030a449..14e22682 100644 --- a/test/unittests/test_log.py +++ b/test/unittests/test_log.py @@ -55,8 +55,9 @@ def test_log(self): log_file = join(LOG.base_path, f"{LOG.name}.log") self.assertFalse(isfile(log_file)) LOG.info("This won't print") - self.assertTrue(isfile(log_file)) + self.assertFalse(isfile(log_file)) LOG.warning("This will print") + self.assertTrue(isfile(log_file)) with open(log_file) as f: lines = f.readlines() self.assertEqual(len(lines), 1) @@ -107,22 +108,42 @@ def test_log(self): self.assertEqual(len(lines), 1) self.assertTrue(lines[0].endswith("99\n")) - def test_disabled_debug_skips_call_site_resolution(self): + def test_disabled_levels_skip_call_site_resolution(self): from ovos_utils.log import LOG - with patch.object(LOG, "level", "INFO"), \ - patch.object(LOG, "_get_real_logger") as get_logger: - LOG.debug("not emitted") - get_logger.assert_not_called() - - def test_enabled_debug_keeps_existing_logger_path(self): + cases = [ + ("debug", logging.DEBUG, logging.INFO), + ("info", logging.INFO, logging.WARNING), + ("warning", logging.WARNING, logging.ERROR), + ("error", logging.ERROR, logging.CRITICAL), + ("exception", logging.ERROR, logging.CRITICAL), + ] + for method_name, _record_level, configured_level in cases: + with self.subTest(method=method_name), \ + patch.object(LOG, "level", configured_level), \ + patch.object(LOG, "_get_real_logger") as get_logger: + getattr(LOG, method_name)("not emitted") + get_logger.assert_not_called() + + def test_enabled_levels_keep_existing_logger_path(self): from ovos_utils.log import LOG - logger = Mock() - with patch.object(LOG, "level", logging.DEBUG), \ - patch.object(LOG, "_get_real_logger", return_value=logger): - LOG.debug("emitted: %s", "value") - logger.debug.assert_called_once_with("emitted: %s", "value") + cases = [ + ("debug", logging.DEBUG), + ("info", logging.INFO), + ("warning", logging.WARNING), + ("error", logging.ERROR), + ("exception", logging.ERROR), + ] + for method_name, configured_level in cases: + logger = Mock() + with self.subTest(method=method_name), \ + patch.object(LOG, "level", configured_level), \ + patch.object(LOG, "_get_real_logger", + return_value=logger): + getattr(LOG, method_name)("emitted: %s", "value") + getattr(logger, method_name).assert_called_once_with( + "emitted: %s", "value") def test_is_enabled_for_accepts_named_and_numeric_levels(self): from ovos_utils.log import LOG