10000 Log which task is blocking startup when debug logging is on by bdraco · Pull Request #38134 · home-assistant/core · GitHub
[go: up one dir, main page]
More Web Proxy on the site http://driver.im/
Skip to content

Log which task is blocking startup when debug logging is on #38134

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Jul 24, 2020
Merged

Log which task is blocking startup when debug logging is on #38134

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
f646213
Log which task is blocking startup when debug logging for homeassista…
bdraco Jul 23, 2020
da25f1e
test needs to go one level deeper now
bdraco Jul 23, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 16 additions & 1 deletion homeassistant/core.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@
Callable,
Coroutine,
Dict,
Iterable,
List,
Mapping,
Optional,
Expand Down Expand Up @@ -99,6 +100,9 @@

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

Expand Down Expand Up @@ -394,10 +398,21 @@ async def async_block_till_done(self) -> None:
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
Expand Down
4 changes: 2 additions & 2 deletions tests/helpers/test_entity_platform.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
21 changes: 21 additions & 0 deletions tests/test_core.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1404,3 +1404,24 @@ def capture_core_state(_):
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
0