Core: Intesishome mode de-sync

[tehbrd]

The problem

At the moment, I get issues with operation mode becoming desynchronized on my deployment. For instance, I have HASS believing the AC is running, when it is not, and vice-versa.

Environment

arch | aarch64
-- | --
chassis | embedded
dev | false
docker | true
hassio | true
host_os | HassOS 3.13
-- | --
installation_type | Home Assistant
os_name | Linux
os_version | 4.19.114-v8
python_version | 3.7.7
supervisor | 222
version | 0.110.1

• Home Assistant release with the issue: 110.1
• Last working Home Assistant release (if known): circa 104/5?
• Operating environment (Hass.io/Docker/Windows/etc.): Hass.io on rpi
• Integration causing this issue: intesishome
• Link to integration documentation on our website: https://www.home-assistant.io/integrations/intesishome/

Problem-relevant configuration.yaml

climate:

• platform: intesishome
  username: intesisuser
  password: !secret intesis_password

Traceback/Error logs

2020-05-23 21:09:15 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
File "/usr/local/lib/python3.7/site-packages/pyintesishome/pyintesishome.py", line 320, in _handle_packets
data = await self._reader.readuntil(b"}}")
File "/usr/local/lib/python3.7/asyncio/streams.py", line 588, in readuntil
await self._wait_for_data('readuntil')
File "/usr/local/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
await self._waiter
File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 814, in _read_ready__data_received
data = self._sock.recv(self.max_size)
TimeoutError: [Errno 110] Operation timed out

2020-05-24 01:30:00 ERROR (MainThread) [pyintesishome] Exception: TimeoutError(110, 'Operation timed out')

Additional information

Set the component to debug, the above error is the only one I can see generated.

It appears that once you get an error of this type the only way to recover is to reboot. With carrier maintenance and congestion an issue with Covid-19 this is becoming a more frequent occurrence on my install. Been using intesishome using a custom component and the new ootb component since 2017.

[probot-home-assistant[bot]]

Hey there @jnimmo, mind taking a look at this issue as its been labeled with a integration (intesishome) you are listed as a codeowner for? Thanks!

[tehbrd]

Any updates @jnimmo?

[jnimmo]

Please update the ticket with what version you’re using now and what error messages are being logged, code has changed a bit since then and if the internet connection is stable it shouldn’t be getting out of sync

[tehbrd]

updated to 110.1 still encountering the same issues.

[jnimmo]

Please enable debug logging of the intesishome platform and send through some logging from the period it is happening in.

[tehbrd]

It's already set to

logger:
default: warning
logs:
homeassistant.components.climate: debug

[jnimmo]

Thanks that’s great I just need to see some more context around the error, there should be messages saying intesishome has lost connection to the server, then it should automatically retry the connection a minute later, so I’m keen to see logs of that process happening

[tehbrd]

brd@host:~$ grep intesis home-assistant.log
2020-05-23 17:10:52 INFO (MainThread) [homeassistant.components.climate] Setting up climate.intesishome
2020-05-23 17:11:04 WARNING (MainThread) [homeassistant.components.climate] Setup of climate platform intesishome is taking over 10 seconds.
  File "/usr/local/lib/python3.7/site-packages/pyintesishome/pyintesishome.py", line 320, in _handle_packets
2020-05-24 01:30:00 ERROR (MainThread) [pyintesishome] Exception: TimeoutError(110, 'Operation timed out')
brd@host:~$

[tehbrd]

Just looking at that, I tested an automation I have setup at 530. So the first error at 17:11 is not related. The error at 1:30am is the one that would've cause the sync error. By morning I had another automation continuing to fire because it couldn't update the state.

Info from the logbook
``
5:30:24 PM
quick on has been triggered
5:30:24 PM
AC changed to heat

[jnimmo]

Please adjust your logging to include homeassistant.components.intesishome: debug,
there will be lines in the logs like 'Connection to IntesisHome API was lost. Reconnecting in 2 minutes'

[tehbrd]

