Live Logbook stopped being live (using Cloud/Google assistant?)

Mariusthvdb commented 2 years ago

The problem

as title

can only see the state changes by reloading the page, or navigating away and return

filtering itself is correct, and only shows the correct entities from my included entities (set in recorder filter)

What version of Home Assistant Core has the issue?

2022.6.1

What was the last working version of Home Assistant Core?

2022.6.0 / 2022.7.0.dev20220602 (?)

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Logbook

Link to integration documentation on our website

https://next.home-assistant.io/integrations/logbook

Diagnostics information

No response

Example YAML snippet

history:
logbook: #!include ../../logging/logbook.yaml
recorder: !include ../../logging/recorder.yaml

during the betas I had a separate logbook filter as you can see, but after the fix for the inheritance of the recorder filters into logbook, I took that out and it simply worked.

recorder.yaml does:

db_url: !secret db_url
purge_keep_days: 7

# https://www.home-assistant.io/integrations/recorder/#configure-filter
exclude:
  !include excluded_entities.yaml

include:
  !include included_entities.yaml

Anything in the logs that might be useful for us?

No response

Additional information

see: https://github.com/home-assistant/core/issues/72662 for background, filters and fix that was made, and confirmed to be functional

probot-home-assistant[bot] commented 2 years ago

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

probot-home-assistant[bot] commented 2 years ago

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

probot-home-assistant[bot] commented 2 years ago

Hey there @home-assistant/core, mind taking a look at this issue as it has been labeled with an integration (logbook) you are listed as a code owner for? Thanks! _{^{(message by CodeOwnersMention)}}

probot-home-assistant[bot] commented 2 years ago

Hey there @home-assistant/core, mind taking a look at this issue as it has been labeled with an integration (recorder) you are listed as a code owner for? Thanks! _{^{(message by CodeOwnersMention)}}

bdraco commented 2 years ago

If you drop your filter, does it work?

Mariusthvdb commented 2 years ago

not tested that, and as said, I am only using a recorder filter, not looking forward to testing 3800+ entities in recorder DB tbh....

Wait, I have 2 other instances which are completely unfiltered (and have way less entities, 326/101) and yes, there live logbook flows nicely

bdraco commented 2 years ago

Also if you turn on debug logging for homeassistant.components.logbook and hit the panel do you see anything interesting in the log?

Mariusthvdb commented 2 years ago

nothing at all after adding it via the services page, but let me restart to be sure that homeassistant.components.logbook: debug sticks via logger.

at startup:

2022-06-03 11:25:11 DEBUG (MainThread) [homeassistant.components.logbook.websocket_api] Recorder is behind more than %s seconds, starting live stream; Some results may be missing

but other than that, all is flowing in now..

what I do see while having a second screen open with logviewer, is this on each new row in Logbook

and now live ;-)

Jun-03-2022 11-31-41

also happening on History page opened a frontend issue on that https://github.com/home-assistant/frontend/issues/12861

Mariusthvdb commented 2 years ago

update:

after some time I can see the switches stop being fed live , and my motion sensors are still reporting nicely. how odd this is

reloading the page makes the switches appear.

which made me think why: whenever I switch anything over Google Home ("hey Google, turn on printer library") , it seems that after that the Loggins stop. I can turn them off via the HA interface (button/toggle) and then no issue arises.

what's more, have a lookout this

and the difference compared to the short live feed above for the same device.

or this happening via a toggle:

and showing after a reload like:

btw, the Google commands should really have been local, so maybe there's something to that too.

bdraco commented 2 years ago

The logbook device and area panels only subscribes to what is available when the page is loaded so if you add new entities after the page is loaded it won't know about them until you resubscribe by reloading the page in the browser or navigating away and coming back.

All of the logbook panels only subscribe to events for integrations that are loaded at the time the subscription is created. If you add a new integration or load one after you start streaming logbook device events won't appear for it since it can't subscribe to events it doesn't know exist yet.

bdraco commented 2 years ago

If you send me your latest and greatest filtering config and the entity_id of an entity that you know should show up and isn't showing up, I'll write an entityfilter test with it to see if we have a problem with the entity filter code.

Mariusthvdb commented 2 years ago

