Flood of websocket-related errors when Home Assistant starts

[rccoleman]

I don't know whether this is specific to HA's use of PyISY, but that's how I'm using it and it does seem to be an issue in PyISY. Fairly often when I start HA, I get a flood of errors that start like this:

2022-01-17 18:55:24 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE
2022-01-17 18:55:24 INFO (SyncWorker_8) [homeassistant.loader] Loaded spotify from homeassistant.components.spotify
2022-01-17 18:55:24 INFO (SyncWorker_10) [homeassistant.loader] Loaded heos from homeassistant.components.heos
2022-01-17 18:55:24 ERROR (MainThread) [pyisy.events.websocket] Error during receive Received frame with non-zero reserved bits
2022-01-17 18:55:24 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE
2022-01-17 18:55:24 INFO (SyncWorker_4) [homeassistant.loader] Loaded homekit from homeassistant.components.homekit
2022-01-17 18:55:24 INFO (SyncWorker_10) [homeassistant.loader] Loaded forked_daapd from homeassistant.components.forked_daapd
2022-01-17 18:55:24 INFO (SyncWorker_1) [homeassistant.loader] Loaded roku from homeassistant.components.roku
2022-01-17 18:55:25 INFO (MainThread) [custom_components.hacs] Stage changed: HacsStage.RUNNING
2022-01-17 18:55:25 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE
2022-01-17 18:55:25 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE
2022-01-17 18:55:26 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE
2022-01-17 18:55:26 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE

It continues with quite a lot of these:
2022-01-17 18:55:50 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE

Interspersed with some

2022-01-17 18:55:49 ERROR (MainThread) [pyisy.events.websocket] Error during receive Received frame with non-zero reserved bits

Eventually it seems to stop on its own - in the last run it was ~1 minute from the first error to when it stopped. It doesn't seem to affect HA functionality and I'm able to control ISY-based devices without any issue afterward and without additional errors/warnings.

I'm using firmware v5.3.4 on my ISY and restarting the ISY doesn't help. It's hard to say how long it's been happening because it doesn't happen on every restart. It could have started with 3.0.0, but I suspect that it was later than that.

[rccoleman]

I enabled debug for pyisy and pyisy.events and got this:

2022-02-26 11:33:08 DEBUG (MainThread) [pyisy.events.websocket] Starting websocket connection.                                                                                    
2022-02-26 11:33:08 INFO (SyncWorker_8) [homeassistant.loader] Loaded kodi from homeassistant.components.kodi                                                                     
2022-02-26 11:33:09 DEBUG (MainThread) [pyisy.events.websocket] Successfully connected to websocket.                                                                              
2022-02-26 11:33:09 INFO (MainThread) [hass_nabucasa.google_report_state] Connected                                                                                               
2022-02-26 11:33:10 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE                                     
2022-02-26 11:33:10 DEBUG (MainThread) [pyisy.events.websocket] Stopping websocket connection.                                                                                 
2022-02-26 11:33:10 INFO (MainThread) [pyisy.events.websocket] PyISY attempting stream reconnect in 0.01s.                                                                     
2022-02-26 11:33:10 DEBUG (MainThread) [pyisy.events.websocket] Starting websocket connection.                                                                                 
2022-02-26 11:33:10 INFO (MainThread) [custom_components.hacs] Stage changed: HacsStage.RUNNING                                                                                   
2022-02-26 11:33:10 DEBUG (MainThread) [pyisy.events.websocket] Successfully connected to websocket.                                                                           
2022-02-26 11:33:10 INFO (SyncWorker_0) [homeassistant.loader] Loaded heos from homeassistant.components.heos                                                                  
2022-02-26 11:33:11 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE                                  
2022-02-26 11:33:11 INFO (SyncWorker_8) [homeassistant.loader] Loaded spotify from homeassistant.components.spotify                                                            
2022-02-26 11:33:11 DEBUG (MainThread) [pyisy.events.websocket] Stopping websocket connection.                                                                                 
2022-02-26 11:33:11 INFO (MainThread) [pyisy.events.websocket] PyISY attempting stream reconnect in 0.01s.                                                                     
2022-02-26 11:33:11 DEBUG (MainThread) [pyisy.events.websocket] Starting websocket connection.                                                                                 
2022-02-26 11:33:11 INFO (SyncWorker_3) [homeassistant.loader] Loaded forked_daapd from homeassistant.components.forked_daapd                                                  
2022-02-26 11:33:11 DEBUG (MainThread) [pyisy.events.websocket] Successfully connected to websocket.                                                               
2022-02-26 11:33:11 INFO (SyncWorker_5) [homeassistant.loader] Loaded cast from homeassistant.components.cast                                                           
2022-02-26 11:33:11 INFO (SyncWorker_4) [homeassistant.loader] Loaded plex from homeassistant.components.plex                                                          
2022-02-26 11:33:11 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE                      
2022-02-26 11:33:11 DEBUG (MainThread) [pyisy.events.websocket] Stopping websocket connection.                                                                          
2022-02-26 11:33:11 INFO (MainThread) [pyisy.events.websocket] PyISY attempting stream reconnect in 0.01s.                                                              
2022-02-26 11:33:11 INFO (SyncWorker_8) [homeassistant.loader] Loaded homekit from homeassistant.components.homekit                                                     
2022-02-26 11:33:11 DEBUG (MainThread) [pyisy.events.websocket] Starting websocket connection.                                                                          
2022-02-26 11:33:12 DEBUG (MainThread) [pyisy.events.websocket] Successfully connected to websocket.                                                                    
2022-02-26 11:33:12 INFO (SyncWorker_7) [homeassistant.loader] Loaded roku from homeassistant.components.roku                                                           
2022-02-26 11:33:12 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE                           
2022-02-26 11:33:12 DEBUG (MainThread) [pyisy.events.websocket] Stopping websocket connection.                                                                          
2022-02-26 11:33:12 INFO (MainThread) [pyisy.events.websocket] PyISY attempting stream reconnect in 0.01s.                                                              
2022-02-26 11:33:12 DEBUG (MainThread) [pyisy.events.websocket] Starting websocket connection.                                                                          
2022-02-26 11:33:12 DEBUG (MainThread) [pyisy.events.websocket] Successfully connected to websocket.                                                                    
2022-02-26 11:33:13 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE                           
2022-02-26 11:33:13 DEBUG (MainThread) [pyisy.events.websocket] Stopping websocket connection.                                                                     
2022-02-26 11:33:13 INFO (MainThread) [pyisy.events.websocket] PyISY attempting stream reconnect in 0.01s.                                                              
2022-02-26 11:33:13 DEBUG (MainThread) [pyisy.events.websocket] Starting websocket connection.                                                                          
2022-02-26 11:33:13 DEBUG (MainThread) [pyisy.events.websocket] Successfully connected to websocket.                                                               
2022-02-26 11:33:13 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE                           
2022-02-26 11:33:13 DEBUG (MainThread) [pyisy.events.websocket] Stopping websocket connection.  

