From 5114a1400f3c583b9d71a51c4ab2390b03cd8df8 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Mon, 24 Apr 2023 21:22:53 -0500 Subject: [PATCH] Ensure logbook still responds if describe event throws (#91961) * Ensure logbook still responds if describe event throws If describe fails, the logbook stream should not collapse * Ensure logbook still responds if describe event throws If describe fails, the logbook stream should not collapse --- homeassistant/components/logbook/processor.py | 18 ++- .../components/logbook/test_websocket_api.py | 149 ++++++++++++++++++ 2 files changed, 165 insertions(+), 2 deletions(-) diff --git a/homeassistant/components/logbook/processor.py b/homeassistant/components/logbook/processor.py index 3aa486272e1..671f8f8f1c2 100644 --- a/homeassistant/components/logbook/processor.py +++ b/homeassistant/components/logbook/processor.py @@ -5,6 +5,7 @@ from collections.abc import Callable, Generator, Sequence from contextlib import suppress from dataclasses import dataclass from datetime import datetime as dt +import logging from typing import Any from sqlalchemy.engine import Result @@ -64,6 +65,8 @@ from .models import EventAsRow, LazyEventPartialState, LogbookConfig, async_even from .queries import statement_for_request from .queries.common import PSEUDO_EVENT_STATE_CHANGED +_LOGGER = logging.getLogger(__name__) + @dataclass(slots=True) class LogbookRun: @@ -206,6 +209,7 @@ def _humanify( if row.context_only: continue event_type = row.event_type + if event_type == EVENT_CALL_SERVICE: continue if event_type is PSEUDO_EVENT_STATE_CHANGED: @@ -235,7 +239,13 @@ def _humanify( elif event_type in external_events: domain, describe_event = external_events[event_type] - data = describe_event(event_cache.get(row)) + try: + data = describe_event(event_cache.get(row)) + except Exception: # pylint: disable=broad-except + _LOGGER.exception( + "Error with %s describe event for %s", domain, event_type + ) + continue data[LOGBOOK_ENTRY_WHEN] = format_time(row) data[LOGBOOK_ENTRY_DOMAIN] = domain context_augmenter.augment(data, row, context_id_bin) @@ -341,7 +351,11 @@ class ContextAugmenter: data[CONTEXT_EVENT_TYPE] = event_type data[CONTEXT_DOMAIN] = domain event = self.event_cache.get(context_row) - described = describe_event(event) + try: + described = describe_event(event) + except Exception: # pylint: disable=broad-except + _LOGGER.exception("Error with %s describe event for %s", domain, event_type) + return if name := described.get(LOGBOOK_ENTRY_NAME): data[CONTEXT_NAME] = name if message := described.get(LOGBOOK_ENTRY_MESSAGE): diff --git a/tests/components/logbook/test_websocket_api.py b/tests/components/logbook/test_websocket_api.py index 9b0b3f2221e..9e991795083 100644 --- a/tests/components/logbook/test_websocket_api.py +++ b/tests/components/logbook/test_websocket_api.py @@ -60,6 +60,31 @@ def listeners_without_writes(listeners: dict[str, int]) -> dict[str, int]: } +async def _async_mock_logbook_platform_with_broken_describe( + hass: HomeAssistant, +) -> None: + class MockLogbookPlatform: + """Mock a logbook platform with broken describe.""" + + @core.callback + def async_describe_events( + hass: HomeAssistant, + async_describe_event: Callable[ + [str, str, Callable[[Event], dict[str, str]]], None + ], + ) -> None: + """Describe logbook events.""" + + @core.callback + def async_describe_test_event(event: Event) -> dict[str, str]: + """Describe mock logbook event.""" + raise ValueError("Broken") + + async_describe_event("test", "mock_event", async_describe_test_event) + + await logbook._process_logbook_platform(hass, "test", MockLogbookPlatform) + + async def _async_mock_logbook_platform(hass: HomeAssistant) -> None: class MockLogbookPlatform: """Mock a logbook platform.""" @@ -86,6 +111,23 @@ async def _async_mock_logbook_platform(hass: HomeAssistant) -> None: await logbook._process_logbook_platform(hass, "test", MockLogbookPlatform) +async def _async_mock_entity_with_broken_logbook_platform( + hass: HomeAssistant, entity_registry: er.EntityRegistry +) -> er.RegistryEntry: + """Mock an integration that provides an entity that are described by the logbook that raises.""" + entry = MockConfigEntry(domain="test", data={"first": True}, options=None) + entry.add_to_hass(hass) + entry = entity_registry.async_get_or_create( + platform="test", + domain="sensor", + config_entry=entry, + unique_id="1234", + suggested_object_id="test", + ) + await _async_mock_logbook_platform_with_broken_describe(hass) + return entry + + async def _async_mock_entity_with_logbook_platform( hass: HomeAssistant, entity_registry: er.EntityRegistry ) -> er.RegistryEntry: @@ -2039,6 +2081,113 @@ async def test_logbook_stream_match_multiple_entities( ) == listeners_without_writes(init_listeners) +@patch("homeassistant.components.logbook.websocket_api.EVENT_COALESCE_TIME", 0) +async def test_logbook_stream_match_multiple_entities_one_with_broken_logbook_platform( + recorder_mock: Recorder, + hass: HomeAssistant, + hass_ws_client: WebSocketGenerator, + entity_registry: er.EntityRegistry, + caplog: pytest.LogCaptureFixture, +) -> None: + """Test logbook stream with a described integration that uses multiple entities. + + One of the entities has a broken logbook platform. + """ + now = dt_util.utcnow() + await asyncio.gather( + *[ + async_setup_component(hass, comp, {}) + for comp in ("homeassistant", "logbook", "automation", "script") + ] + ) + entry = await _async_mock_entity_with_broken_logbook_platform(hass, entity_registry) + entity_id = entry.entity_id + hass.states.async_set(entity_id, STATE_ON) + + await hass.async_block_till_done() + + await async_wait_recording_done(hass) + websocket_client = await hass_ws_client() + init_listeners = hass.bus.async_listeners() + await websocket_client.send_json( + { + "id": 7, + "type": "logbook/event_stream", + "start_time": now.isoformat(), + "entity_ids": [entity_id], + } + ) + + msg = await asyncio.wait_for(websocket_client.receive_json(), 2) + assert msg["id"] == 7 + assert msg["type"] == TYPE_RESULT + assert msg["success"] + + # There are no answers to our initial query + # so we get an empty reply. This is to ensure + # consumers of the api know there are no results + # and its not a failure case. This is useful + # in the frontend so we can tell the user there + # are no results vs waiting for them to appear + msg = await asyncio.wait_for(websocket_client.receive_json(), 2) + assert msg["id"] == 7 + assert msg["type"] == "event" + assert msg["event"]["events"] == [] + assert "partial" in msg["event"] + await async_wait_recording_done(hass) + + msg = await asyncio.wait_for(websocket_client.receive_json(), 2) + assert msg["id"] == 7 + assert msg["type"] == "event" + assert msg["event"]["events"] == [] + assert "partial" not in msg["event"] + await async_wait_recording_done(hass) + + hass.states.async_set("binary_sensor.should_not_appear", STATE_ON) + hass.states.async_set("binary_sensor.should_not_appear", STATE_OFF) + context = core.Context( + id="01GTDGKBCH00GW0X276W5TEDDD", + user_id="b400facee45711eaa9308bfd3d19e474", + ) + hass.bus.async_fire( + "mock_event", {"entity_id": ["sensor.any", entity_id]}, context=context + ) + hass.bus.async_fire("mock_event", {"entity_id": [f"sensor.any,{entity_id}"]}) + hass.bus.async_fire("mock_event", {"entity_id": ["sensor.no_match", "light.off"]}) + hass.states.async_set(entity_id, STATE_OFF, context=context) + await hass.async_block_till_done() + + msg = await asyncio.wait_for(websocket_client.receive_json(), 2) + assert msg["id"] == 7 + assert msg["type"] == "event" + assert msg["event"]["events"] == [ + { + "entity_id": "sensor.test", + "context_domain": "test", + "context_event_type": "mock_event", + "context_user_id": "b400facee45711eaa9308bfd3d19e474", + "state": "off", + "when": ANY, + }, + ] + + await websocket_client.send_json( + {"id": 8, "type": "unsubscribe_events", "subscription": 7} + ) + msg = await asyncio.wait_for(websocket_client.receive_json(), 2) + + assert msg["id"] == 8 + assert msg["type"] == TYPE_RESULT + assert msg["success"] + + # Check our listener got unsubscribed + assert listeners_without_writes( + hass.bus.async_listeners() + ) == listeners_without_writes(init_listeners) + + assert "Error with test describe event" in caplog.text + + async def test_event_stream_bad_end_time( recorder_mock: Recorder, hass: HomeAssistant, hass_ws_client: WebSocketGenerator ) -> None: