Nest thermostat occasionally not reporting heating, but reports all other attributes correctly

mekaneck · February 17, 2022, 5:04pm

I have a Nest thermostat and the integration has been working great for at least a month or more. However starting 2 days ago, it occasionally isn’t reporting when it is actively heating. In other words, the climate entity shows the attribute "hvac_action":"idle" when it should be showing "hvac_action":"heating"

I drew red boxes around the times when the heat was on and clearly heating up the house, but the history log shows heating wasn’t active. So far it’s only been an issue the past 2 days when the set point is changed from 62 to 65, which occurs at 5am.

I went into my database (I use MariaDB so used phpMyAdmin) and verified that the attributes being recorded are what is displayed on the chart.

5am on Feb 17, which is the red box on the right in the graph, when it’s not reporting correctly:
{"hvac_modes":["off","heat_cool","cool","heat","fan_only"],"min_temp":45,"max_temp":95,"fan_modes":["on","off"],"preset_modes":["none","eco"],"current_temperature":65,"temperature":67,"target_temp_high":null,"target_temp_low":null,"fan_mode":"off","hvac_action":"idle","preset_mode":"none","friendly_name":"Living Room Thermostat","supported_features":27}

And for comparison, here is 8:47am later that day, when it is reporting correctly:
{"hvac_modes":["off","heat_cool","cool","heat","fan_only"],"min_temp":45,"max_temp":95,"fan_modes":["on","off"],"preset_modes":["none","eco"],"current_temperature":67,"temperature":67,"target_temp_high":null,"target_temp_low":null,"fan_mode":"off","hvac_action":"heating","preset_mode":"none","friendly_name":"Living Room Thermostat","supported_features":27}

What could I do in order to investigate this further? I can’t even come up with a possible reason that only 1 out of all the attributes are not correct.

allenporter · February 18, 2022, 3:59am

Hi,
Nest states are published from the device to Google and sent to home assistant via a cloud pubsub feed. So for example, any state change from idle to heating will be sent with a pubsub message parsed by the nest library and passed on to update home assistant state.

The integration instructions have details for diagnosing pubsub messages by dumping the contents to the debug log or viewing them in the pubsub console. This can help you determine if this is a.hpme assistant bug or a Google publisher bug. I’m guessing it’s a Google publishing bug based on history.

Let me know what you find.

mekaneck · February 18, 2022, 10:24pm

Thanks for the pointer. I changed the logging verbosity as the integration instructions suggest, and also went into the cloud console to poke around. I’ve got to do some research on that because I have no idea what I’m doing on that site. I can’t figure out how to read or intercept messages. I created a “snapshot” but I’m not sure what that does.

The other downside is that of course, now that I’m investigating the issue, it’s not occurring any more.

I’ll probably put this on the back burner unless it rears it’s head again. I hate not understanding what caused an issue, but this looks like a steep learning curve to dig into a problem which may not exist anymore.

allenporter · February 19, 2022, 2:07pm

Ok just start with the log messages and ignore the site for the time being. You should see various API updates and it’s fairly intuitive to read them and see what fields are changing, to get an idea if the message is delivered.

If it’s only sometimes happening, good to know it’s not systematic.

mekaneck · March 10, 2022, 1:44am

The issue is still occurring, but intermittently. However, if it’s a dropped message or something similar it could be occurring more often but I’m only aware of it when it happens to specific messages.

This time my heat appeared to stay on due to not getting an “IDLE” message. In the plot below, the heat kicks on at 8:52pm, but the thermostat set point changes at 9:00pm and so the heat should kick off. Which it does in reality, but doesn’t appear to do so in the data.

2022-03-07 20:52:10 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '8b07bed9-f9d3-4ffd-a482-b3acaa5a762d', 'timestamp': '2022-03-08T02:52:09.786017Z', 'resourceUpdate': {'name': 'enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEtFb-EoAq-QZ5_tLoIUiLeByKpRR5VvDBbz9BV_DAVpSFQ-TK-SMMoNtr0HAv3RR-2WiXmyXCs2d6t1vRBliO-v1w', 'traits': {'sdm.devices.traits.ThermostatHvac': {'status': 'HEATING'}}}, 'userId': 'AVPHwEubYL1bIuXJ0JDY5MnKdDLIp_XeLTXEbWMd5csK', 'resourceGroup': ['enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEtFb-EoAq-QZ5_tLoIUiLeByKpRR5VvDBbz9BV_DAVpSFQ-TK-SMMoNtr0HAv3RR-2WiXmyXCs2d6t1vRBliO-v1w']}
2022-03-07 20:52:10 DEBUG (MainThread) [google_nest_sdm.device] Processing update 8b07bed9-f9d3-4ffd-a482-b3acaa5a762d @ 2022-03-08 02:52:09.786017+00:00
2022-03-07 20:52:10 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatHvac': <google_nest_sdm.thermostat_traits.ThermostatHvacTrait object at 0x7fb442916190>}
...
2022-03-07 21:00:09 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '3ba52460-7b43-4758-ab97-9c7d6948de19', 'timestamp': '2022-03-08T03:00:02.563514Z', 'resourceUpdate': {'name': 'enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEvmkdCRgV00-JVw5ifFtbspPsOT2xUFyuJaKdwGKH2Es9uo7bHH7EcWChM_uPLej1txObQQ-abzb15FcQ9ywavAjw', 'traits': {'sdm.devices.traits.Temperature': {'ambientTemperatureCelsius': 13.059998}}}, 'userId': 'AVPHwEubYL1bIuXJ0JDY5MnKdDLIp_XeLTXEbWMd5csK', 'resourceGroup': ['enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEvmkdCRgV00-JVw5ifFtbspPsOT2xUFyuJaKdwGKH2Es9uo7bHH7EcWChM_uPLej1txObQQ-abzb15FcQ9ywavAjw']}
2022-03-07 21:00:09 DEBUG (MainThread) [google_nest_sdm.device] Processing update 3ba52460-7b43-4758-ab97-9c7d6948de19 @ 2022-03-08 03:00:02.563514+00:00
2022-03-07 21:00:09 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Temperature': <google_nest_sdm.device_traits.TemperatureTrait object at 0x7fb4488f1490>}
2022-03-07 21:00:18 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '1ea2b2a8-f9e7-45b5-bff6-d4fcd3d8a501', 'timestamp': '2022-03-08T03:00:03.282339Z', 'resourceUpdate': {'name': 'enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEtFb-EoAq-QZ5_tLoIUiLeByKpRR5VvDBbz9BV_DAVpSFQ-TK-SMMoNtr0HAv3RR-2WiXmyXCs2d6t1vRBliO-v1w', 'traits': {'sdm.devices.traits.ThermostatMode': {'mode': 'HEAT', 'availableModes': ['HEAT', 'COOL', 'HEATCOOL', 'OFF']}, 'sdm.devices.traits.ThermostatEco': {'availableModes': ['OFF', 'MANUAL_ECO'], 'mode': 'OFF', 'heatCelsius': 15.634888, 'coolCelsius': 26.86702}, 'sdm.devices.traits.ThermostatTemperatureSetpoint': {'heatCelsius': 16.65866}}}, 'userId': 'AVPHwEubYL1bIuXJ0JDY5MnKdDLIp_XeLTXEbWMd5csK', 'resourceGroup': ['enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEtFb-EoAq-QZ5_tLoIUiLeByKpRR5VvDBbz9BV_DAVpSFQ-TK-SMMoNtr0HAv3RR-2WiXmyXCs2d6t1vRBliO-v1w']}
2022-03-07 21:00:18 DEBUG (MainThread) [google_nest_sdm.device] Processing update 1ea2b2a8-f9e7-45b5-bff6-d4fcd3d8a501 @ 2022-03-08 03:00:03.282339+00:00
2022-03-07 21:00:18 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatMode': <google_nest_sdm.thermostat_traits.ThermostatModeTrait object at 0x7fb444d76430>, 'sdm.devices.traits.ThermostatEco': <google_nest_sdm.thermostat_traits.ThermostatEcoTrait object at 0x7fb444d76730>, 'sdm.devices.traits.ThermostatTemperatureSetpoint': <google_nest_sdm.thermostat_traits.ThermostatTemperatureSetpointTrait object at 0x7fb444d764f0>}
2022-03-07 21:00:28 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '2210f46b-8e58-42ec-9e22-8a6c86035c94', 'timestamp': '2022-03-08T03:00:24.720157Z', 'resourceUpdate': {'name': 'enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEtFb-EoAq-QZ5_tLoIUiLeByKpRR5VvDBbz9BV_DAVpSFQ-TK-SMMoNtr0HAv3RR-2WiXmyXCs2d6t1vRBliO-v1w', 'traits': {'sdm.devices.traits.Fan': {'timerMode': 'OFF'}}}, 'userId': 'AVPHwEubYL1bIuXJ0JDY5MnKdDLIp_XeLTXEbWMd5csK', 'resourceGroup': ['enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEtFb-EoAq-QZ5_tLoIUiLeByKpRR5VvDBbz9BV_DAVpSFQ-TK-SMMoNtr0HAv3RR-2WiXmyXCs2d6t1vRBliO-v1w']}
2022-03-07 21:00:28 DEBUG (MainThread) [google_nest_sdm.device] Processing update 2210f46b-8e58-42ec-9e22-8a6c86035c94 @ 2022-03-08 03:00:24.720157+00:00
2022-03-07 21:00:28 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Fan': <google_nest_sdm.device_traits.FanTrait object at  0x7fb4414758e0>}
2022-03-07 21:00:56 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [140412288041216] Connection closed by client
...
2022-03-07 21:19:08 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'ad2ca5f0-91da-40f6-ab14-a400c864df0e', 'timestamp': '2022-03-08T03:19:08.055164Z', 'resourceUpdate': {'name': 'enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEvmkdCRgV00-JVw5ifFtbspPsOT2xUFyuJaKdwGKH2Es9uo7bHH7EcWChM_uPLej1txObQQ-abzb15FcQ9ywavAjw', 'traits': {'sdm.devices.traits.Temperature': {'ambientTemperatureCelsius': 13.049988}}}, 'userId': 'AVPHwEubYL1bIuXJ0JDY5MnKdDLIp_XeLTXEbWMd5csK', 'resourceGroup': ['enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEvmkdCRgV00-JVw5ifFtbspPsOT2xUFyuJaKdwGKH2Es9uo7bHH7EcWChM_uPLej1txObQQ-abzb15FcQ9ywavAjw']}
2022-03-07 21:19:08 DEBUG (MainThread) [google_nest_sdm.device] Processing update ad2ca5f0-91da-40f6-ab14-a400c864df0e @ 2022-03-08 03:19:08.055164+00:00
2022-03-07 21:19:08 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Temperature': <google_nest_sdm.device_traits.TemperatureTrait object at 0x7fb4429ffa90>}
2022-03-07 21:21:13 INFO (Thread-7) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-terminating stream error 500 Received RST_STREAM with error code 2
2022-03-07 21:21:13 INFO (Thread-7) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed recoverable stream error 500 Received RST_STREAM with error code 2
2022-03-07 21:21:13 INFO (Thread-7) [google.api_core.bidi] Re-established stream
2022-03-07 21:21:13 INFO (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-terminating stream error 500 Received RST_STREAM with error code 2
2022-03-07 21:21:13 INFO (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed recoverable stream error 500 Received RST_STREAM with error code 2
...
2022-03-08 03:49:19 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'c411c7be-8379-4838-8c57-870dd3cb28ae', 'timestamp': '2022-03-08T09:49:18.716724Z', 'resourceUpdate': {'name': 'enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEtFb-EoAq-QZ5_tLoIUiLeByKpRR5VvDBbz9BV_DAVpSFQ-TK-SMMoNtr0HAv3RR-2WiXmyXCs2d6t1vRBliO-v1w', 'traits': {'sdm.devices.traits.Temperature': {'ambientTemperatureCelsius': 17.0}}}, 'userId': 'AVPHwEubYL1bIuXJ0JDY5MnKdDLIp_XeLTXEbWMd5csK', 'resourceGroup': ['enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEtFb-EoAq-QZ5_tLoIUiLeByKpRR5VvDBbz9BV_DAVpSFQ-TK-SMMoNtr0HAv3RR-2WiXmyXCs2d6t1vRBliO-v1w']}
2022-03-08 03:49:19 DEBUG (MainThread) [google_nest_sdm.device] Processing update c411c7be-8379-4838-8c57-870dd3cb28ae @ 2022-03-08 09:49:18.716724+00:00
2022-03-08 03:49:19 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Temperature': <google_nest_sdm.device_traits.TemperatureTrait object at 0x7fb442a9e2b0>}
2022-03-08 03:49:19 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': '2b46d9cf-818d-4e58-b281-98f130f783ce', 'timestamp': '2022-03-08T09:49:18.716724Z', 'resourceUpdate': {'name': 'enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEtFb-EoAq-QZ5_tLoIUiLeByKpRR5VvDBbz9BV_DAVpSFQ-TK-SMMoNtr0HAv3RR-2WiXmyXCs2d6t1vRBliO-v1w', 'traits': {'sdm.devices.traits.ThermostatHvac': {'status': 'OFF'}}}, 'userId': 'AVPHwEubYL1bIuXJ0JDY5MnKdDLIp_XeLTXEbWMd5csK', 'resourceGroup': ['enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEtFb-EoAq-QZ5_tLoIUiLeByKpRR5VvDBbz9BV_DAVpSFQ-TK-SMMoNtr0HAv3RR-2WiXmyXCs2d6t1vRBliO-v1w']}
2022-03-08 03:49:19 DEBUG (MainThread) [google_nest_sdm.device] Processing update 2b46d9cf-818d-4e58-b281-98f130f783ce @ 2022-03-08 09:49:18.716724+00:00
2022-03-08 03:49:19 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.ThermostatHvac': <google_nest_sdm.thermostat_traits.ThermostatHvacTrait object at 0x7fb43bf2ba00>}
2022-03-08 03:53:58 DEBUG (MainThread) [google_nest_sdm.event] EventMessage raw_data={'eventId': 'f2cab77d-efa9-4993-add6-19730ba61648', 'timestamp': '2022-03-08T09:53:57.594693Z', 'resourceUpdate': {'name': 'enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEvmkdCRgV00-JVw5ifFtbspPsOT2xUFyuJaKdwGKH2Es9uo7bHH7EcWChM_uPLej1txObQQ-abzb15FcQ9ywavAjw', 'traits': {'sdm.devices.traits.Humidity': {'ambientHumidityPercent': 34.0}}}, 'userId': 'AVPHwEubYL1bIuXJ0JDY5MnKdDLIp_XeLTXEbWMd5csK', 'resourceGroup': ['enterprises/62623ea9-0d5e-4986-843d-6434ffe81e00/devices/AVPHwEvmkdCRgV00-JVw5ifFtbspPsOT2xUFyuJaKdwGKH2Es9uo7bHH7EcWChM_uPLej1txObQQ-abzb15FcQ9ywavAjw']}
2022-03-08 03:53:58 DEBUG (MainThread) [google_nest_sdm.device] Processing update f2cab77d-efa9-4993-add6-19730ba61648 @ 2022-03-08 09:53:57.594693+00:00
2022-03-08 03:53:58 DEBUG (MainThread) [google_nest_sdm.device] Trait update {'sdm.devices.traits.Humidity': <google_nest_sdm.device_traits.HumidityTrait object at 0x7fb445e32f40>}

It appears to me that a message containing {'sdm.devices.traits.ThermostatHvac': {'status': 'OFF'}} should have been received around timestamp 2022-03-07 21:00:00 but never showed up. Since that message didn’t happen, the heat appeared to stay on until the next ‘off’ message was received, at 3:49:19.

But I am seeing some google cloud pubsub errors (timestamp 2022-03-07 21:21:13) that I can’t tell if they are related or not. The timing seems 20 minutes late, and they occur throughout the log, and often near both the google nest messages as well as my google calendar integration messages. So I’m not sure which integration they’re related to, or if they even indicate a problem.

I haven’t figured out a way to save or view messages on the Cloud Console to assist debugging.

Thanks in advance for any ideas or tips.

allenporter · March 11, 2022, 9:52pm

Those google cloud pubsub errors are normal, and just part of the long running RPC it uses to pull messages.

For viewing messages in the cloud console, on idea could be to create an additional subscriber for the same topic, which will get a copy of every message. You could then try to view the messages received in the console on the messages tab.