search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
72.67k stars 30.42k forks source link

Harmony-related messages in Logs #37164

Closed bouwew closed 4 years ago

bouwew commented 4 years ago

The problem

Since 0.112.0b0 I see several Harmony-related warnings and errors in my Logs. Still present in b2.

Environment

Traceback/Error logs

Logger: slixmpp.stringprep
Source: components/harmony/remote.py:260
First occurred: 9:45:13 AM (1 occurrences)
Last logged: 9:45:13 AM

Using slower stringprep, consider compiling the faster cython/libidn one.
Logger: slixmpp.basexmpp
Source: __main__.py:356
First occurred: 9:45:14 AM (2 occurrences)
Last logged: 9:45:16 AM

Legacy XMPP 0.9 protocol detected.
Logger: homeassistant.core
Source: core.py:157
First occurred: 9:45:23 AM (1 occurrences)
Last logged: 9:45:23 AM

Error doing job: Task was destroyed but it is pending!
Logger: aioharmony.harmonyclient
Source: __main__.py:356
First occurred: 9:45:44 AM (2 occurrences)
Last logged: 9:45:46 AM

Hubbie: Timeout trying to retrieve current activity.
Logger: homeassistant.core
Source: core.py:1013
First occurred: 9:45:53 AM (2 occurrences)
Last logged: 9:45:53 AM

Error doing job: Task was destroyed but it is pending!
Logger: aioharmony.helpers
Source: __main__.py:356
First occurred: 9:46:14 AM (1 occurrences)
Last logged: 9:46:14 AM

get_current_activity was not called due to mismatch in callback type.

I'm not sure whether all these messages relate to the Harmony integration but I've listed them for completeness.

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

harmony documentation harmony source (message by IssueLinks)

jes1417 commented 4 years ago

I am also getting these errors in the beta

grantclem commented 4 years ago

Same issue with 0.112 beta

grantclem commented 4 years ago

Logger: slixmpp.stringprep Source: components/harmony/remote.py:260 First occurred: 4:37:40 PM (1 occurrences) Last logged: 4:37:40 PM

Using slower stringprep, consider compiling the faster cython/libidn one.

bdraco commented 4 years ago

Most of these errors can be ignored.

@ehendrix23 Any thoughts on get_current_activity was not called due to mismatch in callback type.?

bouwew commented 4 years ago

@bdraco Yes, probably you're right. Better to have no messages in the Logs then: turn them into debug-messages. Or solve the underlying reason for the message somehow. There always will be people that are triggered by these messages, like me ;)

chicaneau commented 4 years ago

I'm running the harmony component and also receiving the XMPP errors and the Task was destroyed but it is pending! error

ghost commented 4 years ago

Following this thread.

Having the same errors:

Got them after HA (suddenly) told me to enable XMPP (don't know what it is) for the Harmony integration. So I did. The Harmony integration also worked without XMPP.

2020-07-07 19:50:26 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one.

2020-07-07 19:50:30 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected.

Using Harmony in a network with DHCP, but without internet gateway. (Remote country site house)

arch armv7l
chassis embedded
dev false
docker true
docker_version 19.03.8
hassio true
host_os HassOS 4.11
installation_type Home Assistant OS
os_name Linux
os_version 4.19.127-v7l
python_version 3.7.7
supervisor 228
timezone Europe/Amsterdam
version 0.112.3
virtualenv false
ghost commented 4 years ago

Oeh yeah, anther one:

Logger: slixmpp.basexmpp Source: /usr/local/lib/python3.7/site-packages/slixmpp/basexmpp.py:796 First occurred: 1:21:01 PM (1 occurrences) Last logged: 1:21:01 PM

[Errno 111] Connect call failed ('192.168.66.55', 5222) 1:21:01 PM – /usr/local/lib/python3.7/site-packages/slixmpp/basexmpp.py (ERROR)

Traceback (most recent call last): File "/usr/local/lib/python3.7/site-packages/slixmpp/xmlstream/xmlstream.py", line 834, in handler_callback_routine await cb(data) File "/usr/local/lib/python3.7/site-packages/aioharmony/hubconnector_xmpp.py", line 277, in _disconnected_handler if await self.hub_connect(is_reconnect=is_reconnect): 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 ('192.168.66.55', 5222)

mvjt commented 4 years ago

Following this thread.

Having the same errors:

Got them after HA (suddenly) told me to enable XMPP (don't know what it is) for the Harmony integration. So I did. The Harmony integration also worked without XMPP.

2020-07-07 19:50:26 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one.

2020-07-07 19:50:30 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected.

Using Harmony in a network with DHCP, but without internet gateway. (Remote country site house)

arch armv7l chassis embedded dev false docker true docker_version 19.03.8 hassio true host_os HassOS 4.11 installation_type Home Assistant OS os_name Linux os_version 4.19.127-v7l python_version 3.7.7 supervisor 228 timezone Europe/Amsterdam version 0.112.3 virtualenv false

Same issue as you...

Geoff571 commented 4 years ago

Isn't XMPP supposed to be the older, insecure way of communication with the Harmony device? Surely the messaged should be the other way around and WARNING users who are using XMPP?

My Harmony is currently working, and has been for months without XMPP and this message, so why now?

ehendrix23 commented 4 years ago

Logitech about 1.5 years ago disabled XMPP resulting in an uproar. Multiple people then quickly were able to figure out how to connect to it using WebSockets. Because of the uproar, Logitech ended up re-enabling XMPP and identifying that any 3rd party should be using XMPP. Use of Web Sockets is not "approved" and can be changed or updated in any manner in the future. Logitech for Web Sockets will not worry about 3rd party, but they will keep XMPP working as is. Hence the warning as XMPP is the Logitech "supported" manner for 3rd party to connect.

Personally, I prefer Web Sockets and would have preferred they just announced that they will open up the API for Web Sockets and keep it documented for 3rd parties.

cybergrimes commented 4 years ago

How does the integration work currently? I only vaguely remember the whole XMPP uproar, I know I have XMPP enabled but I noticed it's not mentioned in the integration documentation. Does it connect in a non-local way if XMPP is disabled?

pergolafabio commented 4 years ago

If xmpp still disabled, it uses websockets, it's still local

nicx commented 4 years ago

+1 this "ignorable" error should be fixed :)

ghost commented 4 years ago

Update of current errors with 112.4 (I have a working set-up without internet, remote country house, rest is doing fine)

2020-07-20 17:28:45 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one.

2020-07-20 17:28:48 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected.

2020-07-20 17:28:48 ERROR (MainThread) [slixmpp.xmlstream.xmlstream] Parse error: b'\n<![CDATA[{"hue-00:secretsecret-0b":{"color":{"xy":{"y":0.3798,"x":0.5948},"mode":"xy","temp":153,"hueSat":{"hue":7557,"sat":252}},"brightness":254,"on":true,"status":0}}]]><?xml version=\'1.0\' encoding=\'iso-8859-1\'?><stream:stream from=\'connect.logitech.com\' id=\'0557af5f\' version=\'1.0\' xmlns=\'jabber:client\' xmlns:stream=\'http://etherx.jabber.org/streams\'><mechanisms xmlns=\'urn:ietf:params:xml:ns:xmpp-sasl\'>PLAIN</stream:features>'

2020-07-20 17:28:48 ERROR (MainThread) [slixmpp.xmlstream.xmlstream] Exception raised in send queue: Traceback (most recent call last): File "/usr/local/lib/python3.7/site-packages/slixmpp/xmlstream/xmlstream.py", line 1007, in run_filters self.send_raw(str_data) File "/usr/local/lib/python3.7/site-packages/slixmpp/xmlstream/xmlstream.py", line 1043, in send_raw raise NotConnectedError() slixmpp.xmlstream.xmlstream.NotConnectedError

2020-07-20 17:28:48 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/slixmpp/xmlstream/xmlstream.py", line 1014, in run_filters self.waiting_queue.task_done() File "/usr/local/lib/python3.7/asyncio/queues.py", line 202, in task_done raise ValueError('task_done() called too many times') ValueError: task_done() called too many times

2020-07-20 17:28:48 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/slixmpp/xmlstream/xmlstream.py", line 520, in _consume_send_queue_before_disconnecting self.send_raw(self.stream_footer) File "/usr/local/lib/python3.7/site-packages/slixmpp/xmlstream/xmlstream.py", line 1043, in send_raw raise NotConnectedError() slixmpp.xmlstream.xmlstream.NotConnectedError

2020-07-20 17:29:41 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: harmony

2020-07-20 17:29:48 ERROR (MainThread) [aioharmony.harmonyclient] Harmony Hub: Timeout trying to sync hub.

pergolafabio commented 4 years ago

still seeing the same errors on 113.0

pergolafabio commented 4 years ago

guys with errors above, have you got XMPP enabled in HUB?

bouwew commented 4 years ago

Yes.

When I disable XMPP again, I get this message: 192.168.x.yyy: XMPP is not enabled, using web sockets however this might not work with future Harmony firmware updates, please enable XMPP

Spamming the log in both cases :( Please decide which one is the preferred one to use, and then don't spam the log with a message when that one is active!

pergolafabio commented 4 years ago

when you disable XMPP, are all other messages/error gone on restart HA?

ehendrix23 commented 4 years ago

Update of current errors with 112.4 (I have a working set-up without internet, remote country house, rest is doing fine)

2020-07-20 17:28:45 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one.

2020-07-20 17:28:48 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected.

2020-07-20 17:28:48 ERROR (MainThread) [slixmpp.xmlstream.xmlstream] Parse error: b'\n](http://etherx.jabber.org/streams%5C'%3E)stream:featuresPLAIN</stream:features>'

Please enable debug for aioharmony and slixmpp to determine why this is not working for you. Thx.

ghost commented 4 years ago

Update of current errors with 112.4 (I have a working set-up without internet, remote country house, rest is doing fine) i wanna help you with a debug log. But what is slixmpp????

2020-07-20 17:28:45 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one.

2020-07-20 17:28:48 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected.

2020-07-20 17:28:48 ERROR (MainThread) [slixmpp.xmlstream.xmlstream] Parse error: b'\nstream:featuresPLAIN</stream:features>'

ehendrix23 commented 4 years ago

i wanna help you with a debug log. But what is slixmpp????

slixmpp is the underlying library used by aioharmony to connect to hub using XMPP.

bdraco commented 4 years ago 
logger:
  default: info
  logs:
    slixmpp: debug
    aioharmony: debug

This should give you a full view ^

heyitsyang commented 4 years ago

I am getting the same warnings & errors. Here are my logs if it helps:

2020-07-24 17:19:05 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: Initialize HUB 2020-07-24 17:19:05 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: Initialize HUB 2020-07-24 17:19:05 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: XMPP is enabled 2020-07-24 17:19:05 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: Using XMPP 2020-07-24 17:19:05 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one. 2020-07-24 17:19:05 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: XMPP is enabled 2020-07-24 17:19:05 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: Using XMPP 2020-07-24 17:19:06 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: Retrieving HUB information 2020-07-24 17:19:06 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: Retrieving HUB information 2020-07-24 17:19:07 ERROR (SyncWorker_13) [pyvera] Unhandled exception in callback for device #61 (Sun Room Remote 2) Traceback (most recent call last): File "/srv/homeassistant/lib/python3.7/site-packages/pyvera/init.py", line 1623, in _event_device callback(device) File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/vera/init.py", line 201, in _update_callback self.schedule_update_ha_state(True) File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/entity.py", line 416, in schedule_update_ha_state assert self.hass is not None AssertionError 2020-07-24 17:19:07 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: Getting configuration 2020-07-24 17:19:07 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: Getting configuration 2020-07-24 17:19:07 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected. 2020-07-24 17:19:07 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected. 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: Initialize HUB 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: Initialize HUB 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: XMPP is enabled 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: Using XMPP 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: XMPP is enabled 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: Using XMPP 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: Retrieving HUB information 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: Getting configuration 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: Retrieving HUB information 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: Getting configuration 2020-07-24 17:19:08 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: Retrieving current activity 2020-07-24 17:19:08 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected. 2020-07-24 17:19:09 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: Retrieving current activity 2020-07-24 17:19:09 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected. 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: Timeout trying to retrieve provisioning info, retrying. 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.60: Timeout trying to retrieve discovery info, retrying 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: Timeout trying to retrieve provisioning info, retrying. 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.13.69: Timeout trying to retrieve discovery info, retrying 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: Retrieving current activity 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: Current activity: PowerOff(-1) 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: HUB configuration version is: 123 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: HUB ID : 12533259 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: Connected to HUB on IP 192.168.13.69 with ID 12533259. 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: Retrieving current activity 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: Current activity: PowerOff(-1) 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: HUB configuration version is: 106 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: HUB ID : 12516963 2020-07-24 17:19:22 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: Connected to HUB on IP 192.168.13.60 with ID 12516963. 2020-07-24 17:19:23 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: Timeout trying to retrieve current activity, retrying. 2020-07-24 17:19:24 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: Current activity: PowerOff(-1) 2020-07-24 17:19:24 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: HUB configuration version is: 123 2020-07-24 17:19:24 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: HUB ID : 12533259 2020-07-24 17:19:24 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Master Bedr: Connected to HUB on IP 192.168.13.69 with ID 12533259. 2020-07-24 17:19:24 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: Timeout trying to retrieve current activity, retrying. 2020-07-24 17:19:24 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: Current activity: PowerOff(-1) 2020-07-24 17:19:24 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: HUB configuration version is: 106 2020-07-24 17:19:24 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: HUB ID : 12516963 2020-07-24 17:19:24 DEBUG (MainThread) [aioharmony.harmonyclient] Harmony Hub - Living Room: Connected to HUB on IP 192.168.13.60 with ID 12516963. 2020-07-24 17:20:04 INFO (MainThread) [homeassistant.core] Starting Home Assistant 2020-07-24 17:20:04 INFO (MainThread) [homeassistant.core] Timer:starting 2020-07-24 17:20:05 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending! 2020-07-24 17:20:05 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending! 2020-07-24 17:20:05 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending! 2020-07-24 17:20:05 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending! 2020-07-24 17:20:05 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending! 2020-07-24 17:20:05 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!

ehendrix23 commented 4 years ago

I am getting the same warnings & errors. Here are my logs if it helps:

The warning is just because Logitech has stated that Web sockets is not supported for 3rd party and thus they can change something in the firmware anytime causing it to fail and not being able to be used anymore. For XMPP they stated they will leave as is for 3rd party. Either way, warning is being changed to debug.

I do not see anything else really of issue going on. Few times a timeout when trying to retrieve something from the HUB but then it retries and is able to get it.

bdraco commented 4 years ago

I think we can reduce the risk of timeout if we skip getting the remote id in async_step_ssdp if the ip address is already known.

I'll work up a PR for that

Edit: done here https://github.com/home-assistant/core/pull/38181

heyitsyang commented 4 years ago

Thanks for the info. Glad the warnings are being changed to debug.

Any idea what the "Task was destroyed but is pending" is all about? It seems to be related.

ghost commented 4 years ago

Please note that all IP's and UUID's below are anonimized, in other words the numbers are changed.

Oke I have the same error everybody does:

I agree with everybody's wish to disable that error.

Here's one unique error: (The other error i've reported above before did not happen again last week).

