Harmony Hub Integration loses connection each night and stays disconnected until restart

GerdBlomb commented 3 years ago

The problem

Die Harmony Hub Integration disconnects each night around 01:00 (+/-) and does not connect again until i do a "Reload" in the Integrations Menu (three dot menu of the Harmony Integration) or a complet restart of the HA Server.

After that everything is fine until next morning.

After the disconnect i get no more triggers or events from the hub in HA. Nothing. Which is clear, because the Hub is disconnected.

Hub Firmware: 4.15.280

What is version of Home Assistant Core has the issue?

core-2021.3.3

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

Logitech Harmony Hub

Link to integration documentation on our website

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

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2021-04-11 01:03:38 ERROR (MainThread) [aioharmony.hubconnector_xmpp] 192.168.200.171: Timeout waiting for connecting to hub
2021-04-11 01:03:39 ERROR (MainThread) [slixmpp.basexmpp] 
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/aioharmony/hubconnector_xmpp.py", line 193, in hub_connect
    await connected
  File "/usr/local/lib/python3.8/site-packages/slixmpp/xmlstream/xmlstream.py", line 346, in _connect_routine
    await self.loop.create_connection(lambda: self,
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 1025, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 1010, in create_connection
    sock = await self._connect_sock(
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 924, in _connect_sock
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 496, in sock_connect
    return await fut
  File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 528, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
TimeoutError: [Errno 110] Connect call failed ('192.168.200.171', 5222)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/slixmpp/xmlstream/xmlstream.py", line 886, in handler_callback_routine
    await cb(data)
  File "/usr/local/lib/python3.8/site-packages/aioharmony/hubconnector_xmpp.py", line 296, in _disconnected_handler
    if await self.hub_connect(is_reconnect=is_reconnect):
  File "/usr/local/lib/python3.8/site-packages/aioharmony/hubconnector_xmpp.py", line 200, in hub_connect
    raise aioexc.TimeOut
aioharmony.exceptions.TimeOut
2021-04-11 01:13:57 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!

probot-home-assistant[bot] commented 3 years ago

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

bdraco commented 3 years ago

Does disabling xmpp fix it?

GerdBlomb commented 3 years ago

Thanks for your reply!

I don't know how to disable xmpp but i would like give it a try. How can this be archived?

I think another solution could be to force a restart (or that what is done on a reload of the Integration) when the Integration recognizes that there is no connection for let's say 2, 3 or 5 minutes.

If i can help with testing (beta, whatever) please let me know. But at first i would like to give xmpp disable a try.

But i think, that for whatever reason the connection goes down and the integration can not or does not try to make some kind of "hard" reconnect, this may not fix it. Something like reloading it manually does and i think that will be the way to go...

The described problem persists here for i think > 14 days and it appears every night / in the very early morning. Strange.

bdraco commented 3 years ago

XMPP has to be explicitly enabled on the Harmony HUB. To do so open the Harmony app and go to: Menu > Harmony Setup > Add/Edit Devices & Activities > Remote & Hub > Enable XMPP Same steps can be followed to disable XMPP again.

https://pypi.org/project/aioharmony/#:~:text=XMPP%20has%20to%20be%20explicitly,followed%20to%20disable%20XMPP%20again.

bdraco commented 3 years ago

By default the integration uses websocket if XMPP is disabled. Logitech promised to keep XMPP around and might make changes to the websocket implementation in the future. Now that Logitech is discontinuing the whole Harmony line, it seems like its low risk to use the websocket implementation which is more reliable anyways.

GerdBlomb commented 3 years ago

I'am not able to disable XMPP. The Harmony App on Windows does not offer that option...? Any other way to archive that?

bdraco commented 3 years ago

It can be done in the iOS or Android apps

GerdBlomb commented 3 years ago

Hi bdraco,

thanks one more time for your help here!

After i updated the iOS App (there was an update a few days ago on Apple Appstore), i can access the developer menue item in the app and i could disable xmpp.

I powercycled the hub and after it was up i restarted Home Assistant.

Now there is no connection possible at all. Strange.

I tried it a few times. No success. This is what the log states (and nothing more on that one):

2021-04-15 10:41:37 ERROR (MainThread) [aioharmony.hubconnector_websocket] 192.168.x.x: Exception on post: Connection timeout to host http://192.168.x.x:8088/ 2021-04-15 10:41:37 ERROR (MainThread) [aioharmony.hubconnector_websocket] 192.168.x.x: Unable to retrieve HUB id 2021-04-15 10:41:37 WARNING (MainThread) [homeassistant.components.harmony.data] harmony-hub: Unable to connect to HUB 2021-04-15 10:41:37 WARNING (MainThread) [homeassistant.config_entries] Config entry 'harmony-hub' for harmony integration not ready yet; Retrying in background

I made the ".x.x" in the IP before posting ;)

The hub is reachable in the network e. g. ping.

Strange.

Any other hints?

GerdBlomb commented 3 years ago

Even more strange. I can make use of the hub from HA. The errors in the log file persist, but everything works as expected. I can not see additional messages later on in the log.

I will keep an eye on it and give an update if the disconnects are gone (or not). I do not worry about log file entries ;) if everything is up and stays up.

GerdBlomb commented 3 years ago

The problem persists also when on websocket. The connection breaks once a day and stays disconnected until i do restart of HA. My Apps (iOS) and the remote are working without any problems.

2021-04-16 23:50:56 ERROR (MainThread) [aioharmony.hubconnector_websocket] 192.168.x.x: Connection timed out for hub 8436260

A reload of the integration does not help: 2021-04-17 10:16:15 ERROR (MainThread) [aioharmony.harmonyclient] 192.168.x.x: Unable to determine if XMPP is enabled: [Errno 110] Connect call failed ('192.168.x.x', 5222) 2021-04-17 10:16:15 WARNING (MainThread) [homeassistant.components.harmony.data] harmony-hub: Unable to connect to HUB 2021-04-17 10:16:15 WARNING (MainThread) [homeassistant.config_entries] Config entry 'harmony-hub' for harmony integration not ready yet; Retrying in background 2021-04-17 10:17:14 ERROR (MainThread) [aioharmony.harmonyclient] 192.168.x.x: Unable to determine if XMPP is enabled: [Errno 110] Connect call failed ('192.168.x.x', 5222) 2021-04-17 10:17:14 WARNING (MainThread) [homeassistant.components.harmony.data] harmony-hub: Unable to connect to HUB 2021-04-17 10:17:14 WARNING (MainThread) [homeassistant.config_entries] Config entry 'harmony-hub' for harmony integration not ready yet; Retrying in background 2021-04-17 10:18:30 ERROR (MainThread) [aioharmony.harmonyclient] 192.168.x.x: Unable to determine if XMPP is enabled: [Errno 110] Connect call failed ('192.168.x.x', 5222) 2021-04-17 10:18:30 WARNING (MainThread) [homeassistant.components.harmony.data] harmony-hub: Unable to connect to HUB 2021-04-17 10:19:29 ERROR (MainThread) [aioharmony.harmonyclient] 192.168.x.x: Unable to determine if XMPP is enabled: [Errno 110] Connect call failed ('192.168.x.x', 5222) 2021-04-17 10:19:29 WARNING (MainThread) [homeassistant.components.harmony.data] harmony-hub: Unable to connect to HUB 2021-04-17 10:20:49 ERROR (MainThread) [aioharmony.harmonyclient] 192.168.x.x: Unable to determine if XMPP is enabled: [Errno 110] Connect call failed ('192.168.x.x', 5222) 2021-04-17 10:20:49 WARNING (MainThread) [homeassistant.components.harmony.data] harmony-hub: Unable to connect to HUB

After a restart of HA everything is up and runnning. Other "solution" is remove the integration and install it again. This makes also the connection up and running.

Is it possible to force a working reload by a cron job? Withhout a complete restart of HA? As a work around. I could write a script which detects the logfile entry and reinit the Harmony integration. But i do not know how i can do such a "reinint"..

Thanks again for your support!

bdraco commented 3 years ago

https://www.home-assistant.io/integrations/homeassistant/#service-homeassistantreload_config_entry

That might help

GerdBlomb commented 3 years ago

Thank you! I will see how i can create a work around. Have a nice weekend!

GerdBlomb commented 3 years ago

Hi bdraco,

after investigating and monitoring this issue i can not work around it.

HA needs a restart, when i reload the integration. This means: complete restart of HA. To bad.

The problem still persists and i have no clue. In a timeframe of est. 15 to 22 hours the connection from HA to the hub gets lost. An entry with the exact date time shows up than in the logfiles.

I can only recover from this state by rebooting HA.

On the other hand my tablet and my mobile are still connected to the hub and work in normal operation (or reconnect somehow to heal that by themselve).

Any chance that a auto-reconnect takes place when the integration losts connection without HA reboot? Any other possible work around?

Best regards!

bdraco commented 3 years ago

Your log is showing the integration attempting to reconnect every minute and getting a connection timeout (errno 110) so its definitely trying to reconnect. Does it stop trying?

2021-04-17 10:18:30 ERROR (MainThread) [aioharmony.harmonyclient] 192.168.x.x: Unable to determine if XMPP is enabled: [Errno 110] Connect call failed ('192.168.x.x', 5222)
2021-04-17 10:18:30 WARNING (MainThread) [homeassistant.components.harmony.data] harmony-hub: Unable to connect to HUB
2021-04-17 10:19:29 ERROR (MainThread) [aioharmony.harmonyclient] 192.168.x.x: Unable to determine if XMPP is enabled: [Errno 110] Connect call failed ('192.168.x.x', 5222)
2021-04-17 10:19:29 WARNING (MainThread) [homeassistant.components.harmony.data] harmony-hub: Unable to connect to HUB

