search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.86k stars 3.57k forks source link

[orbitbhyve] Potential orphaned websocket connection #14951

Open mhilbush opened 1 year ago

mhilbush commented 1 year ago

I occasionally see this in my openhab log file.

2023-05-05 07:15:18.386 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler OrbitBhyveBridgeHandler tried updating the thing status although the handler was already disposed.
2023-05-05 07:15:18.387 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler OrbitBhyveBridgeHandler of thing orbitbhyve:sprinkler:bhyve:62991f4e4f0c66c76b45e00c tried updating channel mode although th
e handler was already disposed.
2023-05-05 07:15:18.387 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler OrbitBhyveBridgeHandler of thing orbitbhyve:sprinkler:bhyve:62991f4e4f0c66c76b45e00c tried updating channel control although
 the handler was already disposed.
2023-05-05 07:15:18.387 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler OrbitBhyveBridgeHandler tried updating the thing status although the handler was already disposed.

It seems to coincide with a condition where the bridge and sprinkler things go OFFLINE, then come back ONLINE. This OFFLINE/ONLINE condition occurs pretty regularly (multiple times a day) when the binding detects that the cloud service closes the websocket connection. However, the above condition occurs much more rarely than that.

When it happens, I also see this behavior in the binding DEBUG log.

2023-05-05 07:14:50.875 [DEBUG] [rbitbhyve.internal.handler.OrbitBhyveBridgeHandler] - Sending ping
2023-05-05 07:14:52.663 [DEBUG] [rbitbhyve.internal.handler.OrbitBhyveBridgeHandler] - Sending ping
2023-05-05 07:14:52.741 [DEBUG] [tbhyve.internal.handler.OrbitBhyveSprinklerHandler] - Next start time: 2106-02-07T02:28:15-04:00
2023-05-05 07:15:18.386 [DEBUG] [rbitbhyve.internal.handler.OrbitBhyveBridgeHandler] - Updating mode to: auto
2023-05-05 07:15:18.387 [DEBUG] [rbitbhyve.internal.handler.OrbitBhyveBridgeHandler] - Updating mode to: auto
2023-05-05 07:15:18.387 [DEBUG] [rbitbhyve.internal.handler.OrbitBhyveBridgeHandler] - Received event: device_idle
2023-05-05 07:15:18.459 [DEBUG] [tbhyve.internal.handler.OrbitBhyveSprinklerHandler] - Next start time: 2106-02-07T02:28:15-04:00
2023-05-05 07:15:18.459 [DEBUG] [rbitbhyve.internal.handler.OrbitBhyveBridgeHandler] - Received event: device_idle
2023-05-05 07:15:20.956 [DEBUG] [rbitbhyve.internal.handler.OrbitBhyveBridgeHandler] - Sending ping
2023-05-05 07:15:22.741 [DEBUG] [rbitbhyve.internal.handler.OrbitBhyveBridgeHandler] - Sending ping
2023-05-05 07:15:22.823 [DEBUG] [tbhyve.internal.handler.OrbitBhyveSprinklerHandler] - Next start time: 2106-02-07T02:28:15-04:00

This suggests to me that there are 2 websocket connections open to the OrbigBhyve cloud service. However, it's still unclear the condition(s) under which a 2nd connection is orphaned. If I can pinpoint the cause, I'l submit a fix.

lolodomo commented 1 year ago

Could be a resource not properly released when the thing handler is disposed.

mhilbush commented 1 year ago

Thanks. That was one of my first thoughts, too. But doing a single binding restart didn't cause a problem.

However, when I did several restarts quickly, I was able to create a similar situation with multiple ping jobs running (and open websocket connections), but it wasn't exactly the same behavior as what I showed above.