Google Assistant Response to Execute intent includes incorrect state

coling commented 5 days ago

The problem

I've integrated Google Assistant with my own Action/Project etc. including Local Fulfilment with report_state:true in my configuration.

According to the Homegraph docs, after an EXECUTE command to e.g. turn a light on: Your fulfillment should process each command, transmit it to the corresponding device, and return the new state in the EXECUTE response.

According to my logs, the response appears to be supplying the current state, not the new state-post-execution/fulfillment.

The logs do show that subsequent HomeGraph updates via reportStateAndNotification API does update the state, but this doesn't appear to help the Google Home App on my phone.

The issue is as follows:

I use the Google Home App on my phone.
I hit "Devices" tab in the app and switch a light from Off state to On state.
The UI updates correctly, showing the light in the On state, but then flips back a second later to the Off state.
Waiting does very little to update the UI.
Switching away to e.g. my Favourites tab, then back to Devices appears to trigger a QUERY operation which then responds with the current states and the UI updates the switch with it's correct state.

All in all this is really disconcerting.

I note that people on the Community have reported this kind of issue before, and suggested various workarounds such as an automation to trigger a sync. This doesn't seem to be the correct approach as the sync operation doesn't actually include the necessary state information. While experimenting with these solutions, I found it didn't help and only when a query came in and the appropriate response was given was there any update. I'm not sure why the resportStateAndNotification calls are not sufficient here - As far as I'm aware, there is no easy way to trigger a reportStateAndNotification update manually e.g. after a delay to see if this would help update the Google Home UI.

For some reason, all of my Local Fulfillment Requests come from my Google Hub rather than my phone, despite me interacting with the Google Home app on my phone. I'm not sure if this is relevant.

Anyway, log snippets below with annotations.

What version of Home Assistant Core has the issue?

core-2024.9.1

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

Google Assistant

Link to integration documentation on our website

https://www.home-assistant.io/integrations/google_assistant/

Diagnostics information

No response

Example YAML snippet

google_assistant:
  project_id: myprojectid
  service_account: !include mycreds.json
  report_state: true
  expose_by_default: true
  exposed_domains:
    - switch
    - light

Anything in the logs that might be useful for us?

# Turning lights On in Google Home App from an initial Off state
# NB there are lots of other devies mentioned in my customData messages but I've removed all the others that I'm not interacting with for the sake of berevity

2024-09-11 23:12:26.373 DEBUG (MainThread) [homeassistant.components.google_assistant.helpers] Received local message 4899804129339141705 from 192.168.xx.250 (JS 2.1.6)
2024-09-11 23:12:26.376 DEBUG (MainThread) [homeassistant.components.google_assistant.smart_home] Processing message:
{'devices': [{'customData': {},
              'id': '1ad4***9bde',
              'radioType': 'WIFI',
              'scanData': {'mdnsScanData': {'serviceName': 'home._home-assistant._tcp.local',
                                            'texts': ['location_name=**REDACTED**',
                                                      'uuid=**REDACTED**',
                                                      'version=2024.9.1',
                                                      'external_url=**REDACTED**',
                                                      'internal_url=**REDACTED**',
                                                      'base_url=**REDACTED**',
                                                      'requires_api_password=True']}}},
             {'customData': {'httpPort': 8123,
                             'uuid': '6ad7***5e4e',
                             'webhookId': '031e***55e8'},
              'id': 'light.pontoon_lights'}],
 'inputs': [{'intent': 'action.devices.EXECUTE',
             'payload': {'commands': [{'devices': [{'customData': {'httpPort': 8123,
                                                                   'uuid': '6ad7***5e4e',
                                                                   'webhookId': '031e***55e8'},
                                                    'id': 'light.pontoon_lights'}],
                                       'execution': [{'command': 'action.devices.commands.OnOff',
                                                      'params': {'on': True}}]}],
                         'structureData': {}}}],
 'requestId': '4899804129339141705'}

# The above message seems sensible. It's requesting the pontoon lights be turned on.

