New (0.84.5) harmony component fails with "websockets.exceptions.InvalidStatusCode" on 3 of 4 Harmony Hubs #19466

aderusha · 2018-12-19T17:25:06Z

Home Assistant release with the issue:
0.84.5

Last working Home Assistant release (if known):
N/A - issue was triggered by changes made in latest Harmony firmware

Operating environment (Hass.io/Docker/Windows/etc.):
Standard Home Assistant install in a Python venv on Ubuntu 18.04 LTS. Details:

(homeassistant) homeassistant@hass:~/.homeassistant$ hass --version
0.84.5
(homeassistant) homeassistant@hass:~/.homeassistant$ cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=18.04
DISTRIB_CODENAME=bionic
DISTRIB_DESCRIPTION="Ubuntu 18.04.1 LTS"
(homeassistant) homeassistant@hass:~/.homeassistant$ python3 --version
Python 3.6.7

4 x Harmony Hubs running new 206 firmware.

Component/platform:
remote.harmony

Description of problem:

From inside the venv installed websockets via: pip3 install websockets
Start Home Assistant using previous configuration w/ 4 Harmony Hubs defined (see below for configuration.yaml
Three hubs report error similar to the following:

Dec 19 11:54:10 hass hass[17432]: 2018-12-19 11:54:10 ERROR (MainThread) [homeassistant.helpers.entity] Update for remote.living_room fails
Dec 19 11:54:10 hass hass[17432]: Traceback (most recent call last):
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 221, in async_update_ha_state
Dec 19 11:54:10 hass hass[17432]:     await self.async_device_update()
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 347, in async_device_update
Dec 19 11:54:10 hass hass[17432]:     await self.async_update()
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/components/remote/harmony.py", line 203, in async_update
Dec 19 11:54:10 hass hass[17432]:     await self._client.get_config()
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/pyharmony/client.py", line 205, in get_config
Dec 19 11:54:10 hass hass[17432]:     'vnd.logitech.harmony/vnd.logitech.harmony.engine?config'
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/pyharmony/client.py", line 158, in _send_request
Dec 19 11:54:10 hass hass[17432]:     await self._perform_connect()
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/pyharmony/client.py", line 129, in _perform_connect
Dec 19 11:54:10 hass hass[17432]:     self._ip_address, DEFAULT_HUB_PORT, self._remote_id
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/websockets/py35/client.py", line 20, in __await_impl__
Dec 19 11:54:10 hass hass[17432]:     extra_headers=protocol.extra_headers,
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/websockets/client.py", line 286, in handshake
Dec 19 11:54:10 hass hass[17432]:     raise InvalidStatusCode(status_code)
Dec 19 11:54:10 hass hass[17432]: websockets.exceptions.InvalidStatusCode: Status code not 101: 401

Errors repeat approximately every 6 seconds.
The fourth hub ("Garden Bedroom") initializes on Hass start and works as expected.

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

remote:
  - platform: harmony
    host: 10.0.100.6
    name: Bedroom
    activity: Watch Roku
  - platform: harmony
    host: 10.0.100.146
    name: Lauras Bedroom
    activity: Watch Lauras Desktop
  - platform: harmony
    host: 10.0.100.9
    name: Garden Bedroom
    activity: Roku
  - platform: harmony
    host: 10.0.100.8
    name: Living Room
    activity: Roku

Traceback (if applicable):

Dec 19 11:54:10 hass hass[17432]: 2018-12-19 11:54:10 ERROR (MainThread) [homeassistant.helpers.entity] Update for remote.living_room fails
Dec 19 11:54:10 hass hass[17432]: Traceback (most recent call last):
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 221, in async_update_ha_state
Dec 19 11:54:10 hass hass[17432]:     await self.async_device_update()
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 347, in async_device_update
Dec 19 11:54:10 hass hass[17432]:     await self.async_update()
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/components/remote/harmony.py", line 203, in async_update
Dec 19 11:54:10 hass hass[17432]:     await self._client.get_config()
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/pyharmony/client.py", line 205, in get_config
Dec 19 11:54:10 hass hass[17432]:     'vnd.logitech.harmony/vnd.logitech.harmony.engine?config'
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/pyharmony/client.py", line 158, in _send_request
Dec 19 11:54:10 hass hass[17432]:     await self._perform_connect()
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/pyharmony/client.py", line 129, in _perform_connect
Dec 19 11:54:10 hass hass[17432]:     self._ip_address, DEFAULT_HUB_PORT, self._remote_id
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/websockets/py35/client.py", line 20, in __await_impl__
Dec 19 11:54:10 hass hass[17432]:     extra_headers=protocol.extra_headers,
Dec 19 11:54:10 hass hass[17432]:   File "/srv/homeassistant/lib/python3.6/site-packages/websockets/client.py", line 286, in handshake
Dec 19 11:54:10 hass hass[17432]:     raise InvalidStatusCode(status_code)
Dec 19 11:54:10 hass hass[17432]: websockets.exceptions.InvalidStatusCode: Status code not 101: 401

The text was updated successfully, but these errors were encountered:

aderusha · 2018-12-19T17:26:05Z

Heads up @ehendrix23 (blame @balloob he told me to tag you :P )

ehendrix23 · 2018-12-19T18:00:35Z

@aderusha. LOL. I will .

Issue definitely is with not being able to switch from HTTP to web sockets. During testing when I saw this it was because the wrong hub ID was sent.
Question though is why. :-)

