home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
70.54k stars 29.47k forks source link

Nest Thermostat integration stops working #92927

Closed ianwood closed 2 months ago

ianwood commented 1 year ago

The problem

Nest thermostat integration (using the Google Cloud API) works normally for several hours or even days but then fails and the integration needs to be reloaded to work again. It seems that the more recent versions of core have made this problem worse as I am now having to restart the integration almost daily.

Integration will show as "Off" with no other modes when it has failed. Reloading the integration restores the normal HVAC modes. Looking at the history for the device when the integration has failed, it will show that it was turned off at some point earlier although there was nothing commanding it to do so.

What version of Home Assistant Core has the issue?

core-2023.4.5

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Nest

Link to integration documentation on our website

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

Diagnostics information

{ "home_assistant": { "installation_type": "Home Assistant OS", "version": "2023.4.5", "dev": false, "hassio": true, "virtualenv": false, "python_version": "3.10.10", "docker": true, "arch": "x86_64", "timezone": "America/Los_Angeles", "os_name": "Linux", "os_version": "6.1.24", "supervisor": "2023.04.1", "host_os": "Home Assistant OS 10.0", "docker_version": "23.0.3", "chassis": "embedded", "run_as_root": true }, "custom_components": { "frigate": { "version": "4.0.0", "requirements": [ "pytz==2022.7" ] }, "hacs": { "version": "1.32.1", "requirements": [ "aiogithubapi>=22.10.1" ] } }, "integration_manifest": { "domain": "nest", "name": "Google Nest", "after_dependencies": [ "media_source" ], "codeowners": [ "@allenporter" ], "config_flow": true, "dependencies": [ "ffmpeg", "http", "application_credentials" ], "dhcp": [ { "macaddress": "18B430" }, { "macaddress": "641666" }, { "macaddress": "D8EB46*" } ], "documentation": "https://www.home-assistant.io/integrations/nest", "iot_class": "cloud_push", "loggers": [ "google_nest_sdm", "nest" ], "quality_scale": "platinum", "requirements": [ "python-nest==4.2.0", "google-nest-sdm==2.2.4" ], "is_built_in": true }, "data": { "data": { "name": "REDACTED", "type": "sdm.devices.types.THERMOSTAT", "assignee": "REDACTED", "traits": { "sdm.devices.traits.Info": { "customName": "REDACTED" }, "sdm.devices.traits.Humidity": { "ambientHumidityPercent": 64 }, "sdm.devices.traits.Connectivity": { "status": "ONLINE" }, "sdm.devices.traits.Fan": { "timerMode": "OFF" }, "sdm.devices.traits.ThermostatMode": { "mode": "HEATCOOL", "availableModes": [ "HEAT", "COOL", "HEATCOOL", "OFF" ] }, "sdm.devices.traits.ThermostatEco": { "availableModes": [ "OFF", "MANUAL_ECO" ], "mode": "OFF", "heatCelsius": 15.555527, "coolCelsius": 29.444397 }, "sdm.devices.traits.ThermostatHvac": { "status": "OFF" }, "sdm.devices.traits.Settings": { "temperatureScale": "FAHRENHEIT" }, "sdm.devices.traits.ThermostatTemperatureSetpoint": { "heatCelsius": 20.555555, "coolCelsius": 23.333334 }, "sdm.devices.traits.Temperature": { "ambientTemperatureCelsius": 20.839996 } }, "parentRelations": [ { "parent": "REDACTED", "displayName": "REDACTED" } ] }, "command": { "sdm.devices.commands.ThermostatMode.SetMode_count": 1, "sdm.devices.commands.ThermostatMode.SetMode_sum": 755, "sdm.devices.commands.Fan.SetTimer_count": 1, "sdm.devices.commands.Fan.SetTimer_sum": 771 }, "event_media": { "event": 6 } } }

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 199, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1820, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1857, in _execute_service
await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 216, in handle_service
await service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 798, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 977, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 838, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 287, in async_set_hvac_mode
raise ValueError(f"Unsupported hvac_mode '{hvac_mode}'")
ValueError: Unsupported hvac_mode 'heat_cool'
2023-05-09 19:30:00.195 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139724931415632] Unsupported hvac_mode 'heat_cool'
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 199, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1820, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1857, in _execute_service
await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 216, in handle_service
await service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 798, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 977, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 838, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 287, in async_set_hvac_mode
raise ValueError(f"Unsupported hvac_mode '{hvac_mode}'")
ValueError: Unsupported hvac_mode 'heat_cool'
2023-05-09 19:51:25.585 WARNING (MainThread) [homeassistant.components.websocket_api.http.connection] [139724872852112] Disconnected: Did not receive auth message within 10 seconds
2023-05-09 20:00:00.203 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139724931415632] Unsupported hvac_mode 'heat_cool'
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 199, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1820, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1857, in _execute_service
await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 216, in handle_service
await service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 798, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 977, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 838, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 287, in async_set_hvac_mode
raise ValueError(f"Unsupported hvac_mode '{hvac_mode}'")
ValueError: Unsupported hvac_mode 'heat_cool'
2023-05-09 20:30:00.223 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139724931415632] Unsupported hvac_mode 'heat_cool'
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 199, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1820, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1857, in _execute_service
await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 216, in handle_service
await service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 798, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 977, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 838, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 287, in async_set_hvac_mode
raise ValueError(f"Unsupported hvac_mode '{hvac_mode}'")
ValueError: Unsupported hvac_mode 'heat_cool'

Additional information

No response

home-assistant[bot] commented 1 year ago

