[bug] Unable to connect with Home Assistant

[Depechie]

Is there an existing issue for this?

• I have searched the existing issues

Description

Been using the remote with the Home Assistant connection since the beta release and always worked great.
But since v1.4.8 I have not been able to use the remote ( cfr #206 ).

So I thought to do a factory reset with the firmware being on v1.5.2 to see if things would be better. But I guess this maybe brings up the actual problem?
I can no longer connect to Home Assistant, or rather complete the setup procedure because I think the connection is working, but somehow querying Home Assistant fails.
I can totally understand that this is somehow a local network issue, but I have no idea how to go about checking things and reporting, although it worked well with previous firmwares.

I recorded the procedure and you will see that during it, I also got several remote disconnects, although it was constantly in the dock.

https://github.com/Depechie/RemoteTwo/blob/main/Screen%20Recording%202023-12-26_1080.mov

The log that is reproduced during the procedure several times is this

Logger: aiohttp.server
Source: /usr/local/lib/python3.11/site-packages/aiohttp/web_protocol.py:421
First occurred: 12:34:02 PM (2 occurrences)
Last logged: 12:34:18 PM

Error handling request
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 371, in async_handle
    msg = await wsock.receive()
          ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/web_ws.py", line 440, in receive
    msg = await self._reader.read()
          ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/streams.py", line 663, in read
    return await super().read()
           ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/streams.py", line 622, in read
    await self._waiter
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aiohttp/web_protocol.py", line 452, in _handle_request
    resp = await request_handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/web_app.py", line 543, in _handle
    resp = await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/web_middlewares.py", line 114, in impl
    return await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 85, in security_filter_middleware
    return await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 100, in forwarded_middleware
    return await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 28, in request_context_middleware
    return await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 80, in ban_middleware
    return await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 233, in auth_middleware
    return await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/http/headers.py", line 31, in headers_middleware
    response = await handler(request)
               ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 149, in handle
    result = await handler(request, **request.match_info)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 50, in get
    return await WebSocketHandler(request.app["hass"], request).async_handle()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 435, in async_handle
    await self._writer_task
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 151, in _writer
    await send_str(message)
  File "/usr/local/lib/python3.11/site-packages/aiohttp/web_ws.py", line 336, in send_str
    await self._writer.send(data, binary=False, compress=compress)
  File "/usr/local/lib/python3.11/site-packages/aiohttp/http_websocket.py", line 729, in send
    await self._send_frame(message, WSMsgType.TEXT, compress)
  File "/usr/local/lib/python3.11/site-packages/aiohttp/http_websocket.py", line 691, in _send_frame
    await self.protocol._drain_helper()
  File "/usr/local/lib/python3.11/site-packages/aiohttp/base_protocol.py", line 90, in _drain_helper
    await asyncio.shield(waiter)
  File "/usr/local/lib/python3.11/asyncio/selector_events.py", line 1076, in _write_ready
    n = self._sock.send(self._buffer)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
BrokenPipeError: [Errno 32] Broken pipe

How to Reproduce

Open the web configurator
Go to integrations
Add Home Assistant integration

Expected behavior

Integration has an active connection and would load all entities

System version

v1.5.2

What part of the system affected by the problem?

Integration

Additional context

No response

[Depechie]

And seeing that I own 2 remotes, I unboxed the other one and that one is still running v1.0.5 !
And looking at the recording https://github.com/Depechie/RemoteTwo/blob/main/Screen%20Recording%202023-12-26_2_1080.mov my thoughts are correct.
That version has no problem with my Home Assistant setup and handles the integration perfectly.

[zehnm]

@Depechie can you provide the Home Assistant integration logs from Remote2?
I don't see much in the Home Assistant server logs. The sock send error is most likely because the remote went to sleep during configuration (as seen in the recording).

To make sure the Remote doesn't go to sleep it's best to put it in the dock while configuring with the web-configurator.

In my home setup I'm also using 1.5.2 with HA on a daily basis and haven't seen these issues. I've retested with a new remote with 1.4.4, setup up the HA integration, upgraded the remote to 1.5.2, without getting an error.

From the screen recording I see that you use ws:// protocol and an IPv4 address. Is this correct? Using an IP address already rules out mDNS name resolving.
Is the remote on the same network as your HA server?

With the integration logs I hopefully see what kind of issue you have. The only thing which could maybe cause an issue is the number of entities (> 500). I haven't reached that many yet :-) Depending on the returned data, the Max WebSocket frame size in the extended settings might have to be increased, or the connection timeout setting. But let me have a look at the logs first.

[Depechie]

Hey Markus!
Thx already for the detailed questions. I will try to do some more tests and will upload the logs.

In reference to the remote, it was constantly in the dock!

I reference to the ws:// and the IP address, I use that because I think my setup is not broadcasting with a name.
It are docker compose installs...
I normally use my external public https URL for regular use, can I use that in the remote too?

In reference to the entity count, I do have a lot! But I also have a clean home assistant running on another device with only the Denon integration running and I see the same problems... but if needed I can always do tests with that one too and provide logs.

[Depechie]

UCR2_logs_2023-12-27 (2).txt
UCR2_logs_2023-12-27 (1).txt
UCR2_logs_2023-12-27.txt

@zehnm I the file with (2) at the end is the last one where you can see that I tried both my Home Assistant instances ( difference is one is my main driver with all the integrations I need, the other is for testing things out and now only has the Denon integration and my TV )

[zehnm]

Thanks for the logs. I see two things:

1. Continous Websocket server heartbeat failed, disconnecting! entries.
2. [192.168.1.137:8123] Invalid authentication
   This is only logged if the Home Assistant server rejected the authentication.
   But that could also be a rejection because of too many connection attempts.

There are many Authentication OK entries, which are logged if HA accepted the long lived access token.
Looking at the log timestamps shows something quite interesting: a pair of successfull connection events (Connected to: ws://192.168.1.137:8123/api/websocket and Authentication OK) sometimes appear within the same second, as two client connections are active at the same time and fighting over the server connection (and probably "killing" each other because of modified heartbeat timings). This should not happen, there should only be one client connection.

Since you have 2 HA servers, I suspect there's an issue with connection management when the server configuration is changed and the old HA client (re-)connection handling isn't properly closed.

Could you please do the following to get the startup logs?

1. Change the Home Assistant integration configuration to the server which cannot be connected (192.168.1.137)
2. Reboot the remote
3. Wait two to three minutes and making sure the remote doesn't go to sleep
4. Download again the Home Assistant integration logs with DEBUG, number of entries: 1000

If a simple reboot after changing the HA settings in the integration "fixes" it (or only shows a single reconnection pattern), then my assumption about the connection handling is true. Otherwise, we have to keep digging.

I normally use my external public https URL for regular use, can I use that in the remote too?

If everything is properly setup, then yes. Personally I don't recommend it if your HA server is on the same internal network and accessible with ws://.
Either you need a split DNS setup or the router needs to support NAT hairpinning. The reverse proxy for https has to be setup correctly as well, with a public certificate (not self-signed).
There's another open ticket with a Traefik reverse proxy where it doesn't work: #189
I've successfully tested it with Nginx, but this wasn't on the internal network.

[Depechie]

UCR2_logs_2023-12-29.txt
Here are the latests logs, so I first added the HA integration to the ws://192.168.1.137 endpoint and rebooted the remote.
Waited a few minutes ( while the remote was in the dock ) and then extracted the logs.

It seems the heartbeat problem is still visible in the logs.

Just out of curiosity, would it be better to stop the other HA server I have running?

[Depechie]

UCR2_logs_2023-12-29 (1).txt

So stopping the other HA, does seem to have 'some' effect?
Not always, but it seems that now the integration will actually load the entities... I still sometimes get timeout errors in the UI.

On the other hand, I do have to stress that also the remote itself often is unresponsive even though it is kept in the dock, example:

• so the UI will not load all items when going to Settings
• full page refresh with the 2 dots spinner

Still think that a combination of both is giving me these problems, but hard to tell of course. Just let me know what I can provide as info to get a complete picture.

[zehnm]

Just out of curiosity, would it be better to stop the other HA server I have running?

No, they don't interfere and our HA integration doesn't do any automatic discovery of server instances yet.

There is definitely an issue with the WebSocket ping pong heartbeat. The integration never receives a pong after sending a ping and therefore closes the connection after the configured timeout of 40s.
The HA integration doesn't use regular text messages (as described in the Home Assistant WebSocket API), but native ping frames. This has been working well with the official HA Docker image ghcr.io/home-assistant/home-assistant:stable and with the Home Assistant Yellow.

@Depechie a few more questions about your setup:

• Do you have any proxy, reverse proxy, firewall, etc between the Remote Two and your Home Assistant server (basically anything that could interfere with the WebSocket communication)?
  Or does your Docker Compose setup directly map port 8123 to the Home Assistant server?
• Wich version of Home Assistant do you have?
• Which Docker image do you use in your Docker Compose installation?
• Do you have multiple WiFi access points with roaming?

To rule out a general connection or communication problem with your HA server (and to pin the issue on ping pong frames), I'd like you to try increasing the heartbeat timeout:

1. In the HA integration page: select "Start integration setup"
2. Enable Configure enhanced options and click Next

3. Set Heartbeat timeout to the max value of 300 (the current version doesn't allow disabling it or setting higher values).

This gives you more time to try out setting up an entity and see if the interaction with Home Assistant is working, or if the communication is not working at all. For example with a single light entity.
If the communication is working, then it's the ping pong frames. Otherwise, we need to keep trouble shooting...

In the meantime I start preparing a new version for the next release where one can choose the native ping method (as of now), or the manual ping messages as described in the HA API. A long holiday weekend is coming up, so this will take a few days. But I'll keep an eye on this issue.
Thank you for your patience!

[Depechie]

@zehnm I'm on my holiday so that is why I have time... but please do not feel the urge to respond directly and take time off 😃

Most important thing for me is that someone at least tries to help, how long it takes for replies or suggestions is of no importance.

[Depechie]

Some answers

• If the communication is working, then it's the ping pong frames. Otherwise, we need to keep trouble shooting...

Since I turned of the test HA, it is actually working much better, I can control lights and also my Denon AVR and Panasonic TV through the Remote ( through the HA integration ).
Also the entities seem to load fine. I did reboot the remote a lot also.
I did NOT change the Heartbeat timeout yet and I looked at the logs and that does keep happening ( heartbeat failed ) a lot.
UCR2_logs_2023-12-29 (2).txt

Did a small test with the test HA back up again and I got a timeout again for loading the entities. Could be totally random of course, as you said both should not interfere. But still, going to keep the test HA off to have better playing environment to rule it out.

• Do you have any proxy, reverse proxy, firewall, etc between the Remote Two and your Home Assistant server (basically anything that could interfere with the WebSocket communication)?

Both devices run on the same network, that is hosted by a Unifi Controller. No separated vnet's or anything. I do have 2 pi-hole's on the same network.
If needed I can provide more info ( but maybe not in a public channel? I do have access to the beta repo )

• Or does your Docker Compose setup directly map port 8123 to the Home Assistant server?

The test HA is started on a raspberry pi with: https://github.com/Depechie/HomeLab/blob/main/raspberry/docker-compose.yml it is running netwok mode host
The main HA was done with https://community.home-assistant.io/t/installing-home-assistant-supervised-using-debian-12/200253 ( but that page get's updated a lot when linux versions of HA versions change )

• Which version of Home Assistant do you have?

Main HA: 2023.12.4
Test HA: 2023.12.3

• Which Docker image do you use in your Docker Compose installation?

Cfr github link

• Do you have multiple WiFi access points with roaming?

Yes! Unifi AP's. I could set the remote to a fixed AP in the Unifi config I think. Maybe that worth a shot? On the otherhand, 1 AP is right below the Remote Two dock. If I look at the logs in the Unifi Controller I also do not see it switching to another AP it was always connected to the one in the same room.

[Depechie]

UCR2_logs_2023-12-29 (4).txt
Added the core logs too seeing that I still often have the disconnected remote spinner in the UI even though it is in the dock.