Add debug logging for when a chain of tasks blocks startup

[bdraco]

Proposed change

Add debug logging for when a chain of tasks blocks startup

This is a followup to
#38134 which only
added logging when a single task blocks for more than 60 seconds

This change handles the case were we have a chain of tasks that
block

Type of change

• Dependency upgrade
• Bugfix (non-breaking change which fixes an issue)
• New integration (thank you!)
• New feature (which adds functionality to an existing integration)
• Breaking change (fix/feature causing existing functionality to break)
• Code quality improvements to existing code or addition of tests

Example entry for configuration.yaml:

# Example configuration.yaml

Additional information

• This PR fixes or closes issue: fixes #
• This PR is related to issue:
• Link to documentation pull request:

Checklist

• The code change is tested and works locally.
• Local tests pass. Your PR cannot be merged unless tests pass
• There is no commented out code in this PR.
• I have followed the development checklist
• The code has been formatted using Black (black --fast homeassistant tests)
• Tests have been added to verify that the new code works.

If user exposed functionality or configuration variables are added/changed:

• Documentation added/updated for www.home-assistant.io

If the code communicates with devices, web services, or third-party tools:

• The manifest file has all fields filled out correctly.
  Updated and included derived files by running: python3 -m script.hassfest.
• New or updated dependencies have been added to requirements_all.txt.
  Updated by running python3 -m script.gen_requirements_all.
• Untested files have been added to .coveragerc.

The integration reached or maintains the following Integration Quality Scale:

• No score or internal
• 🥈 Silver
• 🥇 Gold
• 🏆 Platinum

[bdraco]

Testing:

Modified smartir to add the following in async_setup

    async def _task_chain_1():
        await asyncio.sleep(1)
        hass.async_create_task(_task_chain_2())

    async def _task_chain_2():
        await asyncio.sleep(1)
        hass.async_create_task(_task_chain_1())

    hass.async_create_task(_task_chain_1())

Logging as expected after 60 seconds of waiting:

2020-07-28 05:52:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9430' coro=<async_setup.<locals>._task_chain_2() done, defined at /config/custom_components/smartir/__init__.py:59> result=None>
2020-07-28 05:52:04 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9435' coro=<async_setup.<locals>._task_chain_1() done, defined at /config/custom_components/smartir/__init__.py:55> result=None>
2020-07-28 05:52:05 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9441' coro=<async_setup.<locals>._task_chain_2() done, defined at /config/custom_components/smartir/__init__.py:59> result=None>
2020-07-28 05:52:06 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9442' coro=<async_setup.<locals>._task_chain_1() done, defined at /config/custom_components/smartir/__init__.py:55> result=None>
2020-07-28 05:52:07 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9449' coro=<async_setup.<locals>._task_chain_2() done, defined at /config/custom_components/smartir/__init__.py:59> result=None>

[mweinelt]

With this newly introduced testcase I'm most of the time, not always, not on all machines, running into the following test failure.

________________ test_chained_logging_hits_log_timeout[pyloop] _________________

hass = <homeassistant.core.HomeAssistant object at 0x7ffff5c0b3a0>
caplog = <_pytest.logging.LogCaptureFixture object at 0x7ffff5c0bd30>

    async def test_chained_logging_hits_log_timeout(hass, caplog):
        """Ensure we log which task is blocking startup when there is a task chain and debug logging is on."""
        caplog.set_level(logging.DEBUG)

        created = 0

        async def _task_chain_1():
            nonlocal created
            created += 1
            if created > 10:
                return
            hass.async_create_task(_task_chain_2())

        async def _task_chain_2():
            nonlocal created
            created += 1
            if created > 10:
                return
            hass.async_create_task(_task_chain_1())

        with patch.object(ha, "BLOCK_LOG_TIMEOUT", 0.1):
            hass.async_create_task(_task_chain_1())
            await hass.async_block_till_done()

>       assert "_task_chain_" in caplog.text
E       AssertionError: assert '_task_chain_' in ''
E        +  where '' = <_pytest.logging.LogCaptureFixture object at 0x7ffff5c0bd30>.text

tests/test_core.py:1443: AssertionError

The environment is

============================= test session starts ==============================
platform linux -- Python 3.8.3, pytest-5.4.3, py-1.8.1, pluggy-0.13.1
rootdir: /build/source, inifile: setup.cfg, testpaths: tests
plugins: aiohttp-0.3.0, requests-mock-1.8.0

[bdraco]

Please open an issue.