Hey there @allenporter, mind taking a look at this issue as it has been labeled with an integration (nest) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `nest` 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 nest` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)


nest documentation nest source (message by IssueLinks)

MattHadfield113 commented 1 year ago

Mine has recently also started to do the same thing.

allenporter commented 1 year ago

@MattHadfield113 can you also attach diagnostics for the thermostat when this is happening?

allenporter commented 1 year ago

My assumption is that the issue here is the server is returning invalid data over pubsub that makes it look like there are no longer any supported hvac modes. I think it would be helpful if you turn up the debug logging described here https://www.home-assistant.io/integrations/nest/#troubleshooting and then we can look at the updates returned from the server just from around the time the thermostat appears to turn off.

clarsen commented 1 year ago

I am also seeing problems with thermostat not responding to the ThermostatTemperatureSetpoint.SetRange command when submitted via the homeassistant Nest integration, however when manipulated via the native Nest mobile app, temperature can be set just fine.

Earlier I was seeing a 429 resource exhausted response for every set temperature API call from the UI. I tried deleting the integration and creating a new oauth ID and new device access project. Now, I don't see those errors, but no change takes effect.

I am running 2023.6.2 by the way and here is diagnostic from Nest integration config_entry-nest-776cc3d0f37c2b3f3c9262fdf8fc73ef.json.txt

Example logs:

2023-06-16 23:45:12.458 DEBUG (MainThread) [google_nest_sdm.auth] request[post]=https://smartdevicemanagement.google
apis.com/v1/enterprises/199609fb-94b3-4221-81f5-9fb52175674d/devices/AVPHwEsfPQD9JnY7SN88XZDFZk2AJQ28qihbYDBj7Huu7n7
c0CbmBlzBOZe88LNauKfT_x_kmXc8DKwfa4RiI6GzStZCoQ:executeCommand
2023-06-16 23:45:12.459 DEBUG (MainThread) [google_nest_sdm.auth] request[post json]={'command': 'sdm.devices.commands.ThermostatTemperatureSetpoint.SetRange', 'params': {'heatCelsius': 18.333333333333332, 'coolCelsius': 29.444444444444443}}

When I make changes via the native Nest app, the temperature updates do come through and show on the UI, so that part is working:

2023-06-16 23:52:15.151 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'c3c38f78-b648-4d8f-941e-26a1a423e91f', 'timestamp': '2023-06-17T06:52:12.681Z', 'resourceUpdate': {'name': 'enterprises/199609fb-94b3-4221-81f5-9fb52175674d/devices/AVPHwEsfPQD9JnY7SN88XZDFZk2AJQ28qihbYDBj7Huu7n7c0CbmBlzBOZe88LNauKfT_x_kmXc8DKwfa4RiI6GzStZCoQ', 'traits': {'sdm.devices.traits.ThermostatTemperatureSetpoint': {'heatCelsius': 11.666667, 'coolCelsius': 29.444445}}}, 'userId': 'AVPHwEuroOkzYgoJkQLhUab9gQWLi4O3jYgai5pEWLdE', 'resourceGroup': ['enterprises/199609fb-94b3-4221-81f5-9fb52175674d/devices/AVPHwEsfPQD9JnY7SN88XZDFZk2AJQ28qihbYDBj7Huu7n7c0CbmBlzBOZe88LNauKfT_x_kmXc8DKwfa4RiI6GzStZCoQ']}
allenporter commented 1 year ago

@clarsen appreciate the report though it seems like different symptoms than this issue. But it also looks like an issue with the nest API and not a home assistant bug.

allenporter commented 1 year ago

As I replied before, please file a separate issue as it's not related to the parent right?

ianwood commented 1 year ago

This is still happening intermittently and it would make sense that maybe the Nest API is having sporadic issues. However, reloading the integration seems to immediately fix it and it remains stable for several hours before it reoccurs. Is there a state that is established when the integration is first loaded that maybe gets lost if the API hiccups? Is there a way to automatically reload or reinitialize the integration if the Nest API sends a bogus or empty response?

allenporter commented 1 year ago

@ianwood Please see my reply https://github.com/home-assistant/core/issues/92927#issuecomment-1565614251 asking you for additional troubleshooting information which is needed to decide a path forward -- we need to see examples of the update messages in order to know what is happening.

allenporter commented 1 year ago

Also seeing a different symptom, but similar possible root cause where invalid messages are published by the API in #96434 -- getting debug logs of the messages being published would be very helpful.

domoritz commented 1 year ago

I'm seeing the same issue as here and https://github.com/home-assistant/core/issues/96434. How can I provide the debug logs? I enabled debug logging on the integration.

Screenshot 2023-07-15 at 06 16 30
allenporter commented 1 year ago

@domoritz Logs are in Settings -> System -> Logs and you can see the full log, download the log, or filter the log to specific terms e.g. nest

domoritz commented 1 year ago

Here are my anonymized and filtered logs.

2023-07-15 07:06:25.835 DEBUG (ThreadPoolExecutor-1_0) [google_nest_sdm.google_nest_subscriber] Subscriber 'projects/home-assistant-278703/subscriptions/home-assistant-TTT' configured on topic 'projects/sdm-prod/topics/enterprise-ZZZ'
2023-07-15 07:06:25.982 DEBUG (MainThread) [google_nest_sdm.google_nest_subscriber] Starting background watchdog thread
2023-07-15 07:06:26.212 DEBUG (MainThread) [google_nest_sdm.auth] request[get]=https://smartdevicemanagement.googleapis.com/v1/enterprises/ZZZ/structures
2023-07-15 07:06:26.595 DEBUG (MainThread) [google_nest_sdm.auth] response={'structures': [{'name': 'enterprises/ZZZ/structures/YYY-XXX', 'traits': {'sdm.structures.traits.Info': {'customName': 'Home'}}}]}
2023-07-15 07:06:26.596 DEBUG (MainThread) [google_nest_sdm.auth] request[get]=https://smartdevicemanagement.googleapis.com/v1/enterprises/ZZZ/devices
2023-07-15 07:06:27.538 DEBUG (MainThread) [google_nest_sdm.auth] response={'devices': [{'name': 'enterprises/ZZZ/devices/BBB', 'type': 'sdm.devices.types.THERMOSTAT', 'assignee': 'enterprises/ZZZ/structures/YYY-XXX/rooms/AAA', 'traits': {'sdm.devices.traits.Info': {'customName': ''}, 'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 59}, 'sdm.devices.traits.Connectivity': {'status': 'ONLINE'}, 'sdm.devices.traits.Fan': {'timerMode': 'OFF'}, 'sdm.devices.traits.ThermostatMode': {'mode': 'COOL', 'availableModes': ['HEAT', 'COOL', 'HEATCOOL', 'OFF']}, 'sdm.devices.traits.ThermostatEco': {'availableModes': ['OFF', 'MANUAL_ECO'], 'mode': 'OFF', 'heatCelsius': 10, 'coolCelsius': 24.44444}, 'sdm.devices.traits.ThermostatHvac': {'status': 'OFF'}, 'sdm.devices.traits.Settings': {'temperatureScale': 'CELSIUS'}, 'sdm.devices.traits.ThermostatTemperatureSetpoint': {'coolCelsius': 24}, 'sdm.devices.traits.Temperature': {'ambientTemperatureCelsius': 23.87999}}, 'parentRelations': [{'parent': 'enterprises/ZZZ/structures/YYY-XXX/rooms/AAA', 'displayName': 'Living Room'}]}]}
2023-07-15 07:17:23.248 DEBUG (MainThread) [google_nest_sdm.auth] request[post]=https://smartdevicemanagement.googleapis.com/v1/enterprises/ZZZ/devices/BBB:executeCommand
2023-07-15 07:17:23.248 DEBUG (MainThread) [google_nest_sdm.auth] request[post json]={'command': 'sdm.devices.commands.Fan.SetTimer', 'params': {'timerMode': 'ON', 'duration': '43200s'}}
2023-07-15 07:56:52.789 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'ae0e0fff-0a7f-4844-803d-cd0237b6d437', 'timestamp': '2023-07-15T11:56:45.273Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 62.0}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 07:56:52.789 DEBUG (MainThread) [google_nest_sdm.device] Processing update ae0e0fff-0a7f-4844-803d-cd0237b6d437 @ 2023-07-15 11:56:45.273000+00:00
2023-07-15 07:56:52.789 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Humidity': <google_nest_sdm.device_traits.HumidityTrait object at 0x7fad6ea45cd0>}
2023-07-15 08:01:29.827 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'd6592de7-2f0b-4d0d-9b67-c97d74c7c1ca', 'timestamp': '2023-07-15T12:01:27.075Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 68.0}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 08:01:29.828 DEBUG (MainThread) [google_nest_sdm.device] Processing update d6592de7-2f0b-4d0d-9b67-c97d74c7c1ca @ 2023-07-15 12:01:27.075000+00:00
2023-07-15 08:01:29.828 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Humidity': <google_nest_sdm.device_traits.HumidityTrait object at 0x7fad7023d090>}
2023-07-15 08:08:32.127 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '861a7953-fac9-4a01-8924-5472a83e7f01', 'timestamp': '2023-07-15T12:08:25.106Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 71.0}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 08:08:32.128 DEBUG (MainThread) [google_nest_sdm.device] Processing update 861a7953-fac9-4a01-8924-5472a83e7f01 @ 2023-07-15 12:08:25.106000+00:00
2023-07-15 08:08:32.128 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Humidity': <google_nest_sdm.device_traits.HumidityTrait object at 0x7fad70201290>}
2023-07-15 08:22:45.816 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'b2920447-de4a-4385-8411-42aba2593871', 'timestamp': '2023-07-15T12:22:40.322Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 69.0}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 08:22:45.817 DEBUG (MainThread) [google_nest_sdm.device] Processing update b2920447-de4a-4385-8411-42aba2593871 @ 2023-07-15 12:22:40.322000+00:00
2023-07-15 08:22:45.817 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Humidity': <google_nest_sdm.device_traits.HumidityTrait object at 0x7fad805bcbd0>}
2023-07-15 09:06:36.052 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'a6ba0cc1-3521-4940-bec3-7c589bcbaebb', 'timestamp': '2023-07-15T13:06:30.365Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 67.0}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 09:06:36.052 DEBUG (MainThread) [google_nest_sdm.device] Processing update a6ba0cc1-3521-4940-bec3-7c589bcbaebb @ 2023-07-15 13:06:30.365000+00:00
2023-07-15 09:06:36.053 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Humidity': <google_nest_sdm.device_traits.HumidityTrait object at 0x7fad703fb990>}
2023-07-15 09:45:37.153 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'd8e579ce-23bf-49e4-b82d-77ddd3109330', 'timestamp': '2023-07-15T13:45:32.557Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.Temperature': {'ambientTemperatureCelsius': 24.25999}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 09:45:37.153 DEBUG (MainThread) [google_nest_sdm.device] Processing update d8e579ce-23bf-49e4-b82d-77ddd3109330 @ 2023-07-15 13:45:32.557000+00:00
2023-07-15 09:45:37.154 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Temperature': <google_nest_sdm.device_traits.TemperatureTrait object at 0x7fad6ea1e790>}
2023-07-15 09:45:37.228 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '22f550c4-8a74-47ab-9b43-f3efa4baba9f', 'timestamp': '2023-07-15T13:45:32.557Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 65.0}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 09:45:37.229 DEBUG (MainThread) [google_nest_sdm.device] Processing update 22f550c4-8a74-47ab-9b43-f3efa4baba9f @ 2023-07-15 13:45:32.557000+00:00
2023-07-15 09:45:37.229 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Humidity': <google_nest_sdm.device_traits.HumidityTrait object at 0x7fad703b1cd0>}
2023-07-15 10:14:34.703 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '0b12b20d-03ad-42b3-a005-e23f86f45013', 'timestamp': '2023-07-15T14:14:31.378Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.Temperature': {'ambientTemperatureCelsius': 24.23999}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:14:34.704 DEBUG (MainThread) [google_nest_sdm.device] Processing update 0b12b20d-03ad-42b3-a005-e23f86f45013 @ 2023-07-15 14:14:31.378000+00:00
2023-07-15 10:14:34.704 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Temperature': <google_nest_sdm.device_traits.TemperatureTrait object at 0x7fad70316150>}
2023-07-15 10:24:31.237 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'e24b8722-fde8-431b-944e-83c3d050ae9f', 'timestamp': '2023-07-15T14:24:24.516Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.Temperature': {'ambientTemperatureCelsius': 24.26999}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:24:31.238 DEBUG (MainThread) [google_nest_sdm.device] Processing update e24b8722-fde8-431b-944e-83c3d050ae9f @ 2023-07-15 14:24:24.516000+00:00
2023-07-15 10:24:31.238 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Temperature': <google_nest_sdm.device_traits.TemperatureTrait object at 0x7fad6de925d0>}
2023-07-15 10:52:55.534 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'b8c3d89a-8dee-4fc4-8816-8d23699ca9d6', 'timestamp': '2023-07-15T14:52:53.572Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.ThermostatHvac': {'status': 'COOLING'}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:52:55.535 DEBUG (MainThread) [google_nest_sdm.device] Processing update b8c3d89a-8dee-4fc4-8816-8d23699ca9d6 @ 2023-07-15 14:52:53.572000+00:00
2023-07-15 10:52:55.535 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatHvac': <google_nest_sdm.thermostat_traits.ThermostatHvacTrait object at 0x7fad6dbfa010>}
2023-07-15 10:53:27.433 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'b799880a-4dfd-41dc-bbda-cd7627938077', 'timestamp': '2023-07-15T14:53:25.429Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.ThermostatTemperatureSetpoint': {'coolCelsius': 24.5}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:53:27.434 DEBUG (MainThread) [google_nest_sdm.device] Processing update b799880a-4dfd-41dc-bbda-cd7627938077 @ 2023-07-15 14:53:25.429000+00:00
2023-07-15 10:53:27.434 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7fad702862d0>}
2023-07-15 10:53:32.010 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '0c73cfaa-f568-4df7-988d-81454c964e48', 'timestamp': '2023-07-15T14:53:27.001Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.ThermostatTemperatureSetpoint': {}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:53:32.010 DEBUG (MainThread) [google_nest_sdm.device] Processing update 0c73cfaa-f568-4df7-988d-81454c964e48 @ 2023-07-15 14:53:27.001000+00:00
2023-07-15 10:53:32.011 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7fad9de47d10>}
2023-07-15 10:53:32.011 ERROR (ThreadPoolExecutor-ThreadScheduler_0) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Top-level exception occurred in callback while processing a message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 126, in _wrap_callback_errors
    callback(message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 277, in callback_wrapper
    future.result()
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 456, in result
    return self.__get_result()
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 401, in __get_result
    raise self._exception
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 540, in _async_message_callback
    await self._device_manager_task.result().async_handle_event(event)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device_manager.py", line 72, in async_handle_event
    await device.async_handle_event(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 166, in async_handle_event
    await callback(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 133, in handle_event
    target()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 742, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 812, in _async_write_ha_state
    attr.update(self.state_attributes or {})
                ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/climate/__init__.py", line 306, in state_attributes
    self.target_temperature,
    ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 153, in target_temperature
    return trait.cool_celsius
           ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/thermostat_traits.py", line 139, in cool_celsius
    return cast(float, self._data[COOL_CELSIUS])
                       ~~~~~~~~~~^^^^^^^^^^^^^^
KeyError: 'coolCelsius'
2023-07-15 10:53:32.022 DEBUG (ThreadPoolExecutor-ThreadScheduler_0) [google_nest_sdm.google_nest_subscriber] Subscriber disconnected, will restart: <class 'KeyError'>: 'coolCelsius'
2023-07-15 10:53:32.391 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '0c73cfaa-f568-4df7-988d-81454c964e48', 'timestamp': '2023-07-15T14:53:27.001Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.ThermostatTemperatureSetpoint': {}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:53:32.392 DEBUG (MainThread) [google_nest_sdm.device] Processing update 0c73cfaa-f568-4df7-988d-81454c964e48 @ 2023-07-15 14:53:27.001000+00:00
2023-07-15 10:53:32.392 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7fad6ea29c90>}
2023-07-15 10:53:32.394 ERROR (ThreadPoolExecutor-ThreadScheduler_0) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Top-level exception occurred in callback while processing a message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 126, in _wrap_callback_errors
    callback(message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 277, in callback_wrapper
    future.result()
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 456, in result
    return self.__get_result()
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 401, in __get_result
    raise self._exception
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 540, in _async_message_callback
    await self._device_manager_task.result().async_handle_event(event)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device_manager.py", line 72, in async_handle_event
    await device.async_handle_event(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 166, in async_handle_event
    await callback(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 133, in handle_event
    target()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 742, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 812, in _async_write_ha_state
    attr.update(self.state_attributes or {})
                ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/climate/__init__.py", line 306, in state_attributes
    self.target_temperature,
    ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 153, in target_temperature
    return trait.cool_celsius
           ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/thermostat_traits.py", line 139, in cool_celsius
    return cast(float, self._data[COOL_CELSIUS])
                       ~~~~~~~~~~^^^^^^^^^^^^^^
KeyError: 'coolCelsius'
2023-07-15 10:53:32.580 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '29418d8e-0892-4377-b4ca-6c6e6ac645da', 'timestamp': '2023-07-15T14:53:30.746Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.ThermostatHvac': {'status': 'OFF'}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:53:32.580 DEBUG (MainThread) [google_nest_sdm.device] Processing update 29418d8e-0892-4377-b4ca-6c6e6ac645da @ 2023-07-15 14:53:30.746000+00:00
2023-07-15 10:53:32.581 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatHvac': <google_nest_sdm.thermostat_traits.ThermostatHvacTrait object at 0x7fad702103d0>}
2023-07-15 10:53:32.582 ERROR (ThreadPoolExecutor-ThreadScheduler_0) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Top-level exception occurred in callback while processing a message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 126, in _wrap_callback_errors
    callback(message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 277, in callback_wrapper
    future.result()
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 456, in result
    return self.__get_result()
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 401, in __get_result
    raise self._exception
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 540, in _async_message_callback
    await self._device_manager_task.result().async_handle_event(event)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device_manager.py", line 72, in async_handle_event
    await device.async_handle_event(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 166, in async_handle_event
    await callback(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 133, in handle_event
    target()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 742, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 812, in _async_write_ha_state
    attr.update(self.state_attributes or {})
                ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/climate/__init__.py", line 306, in state_attributes
    self.target_temperature,
    ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 153, in target_temperature
    return trait.cool_celsius
           ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/thermostat_traits.py", line 139, in cool_celsius
    return cast(float, self._data[COOL_CELSIUS])
                       ~~~~~~~~~~^^^^^^^^^^^^^^
KeyError: 'coolCelsius'
2023-07-15 10:53:32.691 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '0c73cfaa-f568-4df7-988d-81454c964e48', 'timestamp': '2023-07-15T14:53:27.001Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.ThermostatTemperatureSetpoint': {}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:53:32.691 DEBUG (MainThread) [google_nest_sdm.device] Processing update 0c73cfaa-f568-4df7-988d-81454c964e48 @ 2023-07-15 14:53:27.001000+00:00
2023-07-15 10:53:32.691 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7fad82276b50>}
2023-07-15 10:53:32.693 ERROR (ThreadPoolExecutor-ThreadScheduler_0) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Top-level exception occurred in callback while processing a message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 126, in _wrap_callback_errors
    callback(message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 277, in callback_wrapper
    future.result()
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 456, in result
    return self.__get_result()
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 401, in __get_result
    raise self._exception
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 540, in _async_message_callback
    await self._device_manager_task.result().async_handle_event(event)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device_manager.py", line 72, in async_handle_event
    await device.async_handle_event(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 166, in async_handle_event
    await callback(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 133, in handle_event
    target()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 742, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 812, in _async_write_ha_state
    attr.update(self.state_attributes or {})
                ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/climate/__init__.py", line 306, in state_attributes
    self.target_temperature,
    ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 153, in target_temperature
    return trait.cool_celsius
           ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/thermostat_traits.py", line 139, in cool_celsius
    return cast(float, self._data[COOL_CELSIUS])
                       ~~~~~~~~~~^^^^^^^^^^^^^^
KeyError: 'coolCelsius'
2023-07-15 10:53:32.887 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '29418d8e-0892-4377-b4ca-6c6e6ac645da', 'timestamp': '2023-07-15T14:53:30.746Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.ThermostatHvac': {'status': 'OFF'}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:53:32.888 DEBUG (MainThread) [google_nest_sdm.device] Processing update 29418d8e-0892-4377-b4ca-6c6e6ac645da @ 2023-07-15 14:53:30.746000+00:00
2023-07-15 10:53:32.888 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatHvac': <google_nest_sdm.thermostat_traits.ThermostatHvacTrait object at 0x7fad7016a310>}
2023-07-15 10:53:32.890 ERROR (ThreadPoolExecutor-ThreadScheduler_0) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Top-level exception occurred in callback while processing a message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 126, in _wrap_callback_errors
    callback(message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 277, in callback_wrapper
    future.result()
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 456, in result
    return self.__get_result()
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 401, in __get_result
    raise self._exception
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 540, in _async_message_callback
    await self._device_manager_task.result().async_handle_event(event)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device_manager.py", line 72, in async_handle_event
    await device.async_handle_event(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 166, in async_handle_event
    await callback(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 133, in handle_event
    target()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 742, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 812, in _async_write_ha_state
    attr.update(self.state_attributes or {})
                ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/climate/__init__.py", line 306, in state_attributes
    self.target_temperature,
    ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 153, in target_temperature
    return trait.cool_celsius
           ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/thermostat_traits.py", line 139, in cool_celsius
    return cast(float, self._data[COOL_CELSIUS])
                       ~~~~~~~~~~^^^^^^^^^^^^^^
KeyError: 'coolCelsius'
2023-07-15 10:53:33.067 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '2b689fea-cde2-4f85-b9b7-6a07274b6b10', 'timestamp': '2023-07-15T14:53:28.429Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.ThermostatMode': {'mode': 'COOL', 'availableModes': ['HEAT', 'COOL', 'HEATCOOL', 'OFF']}, 'sdm.devices.traits.ThermostatEco': {'availableModes': ['OFF', 'MANUAL_ECO'], 'mode': 'MANUAL_ECO', 'heatCelsius': 10.0, 'coolCelsius': 24.44444}, 'sdm.devices.traits.ThermostatTemperatureSetpoint': {}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:53:33.068 DEBUG (MainThread) [google_nest_sdm.device] Processing update 2b689fea-cde2-4f85-b9b7-6a07274b6b10 @ 2023-07-15 14:53:28.429000+00:00
2023-07-15 10:53:33.068 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatMode': <google_nest_sdm.thermostat_traits.ThermostatModeTrait object at 0x7fad6ef79a50>, 'sdm.devices.traits.ThermostatEco': <google_nest_sdm.thermostat_traits.ThermostatEcoTrait object at 0x7fad70210950>, 'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7fad805b4c90>}
2023-07-15 10:53:33.109 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '0c73cfaa-f568-4df7-988d-81454c964e48', 'timestamp': '2023-07-15T14:53:27.001Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.ThermostatTemperatureSetpoint': {}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:53:33.109 DEBUG (MainThread) [google_nest_sdm.device] Processing update 0c73cfaa-f568-4df7-988d-81454c964e48 @ 2023-07-15 14:53:27.001000+00:00
2023-07-15 10:53:33.110 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7fad6ef7b350>}
2023-07-15 10:53:33.289 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '29418d8e-0892-4377-b4ca-6c6e6ac645da', 'timestamp': '2023-07-15T14:53:30.746Z', 'resourceUpdate': {'name': 'enterprises/ZZZ/devices/BBB', 'traits': {'sdm.devices.traits.ThermostatHvac': {'status': 'OFF'}}}, 'userId': 'UUU', 'resourceGroup': ['enterprises/ZZZ/devices/BBB']}
2023-07-15 10:53:33.290 DEBUG (MainThread) [google_nest_sdm.device] Processing update 29418d8e-0892-4377-b4ca-6c6e6ac645da @ 2023-07-15 14:53:30.746000+00:00
2023-07-15 10:53:33.290 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatHvac': <google_nest_sdm.thermostat_traits.ThermostatHvacTrait object at 0x7fad70213f10>}
2023-07-15 10:53:37.854 DEBUG (MainThread) [google_nest_sdm.google_nest_subscriber] Watchdog: subscriber shut down; restarting in 10 seconds
2023-07-15 10:53:48.375 DEBUG (ThreadPoolExecutor-2_0) [google_nest_sdm.google_nest_subscriber] Subscriber 'projects/home-assistant-278703/subscriptions/home-assistant-TTT' configured on topic 'projects/sdm-prod/topics/enterprise-ZZZ'
2023-07-15 10:53:48.384 DEBUG (MainThread) [google_nest_sdm.google_nest_subscriber] Subscriber reconnected
2023-07-15 10:53:48.384 DEBUG (MainThread) [google_nest_sdm.google_nest_subscriber] Starting background watchdog thread
ianwood commented 1 year ago

[edited a few times for clarity]

Integration appears to fail at 5am where the thermostat is indicated as being off which it was not. The failures continue indefinitely at that point until the integration is manually reloaded at 1:23pm and then everything works again.

Last successful thermostat setting at 12:12am:

image
2023-07-17 00:12:07.691 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 00:12:09.571 DEBUG (MainThread) [homeassistant.helpers.config_entry_oauth2_flow] Sending token request to https://www.googleapis.com/oauth2/v4/token
2023-07-17 00:12:09.862 DEBUG (MainThread) [google_nest_sdm.auth] request[post]=https://smartdevicemanagement.googleapis.com/v1/enterprises/[redacted]/devices/[redacted]:executeCommand
2023-07-17 00:12:09.862 DEBUG (MainThread) [google_nest_sdm.auth] request[post json]={'command': 'sdm.devices.commands.ThermostatTemperatureSetpoint.SetRange', 'params': {'heatCelsius': 20.0, 'coolCelsius': 21.666666666666668}}
2023-07-17 00:12:10.512 DEBUG (MainThread) [google_nest_sdm.auth] request[post]=https://smartdevicemanagement.googleapis.com/v1/enterprises/[redacted]/devices/[redacted]:executeCommand
2023-07-17 00:12:10.513 DEBUG (MainThread) [google_nest_sdm.auth] request[post json]={'command': 'sdm.devices.commands.Fan.SetTimer', 'params': {'timerMode': 'ON', 'duration': '43200s'}}
2023-07-17 00:12:12.718 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '3ab3d09a-0a04-4abc-9c1a-b679f45c19f6', 'timestamp': '2023-07-17T07:12:10.494045Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.ThermostatMode': {'mode': 'HEATCOOL', 'availableModes': ['HEAT', 'COOL', 'HEATCOOL', 'OFF']}, 'sdm.devices.traits.ThermostatEco': {'availableModes': ['OFF', 'MANUAL_ECO'], 'mode': 'OFF', 'heatCelsius': 15.555527, 'coolCelsius': 29.444397}, 'sdm.devices.traits.ThermostatTemperatureSetpoint': {'heatCelsius': 20.0, 'coolCelsius': 21.666666}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 00:12:12.719 DEBUG (MainThread) [google_nest_sdm.device] Processing update 3ab3d09a-0a04-4abc-9c1a-b679f45c19f6 @ 2023-07-17 07:12:10.494045+00:00
2023-07-17 00:12:12.720 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatMode': <google_nest_sdm.thermostat_traits.ThermostatModeTrait object at 0x7f2f21f69960>, 'sdm.devices.traits.ThermostatEco': <google_nest_sdm.thermostat_traits.ThermostatEcoTrait object at 0x7f2f1d5f6290>, 'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7f2f0dd2afe0>}
2023-07-17 00:12:12.914 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '13550093-d70f-457e-a4b6-2a19a358fb66', 'timestamp': '2023-07-17T07:12:10.494045Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.ThermostatMode': {'mode': 'HEATCOOL', 'availableModes': ['HEAT', 'COOL', 'HEATCOOL', 'OFF']}, 'sdm.devices.traits.ThermostatEco': {'availableModes': ['OFF', 'MANUAL_ECO'], 'mode': 'OFF', 'heatCelsius': 15.555527, 'coolCelsius': 29.444397}, 'sdm.devices.traits.ThermostatTemperatureSetpoint': {'heatCelsius': 20.0, 'coolCelsius': 21.666666}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 00:12:12.916 DEBUG (MainThread) [google_nest_sdm.device] Processing update 13550093-d70f-457e-a4b6-2a19a358fb66 @ 2023-07-17 07:12:10.494045+00:00
2023-07-17 00:12:12.917 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatMode': <google_nest_sdm.thermostat_traits.ThermostatModeTrait object at 0x7f2f0df91de0>, 'sdm.devices.traits.ThermostatEco': <google_nest_sdm.thermostat_traits.ThermostatEcoTrait object at 0x7f2f0df92710>, 'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7f2f0df90790>}
2023-07-17 00:12:12.957 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '0baae936-0a80-4770-b45c-07cd47f19f9e', 'timestamp': '2023-07-17T07:12:11.243909Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.Fan': {'timerMode': 'ON', 'timerTimeout': '2023-07-17T19:12:11Z'}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 00:12:12.958 DEBUG (MainThread) [google_nest_sdm.device] Processing update 0baae936-0a80-4770-b45c-07cd47f19f9e @ 2023-07-17 07:12:11.243909+00:00
2023-07-17 00:12:12.959 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Fan': <google_nest_sdm.device_traits.FanTrait object at 0x7f2f0df91f00>}
2023-07-17 00:12:15.917 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'a03b9ec5-b0f2-4cb2-b909-65cff4d8f271', 'timestamp': '2023-07-17T07:12:13.582816Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.ThermostatHvac': {'status': 'COOLING'}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 00:12:15.918 DEBUG (MainThread) [google_nest_sdm.device] Processing update a03b9ec5-b0f2-4cb2-b909-65cff4d8f271 @ 2023-07-17 07:12:13.582816+00:00
2023-07-17 00:12:15.919 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatHvac': <google_nest_sdm.thermostat_traits.ThermostatHvacTrait object at 0x7f2f0df93e80>}
2023-07-17 00:12:17.718 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

The first indication of failure is 5am where thermostat is incorrectly shown as off. Integration restored manually by reloading it at 1:23pm.

image
2023-07-17 04:30:08.877 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'b68b05c4-d733-47f0-acc2-c17d3218d43b', 'timestamp': '2023-07-17T11:30:07.234709Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 60.0}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 04:30:08.878 DEBUG (MainThread) [google_nest_sdm.device] Processing update b68b05c4-d733-47f0-acc2-c17d3218d43b @ 2023-07-17 11:30:07.234709+00:00
2023-07-17 04:30:08.879 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Humidity': <google_nest_sdm.device_traits.HumidityTrait object at 0x7f2f0dd1d5a0>}
2023-07-17 04:30:11.526 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'b8b8301c-f91c-44c8-a6b8-4017423ec859', 'timestamp': '2023-07-17T11:30:09.230370Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 64.0}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 04:30:11.527 DEBUG (MainThread) [google_nest_sdm.device] Processing update b8b8301c-f91c-44c8-a6b8-4017423ec859 @ 2023-07-17 11:30:09.230370+00:00
2023-07-17 04:30:11.528 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Humidity': <google_nest_sdm.device_traits.HumidityTrait object at 0x7f2f0e01feb0>}
2023-07-17 04:30:12.221 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 20 similar log entries removed ...]

2023-07-17 04:33:52.282 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 04:34:02.191 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [139840029559488] Connection closed by client
2023-07-17 04:34:02.197 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [139840087469376] Connection closed by client
2023-07-17 04:34:02.285 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 27 similar log entries removed ...]

2023-07-17 04:38:52.360 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 04:38:57.156 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '55b7639f-df7e-4b21-9cee-921657d4533a', 'timestamp': '2023-07-17T11:38:44.553Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'events': {'sdm.devices.events.CameraMotion.Motion': {'eventSessionId': 'AVPHwEtRCikrndUPk4v08s7aZFRZOzRkkmv5jfvjHL9nvqpfXke8RR9So4lslL84JNBz5uvCbmE1kE24W_sITFahi-mU', 'eventId': 'CiUA2vuxr_H8ujvFxXBVf_LdFN0hQ491BvyRTwlXXody7yMl4048Eo0BAOdDZOUI_uCCEacC_nuFNxrXkme12oR5dA_Oe1KwU1Cw_9yM9iR5PAhuIj-gloTkrbhxpfZno_QwwCxQebm5yunKKa6zMuu1_7N66vQtUf9OhtAErNwLabG13B4_Ynl7enAw5X6sLBxC9ylO_34cKVKuzL0yt6BDEyabAwi567VBFUFE42IPkpov5CBo'}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 04:38:57.158 DEBUG (MainThread) [google_nest_sdm.device] Processing update 55b7639f-df7e-4b21-9cee-921657d4533a @ 2023-07-17 11:38:44.553000+00:00
2023-07-17 04:38:57.159 DEBUG (MainThread) [google_nest_sdm.event_media] Event Update dict_keys(['AVPHwEtRCikrndUPk4v08s7aZFRZOzRkkmv5jfvjHL9nvqpfXke8RR9So4lslL84JNBz5uvCbmE1kE24W_sITFahi-mU'])
2023-07-17 04:38:57.291 DEBUG (MainThread) [google_nest_sdm.event_media] Message contains notifiable events: {'sdm.devices.events.CameraMotion.Motion': <ImageEventBase {'event_type': 'sdm.devices.events.CameraMotion.Motion', 'event_data': {'eventSessionId': 'AVPHwEtRCikrndUPk4v08s7aZFRZOzRkkmv5jfvjHL9nvqpfXke8RR9So4lslL84JNBz5uvCbmE1kE24W_sITFahi-mU', 'eventId': 'CiUA2vuxr_H8ujvFxXBVf_LdFN0hQ491BvyRTwlXXody7yMl4048Eo0BAOdDZOUI_uCCEacC_nuFNxrXkme12oR5dA_Oe1KwU1Cw_9yM9iR5PAhuIj-gloTkrbhxpfZno_QwwCxQebm5yunKKa6zMuu1_7N66vQtUf9OhtAErNwLabG13B4_Ynl7enAw5X6sLBxC9ylO_34cKVKuzL0yt6BDEyabAwi567VBFUFE42IPkpov5CBo'}, 'timestamp': '2023-07-17T11:38:44.553000+00:00', 'event_image_type': 'image/jpeg'} sessions=1>}
2023-07-17 04:38:57.292 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '55b7639f-df7e-4b21-9cee-921657d4533a', 'timestamp': '2023-07-17T11:38:44.553Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'events': {'sdm.devices.events.CameraMotion.Motion': {'eventSessionId': 'AVPHwEtRCikrndUPk4v08s7aZFRZOzRkkmv5jfvjHL9nvqpfXke8RR9So4lslL84JNBz5uvCbmE1kE24W_sITFahi-mU', 'eventId': 'CiUA2vuxr_H8ujvFxXBVf_LdFN0hQ491BvyRTwlXXody7yMl4048Eo0BAOdDZOUI_uCCEacC_nuFNxrXkme12oR5dA_Oe1KwU1Cw_9yM9iR5PAhuIj-gloTkrbhxpfZno_QwwCxQebm5yunKKa6zMuu1_7N66vQtUf9OhtAErNwLabG13B4_Ynl7enAw5X6sLBxC9ylO_34cKVKuzL0yt6BDEyabAwi567VBFUFE42IPkpov5CBo'}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 04:38:57.292 DEBUG (MainThread) [homeassistant.components.nest] Event Update dict_keys(['sdm.devices.events.CameraMotion.Motion'])
2023-07-17 04:38:57.448 DEBUG (MainThread) [google_nest_sdm.event_media] Checking cache size 985
2023-07-17 04:39:02.328 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 18 similar log entries removed ...]

2023-07-17 04:42:22.403 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 04:42:23.190 INFO (Thread-2373 (_run)) [google.api_core.bidi] Re-established stream
2023-07-17 04:42:32.385 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 43 similar log entries removed ...]

2023-07-17 04:50:02.498 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 04:50:10.389 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [139840070413440] Connection closed by client
2023-07-17 04:50:12.507 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 9 similar log entries removed ...]

2023-07-17 04:52:02.537 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 04:52:08.332 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'ec1d411f-0f42-4065-973c-017e93e530fa', 'timestamp': '2023-07-17T11:52:06.251453Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 66.0}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 04:52:08.333 DEBUG (MainThread) [google_nest_sdm.device] Processing update ec1d411f-0f42-4065-973c-017e93e530fa @ 2023-07-17 11:52:06.251453+00:00
2023-07-17 04:52:08.334 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Humidity': <google_nest_sdm.device_traits.HumidityTrait object at 0x7f2f0dd1e020>}
2023-07-17 04:52:12.539 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 39 similar log entries removed ...]

2023-07-17 04:59:02.617 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 04:59:10.005 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [139840331889296] Connection closed by client
2023-07-17 04:59:12.615 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 3 similar log entries removed ...]

2023-07-17 04:59:52.622 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 05:00:02.338 DEBUG (MainThread) [homeassistant.helpers.config_entry_oauth2_flow] Sending token request to https://www.googleapis.com/oauth2/v4/token
2023-07-17 05:00:02.522 DEBUG (MainThread) [google_nest_sdm.auth] request[post]=https://smartdevicemanagement.googleapis.com/v1/enterprises/[redacted]/devices/[redacted]:executeCommand
2023-07-17 05:00:02.522 DEBUG (MainThread) [google_nest_sdm.auth] request[post json]={'command': 'sdm.devices.commands.ThermostatTemperatureSetpoint.SetRange', 'params': {'heatCelsius': 20.0, 'coolCelsius': 21.666666666666668}}
2023-07-17 05:00:02.637 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 05:00:10.525 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'edc72cec-43fe-445c-b6f1-0e463d4beab6', 'timestamp': '2023-07-17T12:00:06.390232Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.ThermostatMode': {'mode': 'HEATCOOL', 'availableModes': ['HEAT', 'COOL', 'HEATCOOL', 'OFF']}, 'sdm.devices.traits.ThermostatEco': {'availableModes': ['OFF', 'MANUAL_ECO'], 'mode': 'OFF', 'heatCelsius': 15.555527, 'coolCelsius': 29.444397}, 'sdm.devices.traits.ThermostatTemperatureSetpoint': {'heatCelsius': 20.0, 'coolCelsius': 21.666666}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 05:00:10.526 DEBUG (MainThread) [google_nest_sdm.device] Processing update edc72cec-43fe-445c-b6f1-0e463d4beab6 @ 2023-07-17 12:00:06.390232+00:00
2023-07-17 05:00:10.527 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatMode': <google_nest_sdm.thermostat_traits.ThermostatModeTrait object at 0x7f2f0a5afc10>, 'sdm.devices.traits.ThermostatEco': <google_nest_sdm.thermostat_traits.ThermostatEcoTrait object at 0x7f2f0a5af790>, 'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7f2f0a5af5b0>}
2023-07-17 05:00:11.128 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '6cb261d7-fbe3-4565-b37f-2c9fb081f0ec', 'timestamp': '2023-07-17T12:00:06.390232Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.ThermostatMode': {'mode': 'OFF', 'availableModes': ['OFF']}, 'sdm.devices.traits.ThermostatEco': {'availableModes': ['OFF', 'MANUAL_ECO'], 'mode': 'OFF', 'heatCelsius': 0.0, 'coolCelsius': 0.0}, 'sdm.devices.traits.ThermostatTemperatureSetpoint': {}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}
2023-07-17 05:00:11.129 DEBUG (MainThread) [google_nest_sdm.device] Processing update 6cb261d7-fbe3-4565-b37f-2c9fb081f0ec @ 2023-07-17 12:00:06.390232+00:00
2023-07-17 05:00:11.130 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatMode': <google_nest_sdm.thermostat_traits.ThermostatModeTrait object at 0x7f2f0a392e60>, 'sdm.devices.traits.ThermostatEco': <google_nest_sdm.thermostat_traits.ThermostatEcoTrait object at 0x7f2f0a622c20>, 'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7f2f171b41f0>}
2023-07-17 05:00:12.645 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 100 similar log entries removed ...]

2023-07-17 05:17:12.860 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 05:17:21.534 INFO (Thread-2373 (_run)) [google.api_core.bidi] Re-established stream
2023-07-17 05:17:22.872 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 73 similar log entries removed ...]

2023-07-17 05:29:53.054 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 05:30:00.186 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139839988493296] Unsupported hvac_mode 'heat_cool'
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 199, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1849, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1889, in _execute_service
await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 226, in handle_service
await service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 798, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 980, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 838, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 287, in async_set_hvac_mode
raise ValueError(f"Unsupported hvac_mode '{hvac_mode}'")
ValueError: Unsupported hvac_mode 'heat_cool'
2023-07-17 05:30:03.048 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 131 similar log entries removed ...]

2023-07-17 05:52:13.359 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 05:52:20.270 INFO (Thread-2373 (_run)) [google.api_core.bidi] Re-established stream
2023-07-17 05:52:23.361 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"

[... 43 similar log entries removed ...]

2023-07-17 05:59:53.481 INFO (MainThread) [httpx] HTTP Request: POST http://192.168.xxx.xxx:8080/goform/AppCommand.xml "HTTP/1.0 200 OK"
2023-07-17 06:00:00.268 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139839988493296] Unsupported hvac_mode 'heat_cool'
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 199, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1849, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1889, in _execute_service
await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 226, in handle_service
await service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 798, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 980, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 838, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 287, in async_set_hvac_mode
raise ValueError(f"Unsupported hvac_mode '{hvac_mode}'")
ValueError: Unsupported hvac_mode 'heat_cool'
allenporter commented 1 year ago

The problem line is:

2023-07-17 05:00:11.128 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '6cb261d7-fbe3-4565-b37f-2c9fb081f0ec', 'timestamp': '2023-07-17T12:00:06.390232Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.ThermostatMode': {'mode': 'OFF', 'availableModes': ['OFF']}, 'sdm.devices.traits.ThermostatEco': {'availableModes': ['OFF', 'MANUAL_ECO'], 'mode': 'OFF', 'heatCelsius': 0.0, 'coolCelsius': 0.0}, 'sdm.devices.traits.ThermostatTemperatureSetpoint': {}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}

There ThermostatMode availableModes only is OFF

You can see a few lines before it looks normal and the available modes includes ['HEAT', 'COOL', 'HEATCOOL', 'OFF']

2023-07-17 05:00:10.525 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'edc72cec-43fe-445c-b6f1-0e463d4beab6', 'timestamp': '2023-07-17T12:00:06.390232Z', 'resourceUpdate': {'name': 'enterprises/[redacted]/devices/[redacted]', 'traits': {'sdm.devices.traits.ThermostatMode': {'mode': 'HEATCOOL', 'availableModes': ['HEAT', 'COOL', 'HEATCOOL', 'OFF']}, 'sdm.devices.traits.ThermostatEco': {'availableModes': ['OFF', 'MANUAL_ECO'], 'mode': 'OFF', 'heatCelsius': 15.555527, 'coolCelsius': 29.444397}, 'sdm.devices.traits.ThermostatTemperatureSetpoint': {'heatCelsius': 20.0, 'coolCelsius': 21.666666}}}, 'userId': '[redacted]', 'resourceGroup': ['enterprises/[redacted]/devices/[redacted]']}

The right approach here is to get Nest API to fix this error. A good next step is to file an issue at: https://developers.google.com/nest/device-access/support and include the logs that show the incorrect mode and give them information needed to identify your gmail account, project id, and timestamps/timezone of when the incorrect messages were published, and details about the thermostat model invovled. This will give you a direct line with the engineering team that can identify the bug and get this fixed for all users who have devices getting stuck similar to yours.

ianwood commented 1 year ago

I've opened an issue with Google here:

Google Issue Tracker 291659614

I've noticed the issue appears to be related to a persistent state between HA and the Nest API. Once the error occurs, it will continue to occur until the integration is reloaded. Once the integration is reloaded, the error stops occurring.

domoritz commented 1 year ago

Thank you. I agree that it seems like also a bug in HA that the problem doesn’t get resolved once the API responds correctly.

allenporter commented 1 year ago

Oh no just to clarify, see my update above https://github.com/home-assistant/core/issues/92927#issuecomment-1639179479 this is a google nest publisher issue, not a home assistant bug.

The way the integration works is that it polls the API on startup, then uses the subscriber API to efficiently be notified about updates to devices immediately as soon as they happen -- rather than polling constantly and inefficiently. The nest API is incorrectly publishing a command that says: "Your thermostat does not support heating or cooling" and home assistant honors that. On restart, the API returns the right response.

This is a nest publisher bug that is very important to be resolved.

@ianwood your bug report includes the eco trait, which is fine. You need to include an example with sdm.devices.traits.ThermostatMode like i included.

ianwood commented 1 year ago

Thank you for the clarification. Makes sense.

Anyone else experience this issue, please feel free to share debug information as I did on Google Issue Tracker 291659614.

dredjohn21 commented 1 year ago

Thanks @ianwood - I'm having same issue. For all that are seeing this, please go to https://issuetracker.google.com/issues/291659614?pli=1 and click the +1 in top right corner to upvote. This is how Google prioritizes reviewing/fixing issues.

allenporter commented 1 year ago

What's better than +1 is to include detailed bug reports with debug logs showing the incorrect messages published.

dredjohn21 commented 1 year ago

What's better than +1 is to include detailed bug reports with debug logs showing the incorrect messages published.

Just fyi: I suspect whatever broke is now fixed. I had setup an automation to alert me when it happens and no issues over last week. If it does I’ll upload logs. Been in debug logging mode this entire time waiting to capture…

DocBrownInSpace commented 1 year ago

What's better than +1 is to include detailed bug reports with debug logs showing the incorrect messages published.

Just fyi: I suspect whatever broke is now fixed. I had setup an automation to alert me when it happens and no issues over last week. If it does I’ll upload logs. Been in debug logging mode this entire time waiting to capture…

Still broken for me.

sdrapha commented 1 year ago

I have a suspicion about getting to a broken state when my router froze the other day and I lost connectivity. I'm not totally sure and a haven't had time to investigate or experiment. Just saying it here in case that helps anyone figuring out the situation. I know there is the google api bug already documented and I also gave my +1 there as well.

allenporter commented 1 year ago

I have a suspicion about getting to a broken state when my router froze the other day and I lost connectivity. I'm not totally sure and a haven't had time to investigate or experiment. Just saying it here in case that helps anyone figuring out the situation. I know there is the google api bug already documented and I also gave my +1 there as well.

You are welcome to file a separate issue if you get more info. this bug is tracking something very specific.

dredjohn21 commented 1 year ago

What's better than +1 is to include detailed bug reports with debug logs showing the incorrect messages published.

@allenporter - I managed to capture the issue (it happened briefly again this morning). I pasted problem code with eventID info into the above Google issues report. Hope that helps. Thanks again for all your guidance!

robertvanlienden commented 1 year ago

Some months ago (beginning of this year? Can't find the issues from that time) there was some big Google Nest/HA outrage. Since that moment I needed to re-auth every ~7 days.

Today took some time to dive into this, found some post on HA community saying that when the "OAuth consent screen" is on "testing mode", you need to re-auth every ~7 days.

Checked my settings, and yes; I had "testing mode" on. Switched to production right now, hoping the issue will disapear.

Will keep you guys updated! (As I want this to be working again before the winter... Otherwise I need to find some alternative to my Nest Thermostat)

dredjohn21 commented 1 year ago

@robertvanlienden thanks for reporting. Interesting theory & I vaguely recall seeing this setting. Where is it?

robertvanlienden commented 1 year ago

@dredjohn21 Login to https://console.cloud.google.com/ => Go to your project => APIs and Services =>? OAuth consent screen.

There you have "Publishing status".

🤞 Hoping switching the status to "Production" will resolve the issue, but I am afraid that I will find out in 7+ days

dredjohn21 commented 1 year ago

Unfortunately mine was already set to production so doesn’t appear to be the root cause of my issue :(

allenporter commented 1 year ago

@robertvanlienden appreciate the intent to help but we have already identified the root cause of this issue, its a google event message publishing bug. The symptoms of this are entirely different than misconfigured oauth consent screen.

ianwood commented 11 months ago

I noticed this is closed and merged into #99093. Has that been pushed to release? I am on 2023.09.2 and still seeing the same issue. I am using Node Red to catch the API errors and reload the integration which works most of the time but not always.

dredjohn21 commented 11 months ago

@ianwood me too. did you ever get a response from Google on the logs you submitted? I never heard anything back.

https://issuetracker.google.com/issues/291659614?pli=1

allenporter commented 11 months ago

I closed this because Home Assistant now ignores invalid pubsub messages -- it never changes the available hvac modes even if the API publishes a bad message. If you are still seeing a problem, can you re-report more information like error logs / diagnostics, etc? Thanks.

ianwood commented 11 months ago

I need to re-enable the detailed logging but here is one event with normal logging:

Traceback (most recent call last):
File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/auth.py", line 124, in _raise_for_status
resp.raise_for_status()
File "/usr/local/lib/python3.11/site-packages/aiohttp/client_reqrep.py", line 1005, in raise_for_status
raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 400, message='Bad Request', url=URL('https://smartdevicemanagement.googleapis.com/v1/enterprises/632a4de4-c88e-4206-9461-eec6e6508a01/devices/AVPHwEuaLPHQH2m5bjJg_7GrjiakLokRXRJXhflkVxS6ywuG38W-tv7ieMC_QaM_2YyjR1LIh2Zrx709CW8mBmSr_N_X:executeCommand')
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/nest/climate.py", line 301, in async_set_temperature
await trait.set_range(low_temp, high_temp)
File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/thermostat_traits.py", line 166, in set_range
return await self._cmd.execute(data)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/traits.py", line 32, in execute
return await self._auth.post(f"{self._device_id}:executeCommand", json=data)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/auth.py", line 105, in post
return await AbstractAuth._raise_for_status(resp)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/auth.py", line 129, in _raise_for_status
raise ApiException(": ".join(detail)) from err
google_nest_sdm.exceptions.ApiException: Error from API: 400: FAILED_PRECONDITION: sdm.devices.commands.ThermostatTemperatureSetpoint.SetRange command not allowed in current thermostat mode.: Bad Request
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 227, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1969, in async_call
response_data = await coro
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 2006, in _execute_service
return await target(service_call)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 235, in handle_service
return await service.entity_service_call(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 870, in entity_service_call
response_data = await _handle_entity_call(
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 942, in _handle_entity_call
result = await task
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/climate/__init__.py", line 617, in async_service_temperature_set
await entity.async_set_temperature(**kwargs)
File "/usr/src/homeassistant/homeassistant/components/nest/climate.py", line 307, in async_set_temperature
raise HomeAssistantError(
homeassistant.exceptions.HomeAssistantError: Error setting climate.hallway temperature to {'target_temp_low': 20.555555555555554, 'target_temp_high': 23.88888888888889, 'area_id': ['hallway'], 'device_id': ['ba48b2246c04f45562daade80a1f5efa'], 'entity_id': ['climate.hallway']}: Error from API: 400: FAILED_PRECONDITION: sdm.devices.commands.ThermostatTemperatureSetpoint.SetRange command not allowed in current thermostat mode.: Bad Request
2023-09-22 14:00:02.927 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139982361089728] Error setting climate.hallway temperature to {'target_temp_low': 20.555555555555554, 'target_temp_high': 23.88888888888889, 'area_id': ['hallway'], 'device_id': ['ba48b2246c04f45562daade80a1f5efa'], 'entity_id': ['climate.hallway']}: Error from API: 400: FAILED_PRECONDITION: sdm.devices.commands.ThermostatTemperatureSetpoint.SetRange command not allowed in current thermostat mode.: Bad Request
Traceback (most recent call last):
File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/auth.py", line 124, in _raise_for_status
resp.raise_for_status()
File "/usr/local/lib/python3.11/site-packages/aiohttp/client_reqrep.py", line 1005, in raise_for_status
raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 400, message='Bad Request', url=URL('https://smartdevicemanagement.googleapis.com/v1/enterprises/632a4de4-c88e-4206-9461-eec6e6508a01/devices/AVPHwEuaLPHQH2m5bjJg_7GrjiakLokRXRJXhflkVxS6ywuG38W-tv7ieMC_QaM_2YyjR1LIh2Zrx709CW8mBmSr_N_X:executeCommand')
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/nest/climate.py", line 301, in async_set_temperature
await trait.set_range(low_temp, high_temp)
File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/thermostat_traits.py", line 166, in set_range
return await self._cmd.execute(data)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/traits.py", line 32, in execute
return await self._auth.post(f"{self._device_id}:executeCommand", json=data)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/auth.py", line 105, in post
return await AbstractAuth._raise_for_status(resp)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/auth.py", line 129, in _raise_for_status
raise ApiException(": ".join(detail)) from err
google_nest_sdm.exceptions.ApiException: Error from API: 400: FAILED_PRECONDITION: sdm.devices.commands.ThermostatTemperatureSetpoint.SetRange command not allowed in current thermostat mode.: Bad Request
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 227, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1969, in async_call
response_data = await coro
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 2006, in _execute_service
return await target(service_call)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 235, in handle_service
return await service.entity_service_call(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 870, in entity_service_call
response_data = await _handle_entity_call(
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 942, in _handle_entity_call
result = await task
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/climate/__init__.py", line 617, in async_service_temperature_set
await entity.async_set_temperature(**kwargs)
File "/usr/src/homeassistant/homeassistant/components/nest/climate.py", line 307, in async_set_temperature
raise HomeAssistantError(
homeassistant.exceptions.HomeAssistantError: Error setting climate.hallway temperature to {'target_temp_low': 20.555555555555554, 'target_temp_high': 23.88888888888889, 'area_id': ['hallway'], 'device_id': ['ba48b2246c04f45562daade80a1f5efa'], 'entity_id': ['climate.hallway']}: Error from API: 400: FAILED_PRECONDITION: sdm.devices.commands.ThermostatTemperatureSetpoint.SetRange command not allowed in current thermostat mode.: Bad Request
allenporter commented 11 months ago

OK thanks -- definitely keep the discussion going then with the issue tracker -- there is more to this than i thought which may include invalid state on the server as well.

pnbruckner commented 10 months ago

Wasn't sure if I should comment here or in #96434.

I had used the older Nest integration (i.e., the one based on Works with Nest API) for a very long time with very few problems. However, now that that API is closing down, I finally got around to converting my Nest account to a Google account, removing the old HA integration and adding the new one. But it did not take long to experience many errors and incorrect states in HA.

I did some analysis of my HA log (using a Python script I whipped up) and discovered that events coming from Google are being received and processed out of order in HA, which seems to be the root cause (or, at least, one main cause) of the problems I experienced.

E.g., here is a snippet from my log:

2023-09-28 17:53:37.554 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'ba5b7c76-8efe-4d31-a63f-2dc5e22ed7c5', 'timestamp': '2023-09-28T22:53:35.820Z', 'resourceUpdate': {'name': 'REDACTED', 'traits': {'sdm.devices.traits.ThermostatTemperatureSetpoint': {'coolCelsius': 23.01332}}}, 'userId': 'REDACTED', 'resourceGroup': ['REDACTED']}
2023-09-28 17:53:37.555 DEBUG (MainThread) [google_nest_sdm.device] Processing update ba5b7c76-8efe-4d31-a63f-2dc5e22ed7c5 @ 2023-09-28 22:53:35.820000+00:00
2023-09-28 17:53:37.555 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7fb6cc582e10>}
2023-09-28 17:53:37.557 ERROR (ThreadPoolExecutor-ThreadScheduler_0) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Top-level exception occurred in callback while processing a message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 126, in _wrap_callback_errors
    callback(message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 277, in callback_wrapper
    future.result()
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 456, in result
    return self.__get_result()
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/concurrent/futures/_base.py", line 401, in __get_result
    raise self._exception
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/google_nest_subscriber.py", line 540, in _async_message_callback
    await self._device_manager_task.result().async_handle_event(event)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device_manager.py", line 72, in async_handle_event
    await device.async_handle_event(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 166, in async_handle_event
    await callback(event_message)
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/device.py", line 133, in handle_event
    target()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 730, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 830, in _async_write_ha_state
    state, attr = self._async_generate_attributes()
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 773, in _async_generate_attributes
    attr.update(self.state_attributes or {})
                ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/climate/__init__.py", line 318, in state_attributes
    hass, self.target_temperature_low, temperature_unit, precision
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/nest/climate.py", line 168, in target_temperature_low
    return trait.heat_celsius
           ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/google_nest_sdm/thermostat_traits.py", line 134, in heat_celsius
    return cast(float, self._data[HEAT_CELSIUS])
                       ~~~~~~~~~~^^^^^^^^^^^^^^
KeyError: 'heatCelsius'
2023-09-28 17:53:37.570 DEBUG (ThreadPoolExecutor-ThreadScheduler_0) [google_nest_sdm.google_nest_subscriber] Subscriber disconnected, will restart: <class 'KeyError'>: 'heatCelsius'
2023-09-28 17:53:37.817 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'ea91531d-db63-4c07-9cd6-54ee717cc3f6', 'timestamp': '2023-09-28T22:53:35.512Z', 'resourceUpdate': {'name': 'REDACTED', 'traits': {'sdm.devices.traits.ThermostatMode': {'mode': 'COOL', 'availableModes': ['HEAT', 'COOL', 'HEATCOOL', 'OFF']}, 'sdm.devices.traits.ThermostatEco': {'availableModes': ['OFF', 'MANUAL_ECO'], 'mode': 'OFF', 'heatCelsius': 18.63997, 'coolCelsius': 25.56}, 'sdm.devices.traits.ThermostatTemperatureSetpoint': {'coolCelsius': 22.94885}}}, 'userId': 'REDACTED', 'resourceGroup': ['REDACTED']}
2023-09-28 17:53:37.818 DEBUG (MainThread) [google_nest_sdm.device] Processing update ea91531d-db63-4c07-9cd6-54ee717cc3f6 @ 2023-09-28 22:53:35.512000+00:00
2023-09-28 17:53:37.818 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatMode': <google_nest_sdm.thermostat_traits.ThermostatModeTrait object at 0x7fb6b242fe50>, 'sdm.devices.traits.ThermostatEco': <google_nest_sdm.thermostat_traits.ThermostatEcoTrait object at 0x7fb6b242e650>, 'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7fb6b242fd90>}
2023-09-28 17:53:37.819 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=climate.kitchen, old_state=<state climate.kitchen=heat_cool; hvac_modes=[<HVACMode.HEAT: 'heat'>, <HVACMode.COOL: 'cool'>, <HVACMode.HEAT_COOL: 'heat_cool'>, <HVACMode.OFF: 'off'>], min_temp=50, max_temp=90, fan_modes=['on', 'off'], preset_modes=['none', 'eco'], current_temperature=74, temperature=None, target_temp_high=74, target_temp_low=72, fan_mode=off, hvac_action=idle, preset_mode=none, friendly_name=Kitchen Thermostat, supported_features=27 @ 2023-09-28T09:40:33.419900-05:00>, new_state=<state climate.kitchen=cool; hvac_modes=[<HVACMode.HEAT: 'heat'>, <HVACMode.COOL: 'cool'>, <HVACMode.HEAT_COOL: 'heat_cool'>, <HVACMode.OFF: 'off'>], min_temp=50, max_temp=90, fan_modes=['on', 'off'], preset_modes=['none', 'eco'], current_temperature=74, temperature=73, target_temp_high=None, target_temp_low=None, fan_mode=off, hvac_action=idle, preset_mode=none, friendly_name=Kitchen Thermostat, supported_features=27 @ 2023-09-28T17:53:37.819795-05:00>>

The above occurred when I changed the mode of the Nest thermostat from Heat*Cool to Cool in the Nest app.

If you look closely, the first event above is timestamped (in the EventMessage raw_data) as "2023-09-28T22:53:35.820Z" and the next event is timestamped "2023-09-28T22:53:35.512Z". The first event indicates the set point, and the second event indicates a mode change (from HEATCOOL) to COOL.

The problem is that these events are being processed in the wrong order, because it seems they were received in the wrong order. I.e., the timestamp of the first event is AFTER the timestamp of the second event.

Since the first event is being processed when the HA integration still thinks the thermostat is in heat_cool mode (because it has not yet seen the event with the mode change), it causes an exception because it's trying to get the HEAT_CELSIUS value from the event, but it's not there, because the thermostat was already changed to cool mode, so the event only contains the COOL_CELSIUS value.

The script I wrote looks for out of order events, and out of a total of 106 EventMessage's, it found 29 that were out of order! And that's just less than one day's worth of activity in the log where I had debug enabled.

I don't know what's causing the events to be received in the wrong order, or what should be done about it, but I think this is very likely a main cause of the errors & instability of this integration.

pnbruckner commented 10 months ago

I guess I should say, I don't have any evidence that the messages are being received in the wrong order (i.e., if they're in the wrong order "on the wire"), only that it seems they are ultimately being processed in the wrong order.

allenporter commented 10 months ago

Nice find. There is code that will reject out of order messages for the same trait since it can't really reapply them in the right order once delivered. Maybe I will take a closer look at that and make sure it's working well.

However, there is still the problem in the other cases of the wrong or invalid messages being delivered... Like messages with missing fields and modes.

Seems like multiple problems here.

I'll see if anything can be recovered in the case the messages are in the wrong order (e.g. will being defensive against bad states help or still fail the commands?)

pnbruckner commented 10 months ago

I don't claim to know much about this integration, or how it works, but I don't think simply dropping out of order messages will work because it would seem important state updates would be missed. If it were me, I'd try to figure out how/where the messages are getting out of order in the first place and try to fix that. E.g., are multiple messages being received/processed in parallel at some level and there is a race condition, or something like that?

allenporter commented 10 months ago

@pnbruckner Just to clarify: This integration is not doing anything with respect to the root cause of out of order message delivery. The nest side publishes all messages, so what can home assistant even do?

Also, to clarify, what is dropped are out of order messages for any particular "trait". A "trait" state should be complete and replaces an entire previously existing trait.

allenporter commented 10 months ago

@pnbruckner oh, what home assistant version are you running? that looks older than what is being discussed here. I read the stack trace further and that code raising the exception no longer exists given the fix in #99093

pnbruckner commented 10 months ago

This integration is not doing anything with respect to the root cause of out of order message delivery. The nest side publishes all messages, so what can home assistant even do?

Of course, it could to a lot. Again, I haven't taken the time to fully understand the current implementation, but it does look a bit complex. I'm not saying there is, but there could be parallel processes, either in the integration itself or the pymyq package, that could unintentionally be causing messages to be processed out of order.

what home assistant version are you running?

The latest release, 2023.9.3. I haven't tried a beta release.

allenporter commented 10 months ago

@pnbruckner If you'd like to explore this I recommend starting a cli subscriber against the pubsub topic and view the order of messages being received and compare to the log statements. Or use the pubsub subscriber console UI method described on the troubleshooting instructions.

But to clarify my point: this integration is not doing anything interesting with respect to message delivery ordering. Out of order delivery is (1) inherent in pubsub or (2) or the order they are being published in the first place is different (publishing the setpoint before the mode, but technically not necessarily a bug, which is why I'm suggesting the other direction) so I don't think there is a root cause for delivery order to go fix in the integration. If you have data showing otherwise, I'm happy to see it's but it's not where I'm going to look given that it is expected via #1 and needs a data parsing fix either way.

Let's see how this performs with the data parsing rewrite. I had assumed it landed earlier than .10 but I'll check.

allenporter commented 10 months ago

@ianwood Are you still seeing this after 2023.10? In that release, the message parsing was rewritten to be more resilient to invalid messages or out of order messages, but I am not having this happening on my devices so I can't confirm if this made things better. Let me know if you have any feedback and we can take another look.

domoritz commented 10 months ago

I'm still having issues with controlling nest via home assistant. I haven't looked at the logs recently, though.

dredjohn21 commented 10 months ago

@ianwood Are you still seeing this after 2023.10? In that release, the message parsing was rewritten to be more resilient to invalid messages or out of order messages, but I am not having this happening on my devices so I can't confirm if this made things better. Let me know if you have any feedback and we can take another look.

I know you directed to another user - but if helpful: I'm still experiencing the problem. I also haven't heard any follow-up from Google after sending logs: https://issuetracker.google.com/issues/291659614?pli=1 (I know that isn't your area, and you were attempting another fix, but just as an FYI)

allenporter commented 10 months ago

@dredjohn21 Can you clarify what home assistant version you're using and what error you see?

Yes, just to be clear, i'm assuming nothing has changed on the google side, but wanting to explore what options there are for mitigation. (e.g. ignoring broken messages, or in case of out of order messages still trying to have things end up in the correct stateetc). There are probably a handful of issues here, so having data about exactly what is happening is helpful.

dredjohn21 commented 10 months ago

@dredjohn21 Can you clarify what home assistant version you're using and what error you see?

Yes, just to be clear, i'm assuming nothing has changed on the google side, but wanting to explore what options there are for mitigation. (e.g. ignoring broken messages, or in case of out of order messages still trying to have things end up in the correct stateetc). There are probably a handful of issues here, so having data about exactly what is happening is helpful.

Hi - sure: Home Assistant 2023.10.3 Supervisor 2023.10.0 Operating System 10.5 Frontend 20231005.0

The symptoms are same as reported above. I can enable detailed logging again and copy/paste logs after next occurrence. It just happened again this morning, but I didn't leave logging on since previously reported to Google. [I have an automation looking for the issue and restarting the integration usually gets it working... I have a notification to alert when it has to do this and it happens about once a day; usually in the morning]

allenporter commented 10 months ago

Yes, i new error logs would be helpful. I am surprised its the same given that code was rewritten.