Log spammed when device is not reachable

[chemelli74]

When device is not reachable then log is spammed by WebSocket:

2024-02-21 16:55:05.638 ERROR (SyncWorker_51) [websocket] [Errno 113] Host is unreachable - goodbye
2024-02-21 16:55:08.644 ERROR (SyncWorker_31) [websocket] [Errno 113] Host is unreachable - goodbye
2024-02-21 16:55:11.650 ERROR (SyncWorker_31) [websocket] [Errno 113] Host is unreachable - goodbye
2024-02-21 16:55:14.656 ERROR (SyncWorker_17) [websocket] [Errno 113] Host is unreachable - goodbye

Even disabling the integration doesn't solve the issue. You need to delete it from custom_components. (this is the way I was sure it's related to this code).

Will try to debug code in the next days, but if you already have an idea is more than welcome.

[rstrouse]

That is actually coming from inside the websockets library. Unfortunately, the websockets library throws inside of it for things that should probably be a failed return code. The one that blows me away is the warning that a socket successfully connected.

It should disable the socket altogether though if integration is disabled. However, I am pretty sure there is no device object to get those types of events or even a callback indicating a disabled state. I chalked that up to the flag being used for automations.

Still, it does this on async_unload_entry and on async_on_unload which does kill the socket for me. Perhaps there is another forwarding event that I am unaware of I had to find those by digging in the code. As I understand it the integration == device in a hub integration. You will see this message from any integration that uses the python websocket library.

[chemelli74]

I think using https://github.com/websocket-client/websocket-client/blob/master/websocket/_core.py#L572 is safe. Is used on SamsungTV core integration and log is not spammed by a switched off device.

if you want to follow the flow: bridge.py (samsungtv HA integration) -> SamsungTVLegacyBridge -> _try_connect -> Remote -> RemoteWebsocket -> create_connection (websocket-client library)

[rstrouse]

This has to do with the unload entry. It is not joining the thread if it cannot first unload the entry. I will have a fix for this next weekend. That is the library being used and here is the logger that is emitting.

https://github.com/websocket-client/websocket-client/blob/a394b46c560cb78672f95bbb3836305e8511d1b9/websocket/_app.py#L598

[rstrouse]

V2.4.1 should now unload properly when disabled. I also bumped the web socket client.

[chemelli74]

Hi, I still have the issue if I start HA and the device is not reachable:

2024-03-19 18:51:29.132 ERROR (SyncWorker_9) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:51:32.137 ERROR (SyncWorker_51) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:51:35.143 ERROR (SyncWorker_20) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:51:38.150 ERROR (SyncWorker_20) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:51:41.155 ERROR (SyncWorker_44) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:51:44.162 ERROR (SyncWorker_16) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:51:47.167 ERROR (SyncWorker_31) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:51:50.174 ERROR (SyncWorker_29) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:51:53.180 ERROR (SyncWorker_46) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:51:56.186 ERROR (SyncWorker_45) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:51:59.191 ERROR (SyncWorker_10) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:02.197 ERROR (SyncWorker_51) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:05.203 ERROR (SyncWorker_14) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:08.210 ERROR (SyncWorker_15) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:11.216 ERROR (SyncWorker_5) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:14.221 ERROR (SyncWorker_44) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:17.227 ERROR (SyncWorker_17) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:20.233 ERROR (SyncWorker_37) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:23.240 ERROR (SyncWorker_37) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:26.245 ERROR (SyncWorker_62) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:29.251 ERROR (SyncWorker_34) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:32.258 ERROR (SyncWorker_22) [websocket] [Errno 113] Host is unreachable - goodbye
2024-03-19 18:52:35.264 ERROR (SyncWorker_28) [websocket] [Errno 113] Host is unreachable - goodbye

Can you please raise a "ConfigEntryNotReady" instead ?

[rstrouse]

I suppose the code could first check with an http head request but that is wasteful given the configuration should start as soon as a socket is opened. Essentially, the socket is doing that as part of the negotiation. Will HA then try to call the integration later on as a retry if it isn't ready yet? I assume this has to be done for each of the domains in the configuration or is this done only for the async_setup_entry in the init?

The message however is coming from inside of the library when an attempt is made to make the connection. Unfortunately, it logs this error and I haven't found a way to turn it off. It also logs info messages and it is infuriating. I even turned off all logging for the module and it still appears. Perhaps this is my naivety wrt python. Strange that a library module would dump to stderr even though the exceptions are caught. Sadly this will rear its head even with the code above if, the ESP32 module is shut down. I guess unless I first send a head and capture the http request exception.

If there is a tragic flaw in the websockets library it is the inability to turn off that logging. Then again I am not a straight up snake programmer. My attempts to set the logging to a null handler have lead to disappointment despite following several threads about disabling it.

[chemelli74]

The main issue here is not only the growth of the log, but the inability to boot HA because the loop is too busy.

ConfigEntryNotReady is for the "device" as seen by HA, so it needs to be coded only once. The good is that HA will retry to configure the device on its own every X seconds (don't remember exactly, should be 30).

[rstrouse]

I have changed the code to raise ConfigNotReady if the device cannot be reached. However, the SocketListener runs in a separate thread with a lower priority. It should not make the main loop busy during boot.

That being said I like that it shows that the initialization failed and the attempts are reflected but it is odd that this is done with SEH given the need to generate a stack trace and context. Perhaps this is more of a defensive coding technique to determine whether it is catastrophic failure or whether it should retry.

I also tested against the socket drop where simply removing the device from the network drops the socket and that stupid message made its way back. I have no idea why that is in there. It is insane and the only way I can see to get around it is to stand up a session and make an api call. I'm stuck between a BS message and efficiency.

There has to be a successful way of stopping the stderr logging within the library but all attempts have failed at that. This has not yielded the desired results.

https://websockets.readthedocs.io/en/stable/topics/logging.html#disable-logging

[rstrouse]

Well the docs were wrong. The specified logger is not websockets it is websocket. I set it to critical and the messages went away.

[chemelli74]

Confirmed to be fixed! Thx !