GerdBlomb commented 3 years ago

Hi bdraco,

thanks for your response. Yes it does. I got not more than this two entries in the log. Otherwise i would had added them here. Sorry, should have mentioned that.

But i think that the reconnect tries are somewhat other ways to connect than the once done on a complete HA restart. As soon as i do a restart the integration is up and connected again. Without doing any other changes to my environment.

Maybe on an init the integration does some kind of extra "magic" which allows to go on.

Guessing here, i know. But thats what i observe and what is reproduceable so far.

bdraco commented 3 years ago

https://github.com/ehendrix23/aioharmony/blob/master/aioharmony/harmonyclient.py#L147

It looks like your hub is timing out while trying to check XMPP.

Can you try connecting to port 5222 (XMPP) and 8088 (WEBSOCKETS) on the hub with telnet (replace the ip below with your hub's actual ip)

# telnet 192.168.107.78 5222
Trying 192.168.107.78...
telnet: Unable to connect to remote host: Connection refused
# telnet 192.168.107.78 8088
Trying 192.168.107.78...
Connected to 192.168.107.78.
Escape character is '^]'.

GerdBlomb commented 3 years ago

I get the same output:

pi@redone:~ $ telnet 192.168.x.x 5222
Trying 192.168.x.x...
telnet: Unable to connect to remote host: Connection refused

pi@redone:~ $ telnet 192.168.x.x 8088
Trying 192.168.x.x...
Connected to 192.168.200.171.
Escape character is '^]'.

But in the moment everything is up and running with HA. But i will doublecheck this again as soon as i have a disconnection again

bdraco commented 3 years ago

Please try to check it the exact moment its happening. Since the code is already accounting for Connection refused, but the code is seeing error 110 which is a timeout which means the device didn't respond in time to refuse the connection.

GerdBlomb commented 3 years ago

Just had the error, after a restart whilst playing around with new cards and buttons for my frontend

2021-04-27 22:36:07 ERROR (MainThread) [aioharmony.hubconnector_websocket] 192.168.x.x: Exception on post: Connection timeout to host http://192.168.x.x:8088/
2021-04-27 22:36:07 ERROR (MainThread) [aioharmony.hubconnector_websocket] 192.168.x.x: Unable to retrieve HUB id
2021-04-27 22:36:07 WARNING (MainThread) [homeassistant.components.harmony.data] harmony-hub: Unable to connect to HUB
2021-04-27 22:36:07 WARNING (MainThread) [homeassistant.config_entries] Config entry 'harmony-hub' for harmony integration not ready yet; Retrying in background

Tried directly telnet:

pi@redone:~ $ telnet 192.168.x.x 5222
Trying 192.168.x.x...
telnet: Unable to connect to remote host: Connection refused
pi@redone:~ $ telnet 192.168.x.x 8088
Trying 192.168.x.x...
Connected to 192.168.x.x.
Escape character is '^]'.

Mobile devices work.

GerdBlomb commented 3 years ago

Update:

I’ve changed a few things on the network:

Forced harmony hub to connect to a specific Wifi hotspot
New firmware on all Routers (change from TP-Link to OpenWrt on Archer C7 V5)
Limit 2,4 Ghz Wifi to 20 Mhz (found that hint somewhere on the Web)
Moved the Raspi from WLAN to network cableing
Watching and tracing if it does changes anything

It does not.

At some point in time (12 - 18 hours) HA loses the connection to the hub, while my mobile devices (iOS Tablet, Phone) still able to connect and control the hub.

If i recognize the disconnection just in time and try immediately a restart of HA the reconnect does still not work. After let’s say 15 - 30 min. the HA restart fixes the problem for next hours.

GerdBlomb commented 3 years ago

Update:

I moved to 2021.5.2 (HA) and setting Harmony back to XMPP (that was done a few hours after my last post) i have no more disconnects. The log stays clean.

I can not say for sure which of the countless doings did the trick. The system is now stable for more than a week. I've been waiting a few days to be more sure about that.

Thanks again for your support bdraco!

bdraco commented 3 years ago

Glad you got it sorted 👍

GerdBlomb commented 3 years ago

Sorry to reopen this.

Problem reappears two days ago. Just after a thought it's gone. sight

But i found a workaround that should do the trick now. Without a HA reload. For the records and if someone else finds this posts:

I asked the same question in the HA Forum so i just link here to it and hope this is ok and helps others: https://community.home-assistant.io/t/restart-reload-an-integration-with-a-button-or-automation-or-shell/297288/3

home-assistant / core