2020-07-25 03:01:19 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Connection failed: [Errno 111] Connect call failed ('192.168.61.34', 5222)
2020-07-25 03:01:19 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: connection_failed
2020-07-25 03:01:20 ERROR (MainThread) [slixmpp.basexmpp] [Errno 111] Connect call failed ('192.168.61.34', 5222)
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/slixmpp/xmlstream/xmlstream.py", line 834, in handler_callback_routine
    await cb(data)
  File "/usr/local/lib/python3.7/site-packages/aioharmony/hubconnector_xmpp.py", line 277, in _disconnected_handler
    if await self.hub_connect(is_reconnect=is_reconnect):
  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 ('192.168.61.34', 5222)

And here's the startup log until the point he transfers all my home devices, after that it's getting very long. If you still want that. Let me know. I don't know if something interesting is happening here..

2020-07-24 18:14:38 DEBUG (MainThread) [aioharmony.harmonyapi] 192.168.61.34: Initialize
2020-07-24 18:14:38 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.61.34: Initialize HUB
2020-07-24 18:14:38 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler Activity_Changed with UUID 3bf0ba30-d783-49fb-9019-24be1acf07e2
2020-07-24 18:14:38 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler Activity_Starting with UUID 8f743749-d476-4070-8c53-a9c9640eaf8d
2020-07-24 18:14:38 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler Activity_Stopping with UUID 958e6b08-b942-4a9b-b55c-798e4177386a
2020-07-24 18:14:38 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler Notification_Received with UUID bbe8955a-7981-4bda-8264-248e40c7c160
2020-07-24 18:14:38 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Callback handler started
2020-07-24 18:14:39 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.61.34: XMPP is enabled
2020-07-24 18:14:39 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.61.34: Using XMPP
2020-07-24 18:14:39 WARNING (MainThread) [slixmpp.stringprep] Using slower stringprep, consider compiling the faster cython/libidn one.
2020-07-24 18:14:39 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 6120: Stream Feature: STARTTLS
2020-07-24 18:14:39 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 6120: Stream Feature: Resource Binding
2020-07-24 18:14:39 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 3920: Stream Feature: Start Session
2020-07-24 18:14:39 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 6121: Stream Feature: Roster Versioning
2020-07-24 18:14:39 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 6121: Stream Feature: Subscription Pre-Approval
2020-07-24 18:14:39 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 6120: Stream Feature: SASL
2020-07-24 18:14:39 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Registering internal handlers.
2020-07-24 18:14:39 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Connecting to hub
2020-07-24 18:14:39 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: connecting
2020-07-24 18:14:39 DEBUG (MainThread) [slixmpp.xmlstream.resolver] DNS: Querying  for AAAA records.
2020-07-24 18:14:39 DEBUG (MainThread) [slixmpp.xmlstream.resolver] DNS: Exception while querying for  AAAA records: (1, 'DNS server returned answer with no data')
2020-07-24 18:14:39 DEBUG (MainThread) [slixmpp.xmlstream.resolver] DNS: Querying  for A records.
2020-07-24 18:14:40 DEBUG (MainThread) [slixmpp.xmlstream.resolver] DNS: Exception while querying for  A records: (1, 'DNS server returned answer with no data')
2020-07-24 18:14:40 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: connected
2020-07-24 18:14:40 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <stream:stream to='connect.logitech.com' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Connected to hub
2020-07-24 18:14:40 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <stream:stream from="connect.logitech.com" id="0b1f70ef" version="1.0">
2020-07-24 18:14:40 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism></mechanisms></stream:features>
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler get_current_state with UUID d8a35037-afb9-4c05-97b5-041f01ec6b51 that will expire on 2020-07-24 18:15:40.886295+02:00
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Sending payload: {'xmlns': 'connect.logitech.com', 'mime': 'vnd.logitech.connect/vnd.logitech.statedigest?get'} verb=get:format=json
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.61.34: Retrieving HUB information
2020-07-24 18:14:40 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <iq id="01034a97-035a-42d0-ae0c-d59e59871cbf" type="get"><oa xmlns="connect.logitech.com" mime="vnd.logitech.connect/vnd.logitech.statedigest?get">verb=get:format=json</oa></iq>
2020-07-24 18:14:40 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="PLAIN">AHVzZXIAcGFzc3dvcmQ=</auth>
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.61.34: Getting configuration
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler get_config with UUID 3a25e72d-db13-4a24-9cf0-4fd3b3d6fafa that will expire on 2020-07-24 18:15:40.915607+02:00
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Sending payload: {'xmlns': 'connect.logitech.com', 'mime': 'vnd.logitech.harmony/vnd.logitech.harmony.engine?config'} verb=get:format=json
2020-07-24 18:14:40 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <iq id="1c0b5a76-a5f8-4090-8050-ecd306bd63be" type="get"><oa xmlns="connect.logitech.com" mime="vnd.logitech.harmony/vnd.logitech.harmony.engine?config">verb=get:format=json</oa></iq>
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler provision_info with UUID a3f4baeb-a114-4437-b4a8-073ab4b514e1 that will expire on 2020-07-24 18:15:40.931805+02:00
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Sending payload: {'xmlns': 'connect.logitech.com', 'mime': 'setup.account?getProvisionInfo'} verb=get:format=json
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler discovery with UUID f3c1b234-2976-4606-80e4-be7d863408bd that will expire on 2020-07-24 18:15:40.933354+02:00
2020-07-24 18:14:40 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Sending payload: {'xmlns': 'connect.logitech.com', 'mime': 'connect.discoveryinfo?get'} verb=get:format=json
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <iq id="fae1585fa00c4f2fa12b375129f218a5" />
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <iq id="01034a97-035a-42d0-ae0c-d59e59871cbf" type="get"><oa xmlns="connect.logitech.com" mime="vnd.logitech.connect/vnd.logitech.statedigest?get" errorcode="200" errorstring="OK">{&quot;sleepTimerId&quot;:-1,&quot;runningZoneList&quot;:[],&quot;configVersion&quot;:97,&quot;activityId&quot;:&quot;-1&quot;,&quot;syncStatus&quot;:0,&quot;time&quot;:186610,&quot;stateVersion&quot;:55,&quot;tzOffset&quot;:&quot;7200&quot;,&quot;mode&quot;:3,&quot;hubSwVersion&quot;:&quot;4.15.264&quot;,&quot;deviceSetupState&quot;:[],&quot;tzoffset&quot;:&quot;7200&quot;,&quot;isSetupComplete&quot;:true,&quot;contentVersion&quot;:64,&quot;wifiStatus&quot;:1,&quot;discoveryServer&quot;:&quot;https:\/\/svcs.myharmony.com\/Discovery\/Discovery.svc&quot;,&quot;activityStatus&quot;:0,&quot;runningActivityList&quot;:&quot;&quot;,&quot;tz&quot;:&quot;CET-1CEST,M3.4.0,M10.4.0\/3&quot;,&quot;activitySetupState&quot;:false,&quot;updates&quot;:[],&quot;hubUpdate&quot;:false,&quot;sequence&quot;:false,&quot;accountId&quot;:&quot;14095123&quot;}</oa></iq>
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Response payload: {'id': '01034a97-035a-42d0-ae0c-d59e59871cbf', 'xmlns': None, 'cmd': 'vnd.logitech.connect/vnd.logitech.statedigest?get', 'type': None, 'code': 200, 'codestring': 'OK', 'data': {'sleepTimerId': -1, 'runningZoneList': [], 'configVersion': 97, 'activityId': '-1', 'syncStatus': 0, 'time': 186610, 'stateVersion': 55, 'tzOffset': '7200', 'mode': 3, 'hubSwVersion': '4.15.264', 'deviceSetupState': [], 'tzoffset': '7200', 'isSetupComplete': True, 'contentVersion': 64, 'wifiStatus': 1, 'discoveryServer': 'https://svcs.myharmony.com/Discovery/Discovery.svc', 'activityStatus': 0, 'runningActivityList': '', 'tz': 'CET-1CEST,M3.4.0,M10.4.0/3', 'activitySetupState': False, 'updates': [], 'hubUpdate': False, 'sequence': False, 'accountId': '14095123'}}
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <success xmlns="urn:ietf:params:xml:ns:xmpp-sasl" />
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: auth_success
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <stream:stream to='connect.logitech.com' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <iq>
2020-07-24 18:14:41 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected.
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: legacy_protocol
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] End of stream received
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: killed
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: disconnected
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Tried to cancel unscheduled event: Whitespace Keepalive
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Tried to cancel unscheduled event: Disconnect wait
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <iq id="ab2e4c24-e93e-44bb-afe7-9d427770cbcf" type="get"><oa xmlns="connect.logitech.com" mime="setup.account?getProvisionInfo">verb=get:format=json</oa></iq>
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <iq id="507d6fe0-5376-432c-8fd5-6e4511dc5575" type="get"><oa xmlns="connect.logitech.com" mime="connect.discoveryinfo?get">verb=get:format=json</oa></iq>
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Message received: {'id': '01034a97-035a-42d0-ae0c-d59e59871cbf', 'xmlns': None, 'cmd': 'vnd.logitech.connect/vnd.logitech.statedigest?get', 'type': None, 'code': 200, 'codestring': 'OK', 'data': {'sleepTimerId': -1, 'runningZoneList': [], 'configVersion': 97, 'activityId': '-1', 'syncStatus': 0, 'time': 186610, 'stateVersion': 55, 'tzOffset': '7200', 'mode': 3, 'hubSwVersion': '4.15.264', 'deviceSetupState': [], 'tzoffset': '7200', 'isSetupComplete': True, 'contentVersion': 64, 'wifiStatus': 1, 'discoveryServer': 'https://svcs.myharmony.com/Discovery/Discovery.svc', 'activityStatus': 0, 'runningActivityList': '', 'tz': 'CET-1CEST,M3.4.0,M10.4.0/3', 'activitySetupState': False, 'updates': [], 'hubUpdate': False, 'sequence': False, 'accountId': '14095123'}}
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: No match for handler Activity_Changed
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: No match for handler Activity_Starting
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: No match for handler Activity_Stopping
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: No match for handler Notification_Received
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Match for get_current_state
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: No match on msgid for get_config
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: No match on msgid for provision_info
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: No match on msgid for discovery
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.helpers] Future get_current_state with UUID d8a35037-afb9-4c05-97b5-041f01ec6b51 is set
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Unregistering handler with UUID d8a35037-afb9-4c05-97b5-041f01ec6b51
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Checking for expired handlers
2020-07-24 18:14:41 INFO (MainThread) [slixmpp.xmlstream.xmlstream] connection_lost: (None,)
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: disconnected
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Tried to cancel unscheduled event: Whitespace Keepalive
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Tried to cancel unscheduled event: Disconnect wait
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: session_end
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Connection closed, reconnecting
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Removing internal handlers.
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 6120: Stream Feature: STARTTLS
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 6120: Stream Feature: Resource Binding
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 3920: Stream Feature: Start Session
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 6121: Stream Feature: Roster Versioning
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 6121: Stream Feature: Subscription Pre-Approval
2020-07-24 18:14:41 DEBUG (MainThread) [slixmpp.plugins.base] Loaded Plugin: RFC 6120: Stream Feature: SASL
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Registering internal handlers.
2020-07-24 18:14:41 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Connection was closed through disconnect, not reconnecting
2020-07-24 18:14:42 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Scheduled event: IqTimeout_01034a97-035a-42d0-ae0c-d59e59871cbf
2020-07-24 18:14:42 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Scheduled event: IqTimeout_1c0b5a76-a5f8-4090-8050-ecd306bd63be
2020-07-24 18:14:42 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Scheduled event: IqTimeout_ab2e4c24-e93e-44bb-afe7-9d427770cbcf
2020-07-24 18:14:42 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Scheduled event: IqTimeout_507d6fe0-5376-432c-8fd5-6e4511dc5575
2020-07-24 18:14:42 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Connecting to hub
2020-07-24 18:14:42 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: connecting
2020-07-24 18:14:42 DEBUG (MainThread) [slixmpp.xmlstream.resolver] DNS: Querying  for AAAA records.
2020-07-24 18:14:43 DEBUG (MainThread) [slixmpp.xmlstream.resolver] DNS: Exception while querying for  AAAA records: (1, 'DNS server returned answer with no data')
2020-07-24 18:14:43 DEBUG (MainThread) [slixmpp.xmlstream.resolver] DNS: Querying  for A records.
2020-07-24 18:14:43 DEBUG (MainThread) [slixmpp.xmlstream.resolver] DNS: Exception while querying for  A records: (1, 'DNS server returned answer with no data')
2020-07-24 18:14:43 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: connected
2020-07-24 18:14:43 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <stream:stream to='connect.logitech.com' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2020-07-24 18:14:43 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Connected to hub
2020-07-24 18:14:43 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <stream:stream from="connect.logitech.com" id="0b1f7d83" version="1.0">
2020-07-24 18:14:43 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism></mechanisms></stream:features>
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="PLAIN">AHVzZXIAcGFzc3dvcmQ=</auth>
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <success xmlns="urn:ietf:params:xml:ns:xmpp-sasl" />
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: auth_success
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <stream:stream to='connect.logitech.com' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <stream:stream from="connect.logitech.com" id="0b1f7d83" version="1.0">
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /><session xmlns="urn:ietf:params:xml:nx:xmpp-session" /></stream:features>
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.features.feature_bind.bind] Requesting resource: gatorade.
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <iq id="77405cc67e1b468a8b5b9e8e512ece22" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource>gatorade.</resource></bind></iq>
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <iq id="77405cc67e1b468a8b5b9e8e512ece22" type="result"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>1111/gatorade.</jid></bind></iq>
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: session_bind
2020-07-24 18:14:44 INFO (MainThread) [slixmpp.features.feature_bind.bind] JID set to: 1111/gatorade.
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.features.feature_bind.bind] Established Session
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: session_start
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.clientxmpp] Finished processing stream features.
2020-07-24 18:14:44 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Event triggered: stream_negotiated
2020-07-24 18:14:55 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler get_config with UUID 89959665-e63b-475a-9a7e-1284c7a99525 that will expire on 2020-07-24 18:15:55.917305+02:00
2020-07-24 18:14:55 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Sending payload: {'xmlns': 'connect.logitech.com', 'mime': 'vnd.logitech.harmony/vnd.logitech.harmony.engine?config'} verb=get:format=json
2020-07-24 18:14:55 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <iq id="122ffa5f-e2b9-4a7b-9085-2314f250d347" type="get"><oa xmlns="connect.logitech.com" mime="vnd.logitech.harmony/vnd.logitech.harmony.engine?config">verb=get:format=json</oa></iq>
2020-07-24 18:14:55 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <iq id="f1d635bcde214362ba62301b4f4d88df" />
2020-07-24 18:14:55 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.61.34: Timeout trying to retrieve provisioning info, retrying.
2020-07-24 18:14:55 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler provision_info with UUID 667f2f00-fe85-41f5-b2db-43a2b3fae0c3 that will expire on 2020-07-24 18:15:55.934902+02:00
2020-07-24 18:14:55 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Sending payload: {'xmlns': 'connect.logitech.com', 'mime': 'setup.account?getProvisionInfo'} verb=get:format=json
2020-07-24 18:14:55 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <iq id="b4937acd-e7d4-446a-a88b-2377a61699bc" type="get"><oa xmlns="connect.logitech.com" mime="setup.account?getProvisionInfo">verb=get:format=json</oa></iq>
2020-07-24 18:14:55 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.61.34: Timeout trying to retrieve discovery info, retrying
2020-07-24 18:14:55 DEBUG (MainThread) [aioharmony.responsehandler] 192.168.61.34: Registering handler discovery with UUID fa6ed2c2-0f90-4ccf-8573-782f3ae5aa19 that will expire on 2020-07-24 18:15:55.939887+02:00
2020-07-24 18:14:55 DEBUG (MainThread) [aioharmony.hubconnector_xmpp] 192.168.61.34: Sending payload: {'xmlns': 'connect.logitech.com', 'mime': 'connect.discoveryinfo?get'} verb=get:format=json
2020-07-24 18:14:55 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] SEND: <iq id="99807208-610e-4b0d-bd97-ce875b370e82" type="get"><oa xmlns="connect.logitech.com" mime="connect.discoveryinfo?get">verb=get:format=json</oa></iq>
2020-07-24 18:14:56 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Scheduled event: IqTimeout_122ffa5f-e2b9-4a7b-9085-2314f250d347
2020-07-24 18:14:56 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Scheduled event: IqTimeout_b4937acd-e7d4-446a-a88b-2377a61699bc
2020-07-24 18:14:56 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] Scheduled event: IqTimeout_99807208-610e-4b0d-bd97-ce875b370e82
2020-07-24 18:14:57 DEBUG (MainThread) [slixmpp.xmlstream.xmlstream] RECV: <iq id="122ffa5f-e2b9-4a7b-9085-2314f250d347" type="get"><oa xmlns="connect.logitech.com"