I didn’t Add entities, and it’s not about that. Just tested once again: turning on a switch via Google doesn’t log live. Turning that exact same switch off again via its own physical button (zwave) immediately shows up. Happens on any switch I have included in my cloud config

ofc, after a reload of the page, the Cloud state switch is visible.

on my phone now, so can’t drop the filters , but they are unchanged from the linked post.

when I get home I’ll send them first thing

thanks for your trouble!

Mariusthvdb commented 2 years ago

excluded_entities.txt included_entities.txt

couldnt add yaml files here, so I saved them as text. Or I can paste them completely here, please let me know if this works.

a test entty_id would be switch.espresso_keuken.

calisro commented 2 years ago

I was experiencing this as well. Definitely was occuring while I was testing commands with google.

bdraco commented 2 years ago

Includes and Excludes look ok. Writing a test now Excludes

{'domains': ['alarm_control_panel',
             'alert',
             'automation',
             'button',
             'camera',
             'climate',
             'counter',
             'cover',
             'geo_location',
             'group',
             'input_boolean',
             'input_datetime',
             'input_number',
             'input_select',
             'input_text',
             'light',
             'media_player',
             'number',
             'proximity',
             'remote',
             'scene',
             'script',
             'sun',
             'timer',
             'updater',
             'variable',
             'weather',
             'zone'],
 'entities': ['sensor.solaredge_last_updatetime',
              'sensor.solaredge_last_changed'],
 'entity_globs': ['switch.*_light_level', 'switch.sonos_*']}

Includes

{'domains': ['switch', 'person'],
 'entities': ['group.family'],
 'entity_globs': ['sensor.*_sensor_temperature',
                  'sensor.*_actueel',
                  'sensor.*_totaal',
                  'sensor.calculated*',
                  'sensor.solaredge_*',
                  'sensor.speedtest*',
                  'sensor.teller*',
                  'sensor.zp*',
                  'binary_sensor.*_sensor_motion',
                  'binary_sensor.*_door',
                  'sensor.water_*ly',
                  'sensor.gas_*ly']}

bdraco commented 2 years ago

Added a test here https://github.com/home-assistant/core/pull/73005

The filtering is working as expected so its not that

bdraco commented 2 years ago

I don't have a google device to test with so I'm not sure if I can fix this

Mariusthvdb commented 2 years ago

ah thats too bad, because that seems to be the decisive factor. Although, I would have sworn that this did work before the last update. At least when you made the fix, to have logbook inherit recorder filters.

even so, its 100% reproducible in my config.

what remains strange to me is the different way the cloud commands were represented in the above screenshots. maybe another issue, but it did stick out

let me stress again, the logbook itself sees the correct entities, so these filters are consumed alright. its just the Live Logbook going off when using a cloud controlled device.

Is this to stay? or are you considering separating into Logbook (for the past) and Livebook (for streaming).? Maybe that could make things simpler in the end.

bdraco commented 2 years ago

If you can find the row in the database that should've appeared but didn't I might be able to figure out what is different

bdraco commented 2 years ago

The problem is here

https://github.com/home-assistant/core/blob/dev/homeassistant/components/google_assistant/smart_home.py#L179

We don't expect ATTR_ENTITY_ID to be a list.

bdraco commented 2 years ago

To support this we would need to

add support for multiple entities in the entity_id field
change the filtering when using live mode without a list of entities and devices to have a default of accept instead of reject

bdraco commented 2 years ago

The google_assistant special case is quite unpleasant

bdraco commented 2 years ago

I'm not sure if we should change google_assistant since its the only one that does it that way or add support for it in logbook

bdraco commented 2 years ago

I'm guessing it would be a breaking change to fire one event per entity. We have no ability to filter on a list in the database and it is not likely something we could add without a significant performance penalty.

I'll ask around to see if someone has a suggestion on how to solve this

bdraco commented 2 years ago

Looks like we can drop the entity id there so all we need to do is change the filtering when using live mode without a list of entities and devices to have a default of accept instead of reject

Mariusthvdb commented 2 years ago

So great you found the source of the issue ! Not sure I completely follow though… ;-)

mare you saying users should change their filtering on logbook ? Or are you suggesting a backend solution..

bdraco commented 2 years ago

I'm going to work on a solution after I work out the best way to solve it.

