From 001ee0cc0bd13d37caaa2bf7c3bcfbd827627d04 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Mon, 1 Jul 2024 09:26:20 -0700 Subject: [PATCH] Downgrade logging previously reported asyncio block to debug (#120942) --- homeassistant/util/loop.py | 123 +++++++++++----- tests/util/test_loop.py | 282 +++++++++++++++++++++---------------- 2 files changed, 244 insertions(+), 161 deletions(-) diff --git a/homeassistant/util/loop.py b/homeassistant/util/loop.py index 866f35e79e2..d7593013046 100644 --- a/homeassistant/util/loop.py +++ b/homeassistant/util/loop.py @@ -4,6 +4,7 @@ from __future__ import annotations from collections.abc import Callable import functools +from functools import cache import linecache import logging import threading @@ -26,6 +27,11 @@ def _get_line_from_cache(filename: str, lineno: int) -> str: return (linecache.getline(filename, lineno) or "?").strip() +# Set of previously reported blocking calls +# (integration, filename, lineno) +_PREVIOUSLY_REPORTED: set[tuple[str | None, str, int | Any]] = set() + + def raise_for_blocking_call( func: Callable[..., Any], check_allowed: Callable[[dict[str, Any]], bool] | None = None, @@ -42,28 +48,48 @@ def raise_for_blocking_call( offender_filename = offender_frame.f_code.co_filename offender_lineno = offender_frame.f_lineno offender_line = _get_line_from_cache(offender_filename, offender_lineno) + report_key: tuple[str | None, str, int | Any] try: integration_frame = get_integration_frame() except MissingIntegrationFrame: # Did not source from integration? Hard error. + report_key = (None, offender_filename, offender_lineno) + was_reported = report_key in _PREVIOUSLY_REPORTED + _PREVIOUSLY_REPORTED.add(report_key) if not strict_core: - _LOGGER.warning( - "Detected blocking call to %s with args %s in %s, " - "line %s: %s inside the event loop; " - "This is causing stability issues. " - "Please create a bug report at " - "https://github.com/home-assistant/core/issues?q=is%%3Aopen+is%%3Aissue\n" - "%s\n" - "Traceback (most recent call last):\n%s", - func.__name__, - mapped_args.get("args"), - offender_filename, - offender_lineno, - offender_line, - _dev_help_message(func.__name__), - "".join(traceback.format_stack(f=offender_frame)), - ) + if was_reported: + _LOGGER.debug( + "Detected blocking call to %s with args %s in %s, " + "line %s: %s inside the event loop; " + "This is causing stability issues. " + "Please create a bug report at " + "https://github.com/home-assistant/core/issues?q=is%%3Aopen+is%%3Aissue\n" + "%s\n", + func.__name__, + mapped_args.get("args"), + offender_filename, + offender_lineno, + offender_line, + _dev_help_message(func.__name__), + ) + else: + _LOGGER.warning( + "Detected blocking call to %s with args %s in %s, " + "line %s: %s inside the event loop; " + "This is causing stability issues. " + "Please create a bug report at " + "https://github.com/home-assistant/core/issues?q=is%%3Aopen+is%%3Aissue\n" + "%s\n" + "Traceback (most recent call last):\n%s", + func.__name__, + mapped_args.get("args"), + offender_filename, + offender_lineno, + offender_line, + _dev_help_message(func.__name__), + "".join(traceback.format_stack(f=offender_frame)), + ) return if found_frame is None: @@ -77,32 +103,56 @@ def raise_for_blocking_call( f"{_dev_help_message(func.__name__)}" ) + report_key = (integration_frame.integration, offender_filename, offender_lineno) + was_reported = report_key in _PREVIOUSLY_REPORTED + _PREVIOUSLY_REPORTED.add(report_key) + report_issue = async_suggest_report_issue( async_get_hass_or_none(), integration_domain=integration_frame.integration, module=integration_frame.module, ) - _LOGGER.warning( - "Detected blocking call to %s with args %s " - "inside the event loop by %sintegration '%s' " - "at %s, line %s: %s (offender: %s, line %s: %s), please %s\n" - "%s\n" - "Traceback (most recent call last):\n%s", - func.__name__, - mapped_args.get("args"), - "custom " if integration_frame.custom_integration else "", - integration_frame.integration, - integration_frame.relative_filename, - integration_frame.line_number, - integration_frame.line, - offender_filename, - offender_lineno, - offender_line, - report_issue, - _dev_help_message(func.__name__), - "".join(traceback.format_stack(f=integration_frame.frame)), - ) + if was_reported: + _LOGGER.debug( + "Detected blocking call to %s with args %s " + "inside the event loop by %sintegration '%s' " + "at %s, line %s: %s (offender: %s, line %s: %s), please %s\n" + "%s\n", + func.__name__, + mapped_args.get("args"), + "custom " if integration_frame.custom_integration else "", + integration_frame.integration, + integration_frame.relative_filename, + integration_frame.line_number, + integration_frame.line, + offender_filename, + offender_lineno, + offender_line, + report_issue, + _dev_help_message(func.__name__), + ) + else: + _LOGGER.warning( + "Detected blocking call to %s with args %s " + "inside the event loop by %sintegration '%s' " + "at %s, line %s: %s (offender: %s, line %s: %s), please %s\n" + "%s\n" + "Traceback (most recent call last):\n%s", + func.__name__, + mapped_args.get("args"), + "custom " if integration_frame.custom_integration else "", + integration_frame.integration, + integration_frame.relative_filename, + integration_frame.line_number, + integration_frame.line, + offender_filename, + offender_lineno, + offender_line, + report_issue, + _dev_help_message(func.__name__), + "".join(traceback.format_stack(f=integration_frame.frame)), + ) if strict: raise RuntimeError( @@ -117,6 +167,7 @@ def raise_for_blocking_call( ) +@cache def _dev_help_message(what: str) -> str: """Generate help message to guide developers.""" return ( diff --git a/tests/util/test_loop.py b/tests/util/test_loop.py index 585f32a965f..f4846d98898 100644 --- a/tests/util/test_loop.py +++ b/tests/util/test_loop.py @@ -1,5 +1,7 @@ """Tests for async util methods from Python source.""" +from collections.abc import Generator +import contextlib import threading from unittest.mock import Mock, patch @@ -15,57 +17,14 @@ def banned_function(): """Mock banned function.""" -async def test_raise_for_blocking_call_async() -> None: - """Test raise_for_blocking_call detects when called from event loop without integration context.""" - with pytest.raises(RuntimeError): - haloop.raise_for_blocking_call(banned_function) - - -async def test_raise_for_blocking_call_async_non_strict_core( - caplog: pytest.LogCaptureFixture, -) -> None: - """Test non_strict_core raise_for_blocking_call detects from event loop without integration context.""" - haloop.raise_for_blocking_call(banned_function, strict_core=False) - assert "Detected blocking call to banned_function" in caplog.text - assert "Traceback (most recent call last)" in caplog.text - assert ( - "Please create a bug report at https://github.com/home-assistant/core/issues" - in caplog.text - ) - assert ( - "For developers, please see " - "https://developers.home-assistant.io/docs/asyncio_blocking_operations/#banned_function" - ) in caplog.text - - -async def test_raise_for_blocking_call_async_integration( - caplog: pytest.LogCaptureFixture, -) -> None: - """Test raise_for_blocking_call detects and raises when called from event loop from integration context.""" - frames = extract_stack_to_frame( - [ - Mock( - filename="/home/paulus/homeassistant/core.py", - lineno="23", - line="do_something()", - ), - Mock( - filename="/home/paulus/homeassistant/components/hue/light.py", - lineno="23", - line="self.light.is_on", - ), - Mock( - filename="/home/paulus/aiohue/lights.py", - lineno="2", - line="something()", - ), - ] - ) +@contextlib.contextmanager +def patch_get_current_frame(stack: list[Mock]) -> Generator[None, None, None]: + """Patch get_current_frame.""" + frames = extract_stack_to_frame(stack) with ( - pytest.raises(RuntimeError), patch( "homeassistant.helpers.frame.linecache.getline", - return_value="self.light.is_on", + return_value=stack[1].line, ), patch( "homeassistant.util.loop._get_line_from_cache", @@ -79,13 +38,104 @@ async def test_raise_for_blocking_call_async_integration( "homeassistant.helpers.frame.get_current_frame", return_value=frames, ), + ): + yield + + +async def test_raise_for_blocking_call_async() -> None: + """Test raise_for_blocking_call detects when called from event loop without integration context.""" + with pytest.raises(RuntimeError): + haloop.raise_for_blocking_call(banned_function) + + +async def test_raise_for_blocking_call_async_non_strict_core( + caplog: pytest.LogCaptureFixture, +) -> None: + """Test non_strict_core raise_for_blocking_call detects from event loop without integration context.""" + stack = [ + Mock( + filename="/home/paulus/homeassistant/core.py", + lineno="12", + line="do_something()", + ), + Mock( + filename="/home/paulus/homeassistant/core.py", + lineno="12", + line="self.light.is_on", + ), + Mock( + filename="/home/paulus/aiohue/lights.py", + lineno="2", + line="something()", + ), + ] + with patch_get_current_frame(stack): + haloop.raise_for_blocking_call(banned_function, strict_core=False) + assert "Detected blocking call to banned_function" in caplog.text + assert "Traceback (most recent call last)" in caplog.text + assert ( + "Please create a bug report at https://github.com/home-assistant/core/issues" + in caplog.text + ) + assert ( + "For developers, please see " + "https://developers.home-assistant.io/docs/asyncio_blocking_operations/#banned_function" + ) in caplog.text + + warnings = [ + record for record in caplog.get_records("call") if record.levelname == "WARNING" + ] + assert len(warnings) == 1 + caplog.clear() + + # Second call should log at debug + with patch_get_current_frame(stack): + haloop.raise_for_blocking_call(banned_function, strict_core=False) + + warnings = [ + record for record in caplog.get_records("call") if record.levelname == "WARNING" + ] + assert len(warnings) == 0 + assert ( + "For developers, please see " + "https://developers.home-assistant.io/docs/asyncio_blocking_operations/#banned_function" + ) in caplog.text + + # no expensive traceback on debug + assert "Traceback (most recent call last)" not in caplog.text + + +async def test_raise_for_blocking_call_async_integration( + caplog: pytest.LogCaptureFixture, +) -> None: + """Test raise_for_blocking_call detects and raises when called from event loop from integration context.""" + stack = [ + Mock( + filename="/home/paulus/homeassistant/core.py", + lineno="18", + line="do_something()", + ), + Mock( + filename="/home/paulus/homeassistant/components/hue/light.py", + lineno="18", + line="self.light.is_on", + ), + Mock( + filename="/home/paulus/aiohue/lights.py", + lineno="8", + line="something()", + ), + ] + with ( + pytest.raises(RuntimeError), + patch_get_current_frame(stack), ): haloop.raise_for_blocking_call(banned_function) assert ( "Detected blocking call to banned_function with args None" " inside the event loop by integration" - " 'hue' at homeassistant/components/hue/light.py, line 23: self.light.is_on " - "(offender: /home/paulus/aiohue/lights.py, line 2: mock_line), please create " + " 'hue' at homeassistant/components/hue/light.py, line 18: self.light.is_on " + "(offender: /home/paulus/aiohue/lights.py, line 8: mock_line), please create " "a bug report at https://github.com/home-assistant/core/issues?" "q=is%3Aopen+is%3Aissue+label%3A%22integration%3A+hue%22" in caplog.text ) @@ -99,55 +149,37 @@ async def test_raise_for_blocking_call_async_integration_non_strict( caplog: pytest.LogCaptureFixture, ) -> None: """Test raise_for_blocking_call detects when called from event loop from integration context.""" - frames = extract_stack_to_frame( - [ - Mock( - filename="/home/paulus/homeassistant/core.py", - lineno="23", - line="do_something()", - ), - Mock( - filename="/home/paulus/homeassistant/components/hue/light.py", - lineno="23", - line="self.light.is_on", - ), - Mock( - filename="/home/paulus/aiohue/lights.py", - lineno="2", - line="something()", - ), - ] - ) - with ( - patch( - "homeassistant.helpers.frame.linecache.getline", - return_value="self.light.is_on", + stack = [ + Mock( + filename="/home/paulus/homeassistant/core.py", + lineno="15", + line="do_something()", ), - patch( - "homeassistant.util.loop._get_line_from_cache", - return_value="mock_line", + Mock( + filename="/home/paulus/homeassistant/components/hue/light.py", + lineno="15", + line="self.light.is_on", ), - patch( - "homeassistant.util.loop.get_current_frame", - return_value=frames, + Mock( + filename="/home/paulus/aiohue/lights.py", + lineno="1", + line="something()", ), - patch( - "homeassistant.helpers.frame.get_current_frame", - return_value=frames, - ), - ): + ] + with patch_get_current_frame(stack): haloop.raise_for_blocking_call(banned_function, strict=False) + assert ( "Detected blocking call to banned_function with args None" " inside the event loop by integration" - " 'hue' at homeassistant/components/hue/light.py, line 23: self.light.is_on " - "(offender: /home/paulus/aiohue/lights.py, line 2: mock_line), " + " 'hue' at homeassistant/components/hue/light.py, line 15: self.light.is_on " + "(offender: /home/paulus/aiohue/lights.py, line 1: mock_line), " "please create a bug report at https://github.com/home-assistant/core/issues?" "q=is%3Aopen+is%3Aissue+label%3A%22integration%3A+hue%22" in caplog.text ) assert "Traceback (most recent call last)" in caplog.text assert ( - 'File "/home/paulus/homeassistant/components/hue/light.py", line 23' + 'File "/home/paulus/homeassistant/components/hue/light.py", line 15' in caplog.text ) assert ( @@ -158,62 +190,62 @@ async def test_raise_for_blocking_call_async_integration_non_strict( "For developers, please see " "https://developers.home-assistant.io/docs/asyncio_blocking_operations/#banned_function" ) in caplog.text + warnings = [ + record for record in caplog.get_records("call") if record.levelname == "WARNING" + ] + assert len(warnings) == 1 + caplog.clear() + + # Second call should log at debug + with patch_get_current_frame(stack): + haloop.raise_for_blocking_call(banned_function, strict=False) + + warnings = [ + record for record in caplog.get_records("call") if record.levelname == "WARNING" + ] + assert len(warnings) == 0 + assert ( + "For developers, please see " + "https://developers.home-assistant.io/docs/asyncio_blocking_operations/#banned_function" + ) in caplog.text + # no expensive traceback on debug + assert "Traceback (most recent call last)" not in caplog.text async def test_raise_for_blocking_call_async_custom( caplog: pytest.LogCaptureFixture, ) -> None: """Test raise_for_blocking_call detects when called from event loop with custom component context.""" - frames = extract_stack_to_frame( - [ - Mock( - filename="/home/paulus/homeassistant/core.py", - lineno="23", - line="do_something()", - ), - Mock( - filename="/home/paulus/config/custom_components/hue/light.py", - lineno="23", - line="self.light.is_on", - ), - Mock( - filename="/home/paulus/aiohue/lights.py", - lineno="2", - line="something()", - ), - ] - ) - with ( - pytest.raises(RuntimeError), - patch( - "homeassistant.helpers.frame.linecache.getline", - return_value="self.light.is_on", + stack = [ + Mock( + filename="/home/paulus/homeassistant/core.py", + lineno="12", + line="do_something()", ), - patch( - "homeassistant.util.loop._get_line_from_cache", - return_value="mock_line", + Mock( + filename="/home/paulus/config/custom_components/hue/light.py", + lineno="12", + line="self.light.is_on", ), - patch( - "homeassistant.util.loop.get_current_frame", - return_value=frames, + Mock( + filename="/home/paulus/aiohue/lights.py", + lineno="3", + line="something()", ), - patch( - "homeassistant.helpers.frame.get_current_frame", - return_value=frames, - ), - ): + ] + with pytest.raises(RuntimeError), patch_get_current_frame(stack): haloop.raise_for_blocking_call(banned_function) assert ( "Detected blocking call to banned_function with args None" " inside the event loop by custom " - "integration 'hue' at custom_components/hue/light.py, line 23: self.light.is_on" - " (offender: /home/paulus/aiohue/lights.py, line 2: mock_line), " + "integration 'hue' at custom_components/hue/light.py, line 12: self.light.is_on" + " (offender: /home/paulus/aiohue/lights.py, line 3: mock_line), " "please create a bug report at https://github.com/home-assistant/core/issues?" "q=is%3Aopen+is%3Aissue+label%3A%22integration%3A+hue%22" ) in caplog.text assert "Traceback (most recent call last)" in caplog.text assert ( - 'File "/home/paulus/config/custom_components/hue/light.py", line 23' + 'File "/home/paulus/config/custom_components/hue/light.py", line 12' in caplog.text ) assert (