From a7459b3126229b329006af8e3bacd7f134536dd3 Mon Sep 17 00:00:00 2001
From: "J. Nick Koston" <nick@koston.org>
Date: Thu, 23 Jul 2020 16:03:42 -1000
Subject: [PATCH] Log which task is blocking startup when debug logging is on
 (#38134)

* Log which task is blocking startup when debug logging for homeassistant.core is on

* test needs to go one level deeper now
---
 homeassistant/core.py                 | 17 ++++++++++++++++-
 tests/helpers/test_entity_platform.py |  4 ++--
 tests/test_core.py                    | 21 +++++++++++++++++++++
 3 files changed, 39 insertions(+), 3 deletions(-)

diff --git a/homeassistant/core.py b/homeassistant/core.py
index 18493d85629..adeed758555 100644
--- a/homeassistant/core.py
+++ b/homeassistant/core.py
@@ -24,6 +24,7 @@ from typing import (
     Callable,
     Coroutine,
     Dict,
+    Iterable,
     List,
     Mapping,
     Optional,
@@ -99,6 +100,9 @@ CORE_STORAGE_VERSION = 1
 
 DOMAIN = "homeassistant"
 
+# How long to wait to log tasks that are blocking
+BLOCK_LOG_TIMEOUT = 60
+
 # How long we wait for the result of a service call
 SERVICE_CALL_LIMIT = 10  # seconds
 
@@ -394,10 +398,21 @@ class HomeAssistant:
             pending = [task for task in self._pending_tasks if not task.done()]
             self._pending_tasks.clear()
             if pending:
-                await asyncio.wait(pending)
+                await self._await_and_log_pending(pending)
             else:
                 await asyncio.sleep(0)
 
+    async def _await_and_log_pending(self, pending: Iterable[Awaitable[Any]]) -> None:
+        """Await and log tasks that take a long time."""
+        wait_time = 0
+        while pending:
+            _, pending = await asyncio.wait(pending, timeout=BLOCK_LOG_TIMEOUT)
+            if not pending:
+                return
+            wait_time += BLOCK_LOG_TIMEOUT
+            for task in pending:
+                _LOGGER.debug("Waited %s seconds for task: %s", wait_time, task)
+
     def stop(self) -> None:
         """Stop Home Assistant and shuts down all threads."""
         if self.state == CoreState.not_running:  # just ignore
diff --git a/tests/helpers/test_entity_platform.py b/tests/helpers/test_entity_platform.py
index d5b817e0655..ddecd1988ed 100644
--- a/tests/helpers/test_entity_platform.py
+++ b/tests/helpers/test_entity_platform.py
@@ -188,8 +188,8 @@ async def test_platform_warn_slow_setup(hass):
         assert mock_call.called
 
         # mock_calls[0] is the warning message for component setup
-        # mock_calls[5] is the warning message for platform setup
-        timeout, logger_method = mock_call.mock_calls[5][1][:2]
+        # mock_calls[6] is the warning message for platform setup
+        timeout, logger_method = mock_call.mock_calls[6][1][:2]
 
         assert timeout == entity_platform.SLOW_SETUP_WARNING
         assert logger_method == _LOGGER.warning
diff --git a/tests/test_core.py b/tests/test_core.py
index 01a751b6570..c144af86804 100644
--- a/tests/test_core.py
+++ b/tests/test_core.py
@@ -1404,3 +1404,24 @@ async def test_start_events(hass):
         EVENT_HOMEASSISTANT_STARTED,
     ]
     assert core_states == [ha.CoreState.starting, ha.CoreState.running]
+
+
+async def test_log_blocking_events(hass, caplog):
+    """Ensure we log which task is blocking startup when debug logging is on."""
+    caplog.set_level(logging.DEBUG)
+
+    async def _wait_a_bit_1():
+        await asyncio.sleep(0.1)
+
+    async def _wait_a_bit_2():
+        await asyncio.sleep(0.1)
+
+    hass.async_create_task(_wait_a_bit_1())
+    await hass.async_block_till_done()
+
+    with patch.object(ha, "BLOCK_LOG_TIMEOUT", 0.00001):
+        hass.async_create_task(_wait_a_bit_2())
+        await hass.async_block_till_done()
+
+    assert "_wait_a_bit_2" in caplog.text
+    assert "_wait_a_bit_1" not in caplog.text