Downgrade logging previously reported asyncio block to debug (#120942)

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(
+            if was_reported:
-                "Detected blocking call to %s with args %s in %s, "
+                _LOGGER.debug(
-                "line %s: %s inside the event loop; "
+                    "Detected blocking call to %s with args %s in %s, "
-                "This is causing stability issues. "
+                    "line %s: %s inside the event loop; "
-                "Please create a bug report at "
+                    "This is causing stability issues. "
-                "https://github.com/home-assistant/core/issues?q=is%%3Aopen+is%%3Aissue\n"
+                    "Please create a bug report at "
-                "%s\n"
+                    "https://github.com/home-assistant/core/issues?q=is%%3Aopen+is%%3Aissue\n"
-                "Traceback (most recent call last):\n%s",
+                    "%s\n",
-                func.__name__,
+                    func.__name__,
-                mapped_args.get("args"),
+                    mapped_args.get("args"),
-                offender_filename,
+                    offender_filename,
-                offender_lineno,
+                    offender_lineno,
-                offender_line,
+                    offender_line,
-                _dev_help_message(func.__name__),
+                    _dev_help_message(func.__name__),
-                "".join(traceback.format_stack(f=offender_frame)),
+                )
-            )
+            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(
+    if was_reported:
-        "Detected blocking call to %s with args %s "
+        _LOGGER.debug(
-        "inside the event loop by %sintegration '%s' "
+            "Detected blocking call to %s with args %s "
-        "at %s, line %s: %s (offender: %s, line %s: %s), please %s\n"
+            "inside the event loop by %sintegration '%s' "
-        "%s\n"
+            "at %s, line %s: %s (offender: %s, line %s: %s), please %s\n"
-        "Traceback (most recent call last):\n%s",
+            "%s\n",
-        func.__name__,
+            func.__name__,
-        mapped_args.get("args"),
+            mapped_args.get("args"),
-        "custom " if integration_frame.custom_integration else "",
+            "custom " if integration_frame.custom_integration else "",
-        integration_frame.integration,
+            integration_frame.integration,
-        integration_frame.relative_filename,
+            integration_frame.relative_filename,
-        integration_frame.line_number,
+            integration_frame.line_number,
-        integration_frame.line,
+            integration_frame.line,
-        offender_filename,
+            offender_filename,
-        offender_lineno,
+            offender_lineno,
-        offender_line,
+            offender_line,
-        report_issue,
+            report_issue,
-        _dev_help_message(func.__name__),
+            _dev_help_message(func.__name__),
-        "".join(traceback.format_stack(f=integration_frame.frame)),
+        )
-    )
+    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 (

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:
+@contextlib.contextmanager
-    """Test raise_for_blocking_call detects when called from event loop without integration context."""
+def patch_get_current_frame(stack: list[Mock]) -> Generator[None, None, None]:
-    with pytest.raises(RuntimeError):
+    """Patch get_current_frame."""
-        haloop.raise_for_blocking_call(banned_function)
+    frames = extract_stack_to_frame(stack)
-
-
-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()",
-            ),
-        ]
-    )
     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 "
+        " 'hue' at homeassistant/components/hue/light.py, line 18: self.light.is_on "
-        "(offender: /home/paulus/aiohue/lights.py, line 2: mock_line), please create "
+        "(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(
+    stack = [
-        [
+        Mock(
-            Mock(
+            filename="/home/paulus/homeassistant/core.py",
-                filename="/home/paulus/homeassistant/core.py",
+            lineno="15",
-                lineno="23",
+            line="do_something()",
-                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",
         ),
-        patch(
+        Mock(
-            "homeassistant.util.loop._get_line_from_cache",
+            filename="/home/paulus/homeassistant/components/hue/light.py",
-            return_value="mock_line",
+            lineno="15",
+            line="self.light.is_on",
         ),
-        patch(
+        Mock(
-            "homeassistant.util.loop.get_current_frame",
+            filename="/home/paulus/aiohue/lights.py",
-            return_value=frames,
+            lineno="1",
+            line="something()",
         ),
-        patch(
+    ]
-            "homeassistant.helpers.frame.get_current_frame",
+    with patch_get_current_frame(stack):
-            return_value=frames,
-        ),
-    ):
         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 "
+        " 'hue' at homeassistant/components/hue/light.py, line 15: self.light.is_on "
-        "(offender: /home/paulus/aiohue/lights.py, line 2: mock_line), "
+        "(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(
+    stack = [
-        [
+        Mock(
-            Mock(
+            filename="/home/paulus/homeassistant/core.py",
-                filename="/home/paulus/homeassistant/core.py",
+            lineno="12",
-                lineno="23",
+            line="do_something()",
-                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",
         ),
-        patch(
+        Mock(
-            "homeassistant.util.loop._get_line_from_cache",
+            filename="/home/paulus/config/custom_components/hue/light.py",
-            return_value="mock_line",
+            lineno="12",
+            line="self.light.is_on",
         ),
-        patch(
+        Mock(
-            "homeassistant.util.loop.get_current_frame",
+            filename="/home/paulus/aiohue/lights.py",
-            return_value=frames,
+            lineno="3",
+            line="something()",
         ),
-        patch(
+    ]
-            "homeassistant.helpers.frame.get_current_frame",
+    with pytest.raises(RuntimeError), patch_get_current_frame(stack):
-            return_value=frames,
-        ),
-    ):
         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"
+        "integration 'hue' at custom_components/hue/light.py, line 12: self.light.is_on"
-        " (offender: /home/paulus/aiohue/lights.py, line 2: mock_line), "
+        " (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 (