2020-05-24 20:09:59 INFO (SyncWorker_4) [homeassistant.loader] Loaded intesishome from homeassistant.components.intesishome
2020-05-24 20:10:05 INFO (MainThread) [homeassistant.components.climate] Setting up climate.intesishome
2020-05-24 20:10:18 WARNING (MainThread) [homeassistant.components.climate] Setup of climate platform intesishome is taking over 10 seconds.
2020-05-24 20:10:19 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Added climate device with state: {properties}
2020-05-24 20:10:20 INFO (MainThread) [pyintesishome] IntesisHome succesfully authenticated
2020-05-24 20:10:20 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Connection to IntesisHome API was restored
2020-05-24 20:10:20 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device None
2020-05-24 20:10:48 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Setting IntesisHome to off mode
2020-05-24 20:10:48 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Setting IntesisHome to off mode
2020-05-24 20:10:48 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Setting IntesisHome to off mode
2020-05-24 20:10:53 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:10:53 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:11:07 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:11:47 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:14:02 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:16:17 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:19:17 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:22:17 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:27:32 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:39:32 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:48:32 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 20:55:17 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 21:01:17 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 21:08:47 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 21:16:17 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 21:23:02 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 21:32:02 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 21:39:32 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 21:47:47 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 21:59:02 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-24 22:07:17 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device [devid]
2020-05-25 01:30:00 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Setting IntesisHome to off mode
2020-05-25 01:46:16 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
File "/usr/local/lib/python3.7/site-packages/pyintesishome/pyintesishome.py", line 320, in _handle_packets
data = await self._reader.readuntil(b"}}")
File "/usr/local/lib/python3.7/asyncio/streams.py", line 588, in readuntil
await self._wait_for_data('readuntil')
File "/usr/local/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
await self._waiter
File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 814, in _read_ready__data_received
data = self._sock.recv(self.max_size)
TimeoutError: [Errno 110] Operation timed out
2020-05-25 05:30:00 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Setting IntesisHome to heat mode
2020-05-25 05:30:00 ERROR (MainThread) [pyintesishome] Exception: TimeoutError(110, 'Operation timed out')
2020-05-25 05:30:00 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Setting IntesisHome to 25.0 degrees
2020-05-25 08:05:54 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Setting IntesisHome to off mode
2020-05-25 08:28:07 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Setting IntesisHome to heat mode
2020-05-25 08:29:29 DEBUG (MainThread) [homeassistant.components.intesishome.climate] Setting IntesisHome to off mode

Appears to have failed sometime between 815 when it validly shutdown the AC and 130 when the backstop AC shutdown attempted to turn off an AC that wasn't even on. I tried toggling it manually this morning, can see its recording the mode changes in the log but it is not being reflected on the hardware. I am still able to control the hardware with the intesishome app.

[jnimmo]

@tehbrd I've spent 4 hours looking into the cause of this tonight, think I know the reason for it but I'm also trying to tidy up some of the other reconnection code which has taken much longer than hoped.

[tehbrd]

@vannetta please raise a separate ticket. This appears unrelated.

[kaaspad]

Hey any news on this? I'm having the same problem it seems that at some point if connection is lost on any of the devices the whole module stops working. Not just de-sync, but completely not reporting, here is the end of my debug log:

2020-06-23 15:47:29 DEBUG (MainThread) [pyintesishome] IntesisHome API Received: {"command":"status","data":{"rssi":225,"deviceId":224571441671561,"uid":10,"value":32768}} 2020-06-23 15:47:29 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device 224571441671561 2020-06-23 15:47:29 DEBUG (MainThread) [pyintesishome] IntesisHome API Received: {"command":"status","data":{"rssi":225,"deviceId":224571441671561,"uid":12,"value":0}} 2020-06-23 15:47:29 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device 224571441671561 2020-06-23 15:47:29 DEBUG (MainThread) [pyintesishome] IntesisHome API Received: {"command":"status","data":{"rssi":225,"deviceId":224571441671561,"uid":13,"value":9}} 2020-06-23 15:47:29 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device 224571441671561 2020-06-23 15:47:29 DEBUG (MainThread) [pyintesishome] IntesisHome API Received: {"command":"status","data":{"rssi":225,"deviceId":224571441671561,"uid":14,"value":0}} 2020-06-23 15:47:29 DEBUG (MainThread) [homeassistant.components.intesishome.climate] IntesisHome API sent a status update for device 224571441671561 2020-06-23 15:47:32 DEBUG (MainThread) [pyintesishome] IntesisHome API Received: {"command":"status{"command":"rssi","data":{"deviceId":224571441682124,"value":192}} File "/usr/local/lib/python3.7/site-packages/pyintesishome/pyintesishome.py", line 326, in _handle_packets

[stale[bot]]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[vampirete]

Hi.

I have the same problem.

Sometimes the integration says the air conditioner is off but it is actually on, and if I try to change any option the HA does nothing and the air conditioner does not change anything either.

I have 0.117

2020-10-29 17:22:09 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/pyintesishome/pyintesishome.py", line 363, in _handle_packets
await self.parse_api_messages(message)
File "/usr/local/lib/python3.8/site-packages/pyintesishome/pyintesishome.py", line 343, in parse_api_messages
self._update_rssi(resp["data"]["deviceId"], resp["data"]["value"])
File "/usr/local/lib/python3.8/site-packages/pyintesishome/pyintesishome.py", line 630, in _update_rssi
self._devices[str(deviceId)]["rssi"] = rssi
KeyError: '224571441679767'

2020-10-30 15:41:05 ERROR (MainThread) [pyintesishome] Exception: ConnectionResetError('Connection lost')