Can you enable debugging in HASS for components homeassistant.components.remote.harmony and pyharmony.client?

For example (you might already have logger there):

logger:
  default: warning
  logs:
    homeassistant.components.remote.harmony: debug
    pyharmony.client: debug

That will allow me to see what is being sent and received. I'm especially interested in the beginning parts when it is being setup and does 1st connection as that is when it gets the required information.

Thx.

aderusha · 2018-12-19T18:10:51Z

I set default: critical to pare things down a bit and enabled debug on the two components listed above.

ehendrix23 · 2018-12-19T18:21:17Z

OK, errors are not reported in there however I do also find it interesting already that I can only see send requests and responses for your Garden one.

Can you send me the log information from the start till right after you see the errors appearing?

Appreciate it.

aderusha · 2018-12-19T18:22:49Z

That is 100% the contents of the log with the following configuration.yaml setup:

logger:
  default: critical
  logs:
    homeassistant.components.remote.harmony: debug
    pyharmony.client: debug

The log entries repeat every 6 seconds.

ehendrix23 · 2018-12-19T18:31:14Z

So right now no errors being reported? Seems to me that this time the 3 other's are "hanging" then as I do not see log entries there about them actually connecting.

Can you try just 1 hub in your configuration (i.e bedroom)? I have 2 hub's here at home and both work, but just wanna see what would happen then.

Further, can you run the following command just to check what version of websockets you have:
pip show websockets

Thx.

aderusha · 2018-12-19T18:37:59Z

From inside the venv:

(homeassistant) homeassistant@hass:~/.homeassistant$ pip show websockets
Name: websockets
Version: 7.0
Summary: An implementation of the WebSocket Protocol (RFC 6455 & 7692)
Home-page: https://github.com/aaugustin/websockets
Author: Aymeric Augustin
Author-email: aymeric.augustin@m4x.org
License: BSD
Location: /srv/homeassistant/lib/python3.6/site-packages
Requires:
Required-by: pyharmony
(homeassistant) homeassistant@hass:~/.homeassistant$

configuration.yaml has been modified to only include the following remote:

remote:
  - platform: harmony
    host: 10.0.100.6
    name: Bedroom
    activity: Roku

Device is not created

ehendrix23 · 2018-12-19T19:39:23Z

So it looks like it is hanging when trying to connect. Already updated the code here so that there is a timeout instead, but that won't solve you're issue except for getting an error then. :-)

Just with the 1 hub, run it with debug again but this time let's add websockets in there:

logger:
  default: critical
  logs:
    homeassistant.components.remote.harmony: debug
    pyharmony.client: debug
    websockets: debug

I know we're able to connect otherwise we would not be able to get the hub id (7174072 for the bedroom one). Thus the question is why is it hanging when trying to connect with websockets.

aderusha · 2018-12-19T20:31:23Z

Updated logs with websockets: debug enabled

ehendrix23 · 2018-12-19T21:33:29Z

Well .......

You sure you wanna use those other 3? :-)

Here is the portion of the log file:

Dec 19 15:30:02 hass hass[10314]: 2018-12-19 15:30:02 DEBUG (MainThread) [pyharmony.client] Connecting to 10.0.100.6 for hub 7174072
Dec 19 15:30:02 hass hass[10314]: 2018-12-19 15:30:02 DEBUG (MainThread) [websockets.protocol] client - state = CONNECTING
Dec 19 15:30:02 hass hass[10314]: 2018-12-19 15:30:02 DEBUG (MainThread) [websockets.protocol] client - event = connection_made(<_SelectorSocketTransport fd=24 read=idle write=<idle, bufsize=0>>)
Dec 19 15:30:02 hass hass[10314]: 2018-12-19 15:30:02 DEBUG (MainThread) [websockets.protocol] client ! failing WebSocket connection in the CONNECTING state: 1006 [no reason]
Dec 19 15:30:02 hass hass[10314]: 2018-12-19 15:30:02 DEBUG (MainThread) [websockets.protocol] client - event = eof_received()
Dec 19 15:30:02 hass hass[10314]: 2018-12-19 15:30:02 DEBUG (MainThread) [websockets.protocol] client x half-closing TCP connection
Dec 19 15:30:02 hass hass[10314]: 2018-12-19 15:30:02 DEBUG (MainThread) [websockets.protocol] client - event = connection_lost(None)
Dec 19 15:30:02 hass hass[10314]: 2018-12-19 15:30:02 DEBUG (MainThread) [websockets.protocol] client - state = CLOSED
Dec 19 15:30:02 hass hass[10314]: 2018-12-19 15:30:02 DEBUG (MainThread) [websockets.protocol] client x code = 1006, reason = [no reason]

So the web socket connection itself is failing (or being disconnected). When I researched this what I mainly found was stating about a firewall. Now I'm doubtful this is the case here, but can you think of anything different between the 3 HUBs that fail and the one that works? Anything from a network perspective?
Can you try restarting one of those HUBs and then see if that resolves the issue?

aderusha · 2018-12-19T22:52:22Z

You sure you wanna use those other 3? :-)

LOL, well up until your PR I wasn't able to use any of the 4, so being able to use 1 is a massive improvement :D

All 4 Harmony Hubs and Hass are on the same VLAN and /16 address space. All 4 hubs are on the same WiFi SSID while Hass is a VM wired via 10gbit. There are no east/west firewalls in place and being on the same subnet/VLAN the traffic shouldn't traverse the router or be impacted by firewall rules. Prior to the firmware update all 4 Harmony devices were working as expected. Finally, from the Hass VM I can issue a telnet <harmony hub IP> 8088 and it is able to connect.

Power cycling one of the hubs (in this case, the hub labeled "Living Room" @ 10.0.100.8) and changing configuration.yaml to connect to just that one hub hasn't changed the behavior. Log messages are identical to the previous log, just with the new IP and hub ID (now [pyharmony.client] Connecting to 10.0.100.8 for hub 7174902).

ehendrix23 · 2018-12-20T15:58:47Z

I figured that but was hoping. :-) I know that from HASS we're able to connect 8088 cause we can get the Hub ID number. We use HTTP to get that information to the HUB on port 8088.

But when we try to connect for Web Socket it fails. Any way you can do a packet trace between your HASS and a HUB that fails?

Here is another idea. Do you have the Harmony app on a mobile device (i.e. iOS, Android)? If you do, are you able to connect from that app to those HUBs? It uses the same web socket API.

I'm also switching to use the aiohttp websocket implementation. Makes more sense as I already use aiohttp. Maybe an issue in the websocket implementation?

aderusha · 2018-12-20T17:04:52Z

Harmony app on mobile devices (both Android and IOS) continue to work as expected against all 4 hubs. I executed a packet capture of unicast traffic between my Hass VM and the target hub "Living Room" @ 10.0.100.8 via the following command: sudo tcpdump -w bedroomharmony.pcap -i ens160 host 10.0.100.8

In packet 16 we have a request being sent to the hub: http://10.0.100.8:8088/?domain=svcs.myharmony.com&hubId=7174902
In packet 18 we get the response: HTTP/1.1 401 Wrong domain\r\n

ehendrix23 · 2018-12-20T18:06:39Z

I think I got it. :-)

When doing the post, the response returned on my HUB for discoveryServerUri is https://svcs.myharmony.com/Discover/Discover.svc. Then when opening the websocket I provide: domain=svcs.myharmony.com

In yours that is failing, it has https://svcs-preview.myharmony.com/Discover/Discover.svc instead.
So, if it requires the domain provided to be the same as the hostname from discoveryServerUri then I am indeed providing the wrong domain now. And that is also the error you get.

Interesting however that I'm not getting an exception there or so.

Anyways, checking now how I can provide a fix to you for this. I need to know if my theory is right

aderusha · 2018-12-20T18:17:58Z

Ooooohhhh. So this MIGHT just be a "me" thing! Some long time ago Logitech had a beta forum and user group who would receive firmware updates before everyone else. They've since stopped doing that, but seeing that -preview strongly suggests that this is a leftover beta thing still attached to my account.