Mariusthvdb commented 2 years ago

Let me know if/how to help/test!

bdraco commented 2 years ago

I've got a first attempt plan to tackle this now so I'll try to implement it today if I get through more of the issue queue

bdraco commented 2 years ago

There are a few more filtering fixes in .2. I'm not sure it will make any difference for this issue but it would be good to get a new baseline test

bdraco commented 2 years ago

I think the JS error you see on the console should be fixed in https://github.com/home-assistant/frontend/pull/12878 but thats just a guess since I don't know what it actually is

bdraco commented 2 years ago

It looks like this will be reusable for other areas besides logbook so I'm going to rework my poc as an event_filter.py helper

bdraco commented 2 years ago

It gets a bit complex because we need a default reject for when specific entities and devices are specified and a default accept for the all case when we don't have a list of specific entities and devices

bdraco commented 2 years ago

Quick FYI: When the linked PR merges, there is still a possibility it won't work reliably until https://github.com/home-assistant/frontend/pull/12878 is merged as well but its not specifically related to this so I'm going to let it close with the linked PR

Mariusthvdb commented 2 years ago

thanks and will let you know if all is well!

Mariusthvdb commented 2 years ago

check this, live is back on 2022.6.3!:

The way the Google assistant pops up here (with the sent command on/off) is different from how it was before (see screenshots in the opening post) and I dont have that included/excluded or changed anything else for that matter.

but even more important: it shows when no state change has occurred to the entity . Ofc the command was given.....

from bottom to top:

8:51:00 I turned off a printer that was already off 08:51:13 hey Google turn on Toaster 1 second later: Toater Keuken turned on 08:51:36: Hey google turn on Toaster no further live row displayed.

Now this seems much better than before, and ill check if this will remain the case ;-) so thanks!

However, I dont feel we should see the Google Assistant here all the time, and certainly not when no action was taken. so would appreciate if we could filter out those. Especially considering the fact we see Home Assistant Cloud in that line on the entity, and the style before was better imho.

bdraco commented 2 years ago

Now this seems much better than before, and ill check if this will remain the case ;-) so thanks!

Glad its working now 👍

However, I dont feel we should see the Google Assistant here all the time, and certainly not when no action was taken. so would appreciate if we could filter out those.

I think what you are asking for is adding event_types to the logbook filter https://www.home-assistant.io/integrations/recorder/#event_types. That's not something we can do in a bugfix release since its a new feature, but maybe something for the future.

Especially considering the fact we see Home Assistant Cloud in that line on the entity, and the style before was better imho.

I think the Google Assistant descriptions could be improved to be more useful in the future as well, but that's outside the scope of this as they haven't changed in at least 14 months, and we are stepping into feature request territory.

bdraco commented 2 years ago

They are pretty anemic on the information compared to the HomeKit ones (which probably have too much in them 🙈). This isn't something I'm going to be able to improve since I don't have a google assistant, but I'll leave the following note in case someone wants to pick this up:

If someone is reading this in the future, it looks like there is a potentially more useful data to add to the event

https://developers.google.com/assistant/smarthome/develop/process-intents#EXECUTE

{
    "requestId": "ff36a3cc-ec34-11e6-b1a0-64510650abcf",
    "inputs": [{
      "intent": "action.devices.EXECUTE",
      "payload": {
        "commands": [{
          "devices": [{
            "id": "123",
            "customData": {
              "fooValue": 74,
              "barValue": true,
              "bazValue": "sheepdip"
            }
          }, {
            "id": "456",
            "customData": {
              "fooValue": 36,
              "barValue": false,
              "bazValue": "moarsheep"
            }
          }],
          "execution": [{
            "command": "action.devices.commands.OnOff",
            "params": {
              "on": true
            }
          }]
        }]
      }
    }]
}

Mariusthvdb commented 2 years ago

sure, dont want to FR anything, and I have event_types filtering in my recorder. Just dont know if we can filter this in the event_types.

Also, the format has changed. before there was only the single line:

'Turned on triggered by Google Assistant sent command OnOff'

and now we have this additional live row for Google Assistant:

in the current event_types , is there a type we can add to the recorder filtering, so it only removes that Google Assistant line?

bdraco commented 2 years ago

Also, the format has changed