Maybe it's just the ISY mysteriously rejecting the connection until it finally accepts it? As before, it eventually succeeds:

2022-02-26 11:34:07 INFO (MainThread) [pyisy.events.websocket] PyISY attempting stream reconnect in 0.01s.
2022-02-26 11:34:07 DEBUG (MainThread) [pyisy.events.websocket] Starting websocket connection.
2022-02-26 11:34:07 DEBUG (MainThread) [pyisy.events.websocket] Successfully connected to websocket.
2022-02-26 11:34:07 DEBUG (MainThread) [pyisy.events.websocket] ISY HEARTBEAT: 2022-02-26T11:34:07.411401
2022-02-26 11:34:07 DEBUG (MainThread) [pyisy] ISY Node Control Event: NodeProperty('3C E8 A8 1': control='RR', value='31', prec='0', uom='57', formatted='0.1 seconds')
2022-02-26 11:34:07 DEBUG (MainThread) [pyisy] ISY Node Control Event: NodeProperty('3C E8 A8 1': control='OL', value='255', prec='0', uom='100', formatted='100%')

And these are interspersed:

2022-02-26 11:33:42 INFO (MainThread) [pyisy.events.websocket] PyISY attempting stream reconnect in 0.01s.
2022-02-26 11:33:42 DEBUG (MainThread) [pyisy.events.websocket] Starting websocket connection.
2022-02-26 11:33:42 DEBUG (MainThread) [pyisy.events.websocket] Successfully connected to websocket.
2022-02-26 11:33:42 ERROR (MainThread) [pyisy.events.websocket] Error during receive Received frame with non-zero reserved bits
2022-02-26 11:33:42 WARNING (MainThread) [pyisy.events.websocket] Websocket disconnected unexpectedly with code: WSCloseCode.ABNORMAL_CLOSURE
2022-02-26 11:33:42 DEBUG (MainThread) [pyisy.events.websocket] Stopping websocket connection.

[shbatm]

I'm still not sure on this one and can't reproduce from my end. I agree it may be related to home-assistant/core#66003 (after the thermostat errors) but I can't see what's causing the upsets. The closest thing I could find is a closed issue from aiohttp, but that was resolved. I'll wait for bdraco to come back on #248 to see if he found anything else.

[rccoleman]

It took me a while to repro it to capture the logs above. Restarting the ISY doesn't have an effect and I haven't found a reliable trigger for it. The most interesting bit is this:

2022-02-26 11:33:42 ERROR (MainThread) [pyisy.events.websocket] Error during receive Received frame with non-zero reserved bits

but it only shows up periodically in the logs during these retries. It kinda feels like it's out of sync with the ISY somehow and it's getting bits and pieces of packets that look like garbage until it syncs up again.

[shbatm]

Potentially fixed by #248, releases V3.0.3 and V2.1.4

[shbatm]

@rccoleman are you still seeing issues using the latest version?

[rccoleman]

I am, and it's been really difficult to nail down what triggers it. For a while it seemed weirdly correlated to my reloading template entities, which didn't make any sense to me, and isn't a reliable repro method. I'll spend some time over the weekend trying to track it down.