Adjust blocking I/O messages to provide developer help (#120113)

This commit is contained in:
J. Nick Koston 2024-06-21 12:55:22 -05:00 committed by GitHub
parent 2ad5b1c3a6
commit f7e194b32c
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
3 changed files with 70 additions and 28 deletions

View File

@ -31,14 +31,9 @@ def raise_for_blocking_call(
check_allowed: Callable[[dict[str, Any]], bool] | None = None, check_allowed: Callable[[dict[str, Any]], bool] | None = None,
strict: bool = True, strict: bool = True,
strict_core: bool = True, strict_core: bool = True,
advise_msg: str | None = None,
**mapped_args: Any, **mapped_args: Any,
) -> None: ) -> None:
"""Warn if called inside the event loop. Raise if `strict` is True. """Warn if called inside the event loop. Raise if `strict` is True."""
The default advisory message is 'Use `await hass.async_add_executor_job()'
Set `advise_msg` to an alternate message if the solution differs.
"""
if check_allowed is not None and check_allowed(mapped_args): if check_allowed is not None and check_allowed(mapped_args):
return return
@ -55,24 +50,31 @@ def raise_for_blocking_call(
if not strict_core: if not strict_core:
_LOGGER.warning( _LOGGER.warning(
"Detected blocking call to %s with args %s in %s, " "Detected blocking call to %s with args %s in %s, "
"line %s: %s inside the event loop\n" "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", "Traceback (most recent call last):\n%s",
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__),
"".join(traceback.format_stack(f=offender_frame)), "".join(traceback.format_stack(f=offender_frame)),
) )
return return
if found_frame is None: if found_frame is None:
raise RuntimeError( # noqa: TRY200 raise RuntimeError( # noqa: TRY200
f"Detected blocking call to {func.__name__} inside the event loop " f"Caught blocking call to {func.__name__} with args {mapped_args.get("args")} "
f"in {offender_filename}, line {offender_lineno}: {offender_line}. " f"in {offender_filename}, line {offender_lineno}: {offender_line} "
f"{advise_msg or 'Use `await hass.async_add_executor_job()`'}; " "inside the event loop; "
"This is causing stability issues. Please create a bug report at " "This is causing stability issues. "
f"https://github.com/home-assistant/core/issues?q=is%3Aopen+is%3Aissue" "Please create a bug report at "
"https://github.com/home-assistant/core/issues?q=is%3Aopen+is%3Aissue\n"
f"{_dev_help_message(func.__name__)}"
) )
report_issue = async_suggest_report_issue( report_issue = async_suggest_report_issue(
@ -82,10 +84,13 @@ def raise_for_blocking_call(
) )
_LOGGER.warning( _LOGGER.warning(
"Detected blocking call to %s inside the event loop by %sintegration '%s' " "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" "at %s, line %s: %s (offender: %s, line %s: %s), please %s\n"
"%s\n"
"Traceback (most recent call last):\n%s", "Traceback (most recent call last):\n%s",
func.__name__, func.__name__,
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,
@ -95,19 +100,32 @@ def raise_for_blocking_call(
offender_lineno, offender_lineno,
offender_line, offender_line,
report_issue, report_issue,
_dev_help_message(func.__name__),
"".join(traceback.format_stack(f=integration_frame.frame)), "".join(traceback.format_stack(f=integration_frame.frame)),
) )
if strict: if strict:
raise RuntimeError( raise RuntimeError(
"Blocking calls must be done in the executor or a separate thread;" "Caught blocking call to {func.__name__} with args "
f" {advise_msg or 'Use `await hass.async_add_executor_job()`'}; at" f"{mapped_args.get('args')} inside the event loop by"
f" {integration_frame.relative_filename}, line {integration_frame.line_number}:" f"{'custom ' if integration_frame.custom_integration else ''}"
f" {integration_frame.line} " "integration '{integration_frame.integration}' at "
f"(offender: {offender_filename}, line {offender_lineno}: {offender_line})" f"{integration_frame.relative_filename}, line {integration_frame.line_number}:"
f" {integration_frame.line}. (offender: {offender_filename}, line "
f"{offender_lineno}: {offender_line}), please {report_issue}\n"
f"{_dev_help_message(func.__name__)}"
) )
def _dev_help_message(what: str) -> str:
"""Generate help message to guide developers."""
return (
"For developers, please see "
"https://developers.home-assistant.io/docs/asyncio_blocking_operations/"
f"#{what.replace('.', '')}"
)
def protect_loop[**_P, _R]( def protect_loop[**_P, _R](
func: Callable[_P, _R], func: Callable[_P, _R],
loop_thread_id: int, loop_thread_id: int,

View File

@ -61,9 +61,7 @@ async def test_protect_loop_sleep() -> None:
] ]
) )
with ( with (
pytest.raises( pytest.raises(RuntimeError, match="Caught blocking call to sleep with args"),
RuntimeError, match="Detected blocking call to sleep inside the event loop"
),
patch( patch(
"homeassistant.block_async_io.get_current_frame", "homeassistant.block_async_io.get_current_frame",
return_value=frames, return_value=frames,
@ -89,9 +87,7 @@ async def test_protect_loop_sleep_get_current_frame_raises() -> None:
] ]
) )
with ( with (
pytest.raises( pytest.raises(RuntimeError, match="Caught blocking call to sleep with args"),
RuntimeError, match="Detected blocking call to sleep inside the event loop"
),
patch( patch(
"homeassistant.block_async_io.get_current_frame", "homeassistant.block_async_io.get_current_frame",
side_effect=ValueError, side_effect=ValueError,
@ -204,7 +200,8 @@ async def test_protect_loop_importlib_import_module_in_integration(
importlib.import_module("not_loaded_module") importlib.import_module("not_loaded_module")
assert ( assert (
"Detected blocking call to import_module inside the event loop by " "Detected blocking call to import_module with args ('not_loaded_module',) "
"inside the event loop by "
"integration 'hue' at homeassistant/components/hue/light.py, line 23" "integration 'hue' at homeassistant/components/hue/light.py, line 23"
) in caplog.text ) in caplog.text

View File

@ -28,6 +28,14 @@ async def test_raise_for_blocking_call_async_non_strict_core(
haloop.raise_for_blocking_call(banned_function, strict_core=False) haloop.raise_for_blocking_call(banned_function, strict_core=False)
assert "Detected blocking call to banned_function" in caplog.text assert "Detected blocking call to banned_function" in caplog.text
assert "Traceback (most recent call last)" 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( async def test_raise_for_blocking_call_async_integration(
@ -74,12 +82,17 @@ async def test_raise_for_blocking_call_async_integration(
): ):
haloop.raise_for_blocking_call(banned_function) haloop.raise_for_blocking_call(banned_function)
assert ( assert (
"Detected blocking call to banned_function inside the event loop by integration" "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 23: self.light.is_on "
"(offender: /home/paulus/aiohue/lights.py, line 2: mock_line), please create " "(offender: /home/paulus/aiohue/lights.py, line 2: mock_line), please create "
"a bug report at https://github.com/home-assistant/core/issues?" "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 "q=is%3Aopen+is%3Aissue+label%3A%22integration%3A+hue%22" 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_non_strict( async def test_raise_for_blocking_call_async_integration_non_strict(
@ -125,7 +138,8 @@ async def test_raise_for_blocking_call_async_integration_non_strict(
): ):
haloop.raise_for_blocking_call(banned_function, strict=False) haloop.raise_for_blocking_call(banned_function, strict=False)
assert ( assert (
"Detected blocking call to banned_function inside the event loop by integration" "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 23: self.light.is_on "
"(offender: /home/paulus/aiohue/lights.py, line 2: mock_line), " "(offender: /home/paulus/aiohue/lights.py, line 2: mock_line), "
"please create a bug report at https://github.com/home-assistant/core/issues?" "please create a bug report at https://github.com/home-assistant/core/issues?"
@ -136,6 +150,14 @@ async def test_raise_for_blocking_call_async_integration_non_strict(
'File "/home/paulus/homeassistant/components/hue/light.py", line 23' 'File "/home/paulus/homeassistant/components/hue/light.py", line 23'
in caplog.text 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_custom( async def test_raise_for_blocking_call_async_custom(
@ -182,7 +204,8 @@ async def test_raise_for_blocking_call_async_custom(
): ):
haloop.raise_for_blocking_call(banned_function) haloop.raise_for_blocking_call(banned_function)
assert ( assert (
"Detected blocking call to banned_function inside the event loop by custom " "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 23: self.light.is_on"
" (offender: /home/paulus/aiohue/lights.py, line 2: mock_line), " " (offender: /home/paulus/aiohue/lights.py, line 2: mock_line), "
"please create a bug report at https://github.com/home-assistant/core/issues?" "please create a bug report at https://github.com/home-assistant/core/issues?"
@ -193,6 +216,10 @@ async def test_raise_for_blocking_call_async_custom(
'File "/home/paulus/config/custom_components/hue/light.py", line 23' 'File "/home/paulus/config/custom_components/hue/light.py", line 23'
in caplog.text 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_sync( async def test_raise_for_blocking_call_sync(