Add profiler set_asyncio_debug service (#113447)

* Add profiler set_asyncio_debug service

Currently when a user has a problem with there event loop being blocked
the simplest way to enable asyncio debug is to add `debugpy:` to
`configuration.yaml`, however this approach slows the system which
makes the report less useful and harder to track down the problem.

We need a lightweight way to enable debug mode so users can report
problems with the event loop being blocked, and we have a better
chance of finding the source without side effects

* logging

* logging

* logging

* comments

* fix

* icon

* only if enabled

* coverage

homeassistant/components/profiler/__init__.py

@@ -36,6 +36,7 @@ SERVICE_DUMP_LOG_OBJECTS = "dump_log_objects"
 SERVICE_LRU_STATS = "lru_stats"
 SERVICE_LOG_THREAD_FRAMES = "log_thread_frames"
 SERVICE_LOG_EVENT_LOOP_SCHEDULED = "log_event_loop_scheduled"
+SERVICE_SET_ASYNCIO_DEBUG = "set_asyncio_debug"
 
 _LRU_CACHE_WRAPPER_OBJECT = _lru_cache_wrapper.__name__
 _SQLALCHEMY_LRU_OBJECT = "LRUCache"
@@ -57,12 +58,14 @@ SERVICES = (
     SERVICE_LRU_STATS,
     SERVICE_LOG_THREAD_FRAMES,
     SERVICE_LOG_EVENT_LOOP_SCHEDULED,
+    SERVICE_SET_ASYNCIO_DEBUG,
 )
 
 DEFAULT_SCAN_INTERVAL = timedelta(seconds=30)
 
 DEFAULT_MAX_OBJECTS = 5
 
+CONF_ENABLED = "enabled"
 CONF_SECONDS = "seconds"
 CONF_MAX_OBJECTS = "max_objects"
 
@@ -254,6 +257,19 @@ async def async_setup_entry(  # noqa: C901
             arepr.maxstring = original_maxstring
             arepr.maxother = original_maxother
 
+    async def _async_asyncio_debug(call: ServiceCall) -> None:
+        """Enable or disable asyncio debug."""
+        enabled = call.data[CONF_ENABLED]
+        # Always log this at critical level so we know when
+        # it's been changed when reviewing logs
+        _LOGGER.critical("Setting asyncio debug to %s", enabled)
+        # Make sure the logger is set to at least INFO or
+        # we won't see the messages
+        base_logger = logging.getLogger()
+        if enabled and base_logger.getEffectiveLevel() > logging.INFO:
+            base_logger.setLevel(logging.INFO)
+        hass.loop.set_debug(enabled)
+
     async_register_admin_service(
         hass,
         DOMAIN,
@@ -348,6 +364,14 @@ async def async_setup_entry(  # noqa: C901
         _async_dump_scheduled,
     )
 
+    async_register_admin_service(
+        hass,
+        DOMAIN,
+        SERVICE_SET_ASYNCIO_DEBUG,
+        _async_asyncio_debug,
+        schema=vol.Schema({vol.Optional(CONF_ENABLED, default=True): cv.boolean}),
+    )
+
     return True
 
 

homeassistant/components/profiler/icons.json

@@ -9,6 +9,7 @@
     "stop_log_object_sources": "mdi:stop",
     "lru_stats": "mdi:chart-areaspline",
     "log_thread_frames": "mdi:format-list-bulleted",
-    "log_event_loop_scheduled": "mdi:calendar-clock"
+    "log_event_loop_scheduled": "mdi:calendar-clock",
+    "set_asyncio_debug": "mdi:bug-check"
   }
 }

homeassistant/components/profiler/services.yaml

@@ -53,3 +53,9 @@ stop_log_object_sources:
 lru_stats:
 log_thread_frames:
 log_event_loop_scheduled:
+set_asyncio_debug:
+  fields:
+    enabled:
+      default: true
+      selector:
+        boolean:

homeassistant/components/profiler/strings.json

@@ -83,6 +83,16 @@
     "log_event_loop_scheduled": {
       "name": "Log event loop scheduled",
       "description": "Logs what is scheduled in the event loop."
+    },
+    "set_asyncio_debug": {
+      "name": "Set asyncio debug",
+      "description": "Enable or disable asyncio debug.",
+      "fields": {
+        "enabled": {
+          "name": "Enabled",
+          "description": "Whether to enable or disable asyncio debug."
+        }
+      }
     }
   }
 }

tests/components/profiler/test_init.py

@@ -2,6 +2,7 @@
 
 from datetime import timedelta
 from functools import lru_cache
+import logging
 import os
 from pathlib import Path
 from unittest.mock import patch
@@ -12,12 +13,14 @@ import pytest
 from homeassistant.components.profiler import (
     _LRU_CACHE_WRAPPER_OBJECT,
     _SQLALCHEMY_LRU_OBJECT,
+    CONF_ENABLED,
     CONF_SECONDS,
     SERVICE_DUMP_LOG_OBJECTS,
     SERVICE_LOG_EVENT_LOOP_SCHEDULED,
     SERVICE_LOG_THREAD_FRAMES,
     SERVICE_LRU_STATS,
     SERVICE_MEMORY,
+    SERVICE_SET_ASYNCIO_DEBUG,
     SERVICE_START,
     SERVICE_START_LOG_OBJECT_SOURCES,
     SERVICE_START_LOG_OBJECTS,
@@ -368,3 +371,48 @@ async def test_log_object_sources(
         await hass.services.async_call(
             DOMAIN, SERVICE_STOP_LOG_OBJECT_SOURCES, {}, blocking=True
         )
+
+
+async def test_set_asyncio_debug(
+    hass: HomeAssistant, caplog: pytest.LogCaptureFixture
+) -> None:
+    """Test setting asyncio debug."""
+
+    entry = MockConfigEntry(domain=DOMAIN)
+    entry.add_to_hass(hass)
+
+    assert await hass.config_entries.async_setup(entry.entry_id)
+    await hass.async_block_till_done()
+
+    assert hass.services.has_service(DOMAIN, SERVICE_SET_ASYNCIO_DEBUG)
+
+    hass.loop.set_debug(False)
+    original_level = logging.getLogger().getEffectiveLevel()
+    logging.getLogger().setLevel(logging.WARNING)
+
+    await hass.services.async_call(
+        DOMAIN, SERVICE_SET_ASYNCIO_DEBUG, {CONF_ENABLED: False}, blocking=True
+    )
+    # Ensure logging level is only increased if we enable
+    assert logging.getLogger().getEffectiveLevel() == logging.WARNING
+
+    await hass.services.async_call(DOMAIN, SERVICE_SET_ASYNCIO_DEBUG, {}, blocking=True)
+    assert hass.loop.get_debug() is True
+
+    # Ensure logging is at least at INFO level
+    assert logging.getLogger().getEffectiveLevel() == logging.INFO
+
+    await hass.services.async_call(
+        DOMAIN, SERVICE_SET_ASYNCIO_DEBUG, {CONF_ENABLED: False}, blocking=True
+    )
+    assert hass.loop.get_debug() is False
+
+    await hass.services.async_call(
+        DOMAIN, SERVICE_SET_ASYNCIO_DEBUG, {CONF_ENABLED: True}, blocking=True
+    )
+    assert hass.loop.get_debug() is True
+
+    logging.getLogger().setLevel(original_level)
+
+    assert await hass.config_entries.async_unload(entry.entry_id)
+    await hass.async_block_till_done()