I've stopped logging again.

heyitsyang commented 4 years ago

This is somewhat related. I have just updated to 0.113.2. I got tired of seeing the aforementioned messages in the logs and since I'm not doing anything with harmony yet, I decided to delete the integration for my two harmony devices.

Surprisingly, I get the following error even though I deleted the integrations and marked them to ignore in the UI.

2020-07-28 19:49:16 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/data_entry_flow.py", line 129, in async_init flow, flow.init_step, data, init_done File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/data_entry_flow.py", line 201, in _async_handle_step result: Dict = await getattr(flow, method)(user_input) File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/harmony/config_flow.py", line 89, in async_step_ssdp if self._host_already_configured(parsed_url.hostname): File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/harmony/config_flow.py", line 167, in _host_already_configured if entry.data[CONF_HOST] == host: KeyError: 'host' 2020-07-28 19:49:16 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/data_entry_flow.py", line 129, in async_init flow, flow.init_step, data, init_done File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/data_entry_flow.py", line 201, in _async_handle_step result: Dict = await getattr(flow, method)(user_input) File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/harmony/config_flow.py", line 89, in async_step_ssdp if self._host_already_configured(parsed_url.hostname): File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/harmony/config_flow.py", line 167, in _host_already_configured if entry.data[CONF_HOST] == host: KeyError: 'host'

