From 18a7c59e1c829cb1725be12e74c5ea09e71ffb04 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sat, 13 May 2023 09:14:57 +0900 Subject: [PATCH 1/2] Add ssl object logging to the profiler --- homeassistant/components/profiler/__init__.py | 84 +++++++++++++++++++ .../components/profiler/services.yaml | 3 + 2 files changed, 87 insertions(+) diff --git a/homeassistant/components/profiler/__init__.py b/homeassistant/components/profiler/__init__.py index f558b7301c5f92..beb6b03baa16f6 100644 --- a/homeassistant/components/profiler/__init__.py +++ b/homeassistant/components/profiler/__init__.py @@ -1,10 +1,13 @@ """The profiler integration.""" import asyncio +from asyncio.sslproto import SSLProtocol, _SSLProtocolTransport from contextlib import suppress from datetime import timedelta from functools import _lru_cache_wrapper +import json import logging import reprlib +import ssl import sys import threading import time @@ -19,8 +22,10 @@ from homeassistant.const import CONF_SCAN_INTERVAL, CONF_TYPE from homeassistant.core import HomeAssistant, ServiceCall, callback from homeassistant.exceptions import HomeAssistantError +from homeassistant.helpers import template import homeassistant.helpers.config_validation as cv from homeassistant.helpers.event import async_track_time_interval +from homeassistant.helpers.json import ExtendedJSONEncoder from homeassistant.helpers.service import async_register_admin_service from .const import DOMAIN @@ -35,6 +40,7 @@ SERVICE_LRU_STATS = "lru_stats" SERVICE_LOG_THREAD_FRAMES = "log_thread_frames" SERVICE_LOG_EVENT_LOOP_SCHEDULED = "log_event_loop_scheduled" +SERVICE_LOG_SSL = "log_ssl" _LRU_CACHE_WRAPPER_OBJECT = _lru_cache_wrapper.__name__ _SQLALCHEMY_LRU_OBJECT = "LRUCache" @@ -58,6 +64,7 @@ SERVICE_LRU_STATS, SERVICE_LOG_THREAD_FRAMES, SERVICE_LOG_EVENT_LOOP_SCHEDULED, + SERVICE_LOG_SSL, ) DEFAULT_SCAN_INTERVAL = timedelta(seconds=30) @@ -81,6 +88,9 @@ async def async_setup_entry( # noqa: C901 domain_data = hass.data[DOMAIN] = {} async def _async_run_profile(call: ServiceCall) -> None: + _LOGGER.warning( + "Modules: %s", json.dumps(sys.modules, indent=2, cls=ExtendedJSONEncoder) + ) async with lock: await _async_generate_profile(hass, call) @@ -208,6 +218,15 @@ def _lru_stats(call: ServiceCall) -> None: maybe_lru.get_stats(), ) + _LOGGER.critical( + "Cache stats for LRU template_states: %s", + template.CACHED_TEMPLATE_LRU.get_stats(), # type: ignore[attr-defined] + ) + _LOGGER.critical( + "Cache stats for LRU template_states_no_collect: %s", + template.CACHED_TEMPLATE_NO_COLLECT_LRU.get_stats(), # type: ignore[attr-defined] + ) + for lru in objgraph.by_type(_SQLALCHEMY_LRU_OBJECT): if (data := getattr(lru, "_data", None)) and isinstance(data, dict): for key, value in dict(data).items(): @@ -255,6 +274,64 @@ async def _async_dump_scheduled(call: ServiceCall) -> None: arepr.maxstring = original_maxstring arepr.maxother = original_maxother + async def _async_dump_ssl(call: ServiceCall) -> None: + """Log all ssl objects in memory.""" + # Imports deferred to avoid loading modules + # in memory since usually only one part of this + # integration is used at a time + import objgraph # pylint: disable=import-outside-toplevel + + for obj in objgraph.by_type("SSLObject"): + obj = cast(ssl.SSLObject, obj) + try: + cert = obj.getpeercert() + except ValueError as ex: + cert = str(ex) + _LOGGER.critical( + "SSLObject %s server_hostname=%s peercert=%s", + obj, + obj.server_hostname, + cert, + ) + + for obj in objgraph.by_type("SSLProtocol"): + obj = cast(SSLProtocol, obj) + sock = None + if transport := obj._transport: # pylint: disable=protected-access + sock = transport.get_extra_info("socket") + _LOGGER.critical( + "SSLProtocol %s socket=%s", + obj, + sock, + ) + + for obj in objgraph.by_type("_SSLProtocolTransport"): + obj = cast(_SSLProtocolTransport, obj) + try: + ssl_proto = obj.get_protocol() + except AttributeError: + ssl_proto = None + try: + sock = obj.get_extra_info("socket") + except AttributeError: + sock = None + try: + ssl_object = obj.get_extra_info("ssl_object") + except AttributeError: + ssl_object = None + try: + peercert = obj.get_extra_info("peercert") + except (AttributeError, ValueError) as ex: + peercert = str(ex) + _LOGGER.critical( + "_SSLProtocolTransport %s ssl_proto=%s ssl_object=%s peercert=%s sock=%s", + obj, + ssl_proto, + ssl_object, + peercert, + sock, + ) + async_register_admin_service( hass, DOMAIN, @@ -349,6 +426,13 @@ async def _async_dump_scheduled(call: ServiceCall) -> None: _async_dump_scheduled, ) + async_register_admin_service( + hass, + DOMAIN, + SERVICE_LOG_SSL, + _async_dump_ssl, + ) + return True diff --git a/homeassistant/components/profiler/services.yaml b/homeassistant/components/profiler/services.yaml index 3bd6d7636ac6f1..9aff91fe94905c 100644 --- a/homeassistant/components/profiler/services.yaml +++ b/homeassistant/components/profiler/services.yaml @@ -85,3 +85,6 @@ log_thread_frames: log_event_loop_scheduled: name: Log event loop scheduled description: Log what is scheduled in the event loop. +log_ssl: + name: Log SSL objects in memory + description: Log SSL objects to look for leaks. From bc2d3e99e6404eaf85981751f737651122319a66 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sat, 13 May 2023 09:21:23 +0900 Subject: [PATCH 2/2] Add profiler service to investigate ssl object leaks related issue https://github.com/aio-libs/aiohttp/issues/7252 related PR https://github.com/home-assistant/core/pull/93013 --- homeassistant/components/profiler/__init__.py | 15 ------ tests/components/profiler/test_init.py | 54 +++++++++++++++++++ 2 files changed, 54 insertions(+), 15 deletions(-) diff --git a/homeassistant/components/profiler/__init__.py b/homeassistant/components/profiler/__init__.py index beb6b03baa16f6..2c115ceb1cabfc 100644 --- a/homeassistant/components/profiler/__init__.py +++ b/homeassistant/components/profiler/__init__.py @@ -4,7 +4,6 @@ from contextlib import suppress from datetime import timedelta from functools import _lru_cache_wrapper -import json import logging import reprlib import ssl @@ -22,10 +21,8 @@ from homeassistant.const import CONF_SCAN_INTERVAL, CONF_TYPE from homeassistant.core import HomeAssistant, ServiceCall, callback from homeassistant.exceptions import HomeAssistantError -from homeassistant.helpers import template import homeassistant.helpers.config_validation as cv from homeassistant.helpers.event import async_track_time_interval -from homeassistant.helpers.json import ExtendedJSONEncoder from homeassistant.helpers.service import async_register_admin_service from .const import DOMAIN @@ -88,9 +85,6 @@ async def async_setup_entry( # noqa: C901 domain_data = hass.data[DOMAIN] = {} async def _async_run_profile(call: ServiceCall) -> None: - _LOGGER.warning( - "Modules: %s", json.dumps(sys.modules, indent=2, cls=ExtendedJSONEncoder) - ) async with lock: await _async_generate_profile(hass, call) @@ -218,15 +212,6 @@ def _lru_stats(call: ServiceCall) -> None: maybe_lru.get_stats(), ) - _LOGGER.critical( - "Cache stats for LRU template_states: %s", - template.CACHED_TEMPLATE_LRU.get_stats(), # type: ignore[attr-defined] - ) - _LOGGER.critical( - "Cache stats for LRU template_states_no_collect: %s", - template.CACHED_TEMPLATE_NO_COLLECT_LRU.get_stats(), # type: ignore[attr-defined] - ) - for lru in objgraph.by_type(_SQLALCHEMY_LRU_OBJECT): if (data := getattr(lru, "_data", None)) and isinstance(data, dict): for key, value in dict(data).items(): diff --git a/tests/components/profiler/test_init.py b/tests/components/profiler/test_init.py index ca998f25f5f0ad..7f63f22ca072e8 100644 --- a/tests/components/profiler/test_init.py +++ b/tests/components/profiler/test_init.py @@ -15,6 +15,7 @@ CONF_SECONDS, SERVICE_DUMP_LOG_OBJECTS, SERVICE_LOG_EVENT_LOOP_SCHEDULED, + SERVICE_LOG_SSL, SERVICE_LOG_THREAD_FRAMES, SERVICE_LRU_STATS, SERVICE_MEMORY, @@ -387,3 +388,56 @@ def __repr__(self): await hass.services.async_call( DOMAIN, SERVICE_STOP_LOG_OBJECT_SOURCES, {}, blocking=True ) + + +async def test_log_ssl(hass: HomeAssistant, caplog: pytest.LogCaptureFixture) -> None: + """Test logging ssl objects.""" + + 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() + + class SSLProtocol: + def __init__(self): + """Mock an SSLProtocol.""" + self._transport = None + + class SSLObject: + def __init__(self): + """Mock an SSLObject.""" + self._transport = None + + def getpeercert(self, binary_form=False): + """Mock getpeercert.""" + return {"subject": (("commonName", "test"),)} + + def server_hostname(self): + """Mock server_hostname.""" + return "test" + + class _SSLProtocolTransport: + def __init__(self): + """Mock an _SSLProtocolTransport.""" + + ssl_protocol = SSLProtocol() + ssl_object = SSLObject() + ssl_protocol_transport = _SSLProtocolTransport() + assert hass.services.has_service(DOMAIN, SERVICE_LOG_SSL) + + def _mock_by_type(type_): + if type_ == "SSLProtocol": + return [ssl_protocol] + if type_ == "SSLObject": + return [ssl_object] + if type_ == "_SSLProtocolTransport": + return [ssl_protocol_transport] + raise ValueError("Unknown type") + + with patch("objgraph.by_type", side_effect=_mock_by_type): + await hass.services.async_call(DOMAIN, SERVICE_LOG_SSL, blocking=True) + + assert "SSLProtocol" in caplog.text + assert "SSLObject" in caplog.text + assert "_SSLProtocolTransport" in caplog.text