ehendrix23 · 2018-12-20T18:18:43Z

OK,

I created what hopefully is a fix for this. Here is what you need to do:

In your HASS config folder create folder custom_components/remote
Change to that folder
Download updated harmony component (only change here is just for requirement so that it points to my fork instead):
curl https://raw.githubusercontent.com/ehendrix23/home-assistant/harmony_fixes/homeassistant/components/remote/harmony.py -o harmony.py

Now restart HASS. In the logs it should show a warning about custom component.

Check if this works. :-)

aderusha · 2018-12-20T18:23:12Z

CONFIRMED WORKING! That version now discovers and allows control of all 4 of my hubs. Now the component supports people who were in the beta group too!

ehendrix23 · 2018-12-20T18:31:56Z

For anyone else, my plan is to get this into HASS itself with the next release as I do not believe too many would be impacted by this and for anyone who is there is a temporary solution available.

ehendrix23 · 2018-12-26T20:25:26Z

@aderusha,

I've got a full updated version ready using a new module I developed. This one will be able to better handle everything. If you would be willing to test it out and let me know of any issues. Working good here but then again I do not have every scenario here. :-)

It has the following improvements:

Full async support
No more polling for updates, when an activity is changed from another source (i.e. remote) then HASS will be updated through a notification
Set available state if for some reason disconnected from HUB.
Automatic reconnect to HUB if disconnected
When sending a command with repeat it will be send done as 1 "transaction" preventing anything else from HASS to send a command in the middle.
Automatic config update. If anything is changed on the HUB (i.e. device added, rename, ...) then it is detected and configuration is updated. The Harmony files with the configuration are automatically updates as well then.
Unique message identifications ensuring that HUB responses are correctly identified and processed

How to update:

In your HASS config folder create folder custom_components/remote (if not there)
Change to that folder
Make a copy of the current harmony.py (if already there): cp harmony.py harmony.py.bak
Download updated harmony component:
curl https://raw.githubusercontent.com/ehendrix23/home-assistant/Use_aioharmony_for_harmony/homeassistant/components/remote/harmony.py -o harmony.py

Now restart HASS. The new aiomodule will be downloaded automatically.

If you have issues, reverting back is as easy as replacing harmony.py in your custom folder back with the copy made earlier (harmony.py.bak) and restarting HASS.

Appreciate it!

aderusha · 2018-12-26T20:40:05Z

Here's the result on startup:

Dec 26 15:38:11 hass hass[6982]: 2018-12-26 15:38:11 ERROR (MainThread) [homeassistant.components.remote] Error while setting up platform harmony
Dec 26 15:38:11 hass hass[6982]: Traceback (most recent call last):
Dec 26 15:38:11 hass hass[6982]:   File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py", line 128, in _async_setup_platform
Dec 26 15:38:11 hass hass[6982]:     SLOW_SETUP_MAX_WAIT, loop=hass.loop)
Dec 26 15:38:11 hass hass[6982]:   File "/usr/lib/python3.6/asyncio/tasks.py", line 358, in wait_for
Dec 26 15:38:11 hass hass[6982]:     return fut.result()
Dec 26 15:38:11 hass hass[6982]:   File "/home/homeassistant/.homeassistant/custom_components/remote/harmony.py", line 105, in async_setup_platform
Dec 26 15:38:11 hass hass[6982]:     name, address, port, activity, harmony_conf_file, delay_secs)
Dec 26 15:38:11 hass hass[6982]:   File "/home/homeassistant/.homeassistant/custom_components/remote/harmony.py", line 161, in __init__
Dec 26 15:38:11 hass hass[6982]:     disconnect=self.got_disconnected
Dec 26 15:38:11 hass hass[6982]:   File "/srv/homeassistant/lib/python3.6/site-packages/aioharmony/harmonyapi.py", line 44, in __init__
Dec 26 15:38:11 hass hass[6982]:     loop=loop
Dec 26 15:38:11 hass hass[6982]:   File "/srv/homeassistant/lib/python3.6/site-packages/aioharmony/harmonyclient.py", line 89, in __init__
Dec 26 15:38:11 hass hass[6982]:     handler = copy.copy(handlers.HANDLER_START_ACTIVITY_FINISHED)
Dec 26 15:38:11 hass hass[6982]:   File "/usr/lib/python3.6/copy.py", line 88, in copy
Dec 26 15:38:11 hass hass[6982]:     return copier(x)
Dec 26 15:38:11 hass hass[6982]:   File "/srv/homeassistant/lib/python3.6/site-packages/aioharmony/handler.py", line 75, in __copy__
Dec 26 15:38:11 hass hass[6982]:     resp_json=copy.deepcopy(self._resp_json),
Dec 26 15:38:11 hass hass[6982]:   File "/usr/lib/python3.6/copy.py", line 150, in deepcopy
Dec 26 15:38:11 hass hass[6982]:     y = copier(x, memo)
Dec 26 15:38:11 hass hass[6982]:   File "/usr/lib/python3.6/copy.py", line 240, in _deepcopy_dict
Dec 26 15:38:11 hass hass[6982]:     y[deepcopy(key, memo)] = deepcopy(value, memo)
Dec 26 15:38:11 hass hass[6982]:   File "/usr/lib/python3.6/copy.py", line 161, in deepcopy
Dec 26 15:38:11 hass hass[6982]:     y = copier(memo)

