Can't connect to Harmony Hub since 0.112

N1c093 commented 4 years ago

The problem

I've updated HA from 0.111.3 to 0.112 today. After the update I get the following error in the log file and the integration is not working anymore.

I already tried to reboot the harmony hub, deactivate and activate the "XMPP" developer options and readd the integration.

Environment

Home Assistant Core release with the issue: 0.112
Last working Home Assistant Core release (if known): 0.111.3
Operating environment (OS/Container/Supervised/Core): OS
Integration causing this issue: Logitech Harmony Hub
Link to integration documentation on our website: https://www.home-assistant.io/integrations/harmony/

Problem-relevant `configuration.yaml`

remote:
  - platform: harmony
    name: Wohnzimmer
     host: 192.168.xxx.xx

Traceback/Error logs

2020-07-02 11:10:09 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one.
2020-07-02 11:10:10 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
concurrent.futures._base.CancelledError
2020-07-02 11:10:10 ERROR (MainThread) [homeassistant.components.harmony.config_flow] Unexpected exception
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/harmony/config_flow.py", line 63, in async_step_user
    validated = await validate_input(user_input)
  File "/usr/src/homeassistant/homeassistant/components/harmony/config_flow.py", line 36, in validate_input
    harmony = await get_harmony_client_if_available(data[CONF_HOST])
  File "/usr/src/homeassistant/homeassistant/components/harmony/util.py", line 35, in get_harmony_client_if_available
    if not await harmony.connect():
  File "/usr/local/lib/python3.7/site-packages/aioharmony/harmonyapi.py", line 149, in connect
    return await self._harmony_client.connect()
  File "/usr/local/lib/python3.7/site-packages/aioharmony/harmonyclient.py", line 189, in connect
    if not await self._hub_connection.hub_connect():
  File "/usr/local/lib/python3.7/site-packages/aioharmony/hubconnector_xmpp.py", line 188, in hub_connect
    await connected
  File "/usr/local/lib/python3.7/site-packages/slixmpp/xmlstream/xmlstream.py", line 332, in _connect_routine
    server_hostname=self.default_domain if self.use_ssl else None)
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 962, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 949, in create_connection
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 473, in sock_connect
    return await fut
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 503, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 111] Connect call failed ('::', 5222, 0, 0)

Additional information

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

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

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

Hey there @ehendrix23, @bramkragten, @bdraco, mind taking a look at this issue as its been labeled with an integration (harmony) you are listed as a codeowner for? Thanks! _{^{(message by CodeOwnersMention)}}

N1c093 commented 4 years ago

Strange, the problem resolved itselfs... I didn't changed anything.

N1c093 commented 4 years ago

I'm sorry, but I have to reopen this issue. After some restarts the integrations stop to work on my raspberry again.

I installed another test instance of HA in VMWare on my pc. With Version 0.111.3 everything works fine. I can add the harmony hub without any problems. After the update to 0.112 I can't add the harmony hub anymore.

Ra72xx commented 4 years ago

The same here.

bdraco commented 4 years ago

What error do you get with XMPP off?

Whatsek commented 4 years ago

Same problem, will watch this thread, willing to test.

bdraco commented 4 years ago

Please post tracebacks with and without XMPP

Whatsek commented 4 years ago

I have no XMPP, this is my traceback: EDIT: apearantly I misunderstood the XMPP question, I see it in the log

2020-07-03 17:09:14 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Huiskamer for harmony Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/config_entries.py", line 220, in async_setup hass, self File "/usr/src/homeassistant/homeassistant/components/harmony/init.py", line 54, in async_setup_entry connected_ok = await device.connect() File "/usr/src/homeassistant/homeassistant/components/harmony/remote.py", line 260, in connect if not await self._client.connect(): File "/usr/local/lib/python3.7/site-packages/aioharmony/harmonyapi.py", line 149, in connect return await self._harmony_client.connect() File "/usr/local/lib/python3.7/site-packages/aioharmony/harmonyclient.py", line 189, in connect if not await self._hub_connection.hub_connect(): File "/usr/local/lib/python3.7/site-packages/aioharmony/hubconnector_xmpp.py", line 188, in hub_connect await connected File "/usr/local/lib/python3.7/site-packages/slixmpp/xmlstream/xmlstream.py", line 332, in _connect_routine server_hostname=self.default_domain if self.use_ssl else None) File "/usr/local/lib/python3.7/asyncio/base_events.py", line 962, in create_connection raise exceptions[0] File "/usr/local/lib/python3.7/asyncio/base_events.py", line 949, in create_connection await self.sock_connect(sock, address) File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 473, in sock_connect return await fut File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 503, in _sock_connect_cb raise OSError(err, f'Connect call failed {address}') ConnectionRefusedError: [Errno 111] Connect call failed ('::', 5222, 0, 0)

