From 1d6633bd4d4657f30cbb2a7582d9e0d2474511cc Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Sun, 12 Feb 2023 22:03:15 -0500 Subject: [PATCH 01/15] Keep task references while running --- homeassistant/bootstrap.py | 4 +- homeassistant/core.py | 137 ++++++++++++++++++++++------------- tests/common.py | 51 ------------- tests/helpers/test_script.py | 5 +- tests/test_config_entries.py | 11 ++- tests/test_core.py | 35 +++------ 6 files changed, 108 insertions(+), 135 deletions(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 1cc850f31e4469..dd1e142f8b4a12 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -528,7 +528,9 @@ async def _async_set_up_integrations( hass.data[DATA_SETUP_STARTED] = {} setup_time: dict[str, timedelta] = hass.data.setdefault(DATA_SETUP_TIME, {}) - watch_task = asyncio.create_task(_async_watch_pending_setups(hass)) + watch_task = hass.background_tasks.async_create_task( + _async_watch_pending_setups(hass), "watch_pending_setups" + ) domains_to_setup = _get_domains(hass, config) diff --git a/homeassistant/core.py b/homeassistant/core.py index 34d3dabc9a9909..7d51945b22b7c0 100644 --- a/homeassistant/core.py +++ b/homeassistant/core.py @@ -260,6 +260,49 @@ def __str__(self) -> str: return self.value +class BackgroundTasks: + """Class to manage background tasks.""" + + def __init__(self) -> None: + """Initialize the background task runner.""" + self._tasks: set[asyncio.Task[Any]] = set() + self._loop = asyncio.get_running_loop() + self._running = True + + def async_create_task( + self, + target: Coroutine[Any, Any, _R], + name: str, + ) -> asyncio.Task[_R]: + """Create a task and add it to the set of tasks.""" + if not self._running: + raise RuntimeError("BackgroundTasks is no longer running") + task = self._loop.create_task(target, name=name) + self._tasks.add(task) + task.add_done_callback(self._tasks.remove) + return task + + async def async_cancel_all(self) -> None: + """Cancel all tasks.""" + self._running = False + + if not self._tasks: + return + + for task in self._tasks: + task.cancel() + + for task in list(self._tasks): + try: + await task + except asyncio.CancelledError: + pass + except Exception: # pylint: disable=broad-except + _LOGGER.exception("Error cancelling task %s", task) + + self._tasks.clear() + + class HomeAssistant: """Root object of the Home Assistant home automation.""" @@ -276,8 +319,8 @@ def __new__(cls) -> HomeAssistant: def __init__(self) -> None: """Initialize new Home Assistant object.""" self.loop = asyncio.get_running_loop() - self._pending_tasks: list[asyncio.Future[Any]] = [] - self._track_task = True + self._tasks: set[asyncio.Future[Any]] = set() + self.background_tasks = BackgroundTasks() self.bus = EventBus(self) self.services = ServiceRegistry(self) self.states = StateMachine(self.bus, self.loop) @@ -353,12 +396,14 @@ async def async_start(self) -> None: self.bus.async_fire(EVENT_CORE_CONFIG_UPDATE) self.bus.async_fire(EVENT_HOMEASSISTANT_START) - try: - # Only block for EVENT_HOMEASSISTANT_START listener - self.async_stop_track_tasks() - async with self.timeout.async_timeout(TIMEOUT_EVENT_START): - await self.async_block_till_done() - except asyncio.TimeoutError: + if not self._tasks: + pending: set[asyncio.Future[Any]] | None = None + else: + _done, pending = await asyncio.wait( + self._tasks, timeout=TIMEOUT_EVENT_START + ) + + if pending: _LOGGER.warning( ( "Something is blocking Home Assistant from wrapping up the start up" @@ -494,9 +539,8 @@ def async_add_hass_job( hassjob.target = cast(Callable[..., _R], hassjob.target) task = self.loop.run_in_executor(None, hassjob.target, *args) - # If a task is scheduled - if self._track_task: - self._pending_tasks.append(task) + self._tasks.add(task) + task.add_done_callback(self._tasks.remove) return task @@ -517,8 +561,8 @@ def async_create_task(self, target: Coroutine[Any, Any, _R]) -> asyncio.Task[_R] """ task = self.loop.create_task(target) - if self._track_task: - self._pending_tasks.append(task) + self._tasks.add(task) + task.add_done_callback(self._tasks.remove) return task @@ -530,21 +574,11 @@ def async_add_executor_job( task = self.loop.run_in_executor(None, target, *args) # If a task is scheduled - if self._track_task: - self._pending_tasks.append(task) + self._tasks.add(task) + task.add_done_callback(self._tasks.remove) return task - @callback - def async_track_tasks(self) -> None: - """Track tasks so you can wait for all tasks to be done.""" - self._track_task = True - - @callback - def async_stop_track_tasks(self) -> None: - """Stop track tasks so you can't wait for all tasks to be done.""" - self._track_task = False - @overload @callback def async_run_hass_job( @@ -637,30 +671,27 @@ async def async_block_till_done(self) -> None: """Block until all pending work is done.""" # To flush out any call_soon_threadsafe await asyncio.sleep(0) + await asyncio.sleep(0) start_time: float | None = None - - while self._pending_tasks: - pending = [task for task in self._pending_tasks if not task.done()] - self._pending_tasks.clear() - if pending: - await self._await_and_log_pending(pending) - - if start_time is None: - # Avoid calling monotonic() until we know - # we may need to start logging blocked tasks. - start_time = 0 - elif start_time == 0: - # If we have waited twice then we set the start - # time - start_time = monotonic() - elif monotonic() - start_time > BLOCK_LOG_TIMEOUT: - # We have waited at least three loops and new tasks - # continue to block. At this point we start - # logging all waiting tasks. - for task in pending: - _LOGGER.debug("Waiting for task: %s", task) - else: - await asyncio.sleep(0) + current_task = asyncio.current_task() + + while tasks := [task for task in self._tasks if task is not current_task]: + await self._await_and_log_pending(tasks) + + if start_time is None: + # Avoid calling monotonic() until we know + # we may need to start logging blocked tasks. + start_time = 0 + elif start_time == 0: + # If we have waited twice then we set the start + # time + start_time = monotonic() + elif monotonic() - start_time > BLOCK_LOG_TIMEOUT: + # We have waited at least three loops and new tasks + # continue to block. At this point we start + # logging all waiting tasks. + for task in tasks: + _LOGGER.debug("Waiting for task: %s", task) async def _await_and_log_pending(self, pending: Collection[Awaitable[Any]]) -> None: """Await and log tasks that take a long time.""" @@ -702,9 +733,12 @@ async def async_stop(self, exit_code: int = 0, *, force: bool = False) -> None: "Stopping Home Assistant before startup has completed may fail" ) + cancel_background_tasks = asyncio.create_task( + self.background_tasks.async_cancel_all() + ) + # stage 1 self.state = CoreState.stopping - self.async_track_tasks() self.bus.async_fire(EVENT_HOMEASSISTANT_STOP) try: async with self.timeout.async_timeout(STAGE_1_SHUTDOWN_TIMEOUT): @@ -738,6 +772,11 @@ async def async_stop(self, exit_code: int = 0, *, force: bool = False) -> None: # the `result()` which will cause a deadlock when shutting down the executor. shutdown_run_callback_threadsafe(self.loop) + # Run this as part of stage 3. + if not cancel_background_tasks.done(): + self._tasks.add(cancel_background_tasks) + cancel_background_tasks.add_done_callback(self._tasks.remove) + try: async with self.timeout.async_timeout(STAGE_3_SHUTDOWN_TIMEOUT): await self.async_block_till_done() diff --git a/tests/common.py b/tests/common.py index e45efb028e61c4..f548fa6cb5ac50 100644 --- a/tests/common.py +++ b/tests/common.py @@ -22,7 +22,6 @@ import pathlib import threading import time -from time import monotonic import types from typing import Any, NoReturn from unittest.mock import AsyncMock, Mock, patch @@ -221,44 +220,6 @@ def async_create_task(coroutine): return orig_async_create_task(coroutine) - async def async_wait_for_task_count(self, max_remaining_tasks: int = 0) -> None: - """Block until at most max_remaining_tasks remain. - - Based on HomeAssistant.async_block_till_done - """ - # To flush out any call_soon_threadsafe - await asyncio.sleep(0) - start_time: float | None = None - - while len(self._pending_tasks) > max_remaining_tasks: - pending: Collection[Awaitable[Any]] = [ - task for task in self._pending_tasks if not task.done() - ] - self._pending_tasks.clear() - if len(pending) > max_remaining_tasks: - remaining_pending = await self._await_count_and_log_pending( - pending, max_remaining_tasks=max_remaining_tasks - ) - self._pending_tasks.extend(remaining_pending) - - if start_time is None: - # Avoid calling monotonic() until we know - # we may need to start logging blocked tasks. - start_time = 0 - elif start_time == 0: - # If we have waited twice then we set the start - # time - start_time = monotonic() - elif monotonic() - start_time > BLOCK_LOG_TIMEOUT: - # We have waited at least three loops and new tasks - # continue to block. At this point we start - # logging all waiting tasks. - for task in pending: - _LOGGER.debug("Waiting for task: %s", task) - else: - self._pending_tasks.extend(pending) - await asyncio.sleep(0) - async def _await_count_and_log_pending( self, pending: Collection[Awaitable[Any]], max_remaining_tasks: int = 0 ) -> Collection[Awaitable[Any]]: @@ -287,7 +248,6 @@ async def _await_count_and_log_pending( hass.async_add_job = async_add_job hass.async_add_executor_job = async_add_executor_job hass.async_create_task = async_create_task - hass.async_wait_for_task_count = types.MethodType(async_wait_for_task_count, hass) hass._await_count_and_log_pending = types.MethodType( _await_count_and_log_pending, hass ) @@ -328,17 +288,6 @@ async def _await_count_and_log_pending( hass.state = CoreState.running - # Mock async_start - orig_start = hass.async_start - - async def mock_async_start(): - """Start the mocking.""" - # We only mock time during tests and we want to track tasks - with patch.object(hass, "async_stop_track_tasks"): - await orig_start() - - hass.async_start = mock_async_start - @callback def clear_instance(event): """Clear global instance.""" diff --git a/tests/helpers/test_script.py b/tests/helpers/test_script.py index cd6cba56ba5d90..9dbd2ee2b3c65b 100644 --- a/tests/helpers/test_script.py +++ b/tests/helpers/test_script.py @@ -815,7 +815,7 @@ async def test_wait_for_trigger_variables(hass: HomeAssistant) -> None: actions = [ { "alias": "variables", - "variables": {"seconds": 5}, + "variables": {"seconds": 0.01}, }, { "alias": wait_alias, @@ -839,9 +839,6 @@ async def test_wait_for_trigger_variables(hass: HomeAssistant) -> None: assert script_obj.is_running assert script_obj.last_action == wait_alias hass.states.async_set("switch.test", "off") - # the script task + 2 tasks created by wait_for_trigger script step - await hass.async_wait_for_task_count(3) - async_fire_time_changed(hass, dt_util.utcnow() + timedelta(seconds=10)) await hass.async_block_till_done() except (AssertionError, asyncio.TimeoutError): await script_obj.async_stop() diff --git a/tests/test_config_entries.py b/tests/test_config_entries.py index be9c47c8b29aba..63881631b87747 100644 --- a/tests/test_config_entries.py +++ b/tests/test_config_entries.py @@ -3559,14 +3559,17 @@ async def async_step_reauth(self, data): """Mock Reauth.""" await asyncio.sleep(1) + mock_integration(hass, MockModule("test")) + mock_entity_platform(hass, "config_flow.test", None) + with patch.dict( config_entries.HANDLERS, {"comp": MockFlowHandler, "test": MockFlowHandler} ): task = asyncio.create_task( manager.flow.async_init("test", context={"source": "reauth"}) ) - await hass.async_block_till_done() - await manager.flow.async_shutdown() + await hass.async_block_till_done() + await manager.flow.async_shutdown() - with pytest.raises(asyncio.exceptions.CancelledError): - await task + with pytest.raises(asyncio.exceptions.CancelledError): + await task diff --git a/tests/test_core.py b/tests/test_core.py index db89bac36f6146..1e0e69cc3afb77 100644 --- a/tests/test_core.py +++ b/tests/test_core.py @@ -124,7 +124,7 @@ def job(): ha.HomeAssistant.async_add_hass_job(hass, ha.HassJob(job)) assert len(hass.loop.call_soon.mock_calls) == 0 assert len(hass.loop.create_task.mock_calls) == 0 - assert len(hass.loop.run_in_executor.mock_calls) == 1 + assert len(hass.loop.run_in_executor.mock_calls) == 2 def test_async_create_task_schedule_coroutine(event_loop): @@ -205,7 +205,7 @@ def _record_shutdown_run_callback_threadsafe(loop): assert stop_calls[-1] == "async_block_till_done" -async def test_pending_sheduler(hass: HomeAssistant) -> None: +async def test_pending_scheduler(hass: HomeAssistant) -> None: """Add a coro to pending tasks.""" call_count = [] @@ -216,9 +216,9 @@ async def test_coro(): for _ in range(3): hass.async_add_job(test_coro()) - await asyncio.wait(hass._pending_tasks) + await asyncio.wait(hass._tasks) - assert len(hass._pending_tasks) == 3 + assert len(hass._tasks) == 0 assert len(call_count) == 3 @@ -240,7 +240,7 @@ async def wait_finish_callback(): await wait_finish_callback() - assert len(hass._pending_tasks) == 2 + assert len(hass._tasks) == 2 await hass.async_block_till_done() assert len(call_count) == 2 @@ -263,7 +263,7 @@ async def wait_finish_callback(): await wait_finish_callback() - assert len(hass._pending_tasks) == 2 + assert len(hass._tasks) == 2 await hass.async_block_till_done() assert len(call_count) == 2 @@ -286,7 +286,6 @@ async def wait_finish_callback(): await wait_finish_callback() - assert len(hass._pending_tasks) == 2 await hass.async_block_till_done() assert len(call_count) == 2 @@ -312,7 +311,7 @@ async def wait_finish_callback(): await hass.async_block_till_done() - assert len(hass._pending_tasks) == 0 + assert len(hass._tasks) == 0 assert len(call_count) == 2 @@ -1144,11 +1143,10 @@ async def test_start_taking_too_long(event_loop, caplog): """Test when async_start takes too long.""" hass = ha.HomeAssistant() caplog.set_level(logging.WARNING) + hass.async_create_task(asyncio.sleep(0)) try: - with patch.object( - hass, "async_block_till_done", side_effect=asyncio.TimeoutError - ): + with patch("asyncio.wait", return_value=(set(), {asyncio.Future()})): await hass.async_start() assert hass.state == ha.CoreState.running @@ -1159,21 +1157,6 @@ async def test_start_taking_too_long(event_loop, caplog): assert hass.state == ha.CoreState.stopped -async def test_track_task_functions(event_loop): - """Test function to start/stop track task and initial state.""" - hass = ha.HomeAssistant() - try: - assert hass._track_task - - hass.async_stop_track_tasks() - assert not hass._track_task - - hass.async_track_tasks() - assert hass._track_task - finally: - await hass.async_stop() - - async def test_service_executed_with_subservices(hass: HomeAssistant) -> None: """Test we block correctly till all services done.""" calls = async_mock_service(hass, "test", "inner") From 9ab70db1773a6a2bbb9e2111c57bcb1d28f9a210 Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 09:40:44 -0500 Subject: [PATCH 02/15] Update pilight tests pointing at correct logger call --- tests/components/pilight/test_init.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/tests/components/pilight/test_init.py b/tests/components/pilight/test_init.py index 8d7b8172d0d609..cca9843dd0423e 100644 --- a/tests/components/pilight/test_init.py +++ b/tests/components/pilight/test_init.py @@ -239,7 +239,7 @@ async def test_receive_code(mock_debug, hass): }, **PilightDaemonSim.test_message["message"], ) - debug_log_call = mock_debug.call_args_list[-3] + debug_log_call = mock_debug.call_args_list[-1] # Check if all message parts are put on event bus for key, value in expected_message.items(): @@ -272,7 +272,7 @@ async def test_whitelist_exact_match(mock_debug, hass): }, **PilightDaemonSim.test_message["message"], ) - debug_log_call = mock_debug.call_args_list[-3] + debug_log_call = mock_debug.call_args_list[-1] # Check if all message parts are put on event bus for key, value in expected_message.items(): @@ -303,7 +303,7 @@ async def test_whitelist_partial_match(mock_debug, hass): }, **PilightDaemonSim.test_message["message"], ) - debug_log_call = mock_debug.call_args_list[-3] + debug_log_call = mock_debug.call_args_list[-1] # Check if all message parts are put on event bus for key, value in expected_message.items(): @@ -337,7 +337,7 @@ async def test_whitelist_or_match(mock_debug, hass): }, **PilightDaemonSim.test_message["message"], ) - debug_log_call = mock_debug.call_args_list[-3] + debug_log_call = mock_debug.call_args_list[-1] # Check if all message parts are put on event bus for key, value in expected_message.items(): @@ -360,7 +360,7 @@ async def test_whitelist_no_match(mock_debug, hass): await hass.async_start() await hass.async_block_till_done() - debug_log_call = mock_debug.call_args_list[-3] + debug_log_call = mock_debug.call_args_list[-1] assert "Event pilight_received" not in debug_log_call From d977673255729228d35499002285f54d7dc0897d Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 09:59:56 -0500 Subject: [PATCH 03/15] Fix graphite tests --- homeassistant/components/graphite/__init__.py | 2 +- tests/components/graphite/test_init.py | 26 ++++++++++++------- 2 files changed, 17 insertions(+), 11 deletions(-) diff --git a/homeassistant/components/graphite/__init__.py b/homeassistant/components/graphite/__init__.py index 0a6f6fcc1a9569..0f541712d3c5ee 100644 --- a/homeassistant/components/graphite/__init__.py +++ b/homeassistant/components/graphite/__init__.py @@ -69,7 +69,7 @@ def setup(hass: HomeAssistant, config: ConfigType) -> bool: else: _LOGGER.debug("No connection check for UDP possible") - GraphiteFeeder(hass, host, port, protocol, prefix) + hass.data[DOMAIN] = GraphiteFeeder(hass, host, port, protocol, prefix) return True diff --git a/tests/components/graphite/test_init.py b/tests/components/graphite/test_init.py index 395cfbf0a8ba9a..41af73a6b0b0b9 100644 --- a/tests/components/graphite/test_init.py +++ b/tests/components/graphite/test_init.py @@ -1,5 +1,4 @@ """The tests for the Graphite component.""" -import asyncio import socket from unittest import mock from unittest.mock import patch @@ -91,9 +90,10 @@ async def test_start(hass: HomeAssistant, mock_socket, mock_time) -> None: mock_socket.reset_mock() await hass.async_start() + await hass.async_block_till_done() hass.states.async_set("test.entity", STATE_ON) - await asyncio.sleep(0.1) + await hass.async_block_till_done() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) @@ -114,9 +114,10 @@ async def test_shutdown(hass: HomeAssistant, mock_socket, mock_time) -> None: mock_socket.reset_mock() await hass.async_start() + await hass.async_block_till_done() hass.states.async_set("test.entity", STATE_ON) - await asyncio.sleep(0.1) + await hass.async_block_till_done() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) @@ -134,7 +135,7 @@ async def test_shutdown(hass: HomeAssistant, mock_socket, mock_time) -> None: await hass.async_block_till_done() hass.states.async_set("test.entity", STATE_OFF) - await asyncio.sleep(0.1) + await hass.async_block_till_done() assert mock_socket.return_value.connect.call_count == 0 assert mock_socket.return_value.sendall.call_count == 0 @@ -156,9 +157,10 @@ async def test_report_attributes(hass: HomeAssistant, mock_socket, mock_time) -> mock_socket.reset_mock() await hass.async_start() + await hass.async_block_till_done() hass.states.async_set("test.entity", STATE_ON, attrs) - await asyncio.sleep(0.1) + await hass.async_block_till_done() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) @@ -186,9 +188,10 @@ async def test_report_with_string_state( mock_socket.reset_mock() await hass.async_start() + await hass.async_block_till_done() hass.states.async_set("test.entity", "above_horizon", {"foo": 1.0}) - await asyncio.sleep(0.1) + await hass.async_block_till_done() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) @@ -203,7 +206,7 @@ async def test_report_with_string_state( mock_socket.reset_mock() hass.states.async_set("test.entity", "not_float") - await asyncio.sleep(0.1) + await hass.async_block_till_done() assert mock_socket.return_value.connect.call_count == 0 assert mock_socket.return_value.sendall.call_count == 0 @@ -221,13 +224,14 @@ async def test_report_with_binary_state( mock_socket.reset_mock() await hass.async_start() + await hass.async_block_till_done() expected = [ "ha.test.entity.foo 1.000000 12345", "ha.test.entity.state 1.000000 12345", ] hass.states.async_set("test.entity", STATE_ON, {"foo": 1.0}) - await asyncio.sleep(0.1) + await hass.async_block_till_done() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) @@ -246,7 +250,7 @@ async def test_report_with_binary_state( "ha.test.entity.state 0.000000 12345", ] hass.states.async_set("test.entity", STATE_OFF, {"foo": 1.0}) - await asyncio.sleep(0.1) + await hass.async_block_till_done() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) @@ -282,10 +286,12 @@ async def test_send_to_graphite_errors( mock_socket.reset_mock() await hass.async_start() + await hass.async_block_till_done() mock_socket.return_value.connect.side_effect = error hass.states.async_set("test.entity", STATE_ON) - await asyncio.sleep(0.1) + await hass.async_block_till_done() + hass.data[graphite.DOMAIN]._queue.join() assert log_text in caplog.text From a14b11c74ea364506f52edc0c3d2afd102bc449f Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 10:00:29 -0500 Subject: [PATCH 04/15] Fix profiler tests --- tests/components/profiler/test_init.py | 27 +++++++++++++------------- 1 file changed, 13 insertions(+), 14 deletions(-) diff --git a/tests/components/profiler/test_init.py b/tests/components/profiler/test_init.py index 52f15e318e8091..0fc70d3ce0d891 100644 --- a/tests/components/profiler/test_init.py +++ b/tests/components/profiler/test_init.py @@ -43,8 +43,9 @@ def _mock_path(filename): return last_filename with patch("cProfile.Profile"), patch.object(hass.config, "path", _mock_path): - await hass.services.async_call(DOMAIN, SERVICE_START, {CONF_SECONDS: 0.000001}) - await hass.async_block_till_done() + await hass.services.async_call( + DOMAIN, SERVICE_START, {CONF_SECONDS: 0.000001}, blocking=True + ) assert os.path.exists(last_filename) @@ -72,8 +73,9 @@ def _mock_path(filename): return last_filename with patch("guppy.hpy") as mock_hpy, patch.object(hass.config, "path", _mock_path): - await hass.services.async_call(DOMAIN, SERVICE_MEMORY, {CONF_SECONDS: 0.000001}) - await hass.async_block_till_done() + await hass.services.async_call( + DOMAIN, SERVICE_MEMORY, {CONF_SECONDS: 0.000001}, blocking=True + ) mock_hpy.assert_called_once() @@ -97,9 +99,8 @@ async def test_object_growth_logging( with patch("objgraph.growth"): await hass.services.async_call( - DOMAIN, SERVICE_START_LOG_OBJECTS, {CONF_SCAN_INTERVAL: 10} + DOMAIN, SERVICE_START_LOG_OBJECTS, {CONF_SCAN_INTERVAL: 10}, blocking=True ) - await hass.async_block_till_done() assert "Growth" in caplog.text caplog.clear() @@ -108,8 +109,7 @@ async def test_object_growth_logging( await hass.async_block_till_done() assert "Growth" in caplog.text - await hass.services.async_call(DOMAIN, SERVICE_STOP_LOG_OBJECTS, {}) - await hass.async_block_till_done() + await hass.services.async_call(DOMAIN, SERVICE_STOP_LOG_OBJECTS, {}, blocking=True) caplog.clear() async_fire_time_changed(hass, dt_util.utcnow() + timedelta(seconds=21)) @@ -150,9 +150,8 @@ def __repr__(self): assert hass.services.has_service(DOMAIN, SERVICE_DUMP_LOG_OBJECTS) await hass.services.async_call( - DOMAIN, SERVICE_DUMP_LOG_OBJECTS, {CONF_TYPE: "DumpLogDummy"} + DOMAIN, SERVICE_DUMP_LOG_OBJECTS, {CONF_TYPE: "DumpLogDummy"}, blocking=True ) - await hass.async_block_till_done() assert "" in caplog.text assert "Failed to serialize" in caplog.text @@ -174,8 +173,7 @@ async def test_log_thread_frames( assert hass.services.has_service(DOMAIN, SERVICE_LOG_THREAD_FRAMES) - await hass.services.async_call(DOMAIN, SERVICE_LOG_THREAD_FRAMES, {}) - await hass.async_block_till_done() + await hass.services.async_call(DOMAIN, SERVICE_LOG_THREAD_FRAMES, {}, blocking=True) assert "SyncWorker_0" in caplog.text caplog.clear() @@ -197,8 +195,9 @@ async def test_log_scheduled( assert hass.services.has_service(DOMAIN, SERVICE_LOG_EVENT_LOOP_SCHEDULED) - await hass.services.async_call(DOMAIN, SERVICE_LOG_EVENT_LOOP_SCHEDULED, {}) - await hass.async_block_till_done() + await hass.services.async_call( + DOMAIN, SERVICE_LOG_EVENT_LOOP_SCHEDULED, {}, blocking=True + ) assert "Scheduled" in caplog.text caplog.clear() From 83ef67513264138e112e3db338f47a8030c5dc0b Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 11:13:04 -0500 Subject: [PATCH 05/15] More graphite test fixes --- tests/components/graphite/test_init.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/tests/components/graphite/test_init.py b/tests/components/graphite/test_init.py index 41af73a6b0b0b9..55601c1b148a5e 100644 --- a/tests/components/graphite/test_init.py +++ b/tests/components/graphite/test_init.py @@ -118,6 +118,7 @@ async def test_shutdown(hass: HomeAssistant, mock_socket, mock_time) -> None: hass.states.async_set("test.entity", STATE_ON) await hass.async_block_till_done() + hass.data[graphite.DOMAIN]._queue.join() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) @@ -136,6 +137,7 @@ async def test_shutdown(hass: HomeAssistant, mock_socket, mock_time) -> None: hass.states.async_set("test.entity", STATE_OFF) await hass.async_block_till_done() + hass.data[graphite.DOMAIN]._queue.join() assert mock_socket.return_value.connect.call_count == 0 assert mock_socket.return_value.sendall.call_count == 0 @@ -161,6 +163,7 @@ async def test_report_attributes(hass: HomeAssistant, mock_socket, mock_time) -> hass.states.async_set("test.entity", STATE_ON, attrs) await hass.async_block_till_done() + hass.data[graphite.DOMAIN]._queue.join() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) @@ -192,6 +195,7 @@ async def test_report_with_string_state( hass.states.async_set("test.entity", "above_horizon", {"foo": 1.0}) await hass.async_block_till_done() + hass.data[graphite.DOMAIN]._queue.join() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) @@ -207,6 +211,7 @@ async def test_report_with_string_state( hass.states.async_set("test.entity", "not_float") await hass.async_block_till_done() + hass.data[graphite.DOMAIN]._queue.join() assert mock_socket.return_value.connect.call_count == 0 assert mock_socket.return_value.sendall.call_count == 0 @@ -232,6 +237,7 @@ async def test_report_with_binary_state( ] hass.states.async_set("test.entity", STATE_ON, {"foo": 1.0}) await hass.async_block_till_done() + hass.data[graphite.DOMAIN]._queue.join() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) @@ -251,6 +257,7 @@ async def test_report_with_binary_state( ] hass.states.async_set("test.entity", STATE_OFF, {"foo": 1.0}) await hass.async_block_till_done() + hass.data[graphite.DOMAIN]._queue.join() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003)) From c79cd3e75640100dcb6d3b35c3a8a8609393f216 Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 11:56:43 -0500 Subject: [PATCH 06/15] Remove extra sleep --- homeassistant/core.py | 1 - 1 file changed, 1 deletion(-) diff --git a/homeassistant/core.py b/homeassistant/core.py index 7d51945b22b7c0..5df38942fde355 100644 --- a/homeassistant/core.py +++ b/homeassistant/core.py @@ -671,7 +671,6 @@ async def async_block_till_done(self) -> None: """Block until all pending work is done.""" # To flush out any call_soon_threadsafe await asyncio.sleep(0) - await asyncio.sleep(0) start_time: float | None = None current_task = asyncio.current_task() From 062ab081cbe8cf9b94d21ef14c54cdc6d77ebb6d Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 13:45:19 -0500 Subject: [PATCH 07/15] Fix tests --- homeassistant/core.py | 22 +++++++++++-------- .../device_sun_light_trigger/test_init.py | 1 + .../components/hardware/test_websocket_api.py | 1 + tests/test_bootstrap.py | 2 +- 4 files changed, 16 insertions(+), 10 deletions(-) diff --git a/homeassistant/core.py b/homeassistant/core.py index 5df38942fde355..ae088b6f10409c 100644 --- a/homeassistant/core.py +++ b/homeassistant/core.py @@ -289,18 +289,22 @@ async def async_cancel_all(self) -> None: if not self._tasks: return - for task in self._tasks: + tasks = list(self._tasks) + + for task in tasks: task.cancel() - for task in list(self._tasks): - try: - await task - except asyncio.CancelledError: - pass - except Exception: # pylint: disable=broad-except - _LOGGER.exception("Error cancelling task %s", task) + await asyncio.wait(tasks) + + for task in tasks: + if (exception := task.exception()) is None: + continue - self._tasks.clear() + _LOGGER.error( + "Error canceling background task %s - received exception", + task, + exc_info=(type(exception), exception, exception.__traceback__), + ) class HomeAssistant: diff --git a/tests/components/device_sun_light_trigger/test_init.py b/tests/components/device_sun_light_trigger/test_init.py index 0744002d10c1c2..0c5a9ccab145a8 100644 --- a/tests/components/device_sun_light_trigger/test_init.py +++ b/tests/components/device_sun_light_trigger/test_init.py @@ -239,5 +239,6 @@ async def test_initialize_start(hass: HomeAssistant) -> None: ) as mock_activate: hass.bus.fire(EVENT_HOMEASSISTANT_START) await hass.async_block_till_done() + await hass.async_block_till_done() assert len(mock_activate.mock_calls) == 1 diff --git a/tests/components/hardware/test_websocket_api.py b/tests/components/hardware/test_websocket_api.py index 72076cf1964372..b3a3e9ba11468a 100644 --- a/tests/components/hardware/test_websocket_api.py +++ b/tests/components/hardware/test_websocket_api.py @@ -71,6 +71,7 @@ def create_mock_psutil(): ): freezer.tick(TEST_TIME_ADVANCE_INTERVAL) await hass.async_block_till_done() + await hass.async_block_till_done() response = await client.receive_json() assert response["event"] == { diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index cbe33bab6c4186..f749b24f0962c2 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -779,7 +779,7 @@ async def async_setup(hass, config): async def _background_task(): await asyncio.sleep(0.2) - await hass.async_create_task(_background_task()) + hass.async_create_task(_background_task()) return True return async_setup From 8aec73ed35a89d98ee5aebaeb76bc3f35225f305 Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 13:54:13 -0500 Subject: [PATCH 08/15] Shutdown background tasks as part of stage 1 --- homeassistant/core.py | 13 +------------ 1 file changed, 1 insertion(+), 12 deletions(-) diff --git a/homeassistant/core.py b/homeassistant/core.py index ae088b6f10409c..d5d23325030b55 100644 --- a/homeassistant/core.py +++ b/homeassistant/core.py @@ -564,7 +564,6 @@ def async_create_task(self, target: Coroutine[Any, Any, _R]) -> asyncio.Task[_R] target: target to call. """ task = self.loop.create_task(target) - self._tasks.add(task) task.add_done_callback(self._tasks.remove) @@ -576,8 +575,6 @@ def async_add_executor_job( ) -> asyncio.Future[_T]: """Add an executor job from within the event loop.""" task = self.loop.run_in_executor(None, target, *args) - - # If a task is scheduled self._tasks.add(task) task.add_done_callback(self._tasks.remove) @@ -736,12 +733,9 @@ async def async_stop(self, exit_code: int = 0, *, force: bool = False) -> None: "Stopping Home Assistant before startup has completed may fail" ) - cancel_background_tasks = asyncio.create_task( - self.background_tasks.async_cancel_all() - ) - # stage 1 self.state = CoreState.stopping + self.async_create_task(self.background_tasks.async_cancel_all()) self.bus.async_fire(EVENT_HOMEASSISTANT_STOP) try: async with self.timeout.async_timeout(STAGE_1_SHUTDOWN_TIMEOUT): @@ -775,11 +769,6 @@ async def async_stop(self, exit_code: int = 0, *, force: bool = False) -> None: # the `result()` which will cause a deadlock when shutting down the executor. shutdown_run_callback_threadsafe(self.loop) - # Run this as part of stage 3. - if not cancel_background_tasks.done(): - self._tasks.add(cancel_background_tasks) - cancel_background_tasks.add_done_callback(self._tasks.remove) - try: async with self.timeout.async_timeout(STAGE_3_SHUTDOWN_TIMEOUT): await self.async_block_till_done() From df48c8a773194557f4504f794a5ea61d1c1c9091 Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 14:01:42 -0500 Subject: [PATCH 09/15] Remove unnecessary sleep in test --- tests/test_bootstrap.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index f749b24f0962c2..48d161d5b57a31 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -774,8 +774,6 @@ async def test_warning_logged_on_wrap_up_timeout(hass, caplog): def gen_domain_setup(domain): async def async_setup(hass, config): - await asyncio.sleep(0.1) - async def _background_task(): await asyncio.sleep(0.2) From 9483b5e93809ea85343e0263b815893126ffd4a2 Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 14:05:27 -0500 Subject: [PATCH 10/15] Remove unused method on mock hass --- tests/common.py | 39 +-------------------------------------- 1 file changed, 1 insertion(+), 38 deletions(-) diff --git a/tests/common.py b/tests/common.py index f548fa6cb5ac50..0424a5707e2c56 100644 --- a/tests/common.py +++ b/tests/common.py @@ -3,14 +3,7 @@ import asyncio from collections import OrderedDict -from collections.abc import ( - Awaitable, - Callable, - Collection, - Generator, - Mapping, - Sequence, -) +from collections.abc import Awaitable, Callable, Generator, Mapping, Sequence from contextlib import contextmanager from datetime import datetime, timedelta, timezone import functools as ft @@ -22,7 +15,6 @@ import pathlib import threading import time -import types from typing import Any, NoReturn from unittest.mock import AsyncMock, Mock, patch @@ -50,7 +42,6 @@ STATE_ON, ) from homeassistant.core import ( - BLOCK_LOG_TIMEOUT, CoreState, Event, HomeAssistant, @@ -220,37 +211,9 @@ def async_create_task(coroutine): return orig_async_create_task(coroutine) - async def _await_count_and_log_pending( - self, pending: Collection[Awaitable[Any]], max_remaining_tasks: int = 0 - ) -> Collection[Awaitable[Any]]: - """Block at most max_remaining_tasks remain and log tasks that take a long time. - - Based on HomeAssistant._await_and_log_pending - """ - wait_time = 0 - - return_when = asyncio.ALL_COMPLETED - if max_remaining_tasks: - return_when = asyncio.FIRST_COMPLETED - - while len(pending) > max_remaining_tasks: - _, pending = await asyncio.wait( - pending, timeout=BLOCK_LOG_TIMEOUT, return_when=return_when - ) - if not pending or max_remaining_tasks: - return pending - wait_time += BLOCK_LOG_TIMEOUT - for task in pending: - _LOGGER.debug("Waited %s seconds for task: %s", wait_time, task) - - return [] - hass.async_add_job = async_add_job hass.async_add_executor_job = async_add_executor_job hass.async_create_task = async_create_task - hass._await_count_and_log_pending = types.MethodType( - _await_count_and_log_pending, hass - ) hass.data[loader.DATA_CUSTOM_COMPONENTS] = {} From 16af8f36e3a959c2b3241d1e9661446e3b3aca95 Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 14:07:59 -0500 Subject: [PATCH 11/15] Skip on cancelled too --- homeassistant/core.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/homeassistant/core.py b/homeassistant/core.py index d5d23325030b55..64a29aafccbebc 100644 --- a/homeassistant/core.py +++ b/homeassistant/core.py @@ -297,7 +297,9 @@ async def async_cancel_all(self) -> None: await asyncio.wait(tasks) for task in tasks: - if (exception := task.exception()) is None: + if (exception := task.exception()) is None or isinstance( + exception, asyncio.CancelledError + ): continue _LOGGER.error( From 4d47fd39f68ed4aff72776bdb025b695c5577050 Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 20:57:34 -0500 Subject: [PATCH 12/15] Remove background tasks --- homeassistant/bootstrap.py | 4 +-- homeassistant/core.py | 51 -------------------------------------- 2 files changed, 1 insertion(+), 54 deletions(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index dd1e142f8b4a12..1cc850f31e4469 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -528,9 +528,7 @@ async def _async_set_up_integrations( hass.data[DATA_SETUP_STARTED] = {} setup_time: dict[str, timedelta] = hass.data.setdefault(DATA_SETUP_TIME, {}) - watch_task = hass.background_tasks.async_create_task( - _async_watch_pending_setups(hass), "watch_pending_setups" - ) + watch_task = asyncio.create_task(_async_watch_pending_setups(hass)) domains_to_setup = _get_domains(hass, config) diff --git a/homeassistant/core.py b/homeassistant/core.py index 64a29aafccbebc..6494593beee6d7 100644 --- a/homeassistant/core.py +++ b/homeassistant/core.py @@ -260,55 +260,6 @@ def __str__(self) -> str: return self.value -class BackgroundTasks: - """Class to manage background tasks.""" - - def __init__(self) -> None: - """Initialize the background task runner.""" - self._tasks: set[asyncio.Task[Any]] = set() - self._loop = asyncio.get_running_loop() - self._running = True - - def async_create_task( - self, - target: Coroutine[Any, Any, _R], - name: str, - ) -> asyncio.Task[_R]: - """Create a task and add it to the set of tasks.""" - if not self._running: - raise RuntimeError("BackgroundTasks is no longer running") - task = self._loop.create_task(target, name=name) - self._tasks.add(task) - task.add_done_callback(self._tasks.remove) - return task - - async def async_cancel_all(self) -> None: - """Cancel all tasks.""" - self._running = False - - if not self._tasks: - return - - tasks = list(self._tasks) - - for task in tasks: - task.cancel() - - await asyncio.wait(tasks) - - for task in tasks: - if (exception := task.exception()) is None or isinstance( - exception, asyncio.CancelledError - ): - continue - - _LOGGER.error( - "Error canceling background task %s - received exception", - task, - exc_info=(type(exception), exception, exception.__traceback__), - ) - - class HomeAssistant: """Root object of the Home Assistant home automation.""" @@ -326,7 +277,6 @@ def __init__(self) -> None: """Initialize new Home Assistant object.""" self.loop = asyncio.get_running_loop() self._tasks: set[asyncio.Future[Any]] = set() - self.background_tasks = BackgroundTasks() self.bus = EventBus(self) self.services = ServiceRegistry(self) self.states = StateMachine(self.bus, self.loop) @@ -737,7 +687,6 @@ async def async_stop(self, exit_code: int = 0, *, force: bool = False) -> None: # stage 1 self.state = CoreState.stopping - self.async_create_task(self.background_tasks.async_cancel_all()) self.bus.async_fire(EVENT_HOMEASSISTANT_STOP) try: async with self.timeout.async_timeout(STAGE_1_SHUTDOWN_TIMEOUT): From 6fe9569583f84d682b6ac7c70d154d41f1e3a306 Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 20:57:56 -0500 Subject: [PATCH 13/15] Test trigger variables without actually sleeping --- tests/helpers/test_script.py | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/tests/helpers/test_script.py b/tests/helpers/test_script.py index 9dbd2ee2b3c65b..a2c0f0b373fef8 100644 --- a/tests/helpers/test_script.py +++ b/tests/helpers/test_script.py @@ -815,15 +815,13 @@ async def test_wait_for_trigger_variables(hass: HomeAssistant) -> None: actions = [ { "alias": "variables", - "variables": {"seconds": 0.01}, + "variables": {"state": "off"}, }, { "alias": wait_alias, "wait_for_trigger": { - "platform": "state", - "entity_id": "switch.test", - "to": "off", - "for": {"seconds": "{{ seconds }}"}, + "platform": "template", + "value_template": "{{ states.switch.test.state == state }}", }, }, ] From 1e92276b350bb66535b0d84c3127b299b601fdb3 Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 21:34:18 -0500 Subject: [PATCH 14/15] Fix graphite --- tests/components/graphite/test_init.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/components/graphite/test_init.py b/tests/components/graphite/test_init.py index 55601c1b148a5e..8ede3e632a8659 100644 --- a/tests/components/graphite/test_init.py +++ b/tests/components/graphite/test_init.py @@ -137,7 +137,6 @@ async def test_shutdown(hass: HomeAssistant, mock_socket, mock_time) -> None: hass.states.async_set("test.entity", STATE_OFF) await hass.async_block_till_done() - hass.data[graphite.DOMAIN]._queue.join() assert mock_socket.return_value.connect.call_count == 0 assert mock_socket.return_value.sendall.call_count == 0 From 3cfe0e46c257bd41bbb43dcf487fd1dcf65f2789 Mon Sep 17 00:00:00 2001 From: Paulus Schoutsen Date: Mon, 13 Feb 2023 21:58:41 -0500 Subject: [PATCH 15/15] One more graphite grrrrrrr --- tests/components/graphite/test_init.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/components/graphite/test_init.py b/tests/components/graphite/test_init.py index 8ede3e632a8659..1370b6c46eb9f6 100644 --- a/tests/components/graphite/test_init.py +++ b/tests/components/graphite/test_init.py @@ -94,6 +94,7 @@ async def test_start(hass: HomeAssistant, mock_socket, mock_time) -> None: hass.states.async_set("test.entity", STATE_ON) await hass.async_block_till_done() + hass.data[graphite.DOMAIN]._queue.join() assert mock_socket.return_value.connect.call_count == 1 assert mock_socket.return_value.connect.call_args == mock.call(("localhost", 2003))