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

@@ -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)
+                _augment_data_with_context(
-                if context_event and context_event != event:
+                    data,
-                    _augment_data_with_context(
+                    entity_id,
-                        data,
+                    event,
-                        entity_id,
+                    context_lookup,
-                        event,
+                    entity_attr_cache,
-                        context_event,
+                    external_events,
-                        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(
-                    _augment_data_with_context(
+                    data,
-                        data,
+                    data.get(ATTR_ENTITY_ID),
-                        data.get(ATTR_ENTITY_ID),
+                    event,
-                        event,
+                    context_lookup,
-                        context_event,
+                    entity_attr_cache,
-                        entity_attr_cache,
+                    external_events,
-                        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)
+                _augment_data_with_context(
-                if context_event and context_event != event:
+                    data,
-                    _augment_data_with_context(
+                    entity_id,
-                        data,
+                    event,
-                        entity_id,
+                    context_lookup,
-                        event,
+                    entity_attr_cache,
-                        context_event,
+                    external_events,
-                        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
+    if not context_event:
-    context_entity_id = context_event.entity_id
-
-    if entity_id and context_entity_id == entity_id:
         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

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)