logbook card show no automation trigger after update

[yasars]

Checklist

• I have updated to the latest available Home Assistant version.
• I have cleared the cache of my browser.
• I have tried a different browser to see if it is related to my browser.

Describe the issue you are experiencing

i have a problem , after update to the latest update, i can not see the trigged automation info , in my lovelance logbook card in the system logbook i see it but not in the card... before update no problem any one have an solution<? bug in automation.trigger? when i set on/off i see it in log card , not when it trigged :(

Describe the behavior you expected

automation.trigger not showing in the logbook card ... 2021.7 no problem

Steps to reproduce the issue

1. see picture

...

What version of Home Assistant Core has the issue?

2021.8.2

What was the last working version of Home Assistant Core?

2021.7

In which browser are you experiencing the issue with?

all

Which operating system are you using to run this browser?

Big Sur

State of relevant entities

No response

Problem-relevant frontend configuration

No response

Javascript errors shown in your browser console/inspector

No response

Additional information

[pratesbh]

Probably same issue here: custom entries created with logbook.log service are no longer shown in logbook card. They are still shown in the logbook menu, so only the lovelace card was affected, I think.
Tested on 2021.8.2

[mrsnyds]

My experience is the same as pratesbh ... the problem is only with custom logbook entries created with the logbook.log service. If I configure the logbook card to display entries for an entry that is automatically created by HASS, the card will display those entries, as before. Just tested and this issue is still present in 2021.8.6

[mstuij]

I have the same problem. I have this dummy sensor:

sensor:
  - platform: template
    sensors:
      dummy_log_entity:
        friendly_name: "Dummy log entity"
        value_template: "on"

When I create a log entry (by developer tools, Node-Red, etc...) on this sensor, it is visible in logbook on the sidebar. But it is NOT visible in the lovelace logbook card.

[N3rdix]

Same issue here, I use the logbook.log service and it’s visible in the logbooks but not the card.
Stopped working with 2021.8

[bennijamm]

+1

[tathamoddie]

I've been debugging against 2021.9.1

Expectations

I believe we should be able to call the logbook.log service to write a custom note related to an entity, and then see that note on both the Logbook panel, and the Logbook card.

Since 2021.8, these messages show on the panel, but not the card.

Why are the logger panel and the logger card returning different results?

The logbook page does a request to:

http://homeassistant:8123/api/logbook/{start_time}?end_time={end_time}&entity={entity_id}

The logbook panel does a request to

http://homeassistant:8123/api/logbook/{start_time}?end_time={end_time}&entity={entity_id}&entity_matches_only=

For the same timespan, this additional query parameter causes two changes in my environment:

1. It returns less results, dropping ones where I've explicitly written log messages related to the entity
2. It returns less properties for each (specifically, it drops the context_* properties)

What does entity_matches_only do to the query?

It introduces an extra SQL query filter:

def _apply_event_entity_id_matchers(events_query, entity_ids):
    return events_query.filter(
        sqlalchemy.or_(
            *(
                Events.event_data.contains(ENTITY_ID_JSON_TEMPLATE.format(entity_id))
                for entity_id in entity_ids
            )
        )
    )

Where that constant is currently defined as:

ENTITY_ID_JSON_TEMPLATE = '"entity_id": ?"{}"'

This produces a string to look for that will never be found in a JSON blob (e.g. "entity_id": ?"sensor.foo"), thus causing this part of the query to never match.

What has changed?

Sep 2020

The entity_matches_only concept was introduced by #39555

In the signature for logbook._get_events, the default for this argument was set as False, and still is today:

core/homeassistant/components/logbook/__init__.py

Lines 413 to 422 in c875ff8

	def _get_events(
	hass,
	start_day,
	end_day,
	entity_ids=None,
	filters=None,
	entities_filter=None,
	entity_matches_only=False,
	context_id=None,
	):

Nov 2020

The Logbook card was introduced by home-assistant/frontend#6976.

Since its introduction, it has set entity_matches_only to true in the underlying data request:

https://github.com/home-assistant/frontend/pull/6976/files#diff-0b35de5f4b464effc0ac60e26e6977106174e946497ba765e7c07b235eae964fR232-R238

This hasn't changed since.

Jul 2021

A database optimisation was introduced by #53364. This optimisation changes the JSON encoding of the JSON blobs in the events table to use less whitespace, aiming for storage savings.

It was noted that this PR as initially implemented would break some current logbook related queries: #53364 (comment)

A fix for this was implemented as ad5d90d and included in the PR before it landed.

The timing of this change lines up with when this issue was reported, and it touches the template used in this branch of the query.

Where to?

@bdraco - You introduced the entity_matches_only path. Can you see a reason why the Logbook card should explicitly set this to true, where the Logbook panel does not?

@zsarnett - You built the card. Can you remember an explicit intent for setting entity_matches_only to true in the query for the card?

[tathamoddie]

This is a flakey code path overall because of the string matching, but I think the bug particularly came to life in https://github.com/home-assistant/core/pull/53364/files#diff-1c6068d2025d7d23111929ff066852fba3a7ebc285d8c9c3f05563ee257fa6f2R51-R54, landed with #53364

These four lines were updated to be 'whitespace-flexible', so they could work with the compact JSON optimisation:

ENTITY_ID_JSON_TEMPLATE = '"entity_id": "{}"'
ENTITY_ID_JSON_EXTRACT = re.compile('"entity_id": "([^"]+)"')
DOMAIN_JSON_EXTRACT = re.compile('"domain": "([^"]+)"')
ICON_JSON_EXTRACT = re.compile('"icon": "([^"]+)"')

They were updated to:

ENTITY_ID_JSON_TEMPLATE = '"entity_id": ?"{}"'
ENTITY_ID_JSON_EXTRACT = re.compile('"entity_id": ?"([^"]+)"')
DOMAIN_JSON_EXTRACT = re.compile('"domain": ?"([^"]+)"')
ICON_JSON_EXTRACT = re.compile('"icon": ?"([^"]+)"')

A ? never should have been introduced into ENTITY_ID_JSON_TEMPLATE. It's been treated like a regex, which it isn't; it's just near some. The template now produces a piece of text that will never be found in the string contains matching.

The target-state change would have been to remove the whitespace instead:

ENTITY_ID_JSON_TEMPLATE = '"entity_id":"{}"'

But thanks to the mixed whitespace now in everyone's databases, that would only match new records.

So I think there are four light-touch options:

1. Change that template to the whitespace-free version, matching the new 'compact' JSON approach:

     ENTITY_ID_JSON_TEMPLATE = '"entity_id":"{}"'

   This would match newly written logbook records, which probably serves the most common uses of this card (a summary of recent events).

   It's still susceptible to string formatting changes breaking it again, when somebody later decides on ultra-compact JSON.

2. Introduce two templates: one with the original whitespace, and one without.

     ENTITY_ID_JSON_TEMPLATE = '"entity_id": "{}"'
     ENTITY_ID_JSON_TEMPLATE_COMPACT = '"entity_id":"{}"'

   The query would then need to check for instances of either format.

   This would match old and new format logbook records, but at a higher query cost (twice the things to check), and a generally more complex codebase.

   It's still susceptible to string formatting changes breaking it again, when somebody later decides on ultra-compact JSON.

3. Drop this template entirely (it's not working now anyway), and just rely on structured column matching or parsing.

   I don't yet understand the full implications of that. I'm hoping @bdraco might.

4. Make the Logbook card the same as the Logbook panel, so we're at least consistent in the results returned.

   This just bypasses the code path and sweeps the problem under the rug for another day.

This is my first time really trawling through the HA code, so I'm hoping for guidance on what approach would be considered preferable.

[bdraco]

A ? never should have been introduced into ENTITY_ID_JSON_TEMPLATE.

Oops. I obviously missed that. Looks like we need another test to prevent this from breaking in the future as its a bit brittle.

The goal of the template matcher is to have the database code do the matching so we can reject the row in the must faster C code and avoid de-serializing the data. The cost of de-serializing the json can be multiple orders of magnitude higher than any other operation in the logbook since we can potentially be rejecting the majority of the rows that don't match the entity id. When the logbook card first came out we hard a large number of reports of system instability (the query couldn't finish in time before the next one started which lead to a cascading failure and executor overload) due to the duration and cpu cost of the queries which lead to this compromise.

Ideally we would have more normalized data in the database and could do cleaner solution, but thats outside the scope of this discussion as it would be too large of a change and require data migration.

3. Drop this template entirely (it's not working now anyway), and just rely on structured column matching or parsing.
I don't yet understand the full implications of that. I'm hoping @bdraco might.

I think it is ok to change ENTITY_ID_JSON_TEMPLATE to only match the compact format since most people's database who have upgraded will only have the compact data in it at this time since they have been running the new code for a while.

tathamoddie: Nice work on analyzing the root cause.

[bdraco]

This is likely needs to be solved in core so I'm transferring the issue there.

[probot-home-assistant]

logbook documentation
logbook source
_{^{(message by IssueLinks)}}

[tathamoddie]

I've proposed a fix, and a test to prevent future regression, in #55761. Now pending review.