bdraco commented 4 years ago

For clarity, do you have XMPP turned on from the harmony app ?

N1c093 commented 4 years ago

@bdraco

Here are the required logs.

XMPP turned on:

2020-07-03 21:56:31 ERROR (MainThread) [homeassistant.components.harmony.config_flow] Unexpected exception
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/harmony/config_flow.py", line 63, in async_step_user
    validated = await validate_input(user_input)
  File "/usr/src/homeassistant/homeassistant/components/harmony/config_flow.py", line 36, in validate_input
    harmony = await get_harmony_client_if_available(data[CONF_HOST])
  File "/usr/src/homeassistant/homeassistant/components/harmony/util.py", line 35, in get_harmony_client_if_available
    if not await harmony.connect():
  File "/usr/local/lib/python3.7/site-packages/aioharmony/harmonyapi.py", line 149, in connect
    return await self._harmony_client.connect()
  File "/usr/local/lib/python3.7/site-packages/aioharmony/harmonyclient.py", line 189, in connect
    if not await self._hub_connection.hub_connect():
  File "/usr/local/lib/python3.7/site-packages/aioharmony/hubconnector_xmpp.py", line 188, in hub_connect
    await connected
  File "/usr/local/lib/python3.7/site-packages/slixmpp/xmlstream/xmlstream.py", line 332, in _connect_routine
    server_hostname=self.default_domain if self.use_ssl else None)
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 962, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 949, in create_connection
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 473, in sock_connect
    return await fut
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 503, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 111] Connect call failed ('::', 5222, 0, 0)

XMPP turned off:

2020-07-03 21:59:07 WARNING (MainThread) [aioharmony.harmonyclient] 192.168.xxx.xx: XMPP is not enabled, using web sockets however this might not work with future Harmony firmware updates, please enable XMPP

Normally I have XMPP turned on. Before 0.112 this wasn't a problem and worked really well. As already mentioned everything still works fine with XMPP turned on, if I just HA version 0.111.3.

Do you need more information/logs? Thank you in advance.

bdraco commented 4 years ago

Did you setup from the UI or yaml?

What do you configured for host / CONF_HOST ?

N1c093 commented 4 years ago

This time I've setup the integration via UI. But the error also exist via yaml.

I setup the ip adress of the hub as host (see below)

bdraco commented 4 years ago

Does setup via the UI and then it does appear, or can you not get though setup?

N1c093 commented 4 years ago

With XMPP turned off everything seems to work fine. I can control the hub and receive the current status. I just get the warning in the log, which I mentioned above.

With XMPP turned on it's not possible to add the integration. I get the error in the log (see above) and this error in the UI. IP address and hub-name was the same as above.

bdraco commented 4 years ago

Probably best to leave XMPP off until @ehendrix23 can take a look.

jimmyhawkin commented 4 years ago

Can verify that i allso have the exakt same problem. Ill turn off xmpp for now then.

ehendrix23 commented 4 years ago

Can someone enable debug for aioharmony in HA, reproduce, and then post respective log entries here?

N1c093 commented 4 years ago

@ehendrix23 Here is the required log file

XMPP turned on:

2020-07-05 13:49:48 DEBUG (MainThread) [aioharmony.harmonyapi] 192.168.xxx.xx: Initialize
2020-07-05 13:49:48 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.xxx.xx: Initialize HUB
2020-07-05 13:49:48 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.xxx.xx: Registering handler Activity_Changed with UUID a1a5dba1-94c5-485c-b5ca-13e888941f5d
2020-07-05 13:49:48 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.xxx.xx: Registering handler Activity_Starting with UUID f0a41474-6cba-46f9-a179-6215b0ca0f21
2020-07-05 13:49:48 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.xxx.xx: Registering handler Activity_Stopping with UUID 72d1ff48-d85c-4bb0-8534-d5386c883291
2020-07-05 13:49:48 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.xxx.xx: Registering handler Notification_Received with UUID f5d48caa-0ee8-48b7-9255-f1ef43ce887a
2020-07-05 13:49:48 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.xxx.xx: Callback handler started
2020-07-05 13:49:48 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.xxx.xx: XMPP is enabled
2020-07-05 13:49:48 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.xxx.xx: Using XMPP
2020-07-05 13:49:48 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one.
2020-07-05 13:49:49 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.xxx.xx: Registering internal handlers.
2020-07-05 13:49:49 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.xxx.xx: Connecting to hub
2020-07-05 13:49:49 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
concurrent.futures._base.CancelledError
2020-07-05 13:49:49 ERROR (MainThread) [homeassistant.components.harmony.config_flow] Unexpected exception
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/harmony/config_flow.py", line 63, in async_step_user
    validated = await validate_input(user_input)
  File "/usr/src/homeassistant/homeassistant/components/harmony/config_flow.py", line 36, in validate_input
    harmony = await get_harmony_client_if_available(data[CONF_HOST])
  File "/usr/src/homeassistant/homeassistant/components/harmony/util.py", line 35, in get_harmony_client_if_available
    if not await harmony.connect():
  File "/usr/local/lib/python3.7/site-packages/aioharmony/harmonyapi.py", line 149, in connect
    return await self._harmony_client.connect()
  File "/usr/local/lib/python3.7/site-packages/aioharmony/harmonyclient.py", line 189, in connect
    if not await self._hub_connection.hub_connect():
  File "/usr/local/lib/python3.7/site-packages/aioharmony/hubconnector_xmpp.py", line 188, in hub_connect
    await connected
  File "/usr/local/lib/python3.7/site-packages/slixmpp/xmlstream/xmlstream.py", line 332, in _connect_routine
    server_hostname=self.default_domain if self.use_ssl else None)
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 962, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 949, in create_connection
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 473, in sock_connect
    return await fut
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 503, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 111] Connect call failed ('::', 5222, 0, 0)

Do you also need the debug log for XMPP turned off?

donkawechico commented 4 years ago

I'm also experiencing this issue. I found additional helpful log messages that I don't see in the above posts:

2020-07-06 19:52:34 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one.
2020-07-06 19:52:35 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected.
2020-07-06 19:52:35 INFO (MainThread) [slixmpp.xmlstream.xmlstream] connection_lost: (None,)
2020-07-06 19:52:36 INFO (MainThread) [slixmpp.features.feature_bind.bind] JID set to: 1111/gatorade.
2020-07-06 21:11:20 INFO (MainThread) [slixmpp.xmlstream.xmlstream] connection_lost: (ConnectionResetError(104, 'Connection reset by peer'),)

Specifically, the bit about "Legacy XMPP 0.9 protocol detected".

Sounds like a problem with aioharmony module, to me. Looks like there was some XMPP-related code merged a couple weeks ago that probably got pulled into 0.112... might be related?

guillaumelamirand commented 4 years ago

Hi,

I have the same problem here since 0.112. Sometime after a reboot ha is not able to connect sometimes it is working.

Also I do have another issue about activiry name encoding. I can open a new issue for this one.

Thanks

bdraco commented 4 years ago

I need issue for the encoding would be great. It’s probably not converting utf8 from a bytes string or something similar

ehendrix23 commented 4 years ago

@ehendrix23 Here is the required log file

XMPP turned on:

2020-07-05 13:49:49 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.xxx.xx: Connecting to hub
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 503, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 111] Connect call failed ('::', 5222, 0, 0)

Do you also need the debug log for XMPP turned off?

Based on this, we were able to open a port connection to the HUB on port 5222 (that is how we test if XMPP is enabled on the HUB or not). But when then trying to connect to the HUB using XMPP the connection is refused. Can you add the following entry for debug as well: slixmpp: debug

