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
This commit is contained in:
J. Nick Koston 2023-04-24 21:22:53 -05:00 committed by GitHub
parent 18532e453a
commit 5114a1400f
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 165 additions and 2 deletions

View File

@ -5,6 +5,7 @@ from collections.abc import Callable, Generator, Sequence
from contextlib import suppress from contextlib import suppress
from dataclasses import dataclass from dataclasses import dataclass
from datetime import datetime as dt from datetime import datetime as dt
import logging
from typing import Any from typing import Any
from sqlalchemy.engine import Result 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 import statement_for_request
from .queries.common import PSEUDO_EVENT_STATE_CHANGED from .queries.common import PSEUDO_EVENT_STATE_CHANGED
_LOGGER = logging.getLogger(__name__)
@dataclass(slots=True) @dataclass(slots=True)
class LogbookRun: class LogbookRun:
@ -206,6 +209,7 @@ def _humanify(
if row.context_only: if row.context_only:
continue continue
event_type = row.event_type event_type = row.event_type
if event_type == EVENT_CALL_SERVICE: if event_type == EVENT_CALL_SERVICE:
continue continue
if event_type is PSEUDO_EVENT_STATE_CHANGED: if event_type is PSEUDO_EVENT_STATE_CHANGED:
@ -235,7 +239,13 @@ def _humanify(
elif event_type in external_events: elif event_type in external_events:
domain, describe_event = external_events[event_type] 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_WHEN] = format_time(row)
data[LOGBOOK_ENTRY_DOMAIN] = domain data[LOGBOOK_ENTRY_DOMAIN] = domain
context_augmenter.augment(data, row, context_id_bin) context_augmenter.augment(data, row, context_id_bin)
@ -341,7 +351,11 @@ class ContextAugmenter:
data[CONTEXT_EVENT_TYPE] = event_type data[CONTEXT_EVENT_TYPE] = event_type
data[CONTEXT_DOMAIN] = domain data[CONTEXT_DOMAIN] = domain
event = self.event_cache.get(context_row) 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): if name := described.get(LOGBOOK_ENTRY_NAME):
data[CONTEXT_NAME] = name data[CONTEXT_NAME] = name
if message := described.get(LOGBOOK_ENTRY_MESSAGE): if message := described.get(LOGBOOK_ENTRY_MESSAGE):

View File

@ -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: async def _async_mock_logbook_platform(hass: HomeAssistant) -> None:
class MockLogbookPlatform: class MockLogbookPlatform:
"""Mock a logbook platform.""" """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) 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( async def _async_mock_entity_with_logbook_platform(
hass: HomeAssistant, entity_registry: er.EntityRegistry hass: HomeAssistant, entity_registry: er.EntityRegistry
) -> er.RegistryEntry: ) -> er.RegistryEntry:
@ -2039,6 +2081,113 @@ async def test_logbook_stream_match_multiple_entities(
) == listeners_without_writes(init_listeners) ) == 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( async def test_event_stream_bad_end_time(
recorder_mock: Recorder, hass: HomeAssistant, hass_ws_client: WebSocketGenerator recorder_mock: Recorder, hass: HomeAssistant, hass_ws_client: WebSocketGenerator
) -> None: ) -> None: