Open rccoleman opened 2 months ago
Hey there @lash-l, mind taking a look at this issue as it has been labeled with an integration (anova
) you are listed as a code owner for? Thanks!
(message by CodeOwnersMention)
anova documentation anova source (message by IssueLinks)
How long does it normally take until it stops working?
I reloaded the integration around 7PM last night because it had stopped working, it worked during my 30min cook time, and the log indicates that it stopped updating just after midnight. I confirmed that it's no longer reporting status this morning. If I don't have debug logging enabled, there's no indication in the log at all about whether it's working or if/when it fails.
From the response from the API, I can see that it hasn't disconnected in a few days (when I unplugged it and plugged it back in):
'lastDisconnectedTimestamp': '2024-09-09T16:00:29Z'
Edit: I just looked at my logs and I see that it stopped updating about 14 minutes ago. The last debug message was:
2024-09-12 13:07:13.511 DEBUG (MainThread) [anova_wifi.websocket_handler] Found message {'command': 'EVENT_APC_STATE', 'payload': {'cookerId': '4vMw8eC1zGQcwAWISSgMc0', 'type': 'a7', 'state': {'version': 1, 'updatedTimestamp': '2024-09-12T20:07:12Z', 'systemInfo': {'deviceId': '4vMw8eC1zGQcwAWISSgMc0', 'online': True, 'firmwareVersion': '01.01.12', 'releaseTrack': 'production', 'firmwareUpdatedTimestamp': '2024-08-16T02:03:00Z', 'lastConnectedTimestamp': '2024-09-12T18:51:25Z', 'lastDisconnectedTimestamp': '2024-09-09T16:00:29Z', 'hardwareVersion': '1.0.0', 'triacsFailed': False}, 'state': {'mode': 'idle', 'temperatureUnit': 'F', 'processedCommandIds': ['5f5aa28a-519f-4092-b33f-55c21308b193', 'ea74985c-835c-4e81-bc3d-26009633c318', '2ec36216-a452-45e1-af8e-08089a532785', '607d1dd3-9fce-4335-8638-31ad98a89dab', '9f1a4c3f-c500-4a51-bfec-7efd3aa30c0b', '04294602-27ca-491d-8727-1cbd3beef159', '01bdc39b-97fb-472a-9a1d-7410b47d3779', 'ebce116a-31f3-4b03-84ee-52ec88872557', '2ce4ab41-ab7a-407d-bf46-f2bdef91d5b2', 'aba723af-0317-489c-ab2b-f892dd4d49cc'], 'resumeAfterPowerInterruption': False}, 'nodes': {'lowWater': {'warning': False, 'empty': False}, 'waterTemperatureSensor': {'current': {'celsius': 30.76}, 'setpoint': {'celsius': 48.88}, 'enabled': True}, 'timer': {'mode': 'idle', 'initial': 1800}}, 'metadata': {}}}}
2024-09-12 13:07:13.511 DEBUG (MainThread) [homeassistant.components.anova.coordinator] Manually updated Anova Precision Cooker data
I'm also missing some of the sensors mentioned in the documentation, but maybe my unit doesn't report them. This is the output from an update while it's cooking, but not yet up to temp:
2024-09-12 10:09:29.904 DEBUG (MainThread) [anova_wifi.websocket_handler] Found message {'command': 'EVENT_APC_STATE', 'payload': {'cookerId': '4vMw8eC1zGQcwAWISSgMc0', 'type': 'a7', 'state': {'state': {'processedCommandIds': ['ce01f0a4-0746-45cb-8f93-b11afa53f709', 'dbcfefcb-92e0-459a-9862-cbd48f1f303e', 'ee6c7729-e13f-485d-9b42-b8ec409176c5', '4ebad4e4-06d3-4655-8fef-fe4bc6a1e0b0', 'cb9121c996f9d46f7a04dd', 'e2d827f4-5902-4392-a610-b5818eb06e6f', '1abdefe9-6d6b-4eeb-b77f-f92b336d25a0', 'b2a484f6-e09d-41e4-88e0-0f1ddb8d2da9', 'ade0d786-e412-4f5f-83c9-fe9fe6c92559', '632592d9-bfc7-4ab1-a69f-9e512159d9a3'], 'temperatureUnit': 'F', 'mode': 'cook', 'resumeAfterPowerInterruption': False}, 'cook': {'originSource': 'ios', 'cookableType': 'manual', 'activeStageId': 'cook-id', 'stageTransitionPendingUserAction': False, 'stages': [{'entry': {'conditions': {'and': {'nodes.waterTemperatureSensor.current.celsius': {'<=': 49.19, '>=': 48.59}}}}, 'do': {'waterTemperatureSensor': {'setpoint': {'celsius': 48.89}}, 'type': 'cook'}, 'id': 'cook-id', 'exit': {'conditions': {}}, 'title': 'App Started Cook'}], 'activeStageStartedTimestamp': '2024-09-12T17:09:05Z', 'cookId': 'c3d5c673-68bb-4a0a-9890-6fb1870c4790', 'startedTimestamp': '2024-09-12T17:09:05Z', 'activeStageMode': 'entering', 'activeStageIndex': 0}, 'nodes': {'waterTemperatureSensor': {'setpoint': {'celsius': 48.88}, 'current': {'celsius': 25.37}, 'enabled': True}, 'timer': {'startedAtTimestamp': '2024-09-12T17:09:05Z', 'initial': 1800, 'mode': 'running'}, 'lowWater': {'warning': False, 'empty': False}}, 'systemInfo': {'lastDisconnectedTimestamp': '2024-09-09T16:00:29Z', 'triacsFailed': False, 'lastConnectedTimestamp': '2024-09-12T16:51:20Z', 'releaseTrack': 'production', 'firmwareVersion': '01.01.12', 'firmwareUpdatedTimestamp': '2024-08-16T02:03:00Z', 'hardwareVersion': '1.0.0', 'online': True, 'deviceId': '4vMw8eC1zGQcwAWISSgMc0'}, 'version': 1, 'metadata': {}, 'updatedTimestamp': '2024-09-12T17:09:29Z'}}}
I'll grab another when it's up to temp and has started cooking. The "remaining time" sensor is the one I'm most interested in, as I currently have to derive that in a template sensor from the state of the device and whether it looks like it's reached the target temp.
Here's what a report when it's reached the target temp:
2024-09-12 10:17:41.785 DEBUG (MainThread) [anova_wifi.websocket_handler] Found message {'command': 'EVENT_APC_STATE', 'payload': {'cookerId': '4vMw8eC1zGQcwAWISSgMc0', 'type': 'a7', 'state': {'state': {'processedCommandIds': ['54a666b7-4ade-4351-b6c8-a6fd44aedcbd', '5078807f-480f-421f-9e02-07e45fdc5461', 'a9cb914e-95a1-4b71-84c3-8fae02dc3a62', '9738d571-14e0-47be-846f-82006fc48d19', '76ca052e-3bb4-43a7-af4c-19a44ae98a61', '63c5fb92-08a5-4566-be4b-6ffc74130451', '5c267d87-9489-428e-95fa-bc7b46f3f50e', 'b15ca2e6-6dd6-42bf-87b9-4c2a6ed6c812', '22155856-2663-4a0c-a18e-3148855062e5', '4081769e-c10a-4fb7-ab95-a65f5113861f'], 'temperatureUnit': 'F', 'mode': 'cook', 'resumeAfterPowerInterruption': False}, 'cook': {'originSource': 'ios', 'cookableType': 'manual', 'activeStageId': 'cook-id', 'stageTransitionPendingUserAction': False, 'stages': [{'entry': {'conditions': {'and': {'nodes.waterTemperatureSensor.current.celsius': {'<=': 49.19, '>=': 48.59}}}}, 'do': {'waterTemperatureSensor': {'setpoint': {'celsius': 48.89}}, 'timer': {'entry': {'conditions': {'and': {'nodes.waterTemperatureSensor.current.celsius': {'<=': 49.19, '>=': 48.59}}}}, 'initial': 1800}, 'type': 'cook'}, 'id': 'cook-id', 'exit': {'conditions': {}}, 'title': 'App Started Cook'}], 'activeStageStartedTimestamp': '2024-09-12T17:12:20Z', 'cookId': '1951f679-4d08-4f24-8e2a-b82de26919c1', 'startedTimestamp': '2024-09-12T17:12:20Z', 'activeStageMode': 'running', 'activeStageIndex': 0}, 'nodes': {'waterTemperatureSensor': {'setpoint': {'celsius': 48.88}, 'current': {'celsius': 48.77}, 'enabled': True}, 'timer': {'startedAtTimestamp': '2024-09-12T17:17:30Z', 'initial': 1800, 'mode': 'running'}, 'lowWater': {'warning': False, 'empty': False}}, 'systemInfo': {'lastDisconnectedTimestamp': '2024-09-09T16:00:29Z', 'triacsFailed': False, 'lastConnectedTimestamp': '2024-09-12T16:51:20Z', 'releaseTrack': 'production', 'firmwareVersion': '01.01.12', 'firmwareUpdatedTimestamp': '2024-08-16T02:03:00Z', 'hardwareVersion': '1.0.0', 'online': True, 'deviceId': '4vMw8eC1zGQcwAWISSgMc0'}, 'version': 1, 'metadata': {}, 'updatedTimestamp': '2024-09-12T17:17:40Z'}}}
2024-09-12 10:17:41.786 DEBUG (MainThread) [homeassistant.components.anova.coordinator] Manually updated Anova Precision Cooker data
Definitely looks like some useful data in there: activeStageMode
transitions from entering
to running
when it starts to cook, for instance. At least being able to grab the startedAtTimestamp
would be helpful.
I added some debug info in the message handling loop in anova-wifi
to see if it's dropping out, hanging reading from the websocket, or raising an exception, but it's still running fine this morning. I'll keep an eye on it and report back if I find something.
Edit: So it just dropped out of the message processing loop for no obvious reason:
2024-09-13 11:55:19.982 DEBUG (MainThread) [anova_wifi.websocket_handler] Waiting for message
2024-09-13 11:55:19.983 DEBUG (MainThread) [anova_wifi.websocket_handler] Found message {'command': 'EVENT_APC_STATE', 'payload': {'cookerId': '4vMw8eC1zGQcwAWISSgMc0', 'type': 'a7', 'state': {'version': 1, 'updatedTimestamp': '2024-09-13T18:55:19Z', 'systemInfo': {'deviceId': '4vMw8eC1zGQcwAWISSgMc0', 'online': True, 'firmwareVersion': '01.01.12', 'releaseTrack': 'production', 'firmwareUpdatedTimestamp': '2024-08-16T02:03:00Z', 'lastConnectedTimestamp': '2024-09-13T18:52:14Z', 'lastDisconnectedTimestamp': '2024-09-09T16:00:29Z', 'hardwareVersion': '1.0.0', 'triacsFailed': False}, 'state': {'mode': 'idle', 'temperatureUnit': 'F', 'processedCommandIds': ['9ff8cba6-baa9-46a0-aa30-5edca5ef2702', '39a824f3-8efa-403f-b121-1dbbb07bb8b6', '636b3b56-6a17-4649-b2de-b7fdbb6e3831', '0e8b9a95-be4c-49ee-a48e-8f5a66a73ade', '31128ebb-168a-4d0a-80e7-1ac817ca163a', 'a9afbe10-52b9-4060-9a9f-1904effb79d1', '65438cef-0eb1-4a50-a94e-910070d7d605', '2b412af9-b5bc-487d-83f6-8c7177d5ae76', 'fc3d0e7b-d0eb-4312-92c5-5baea7e5b03a', '17a8e39f-333b-4918-b231-6bc290827282'], 'resumeAfterPowerInterruption': False}, 'nodes': {'lowWater': {'warning': False, 'empty': False}, 'waterTemperatureSensor': {'current': {'celsius': 23.04}, 'setpoint': {'celsius': 0}, 'enabled': True}, 'timer': {'mode': 'idle', 'initial': 0}}, 'metadata': {}}}}
2024-09-13 11:55:19.983 DEBUG (MainThread) [homeassistant.components.anova.coordinator] Manually updated Anova Precision Cooker data
2024-09-13 11:55:19.983 DEBUG (MainThread) [anova_wifi.websocket_handler] After processing message
2024-09-13 11:55:23.424 DEBUG (MainThread) [anova_wifi.websocket_handler] Exiting listener
Here's the debug I added:
async def message_listener(self) -> None:
try:
_LOGGER.debug("Starting listener")
if self.ws is not None:
_LOGGER.debug("Websocket opened")
async for msg in self.ws:
_LOGGER.debug("Waiting for message")
self.on_message(json.loads(msg.data))
_LOGGER.debug("After processing message")
except Exception as e:
_LOGGER.debug(e, exc_info=True)
_LOGGER.debug("Exiting listener")
No exception, it just dropped out of the for
loop. I guess the websocket is closing, so I could just try to reconnect when it happens.
I've been monitoring this over the weekend and I haven't seen it fail yet. I added the following at the end of message_listener
, but I haven't seen it actually happen in the logs and it hasn't stopped updating.
_LOGGER.debug("Exiting listener, restarting")
await self.connect()
I'm still trying to track this down without much success. In the end, the I get an ABNORMAL_CLOSURE from the aiohttp
websocket and it's never able to recover even if I disconnect and reconnect the websocket:
2024-09-22 08:32:13.389 DEBUG (MainThread) [homeassistant.components.anova.coordinator] Manually updated Anova Precision Cooker data
2024-09-22 08:32:13.390 DEBUG (MainThread) [anova_wifi.websocket_handler] After processing message
2024-09-22 08:32:20.055 DEBUG (MainThread) [anova_wifi.websocket_handler] Received message msg.type=<WSMsgType.TEXT: 1>
2024-09-22 08:32:20.055 DEBUG (MainThread) [anova_wifi.websocket_handler] Found message {'command': 'EVENT_APC_STATE', 'payload': {'cookerId': '4vMw8eC1zGQcwAWISSgMc0', 'type': 'a7', 'state': {'version': 1, 'updatedTimestamp': '2024-09-22T15:32:19Z', 'systemInfo': {'deviceId': '4vMw8eC1zGQcwAWISSgMc0', 'online': True, 'firmwareVersion': '01.01.12', 'releaseTrack': 'production', 'firmwareUpdatedTimestamp': '2024-08-16T02:03:00Z', 'lastConnectedTimestamp': '2024-09-22T15:20:45Z', 'lastDisconnectedTimestamp': '2024-09-17T14:12:35Z', 'hardwareVersion': '1.0.0', 'triacsFailed': False}, 'state': {'mode': 'idle', 'temperatureUnit': 'F', 'processedCommandIds': ['154f6fe9-aaae-4073-9200-73ef45792067', '9908ac04-1c94-4d1b-9548-ff997f2cfb60', '4bad3fdc-9559-485c-9cf7-f177302fd121', 'bcda3850-c94c-45a1-bfc6-d7fcd4a2994e', '8b8dc2f5-b088-4399-9ea0-88892664646c', '76709969-1056-48d4-896e-214614a0770b', '688f9b8c-b27c-42f2-97f6-77754b9bbd57', 'a6a9846e-c8ff-4a51-be85-a005630f4b39', 'c34dc9b5-d901-4910-be43-b534ef3c2e1d', '7caf9d37-412c-4f76-a922-5d1ffbfd51d1'], 'resumeAfterPowerInterruption': False}, 'nodes': {'lowWater': {'warning': False, 'empty': False}, 'waterTemperatureSensor': {'current': {'celsius': 22.68}, 'setpoint': {'celsius': 48.88}, 'enabled': True}, 'timer': {'mode': 'idle', 'initial': 0}}, 'metadata': {}}}}
2024-09-22 08:32:20.056 DEBUG (MainThread) [homeassistant.components.anova.coordinator] Manually updated Anova Precision Cooker data
2024-09-22 08:32:20.056 DEBUG (MainThread) [anova_wifi.websocket_handler] After processing message
2024-09-22 08:42:20.051 ERROR (MainThread) [anova_wifi.websocket_handler] Anova Exiting listener self.ws.close_code=<WSCloseCode.ABNORMAL_CLOSURE: 1006>, reconnecting!
After that, I just keep successfully opening the websocket and then immediately see the ABNORMAL_CLOSURE
return code.
This is what I get from the aiohttp
docs:
ABNORMAL_CLOSURE¶ Used to indicate that a connection was closed abnormally (that is, with no close frame being sent) when a status code is expected.
I'm now wondering if there's something broken in the aiohttp
session that's passed in when creating the AnovaAPI class instance :shrug:. I can often "fix" this by manually reloading the integration, but that didn't help this last time. It always comes back up find when I restart HA.
Interestingly, it's almost like the socket goes into non-blocking mode somehow. If I keep reconnecting the websocket whenever it closes, I do still get messages on the websocket periodically before it closes (again).
2024-09-22 08:47:47.211 ERROR (MainThread) [anova_wifi.websocket_handler] Anova Exiting listener self.ws.close_code=<WSCloseCode.ABNORMAL_CLOSURE: 1006>, reconnecting!
2024-09-22 08:47:47.211 ERROR (MainThread) [anova_wifi.websocket_handler] Reconnecting...
2024-09-22 08:47:47.317 DEBUG (MainThread) [anova_wifi.websocket_handler] Starting listener
2024-09-22 08:47:47.317 DEBUG (MainThread) [anova_wifi.websocket_handler] Websocket opened
2024-09-22 08:47:47.370 DEBUG (MainThread) [anova_wifi.websocket_handler] Received message msg.type=<WSMsgType.TEXT: 1>
2024-09-22 08:47:47.370 DEBUG (MainThread) [anova_wifi.websocket_handler] Found message {'command': 'EVENT_APC_WIFI_LIST', 'payload': [{'cookerId': '4vMw8eC1zGQcwAWISSgMc0', 'type': 'a7', 'pairedAt': '2024-09-22T15:47:47.350Z', 'name': 'Anova Precision Cooker 3.0'}]}
2024-09-22 08:47:47.370 DEBUG (MainThread) [anova_wifi.websocket_handler] After processing message
2024-09-22 08:47:47.371 DEBUG (MainThread) [anova_wifi.websocket_handler] Received message msg.type=<WSMsgType.TEXT: 1>
2024-09-22 08:47:47.372 DEBUG (MainThread) [anova_wifi.websocket_handler] Found message {'command': 'EVENT_USER_STATE', 'payload': {'isConnectedToAlexa': False, 'isConnectedToGoogleHome': False, 'sousVideSubscription': {'hasValidSubscription': True, 'isLegacyAccount': True}, 'ovenSubscription': {'hasValidSubscription': True, 'isLegacyAccount': True}}}
2024-09-22 08:47:47.372 DEBUG (MainThread) [anova_wifi.websocket_handler] After processing message
2024-09-22 08:47:47.376 DEBUG (MainThread) [anova_wifi.websocket_handler] Received message msg.type=<WSMsgType.TEXT: 1>
2024-09-22 08:47:47.376 DEBUG (MainThread) [anova_wifi.websocket_handler] Found message {'command': 'EVENT_APC_STATE', 'payload': {'cookerId': '4vMw8eC1zGQcwAWISSgMc0', 'type': 'a7', 'state': {'version': 1, 'updatedTimestamp': '2024-09-22T15:32:19Z', 'systemInfo': {'deviceId': '4vMw8eC1zGQcwAWISSgMc0', 'online': True, 'firmwareVersion': '01.01.12', 'releaseTrack': 'production', 'firmwareUpdatedTimestamp': '2024-08-16T02:03:00Z', 'lastConnectedTimestamp': '2024-09-22T15:20:45Z', 'lastDisconnectedTimestamp': '2024-09-17T14:12:35Z', 'hardwareVersion': '1.0.0', 'triacsFailed': False}, 'state': {'mode': 'idle', 'temperatureUnit': 'F', 'processedCommandIds': ['154f6fe9-aaae-4073-9200-73ef45792067', '9908ac04-1c94-4d1b-9548-ff997f2cfb60', '4bad3fdc-9559-485c-9cf7-f177302fd121', 'bcda3850-c94c-45a1-bfc6-d7fcd4a2994e', '8b8dc2f5-b088-4399-9ea0-88892664646c', '76709969-1056-48d4-896e-214614a0770b', '688f9b8c-b27c-42f2-97f6-77754b9bbd57', 'a6a9846e-c8ff-4a51-be85-a005630f4b39', 'c34dc9b5-d901-4910-be43-b534ef3c2e1d', '7caf9d37-412c-4f76-a922-5d1ffbfd51d1'], 'resumeAfterPowerInterruption': False}, 'nodes': {'lowWater': {'warning': False, 'empty': False}, 'waterTemperatureSensor': {'current': {'celsius': 22.68}, 'setpoint': {'celsius': 48.88}, 'enabled': True}, 'timer': {'mode': 'idle', 'initial': 0}}, 'metadata': {}}}}
2024-09-22 08:47:47.376 DEBUG (MainThread) [anova_wifi.websocket_handler] After processing message
2024-09-22 08:47:47.389 ERROR (MainThread) [anova_wifi.websocket_handler] ...Reconnected
2024-09-22 08:47:47.389 DEBUG (MainThread) [anova_wifi.websocket_handler] Starting listener
2024-09-22 08:47:47.389 DEBUG (MainThread) [anova_wifi.websocket_handler] Websocket opened
2024-09-22 08:47:47.436 ERROR (MainThread) [anova_wifi.websocket_handler] Anova Exiting listener self.ws.close_code=<WSCloseCode.ABNORMAL_CLOSURE: 1006>, reconnecting!
The problem
I have my new Anova Precision Cooker 3.0 connected to my local wifi network and to the Home Assistant integration. It works well for a while, but then just stops updating for no apparent reason. Reloading the integration or restarting HA recovers the connection. The Anova iOS app continues to work to send commands and to reflect changes that I make on the Anova device manually.
I've seen this many times over the past week or so and have been monitoring the logs for issues, but I don't see any errors or reason for it. It's like the update coordinator just stops being called, and reloading the integration from the Integrations page gets it working again.
What version of Home Assistant Core has the issue?
core-2024.9.1
What was the last working version of Home Assistant Core?
No response
What type of installation are you running?
Home Assistant Container
Integration causing the issue
Anova
Link to integration documentation on our website
https://www.home-assistant.io/integrations/anova/
Diagnostics information
home-assistant_anova_2024-09-12T16-05-38.340Z.log
Example YAML snippet
No response
Anything in the logs that might be useful for us?
I turned on debug logging and I can see the integration regularly updating the Anova data, but then it just inexplicably stops. The last message is just a normal update:
Additional information
No response