ehendrix23 · 2018-12-26T20:52:01Z

Well, that is definitely not the fireworks I was expecting. :-)

Clearly something different between Python 3.6 and 3.7 here.

Just pushed a new update. Download it with curl and see if that works. I might need to see to get Python 3.6 and 3.5.3 as well locally to test with.

aderusha · 2018-12-26T21:36:39Z

Updated version now works as expected across all 4 hubs!

cgarwood added the platform: remote.harmony label Dec 19, 2018

aderusha closed this as completed Dec 20, 2018

ehendrix23 mentioned this issue Dec 26, 2018

Use aioharmony for remote.harmony platform #19595

Merged

6 tasks

ghost added integration: harmony and removed platform: remote.harmony labels Mar 21, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

New (0.84.5) harmony component fails with "websockets.exceptions.InvalidStatusCode" on 3 of 4 Harmony Hubs #19466

New (0.84.5) harmony component fails with "websockets.exceptions.InvalidStatusCode" on 3 of 4 Harmony Hubs #19466

aderusha commented Dec 19, 2018 •

edited

aderusha commented Dec 19, 2018

ehendrix23 commented Dec 19, 2018

aderusha commented Dec 19, 2018 •

edited

ehendrix23 commented Dec 19, 2018

aderusha commented Dec 19, 2018

ehendrix23 commented Dec 19, 2018

aderusha commented Dec 19, 2018 •

edited

ehendrix23 commented Dec 19, 2018

aderusha commented Dec 19, 2018 •

edited

ehendrix23 commented Dec 19, 2018

aderusha commented Dec 19, 2018

ehendrix23 commented Dec 20, 2018

aderusha commented Dec 20, 2018 •

edited

ehendrix23 commented Dec 20, 2018

aderusha commented Dec 20, 2018

ehendrix23 commented Dec 20, 2018

aderusha commented Dec 20, 2018

ehendrix23 commented Dec 20, 2018

ehendrix23 commented Dec 26, 2018

aderusha commented Dec 26, 2018

ehendrix23 commented Dec 26, 2018

aderusha commented Dec 26, 2018

New (0.84.5) harmony component fails with "websockets.exceptions.InvalidStatusCode" on 3 of 4 Harmony Hubs #19466

New (0.84.5) harmony component fails with "websockets.exceptions.InvalidStatusCode" on 3 of 4 Harmony Hubs #19466

Comments

aderusha commented Dec 19, 2018 • edited

aderusha commented Dec 19, 2018

ehendrix23 commented Dec 19, 2018

aderusha commented Dec 19, 2018 • edited

ehendrix23 commented Dec 19, 2018

aderusha commented Dec 19, 2018

ehendrix23 commented Dec 19, 2018

aderusha commented Dec 19, 2018 • edited

ehendrix23 commented Dec 19, 2018

aderusha commented Dec 19, 2018 • edited

ehendrix23 commented Dec 19, 2018

aderusha commented Dec 19, 2018

ehendrix23 commented Dec 20, 2018

aderusha commented Dec 20, 2018 • edited

ehendrix23 commented Dec 20, 2018

aderusha commented Dec 20, 2018

ehendrix23 commented Dec 20, 2018

aderusha commented Dec 20, 2018

ehendrix23 commented Dec 20, 2018

ehendrix23 commented Dec 26, 2018

aderusha commented Dec 26, 2018

ehendrix23 commented Dec 26, 2018

aderusha commented Dec 26, 2018

aderusha commented Dec 19, 2018 •

edited

aderusha commented Dec 19, 2018 •

edited

aderusha commented Dec 19, 2018 •

edited

aderusha commented Dec 19, 2018 •

edited

aderusha commented Dec 20, 2018 •

edited