# HA then responds as follows
2024-09-11 23:12:26.377 DEBUG (MainThread) [homeassistant.components.google_assistant.smart_home] Response:
{'commands': [{'ids': ['light.pontoon_lights'],
               'states': {'on': False, 'online': True},
               'status': 'SUCCESS'}]}
2024-09-11 23:12:26.378 DEBUG (MainThread) [homeassistant.components.google_assistant.helpers] Responding to local message 4899804129339141705
# This, I'm not sure about. As per the HomeGraph specs, we should be supplying the NEW state here but we're reporting 'on': False.

# We do then supply an update a few m/s later...
2024-09-11 23:12:26.405 DEBUG (MainThread) [homeassistant.components.google_assistant.report_state] Scheduling report state for light.pontoon_lights: {'online': True, 'on': True}
2024-09-11 23:12:27.604 DEBUG (MainThread) [homeassistant.components.google_assistant.http] Response on https://homegraph.googleapis.com/v1/devices:reportStateAndNotification with data {'requestId': 'ed282a202349452da6da10a69b3e9218', 'agentUserId': '1ad4b43c821f4922a9ca576070889bde', 'payload': {'devices': {'states': {'light.pontoon_lights': {'online': True, 'on': True}}}}} was {
  "requestId": "ed282a202349452da6da10a69b3e9218"
}
# And this has the *correct* 'on': True state supplied, however this doesn't seem to help the Google Home App's UI.

# At this point the Google Home App's UI incorrectly says the switch is Off.
# Changing tabs from Devices -> Favourites and back again in the Google Home App triggers the following updates:
2024-09-11 23:12:34.596 DEBUG (MainThread) [homeassistant.components.google_assistant.smart_home] Processing message:
{'inputs': [{'intent': 'action.devices.SYNC'}],
 'requestId': '2344299052541567691'}
2024-09-11 23:12:34.608 DEBUG (MainThread) [homeassistant.components.google_assistant.smart_home] Response:
{'agentUserId': '1ad4***9bde',
 'devices': [{'attributes': {'colorTemperatureRange': {'temperatureMaxK': 4000,
                                                       'temperatureMinK': 2202}},
              'customData': {'httpPort': 8123,
                             'uuid': '6ad7***5e4e',
                             'webhookId': '031e***55e8'},
              'id': 'light.bedroom_lights',
              'name': {'name': 'Bedroom Lights'},
              'otherDeviceIds': [{'deviceId': 'light.bedroom_lights'}],
              'roomHint': 'Bedroom',
              'traits': ['action.devices.traits.Brightness',
                         'action.devices.traits.OnOff',
                         'action.devices.traits.ColorSetting'],
              'type': 'action.devices.types.LIGHT',
              'willReportState': True}]}
# Note: Lot's of my light and switch devices are included in this response, but NOT the light I'm actually controlling for some reason.

# Then comes a QUERY action (again both the devices in the message and the devices in the QUERY intent incuded many of my other devices but I've excluded them for clarity)
2024-09-11 23:12:36.936 DEBUG (MainThread) [homeassistant.components.google_assistant.helpers] Received local message 11444078897798979529 from 192.168.xx.250 (JS 2.1.6)
2024-09-11 23:12:36.942 DEBUG (MainThread) [homeassistant.components.google_assistant.smart_home] Processing message:
{'devices': [{'customData': {},
              'id': '1ad4***9bde',
              'radioType': 'WIFI',
              'scanData': {'mdnsScanData': {'serviceName': 'home._home-assistant._tcp.local',
                                            'texts': ['location_name=**REDACTED**',
                                                      'uuid=**REDACTED**',
                                                      'version=2024.9.1',
                                                      'external_url=**REDACTED**',
                                                      'internal_url=**REDACTED**',
                                                      'base_url=**REDACTED**',
                                                      'requires_api_password=True']}}},
             {'customData': {'httpPort': 8123,
                             'uuid': '6ad7***5e4e',
                             'webhookId': '031e***55e8'},
              'id': 'light.pontoon_lights'}],
 'inputs': [{'intent': 'action.devices.QUERY',
             'payload': {'devices': [{'customData': {'httpPort': 8123,
                                                     'uuid': '6ad7***5e4e',
                                                     'webhookId': '031e***55e8'},
                                      'id': 'light.pontoon_lights'}],
                         'structureData': {}}}],
 'requestId': '11444078897798979529'}