I can see how it feels that way, but they haven't changed, they just are not missing anymore.

in the current event_types , is there a type we can add to the recorder filtering, so it only removes that Google Assistant line?

Its this event type here https://github.com/home-assistant/core/blob/a8763d74798ecc95d4a2b323235aabea5463da66/homeassistant/components/google_assistant/const.py#L119

But it will still show up in live logbook even if you exclude it from the recorder since logbook doesn't know about event_type excludes (https://www.home-assistant.io/integrations/logbook/#configuration-variables)

Mariusthvdb commented 2 years ago

please allow me this (being aware Logbook doesnt/can not filter event_types):

But it will still show up in live logbook even if you exclude it from the recorder since logbook doesn't know about event_type excludes (https://www.home-assistant.io/integrations/logbook/#configuration-variables)

if this is the case, how can it be Live logbook does not show any other event_type? ( I mean I didnt expect them to, because Ive filtered most from Recorder before, but now you mention this, it seems strange it doesnt show them)

if I add google_assistant_command, will it still show the top line of the 2 too? Or stop Google Assistant from working alltogether?

bdraco commented 2 years ago

if this is the case, how can it be Live logbook does not show any other event_type? ( I mean I didnt expect them to, because Ive filtered most from Recorder before, but now you mention this, it seems strange it doesnt show them)

The integration has to provide a logbook platform to describe events for them to be shown. Only a few integrations have implemented that as shown below. If they aren't on this list it explains why you don't see them.

alexa/logbook.py        doorbird/logbook.py     homeassistant/logbook.py    lutron_caseta/logbook.py    shelly/logbook.py
automation/logbook.py       elkm1/logbook.py        homekit/logbook.py      mobile_app/logbook.py       zwave_js/logbook.py
deconz/logbook.py       google_assistant/logbook.py hue/logbook.py          script/logbook.py

if I add google_assistant_command, will it still show the top line of the 2 too? Or stop Google Assistant from working alltogether?

If you exclude google_assistant_command from the recorder, the state changed event itself should still show up but it won't be attributed to google assistant since the row will not be in the database, and the google assistant line (with the logo) should also disappear.

Mariusthvdb commented 2 years ago

I have that now, and it still shows like:

this is for switches in the cloud config

it does however not show this for my light settings at all, none of the 2 lines.

if I ask google to activate a scene, it shows only:

and not the Google assistant line we see with the switches

all in all, I cant completely see the logic just yet of those live row representation for Google Assistant yet

of those integrations, I use automation, google_assistant, homeassistant..., hue, mobile_app, script, shelly, zwave_js.

many of the entities of these integrations I filter from recorder, but give what you said earlier, it these should still throw events in the logbook ....

bdraco commented 2 years ago

Not really sure whats going on there. I'd guess that you don't see the google row for the scene because that one doesn't have an entity id attached to the event (could actually be the other way around), but I don't have a google assistant so its a bit of a shot in the dark.

bdraco commented 2 years ago

it these should still throw events in the logbook ....

Not all of them describe every event they fire. It is quite fragmented and not well documented as of today.

Mariusthvdb commented 2 years ago

lastly: it is correct that the row changes to

upon reload? the whole 'triggered by etc etc' is gone then?

bdraco commented 2 years ago

lastly: it is correct that the row changes to

upon reload? the whole 'triggered by etc etc' is gone then?

Assuming you excluded the event, yes

Mariusthvdb commented 2 years ago

right, I believe this happened before I filtered that, but let me test that once again. brb.

live:

reload:

Not filtering google_assistant_command

bdraco commented 2 years ago

That makes sense. I forget we had talked about changing google_assistant to use a single entity_id in the events instead of a list so the database could filter them as well but that would have been a breaking change to the google assistant events that could make someone's automations fail if they are watching for them so we didn't move that forward. We would need to do that to get the database filter to see that.

Mariusthvdb commented 2 years ago

ok, so if you say all is as designed now, I guess we should stop this here ;-)

I do think it would be nice if we could filter that out, so Id create a feature request, if I understood what you're saying about the breaking change to google assistant.

as that is not exactly the case, I am afraid I wouldn't be able to word it differently that I did above.. to Not show the Google Assistant sent command OnOff in Live logbook.

home-assistant / core