ehendrix23 commented 4 years ago
  • Using slower stringprep, consider compiling the faster cython/libidn one
  • Legacy XMPP 0.9 protocol detected

These I cannot change. They are from an underlying library being used.

ehendrix23 commented 4 years ago

Here's one unique error: (The other error i've reported above before did not happen again last week).

For that error, it was already connected to the Hub and then seems the connection broke and upon reconnection it failed to connect. Is that accurate?

pergolafabio commented 4 years ago

i just disabled xmpp on my hub forcing websockets , like it was in releases before 112.0 , no issues then offcourse anymore

only this line , maybe you can make it a debug line instead of a warning?

2020-07-29 15:03:55 WARNING (MainThread) [aioharmony.harmonyclient] 192.168.0.21: XMPP is not enabled, using web sockets however this might not work with future Harmony firmware updates, please enable XMPP

ehendrix23 commented 4 years ago

only this line , maybe you can make it a debug line instead of a warning?

Yep, that will be set to DEBUG

ghost commented 4 years ago

Here's one unique error: (The other error i've reported above before did not happen again last week).

For that error, it was already connected to the Hub and then seems the connection broke and upon reconnection it failed to connect. Is that accurate?

It's hard to tell, but I assume that's the case. Would be a nice if the system would do a ping ping after such an error to determine if it's an self-error or a reachability error. (Than I know if i'm to blaim or the integration hahaha).

