From 6421a08ba852cc38d77b923bb93bbbb1a26bfa71 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sat, 2 Mar 2024 16:50:35 -1000 Subject: [PATCH] Avoid expensive inspect calls in config validators (#112085) * Avoid expensive inspect calls in config validators inspect has a performance problem https://github.com/python/cpython/issues/92041 We now avoid calling inspect unless we are going to log * remove unused * reduce * get_integration_logger --- homeassistant/helpers/config_validation.py | 49 +++++-------------- homeassistant/helpers/frame.py | 20 ++++++++ tests/helpers/test_config_validation.py | 41 ++++++++-------- tests/helpers/test_frame.py | 43 ++++++++++++++++ .../test_integration_frame/__init__.py | 7 +++ 5 files changed, 101 insertions(+), 59 deletions(-) diff --git a/homeassistant/helpers/config_validation.py b/homeassistant/helpers/config_validation.py index b9ff5704246..59e4f09d26f 100644 --- a/homeassistant/helpers/config_validation.py +++ b/homeassistant/helpers/config_validation.py @@ -10,7 +10,6 @@ from datetime import ( timedelta, ) from enum import Enum, StrEnum -import inspect import logging from numbers import Number import os @@ -103,6 +102,7 @@ import homeassistant.util.dt as dt_util from homeassistant.util.yaml.objects import NodeStrClass from . import script_variables as script_variables_helper, template as template_helper +from .frame import get_integration_logger TIME_PERIOD_ERROR = "offset {} should be format 'HH:MM', 'HH:MM:SS' or 'HH:MM:SS.F'" @@ -890,24 +890,17 @@ def _deprecated_or_removed( - No warning if neither key nor replacement_key are provided - Adds replacement_key with default value in this case """ - module = inspect.getmodule(inspect.stack(context=0)[2].frame) - if module is not None: - module_name = module.__name__ - else: - # If Python is unable to access the sources files, the call stack frame - # will be missing information, so let's guard. - # https://github.com/home-assistant/core/issues/24982 - module_name = __name__ - if option_removed: - logger_func = logging.getLogger(module_name).error - option_status = "has been removed" - else: - logger_func = logging.getLogger(module_name).warning - option_status = "is deprecated" def validator(config: dict) -> dict: """Check if key is in config and log warning or error.""" if key in config: + if option_removed: + level = logging.ERROR + option_status = "has been removed" + else: + level = logging.WARNING + option_status = "is deprecated" + try: near = ( f"near {config.__config_file__}" # type: ignore[attr-defined] @@ -928,7 +921,7 @@ def _deprecated_or_removed( if raise_if_present: raise vol.Invalid(warning % arguments) - logger_func(warning, *arguments) + get_integration_logger(__name__).log(level, warning, *arguments) value = config[key] if replacement_key or option_removed: config.pop(key) @@ -1112,19 +1105,9 @@ def expand_condition_shorthand(value: Any | None) -> Any: def empty_config_schema(domain: str) -> Callable[[dict], dict]: """Return a config schema which logs if there are configuration parameters.""" - module = inspect.getmodule(inspect.stack(context=0)[2].frame) - if module is not None: - module_name = module.__name__ - else: - # If Python is unable to access the sources files, the call stack frame - # will be missing information, so let's guard. - # https://github.com/home-assistant/core/issues/24982 - module_name = __name__ - logger_func = logging.getLogger(module_name).error - def validator(config: dict) -> dict: if domain in config and config[domain]: - logger_func( + get_integration_logger(__name__).error( ( "The %s integration does not support any configuration parameters, " "got %s. Please remove the configuration parameters from your " @@ -1146,16 +1129,6 @@ def _no_yaml_config_schema( ) -> Callable[[dict], dict]: """Return a config schema which logs if attempted to setup from YAML.""" - module = inspect.getmodule(inspect.stack(context=0)[2].frame) - if module is not None: - module_name = module.__name__ - else: - # If Python is unable to access the sources files, the call stack frame - # will be missing information, so let's guard. - # https://github.com/home-assistant/core/issues/24982 - module_name = __name__ - logger_func = logging.getLogger(module_name).error - def raise_issue() -> None: # pylint: disable-next=import-outside-toplevel from .issue_registry import IssueSeverity, async_create_issue @@ -1176,7 +1149,7 @@ def _no_yaml_config_schema( def validator(config: dict) -> dict: if domain in config: - logger_func( + get_integration_logger(__name__).error( ( "The %s integration does not support YAML setup, please remove it " "from your configuration file" diff --git a/homeassistant/helpers/frame.py b/homeassistant/helpers/frame.py index 9c17e17a2c6..04f16ebddd0 100644 --- a/homeassistant/helpers/frame.py +++ b/homeassistant/helpers/frame.py @@ -34,6 +34,26 @@ class IntegrationFrame: relative_filename: str +def get_integration_logger(fallback_name: str) -> logging.Logger: + """Return a logger by checking the current integration frame. + + If Python is unable to access the sources files, the call stack frame + will be missing information, so let's guard by requiring a fallback name. + https://github.com/home-assistant/core/issues/24982 + """ + try: + integration_frame = get_integration_frame() + except MissingIntegrationFrame: + return logging.getLogger(fallback_name) + + if integration_frame.custom_integration: + logger_name = f"custom_components.{integration_frame.integration}" + else: + logger_name = f"homeassistant.components.{integration_frame.integration}" + + return logging.getLogger(logger_name) + + def get_integration_frame(exclude_integrations: set | None = None) -> IntegrationFrame: """Return the frame, integration and integration path of the current stack frame.""" found_frame = None diff --git a/tests/helpers/test_config_validation.py b/tests/helpers/test_config_validation.py index c16d7b1ec51..060800be62d 100644 --- a/tests/helpers/test_config_validation.py +++ b/tests/helpers/test_config_validation.py @@ -2,6 +2,7 @@ from collections import OrderedDict from datetime import date, datetime, timedelta import enum +import logging import os from socket import _GLOBAL_DEFAULT_TIMEOUT from unittest.mock import Mock, patch @@ -986,7 +987,11 @@ def test_deprecated_with_default(caplog: pytest.LogCaptureFixture, schema) -> No deprecated_schema = vol.All(cv.deprecated("mars", default=False), schema) test_data = {"mars": True} - output = deprecated_schema(test_data.copy()) + with patch( + "homeassistant.helpers.config_validation.get_integration_logger", + return_value=logging.getLogger(__name__), + ): + output = deprecated_schema(test_data.copy()) assert len(caplog.records) == 1 assert caplog.records[0].name == __name__ assert ( @@ -1062,21 +1067,19 @@ def test_deprecated_with_replacement_key_and_default( def test_deprecated_cant_find_module() -> None: - """Test if the current module cannot be inspected.""" - with patch("inspect.getmodule", return_value=None): - # This used to raise. - cv.deprecated( - "mars", - replacement_key="jupiter", - default=False, - ) + """Test if the current module cannot be found.""" + # This used to raise. + cv.deprecated( + "mars", + replacement_key="jupiter", + default=False, + ) - with patch("inspect.getmodule", return_value=None): - # This used to raise. - cv.removed( - "mars", - default=False, - ) + # This used to raise. + cv.removed( + "mars", + default=False, + ) def test_deprecated_or_removed_logger_with_config_attributes( @@ -1551,8 +1554,7 @@ def test_empty_schema(caplog: pytest.LogCaptureFixture) -> None: def test_empty_schema_cant_find_module() -> None: """Test if the current module cannot be inspected.""" - with patch("inspect.getmodule", return_value=None): - cv.empty_config_schema("test_domain")({"test_domain": {"foo": "bar"}}) + cv.empty_config_schema("test_domain")({"test_domain": {"foo": "bar"}}) def test_config_entry_only_schema( @@ -1582,10 +1584,7 @@ def test_config_entry_only_schema( def test_config_entry_only_schema_cant_find_module() -> None: """Test if the current module cannot be inspected.""" - with patch("inspect.getmodule", return_value=None): - cv.config_entry_only_config_schema("test_domain")( - {"test_domain": {"foo": "bar"}} - ) + cv.config_entry_only_config_schema("test_domain")({"test_domain": {"foo": "bar"}}) def test_config_entry_only_schema_no_hass( diff --git a/tests/helpers/test_frame.py b/tests/helpers/test_frame.py index 5010c459345..fa495e9dbc9 100644 --- a/tests/helpers/test_frame.py +++ b/tests/helpers/test_frame.py @@ -22,6 +22,14 @@ async def test_extract_frame_integration( ) +async def test_get_integration_logger( + caplog: pytest.LogCaptureFixture, mock_integration_frame: Mock +) -> None: + """Test extracting the current frame to get the logger.""" + logger = frame.get_integration_logger(__name__) + assert logger.name == "homeassistant.components.hue" + + async def test_extract_frame_resolve_module( hass: HomeAssistant, enable_custom_integrations ) -> None: @@ -39,6 +47,17 @@ async def test_extract_frame_resolve_module( ) +async def test_get_integration_logger_resolve_module( + hass: HomeAssistant, enable_custom_integrations +) -> None: + """Test getting the logger from integration context.""" + from custom_components.test_integration_frame import call_get_integration_logger + + logger = call_get_integration_logger(__name__) + + assert logger.name == "custom_components.test_integration_frame" + + async def test_extract_frame_integration_with_excluded_integration( caplog: pytest.LogCaptureFixture, ) -> None: @@ -102,6 +121,30 @@ async def test_extract_frame_no_integration(caplog: pytest.LogCaptureFixture) -> frame.get_integration_frame() +async def test_get_integration_logger_no_integration( + caplog: pytest.LogCaptureFixture, +) -> None: + """Test getting fallback logger without integration context.""" + with patch( + "homeassistant.helpers.frame.extract_stack", + return_value=[ + Mock( + filename="/home/paulus/homeassistant/core.py", + lineno="23", + line="do_something()", + ), + Mock( + filename="/home/paulus/aiohue/lights.py", + lineno="2", + line="something()", + ), + ], + ): + logger = frame.get_integration_logger(__name__) + + assert logger.name == __name__ + + @patch.object(frame, "_REPORTED_INTEGRATIONS", set()) async def test_prevent_flooding( hass: HomeAssistant, caplog: pytest.LogCaptureFixture, mock_integration_frame: Mock diff --git a/tests/testing_config/custom_components/test_integration_frame/__init__.py b/tests/testing_config/custom_components/test_integration_frame/__init__.py index d342509d52e..31e894dddcd 100644 --- a/tests/testing_config/custom_components/test_integration_frame/__init__.py +++ b/tests/testing_config/custom_components/test_integration_frame/__init__.py @@ -1,8 +1,15 @@ """An integration which calls helpers.frame.get_integration_frame.""" +import logging + from homeassistant.helpers import frame +def call_get_integration_logger(fallback_name: str) -> logging.Logger: + """Call get_integration_logger.""" + return frame.get_integration_logger(fallback_name) + + def call_get_integration_frame() -> frame.IntegrationFrame: """Call get_integration_frame.""" return frame.get_integration_frame()