From e35e460e696f542826214fe968c05150ae363256 Mon Sep 17 00:00:00 2001 From: Michael Chisholm Date: Fri, 8 Jan 2021 17:27:03 +1100 Subject: [PATCH] Use parent_id to find cause of logbook events with new contexts (#44416) * Use parent_id to find cause of events with new contexts When looking up the causing event for logbook display, use the `parent_id` of the current context if the current context just points back to the current event. This now shows in the logbook the cause of an event in the case that a component has created a new context from an existing context and tied them together via the `Context.parent_id`. * Fix exception when parent event not available * Use async_Log_entry to avoid jump into executor --- homeassistant/components/logbook/__init__.py | 81 ++++---- tests/components/logbook/test_init.py | 183 +++++++++++++++++++ 2 files changed, 228 insertions(+), 36 deletions(-) diff --git a/homeassistant/components/logbook/__init__.py b/homeassistant/components/logbook/__init__.py index 254d99ed848..e2d8a22c251 100644 --- a/homeassistant/components/logbook/__init__.py +++ b/homeassistant/components/logbook/__init__.py @@ -93,6 +93,7 @@ EVENT_COLUMNS = [ Events.time_fired, Events.context_id, Events.context_user_id, + Events.context_parent_id, ] SCRIPT_AUTOMATION_EVENTS = [EVENT_AUTOMATION_TRIGGERED, EVENT_SCRIPT_STARTED] @@ -320,16 +321,14 @@ def humanify(hass, events, entity_attr_cache, context_lookup): if event.context_user_id: data["context_user_id"] = event.context_user_id - context_event = context_lookup.get(event.context_id) - if context_event and context_event != event: - _augment_data_with_context( - data, - entity_id, - event, - context_event, - entity_attr_cache, - external_events, - ) + _augment_data_with_context( + data, + entity_id, + event, + context_lookup, + entity_attr_cache, + external_events, + ) yield data @@ -340,16 +339,15 @@ def humanify(hass, events, entity_attr_cache, context_lookup): data["domain"] = domain if event.context_user_id: data["context_user_id"] = event.context_user_id - context_event = context_lookup.get(event.context_id) - if context_event: - _augment_data_with_context( - data, - data.get(ATTR_ENTITY_ID), - event, - context_event, - entity_attr_cache, - external_events, - ) + + _augment_data_with_context( + data, + data.get(ATTR_ENTITY_ID), + event, + context_lookup, + entity_attr_cache, + external_events, + ) yield data elif event.event_type == EVENT_HOMEASSISTANT_START: @@ -397,16 +395,14 @@ def humanify(hass, events, entity_attr_cache, context_lookup): if event.context_user_id: data["context_user_id"] = event.context_user_id - context_event = context_lookup.get(event.context_id) - if context_event and context_event != event: - _augment_data_with_context( - data, - entity_id, - event, - context_event, - entity_attr_cache, - external_events, - ) + _augment_data_with_context( + data, + entity_id, + event, + context_lookup, + entity_attr_cache, + external_events, + ) yield data @@ -597,16 +593,27 @@ def _keep_event(hass, event, entities_filter): def _augment_data_with_context( - data, entity_id, event, context_event, entity_attr_cache, external_events + data, entity_id, event, context_lookup, entity_attr_cache, external_events ): - event_type = context_event.event_type + context_event = context_lookup.get(event.context_id) - # State change - context_entity_id = context_event.entity_id - - if entity_id and context_entity_id == entity_id: + if not context_event: return + if event == context_event: + # This is the first event with the given ID. Was it directly caused by + # a parent event? + if event.context_parent_id: + context_event = context_lookup.get(event.context_parent_id) + # Ensure the (parent) context_event exists and is not the root cause of + # this log entry. + if not context_event or event == context_event: + return + + event_type = context_event.event_type + context_entity_id = context_event.entity_id + + # State change if context_entity_id: data["context_entity_id"] = context_entity_id data["context_entity_id_name"] = _entity_name_from_event( @@ -672,6 +679,7 @@ class LazyEventPartialState: "domain", "context_id", "context_user_id", + "context_parent_id", "time_fired_minute", ] @@ -687,6 +695,7 @@ class LazyEventPartialState: self.domain = self._row.domain self.context_id = self._row.context_id self.context_user_id = self._row.context_user_id + self.context_parent_id = self._row.context_parent_id self.time_fired_minute = self._row.time_fired.minute @property diff --git a/tests/components/logbook/test_init.py b/tests/components/logbook/test_init.py index 8360759d564..cd3fb519ded 100644 --- a/tests/components/logbook/test_init.py +++ b/tests/components/logbook/test_init.py @@ -282,6 +282,7 @@ def create_state_changed_event_from_old_new( "time_fired" "context_id" "context_user_id" + "context_parent_id" "state" "entity_id" "domain" @@ -300,6 +301,7 @@ def create_state_changed_event_from_old_new( row.domain = entity_id and ha.split_entity_id(entity_id)[0] row.context_id = None row.context_user_id = None + row.context_parent_id = None row.old_state_id = old_state and 1 row.state_id = new_state and 1 return logbook.LazyEventPartialState(row) @@ -946,6 +948,187 @@ async def test_logbook_entity_context_id(hass, hass_client): assert json_dict[7]["context_user_id"] == "9400facee45711eaa9308bfd3d19e474" +async def test_logbook_entity_context_parent_id(hass, hass_client): + """Test the logbook view links events via context parent_id.""" + await hass.async_add_executor_job(init_recorder_component, hass) + await async_setup_component(hass, "logbook", {}) + await async_setup_component(hass, "automation", {}) + await async_setup_component(hass, "script", {}) + + await hass.async_add_executor_job(hass.data[recorder.DATA_INSTANCE].block_till_done) + + context = ha.Context( + id="ac5bd62de45711eaaeb351041eec8dd9", + user_id="b400facee45711eaa9308bfd3d19e474", + ) + + # An Automation triggering scripts with a new context + automation_entity_id_test = "automation.alarm" + hass.bus.async_fire( + EVENT_AUTOMATION_TRIGGERED, + {ATTR_NAME: "Mock automation", ATTR_ENTITY_ID: automation_entity_id_test}, + context=context, + ) + + child_context = ha.Context( + id="2798bfedf8234b5e9f4009c91f48f30c", + parent_id="ac5bd62de45711eaaeb351041eec8dd9", + user_id="b400facee45711eaa9308bfd3d19e474", + ) + hass.bus.async_fire( + EVENT_SCRIPT_STARTED, + {ATTR_NAME: "Mock script", ATTR_ENTITY_ID: "script.mock_script"}, + context=child_context, + ) + hass.states.async_set( + automation_entity_id_test, + STATE_ON, + {ATTR_FRIENDLY_NAME: "Alarm Automation"}, + context=child_context, + ) + + entity_id_test = "alarm_control_panel.area_001" + hass.states.async_set(entity_id_test, STATE_OFF, context=child_context) + await hass.async_block_till_done() + hass.states.async_set(entity_id_test, STATE_ON, context=child_context) + await hass.async_block_till_done() + entity_id_second = "alarm_control_panel.area_002" + hass.states.async_set(entity_id_second, STATE_OFF, context=child_context) + await hass.async_block_till_done() + hass.states.async_set(entity_id_second, STATE_ON, context=child_context) + await hass.async_block_till_done() + + hass.bus.async_fire(EVENT_HOMEASSISTANT_START) + await hass.async_block_till_done() + + logbook.async_log_entry( + hass, + "mock_name", + "mock_message", + "alarm_control_panel", + "alarm_control_panel.area_003", + child_context, + ) + await hass.async_block_till_done() + + logbook.async_log_entry( + hass, + "mock_name", + "mock_message", + "homeassistant", + None, + child_context, + ) + await hass.async_block_till_done() + + # A state change via service call with the script as the parent + light_turn_off_service_context = ha.Context( + id="9c5bd62de45711eaaeb351041eec8dd9", + parent_id="2798bfedf8234b5e9f4009c91f48f30c", + user_id="9400facee45711eaa9308bfd3d19e474", + ) + hass.states.async_set("light.switch", STATE_ON) + await hass.async_block_till_done() + + hass.bus.async_fire( + EVENT_CALL_SERVICE, + { + ATTR_DOMAIN: "light", + ATTR_SERVICE: "turn_off", + ATTR_ENTITY_ID: "light.switch", + }, + context=light_turn_off_service_context, + ) + await hass.async_block_till_done() + + hass.states.async_set( + "light.switch", STATE_OFF, context=light_turn_off_service_context + ) + await hass.async_block_till_done() + + # An event with a parent event, but the parent event isn't available + missing_parent_context = ha.Context( + id="fc40b9a0d1f246f98c34b33c76228ee6", + parent_id="c8ce515fe58e442f8664246c65ed964f", + user_id="485cacf93ef84d25a99ced3126b921d2", + ) + logbook.async_log_entry( + hass, + "mock_name", + "mock_message", + "alarm_control_panel", + "alarm_control_panel.area_009", + missing_parent_context, + ) + await hass.async_block_till_done() + + await hass.async_add_executor_job(trigger_db_commit, hass) + await hass.async_block_till_done() + await hass.async_add_executor_job(hass.data[recorder.DATA_INSTANCE].block_till_done) + + client = await hass_client() + + # Today time 00:00:00 + start = dt_util.utcnow().date() + start_date = datetime(start.year, start.month, start.day) + + # Test today entries with filter by end_time + end_time = start + timedelta(hours=24) + response = await client.get( + f"/api/logbook/{start_date.isoformat()}?end_time={end_time}" + ) + assert response.status == 200 + json_dict = await response.json() + + assert json_dict[0]["entity_id"] == "automation.alarm" + assert "context_entity_id" not in json_dict[0] + assert json_dict[0]["context_user_id"] == "b400facee45711eaa9308bfd3d19e474" + + # New context, so this looks to be triggered by the Alarm Automation + assert json_dict[1]["entity_id"] == "script.mock_script" + assert json_dict[1]["context_event_type"] == "automation_triggered" + assert json_dict[1]["context_entity_id"] == "automation.alarm" + assert json_dict[1]["context_entity_id_name"] == "Alarm Automation" + assert json_dict[1]["context_user_id"] == "b400facee45711eaa9308bfd3d19e474" + + assert json_dict[2]["entity_id"] == entity_id_test + assert json_dict[2]["context_event_type"] == "script_started" + assert json_dict[2]["context_entity_id"] == "script.mock_script" + assert json_dict[2]["context_entity_id_name"] == "mock script" + assert json_dict[2]["context_user_id"] == "b400facee45711eaa9308bfd3d19e474" + + assert json_dict[3]["entity_id"] == entity_id_second + assert json_dict[3]["context_event_type"] == "script_started" + assert json_dict[3]["context_entity_id"] == "script.mock_script" + assert json_dict[3]["context_entity_id_name"] == "mock script" + assert json_dict[3]["context_user_id"] == "b400facee45711eaa9308bfd3d19e474" + + assert json_dict[4]["domain"] == "homeassistant" + + assert json_dict[5]["entity_id"] == "alarm_control_panel.area_003" + assert json_dict[5]["context_event_type"] == "script_started" + assert json_dict[5]["context_entity_id"] == "script.mock_script" + assert json_dict[5]["domain"] == "alarm_control_panel" + assert json_dict[5]["context_entity_id_name"] == "mock script" + assert json_dict[5]["context_user_id"] == "b400facee45711eaa9308bfd3d19e474" + + assert json_dict[6]["domain"] == "homeassistant" + assert json_dict[6]["context_user_id"] == "b400facee45711eaa9308bfd3d19e474" + + assert json_dict[7]["entity_id"] == "light.switch" + assert json_dict[7]["context_event_type"] == "call_service" + assert json_dict[7]["context_domain"] == "light" + assert json_dict[7]["context_service"] == "turn_off" + assert json_dict[7]["context_user_id"] == "9400facee45711eaa9308bfd3d19e474" + + assert json_dict[8]["entity_id"] == "alarm_control_panel.area_009" + assert json_dict[8]["domain"] == "alarm_control_panel" + assert "context_event_type" not in json_dict[8] + assert "context_entity_id" not in json_dict[8] + assert "context_entity_id_name" not in json_dict[8] + assert json_dict[8]["context_user_id"] == "485cacf93ef84d25a99ced3126b921d2" + + async def test_logbook_context_from_template(hass, hass_client): """Test the logbook view with end_time and entity with automations and scripts.""" await hass.async_add_executor_job(init_recorder_component, hass)