Core: Harmony-related messages in Logs

[bouwew]

The problem

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

Environment

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

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.



md5-c0d51280637820a26476af21b25166eb



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!



md5-c0d51280637820a26476af21b25166eb



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.



md5-c0d51280637820a26476af21b25166eb



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!



md5-c0d51280637820a26476af21b25166eb



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]]

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

[jes1417]

I am also getting these errors in the beta

[grantclem]

Same issue with 0.112 beta

[grantclem]

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]

Most of these errors can be ignored.

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

[bouwew]

@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]

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

[MrUserY]

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

[MrUserY]

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]

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]

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]

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]

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]

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

[nicx]

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

[MrUserY]

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'nPLAIN'

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]

still seeing the same errors on 113.0

[pergolafabio]

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

[bouwew]

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]

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

[ehendrix23]

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'nhttp://etherx.jabber.org/streams\'>stream:featuresPLAIN'

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

[MrUserY]

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'

[ehendrix23]

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]

logger:
  default: info
  logs:
    slixmpp: debug
    aioharmony: debug

This should give you a full view ^

[yang3535]

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]

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]

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

[yang3535]

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.

[MrUserY]

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:

• Using slower stringprep, consider compiling the faster cython/libidn one
• Legacy XMPP 0.9 protocol detected

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.

[yang3535]

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]

• 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]

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]

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]

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

Yep, that will be set to DEBUG

[MrUserY]

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]

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.

[MrUserY]

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]

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]

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.

[jonathanbower]

I'm experiencing exactly the same thing.

[pergolafabio]

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

[bouwew]

@wormuths I would appreciate you creating a new issue.

[bouwew]

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]

New Issue Created.

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