ehendrix23 commented 4 years ago

For that error, it was already connected to the Hub and then seems the connection broke and upon reconnection it failed to connect. Is that accurate?

It's hard to tell, but I assume that's the case. Would be a nice if the system would do a ping ping after such an error to determine if it's an self-error or a reachability error. (Than I know if i'm to blaim or the integration hahaha).

There was an issue in aioharmony where the exception for connection refused was not captured resulting in the traceback. And not sure but that might then also stop any retries for connecting again. A fixed this in 0.2.6 and just pushed a request to get the integration in HA updated to 0.2.6 (#38360). Then if the connection is refused an error would be reported but the integration would keep on retrying to connect to the Hub again.

ghost commented 4 years ago

There was an issue in aioharmony where the exception for connection refused was not captured resulting in the traceback. And not sure but that might then also stop any retries for connecting again. A fixed this in 0.2.6 and just pushed a request to get the integration in HA updated to 0.2.6 (#38360). Then if the connection is refused an error would be reported but the integration would keep on retrying to connect to the Hub again.

Thanks, we'll see if an comes up after the update.

bdraco commented 4 years ago

This is somewhat related. I have just updated to 0.113.2. I got tired of seeing the aforementioned messages in the logs and since I'm not doing anything with harmony yet, I decided to delete the integration for my two harmony devices.

Surprisingly, I get the following error even though I deleted the integrations and marked them to ignore in the UI.

2020-07-28 19:49:16 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/data_entry_flow.py", line 129, in async_init flow, flow.init_step, data, init_done File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/data_entry_flow.py", line 201, in _async_handle_step result: Dict = await getattr(flow, method)(user_input) File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/harmony/config_flow.py", line 89, in async_step_ssdp if self._host_already_configured(parsed_url.hostname): File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/harmony/config_flow.py", line 167, in _host_already_configured if entry.data[CONF_HOST] == host: KeyError: 'host' 2020-07-28 19:49:16 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/data_entry_flow.py", line 129, in async_init flow, flow.init_step, data, init_done File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/data_entry_flow.py", line 201, in _async_handle_step result: Dict = await getattr(flow, method)(user_input) File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/harmony/config_flow.py", line 89, in async_step_ssdp if self._host_already_configured(parsed_url.hostname): File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/harmony/config_flow.py", line 167, in _host_already_configured if entry.data[CONF_HOST] == host: KeyError: 'host'

Fixed here https://github.com/home-assistant/core/pull/38367

wormuths commented 4 years ago

I didn't know if this should be an additional ticket, but it seems similar. Since 113 upgrade (now on 114.1) my Harmony Hub is consistently on/off in Home Assistant Core. It's not dropping in reality, but HA is reporting it that way.

Harmony

jonathanbower commented 4 years ago

I'm experiencing exactly the same thing.

pergolafabio commented 4 years ago

You guys using websocket or xmpp? Was it also present in 114.0 ?

bouwew commented 4 years ago

@wormuths I would appreciate you creating a new issue.

bouwew commented 4 years ago

I'm closing this issue, as some of the message have been removed (changed to debug) and the presence of others have been explained.

Thanks all, for reporting and fixing were possible!

wormuths commented 4 years ago

New Issue Created.

https://github.com/home-assistant/core/issues/38936