2024-09-11 23:12:36.943 DEBUG (MainThread) [homeassistant.components.google_assistant.smart_home] Response:
{'devices': {'light.pontoon_lights': {'on': True, 'online': True}}}
2024-09-11 23:12:36.943 DEBUG (MainThread) [homeassistant.components.google_assistant.helpers] Responding to local message 11444078897798979529

# At this point the Google Home App's UI reports the state correctly!!

Additional information

No response

home-assistant[bot] commented 5 days ago

Hey there @home-assistant/cloud, mind taking a look at this issue as it has been labeled with an integration (google_assistant) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `google_assistant` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign google_assistant` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

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

coling commented 5 days ago

I'm really not a Python coder and nor do I understand any of the HA code or internal architecture but looking at the code here, I see EXECUTE command appears to be queued asynchronously in the hass bus and then the state of the entities in question are read in a few lines below. Could the problem be that the code is just not waiting for the async requests to complete (albeit with a timeout) before returning the response, thus the current state is being returned?

elupus commented 5 days ago

Execution actually occur here: https://github.com/home-assistant/core/blob/d530fd31b063c9b3784ac2378e9eb5848dd03b87/homeassistant/components/google_assistant/smart_home.py#L258

That is blocking. Your pontoon light might not block and update its state on turn on. What integration is providing that light?

elupus commented 5 days ago

So.. here is the smoking gun: https://github.com/home-assistant/core/blob/d530fd31b063c9b3784ac2378e9eb5848dd03b87/homeassistant/components/google_assistant/trait.py#L359

When we have state reporting turned on, we dont block on execution.

https://github.com/home-assistant/core/blob/d530fd31b063c9b3784ac2378e9eb5848dd03b87/homeassistant/components/google_assistant/trait.py#L366

elupus commented 5 days ago

And here is the change that introduced the behavior: https://github.com/home-assistant/core/commit/814a742518e88609e318de7ad0fa378d085bfa73

coling commented 5 days ago

Thanks so much for digging into it @elupus!

I've done a bit of poking and turned of the report_state in my config and sync'ed devices (confirming that willReportState:False is sent). I can see in my logs that I no longer call reportStateAndNotification but my response to the EXECUTE intent to turn the light on is still showing the incorrect state in it's response. This response is sent 4 hundredths of a second after the message, which is very fast to make the blocking call, but my initial logs do have the response 1 hundredth of a second later so it's technically 4x slower now 😆 - anyway can't really tell from the outside if that signifies a blocking call or not. I'll see if I can enable debug logging for my light and see if it shows up inbetween the request and response.

As per your original comment, this could be related to the specific integration (the pontoon lights are technically an ESPHome based Wifi plug socket) so will try with some other lights via Zigbee and see if I get the same behaviour.

Thanks again for the input so far.

Either way, the spec does I linked to suggest the call should be fulfilled before the response - not sure if state reporting should negate that (even if, in theory at least, state reporting should make automatic updates to states)

coling commented 4 days ago

Managed to do a bit of testing. With some Zigbee lights, and report_state:False, Google Home app is now behaving as expected 👍🏼

Some virtual switch groups in HA don't work properly (as they should go off when all lights are off and on when any light is on but due to states not being pushed, they don't correctly reflect their state until a QUERY is issued and responded to) - but I guess that's expected with report_state:false. It's probably not a good idea to expose these groups to GH anyway - probably best to do the grouping in GH itself.

I'll double check if turning report_state:true back on again makes these now perfectly working Zigbee devices misbehave again due to the old state being sent (I guess it might be racey generally, but I'm sure I observed them misbehaving previously).

coling commented 4 days ago

OK, I've turned report_state:true back on again and managed to break my Zigbee light state in the Google Home app.

It's odd however. Lot's of cycles and it seemed to behave initially, despite the same behaviour as the pontoon lights with the state response being initially incorrect (as expected due to the async handling). The odd thing is that, initially,despite the incorrect state, the Google Home UI does not flip back like it does with my ESPHome/pontoon lights. Because I have a virtual switch, the report state for that is also included if it changes state, and indeed I see the update in Google Home App's UI in response to that state being reported - the delay is sufficient that I know it takes a while for it all to propagate so the fact that it doesn't flip back like the ESPHome/pontoon lights is just really odd.

However, after playing for a while, and playing with the pontoon lights too, these lights started to behave the same way again. It's almost like the reportState is getting ignored. I honestly cannot explain it.

It would be nice to allow for sync responses separate from the report_state variable to allow further investigation. Perhaps a new config entry could be added to tweak that? Can default to the inverse of report_state?

coling commented 4 days ago

I did a drive by patch to separate the blocking out from the report_state config.

I'm not a great python coder and I have no dev env to setup and build HA nor do I have an easy way to run that (run it via a docker container, so this very much is a drive by patch.

I've no idea if I've done the config handling correctly or if the default value handling is correct (monkey see, monkey do approach!), but if you think it's a good idea to allow this, it perhaps saves a bit of time implementing.

Happy to turn it into a pull request albeit unable to test.

IngeJones commented 7 hours ago

I came to see if there was already a report as I am having the same trouble with state not being reported to Google Home. So if I turn on a switch on Google Home, then a little later turn it off in Home Assistant UI, the switch still shows as on in Google Home. I do of course have Enable State Reporting set to Enabled. This is all via standard UI, no custom coding.

coling commented 7 hours ago

So if I turn on a switch on Google Home, then a little later turn it off in Home Assistant UI, the switch still shows as on in Google Home. I do of course have Enable State Reporting set to Enabled.

If you close, then reopen Google Home (or switch tabs internally if on a phone - not sure how to do on a Hub), then this should trigger a QUERY and thus update the state. Do you see this same behaviour?

I have found that regardless of the state reporting calls being sent, that Google Home doesn't update it's UIs. Doubt this can be a Home Assistant problem, unless there are some nuances of the API that are incorrect, but it's still super frustrating.

coling commented 7 hours ago

(Just FYI, I've updated the title to avoid the use of the word "report" as this "reporting" state is technically a different operation to the bit I'm specifically questioning in this report)

IngeJones commented 7 hours ago

So if I turn on a switch on Google Home, then a little later turn it off in Home Assistant UI, the switch still shows as on in Google Home. I do of course have Enable State Reporting set to Enabled.

If you close, then reopen Google Home (or switch tabs internally if on a phone - not sure how to do on a Hub), then this should trigger a QUERY and thus update the state. Do you see this same behaviour?

I have found that regardless of the state reporting calls being sent, that Google Home doesn't update it's UIs. Doubt this can be a Home Assistant problem, unless there are some nuances of the API that are incorrect, but it's still super frustrating.

Well this is weird. Been struggling with this for over a day, and just posting here appears to have fixed it. That and I just installed the latest update to HA Core... Hmmm Ok thanks, I hope it stays fixed.

coling commented 34 minutes ago

Well this is weird. Been struggling with this for over a day, and just posting here appears to have fixed it. That and I just installed the latest update to HA Core... Hmmm Ok thanks, I hope it stays fixed.

When hammering Google Home App for my testing above with report_state: true, I did find, after a while, that it seemed to stop responding to the data in the reportStateAndNotification call. I was able to test this with a virtual light group which was synced to Google. It was correctly updated for a while, but eventually it just seemed to stop seeing the data. I know HA was still sending the API calls and I know from logs in GCP that there were not specific errors with those calls - sadly likely very hard to then debug as to why it never made it into updates as reflected in the Google Home App. So perhaps it'll work for a while for you but it might ultimately just stop too. Think that is a related, but separate, issue to this one tho'.

home-assistant / core