Hoping to be able to determine then why it is getting connection refused when it tries to connect using XMPP.

Note, 0.112 added support back in to connect to XMPP. 0.111 and before would only connect using web sockets and did not support XMPP even if it was enabled on the HUB. Hence in your case it would have been using web sockets until 0.112 and now it is trying to connect using XMPP as it is enabled on the HUB.

ehendrix23 commented 4 years ago

I'm also experiencing this issue. I found additional helpful log messages that I don't see in the above posts:
2020-07-06 19:52:34 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one.
2020-07-06 19:52:35 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected.
2020-07-06 19:52:35 INFO (MainThread) [slixmpp.xmlstream.xmlstream] connection_lost: (None,)
2020-07-06 19:52:36 INFO (MainThread) [slixmpp.features.feature_bind.bind] JID set to: 1111/gatorade.
2020-07-06 21:11:20 INFO (MainThread) [slixmpp.xmlstream.xmlstream] connection_lost: (ConnectionResetError(104, 'Connection reset by peer'),)
Specifically, the bit about "Legacy XMPP 0.9 protocol detected".

Sounds like a problem with aioharmony module, to me. Looks like there was some XMPP-related code merged a couple weeks ago that probably got pulled into 0.112... might be related?

0.112 brought in support again for XMPP. Before XMPP was not supported and only web sockets were used (even if XMPP was enabled on the HUB). Now if XMPP is enabled on the Hub it will use XMPP to connect to the HUB, if it is not enabled on the HUB it will go to web sockets.

The warning about 0.9 is because the HUB does not support newer XMPP protocols. XMPP is derived from protocols original developed in the Jabber community and servers only supporting this are considered to be XMPP 0.9. Also see: https://xmpp.org/rfcs/rfc3920.html#diffs This warning can be safely ignored. If you want it removed then just add the following in the configuration.yaml for logger: slixmpp: error

The connection lost messages are going to be due to the HUB dropping the connection (or the HUB temporary loosing connection with your network). When this happens the integration will try to reconnect back to the HUB. You can see the "Connection reset by peer", this is stating the it was detected the connection is not there anymore and the the reset for the connection was initiated by the HUB.

ehendrix23 commented 4 years ago

I have the same problem here since 0.112. Sometime after a reboot ha is not able to connect sometimes it is working.

For this, please provide debug log entries by putting in the following for logger:

aioharmony: debug
slixmpp: debug

Thx.

N1c093 commented 4 years ago

Thanks for the feedback and the explanation :)

I'm currently on vacation, so I can only provide new log files at the end of the month. Hopefully anybody else can add the required log files.

Alfiegerner commented 4 years ago

Hi,

EDIT: Leaving comment below for now, but Reverted back to 0.1.13 last night and found hub unresponsive this morning with dreaded red light back on. So for time being I'm assuming that .112 bump is coincidental with issues. Still not 100% sure if my testing is valid, e.g. reverted correctly, as hub worked fine for 1+ years with current config with HA, still investigating.

I've been having issues since 112 also with failure to connect to harmony hub. Not sure if anyone else has seen this but the hub also becomes unresponsive to remotes / harmony mobile app after it has become unresponsive to HA.

I've attached extract from log with debug enabled, selecting harmony or slipxmpp entries. Typically what I'm seeing is when it gets disconnected it's not able to connect again until I reboot the hub, and as mentioned the hub is also unresponsive to other inputs.

I've reverted back to aioharmony 0.1.13 and corresponding HA code and so far stable again tonight, will see how that goes.

home-assistant.log_harmon_slip.txt

Anything else I can do let me know, happy to help.

ehendrix23 commented 4 years ago

EDIT: Leaving comment below for now, but Reverted back to 0.1.13 last night and found hub unresponsive this morning with dreaded red light back on. So for time being I'm assuming that .112 bump is coincidental with issues. Still not 100% sure if my testing is valid, e.g. reverted correctly, as hub worked fine for 1+ years with current config with HA, still investigating.

If you turn off XMPP on the HUB then HASS will revert back to using Web Sockets similar like it did before .112. Version .112 brought back supporting XMPP protocol and uses that if enabled on the HUB.

home-assistant / core