[ecovacs] Robot not updated after some time

mueller-ma commented 9 months ago

Expected Behavior

As long as the things for the API account and the robot (DEEBOT OZMO 900 Series) are online, sending a command should work.

Current Behavior

After some days the robot cannot be controlled via openHAB anymore and passive data isn't updated anymore (e.g. current cleaning time). Both the account and the bot are still online in openHAB and in the official Ecovacs app.

In the log I can see the following lines:

10:31:08.835 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel total-stats#total-cleaned-area although the handler was already disposed.
10:31:08.837 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel total-stats#total-cleaning-time although the handler was already disposed.
10:31:08.839 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel total-stats#total-clean-runs although the handler was already disposed.
10:31:08.941 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel settings#continuous-cleaning although the handler was already disposed.
10:31:09.045 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel last-clean#last-clean-start although the handler was already disposed.
10:31:09.046 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel last-clean#last-clean-duration although the handler was already disposed.
10:31:09.050 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel last-clean#last-clean-area although the handler was already disposed.
10:31:10.492 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel settings#suction-power although the handler was already disposed.
10:31:10.578 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel settings#water-amount although the handler was already disposed.
10:31:10.683 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel consumables#side-brush-lifetime although the handler was already disposed.
10:31:10.780 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel consumables#dust-filter-lifetime although the handler was already disposed.
10:31:10.887 [WARN ] [b.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler of thing ecovacs:vacuum:2b4b2f4b73:E0001206219602620054 tried updating channel consumables#main-brush-lifetime although the handler was already disposed.

Possible Solution

Steps to Reproduce (for Bugs)

Wait for a few days

Context

Your Environment

Version used: (e.g., openHAB and add-on versions) Docker container openhab/openhab:4.0.4
Operating System and version (desktop or mobile, Windows 10, Raspbian Buster, ...): Raspbian Bullseye

mueller-ma commented 9 months ago

A manual disable and enable of the bot thing fixes the issue for now until it breaks again in a few days.

maniac103 commented 9 months ago

Is there anything in the log before the 'Handler already disposed' lines? Since the handler doesn't dispose itself, I assume something must have happened to make the framework dispose of it - a crash or something. Is there any sign in the log of something like that happening?

mueller-ma commented 9 months ago

I see several [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EcovacsVacuumHandler tried updating the thing status although the handler was already disposed., but nothing else ecovacs related. For what tags should I look?

maniac103 commented 9 months ago

Not sure ;-) Anything that might be indicative of potential crashes / uncaught exceptions.

Maybe enable DEBUG for org.openhab.core.thing to find the exact moment of disposal. For that, especially ThingManagerImpl log lines right before the failure would be interesting.

maniac103 commented 9 months ago

Probably could additionally enable DEBUG for org.openhab.binding.ecovacs and see if there's anything right before the failure.

mueller-ma commented 9 months ago

I enabled debug logging and will wait until the next time the issue occurs.

maniac103 commented 8 months ago

@mueller-ma Any news - did the issue reoccur already?

mueller-ma commented 8 months ago

Not yet. I'll reopen this issue when it happens again.

maniac103 commented 8 months ago

You can also keep it open ... my intent in the question was just whether there's something to look into before 4.1 release ;-)

mueller-ma commented 8 months ago

Issue appeared again and I got this exception:

[DEBUG] [internal.handler.EcovacsVacuumHandler] - E0001206219602620054: Failed communicating to device, reconnecting
org.openhab.binding.ecovacs.internal.api.EcovacsApiException: java.util.concurrent.ExecutionException: java.util.concurrent.RejectedExecutionException: HttpClient@270fb9bd{STOPPED} is stopped
        at org.openhab.binding.ecovacs.internal.api.impl.EcovacsApiImpl.executeRequest(EcovacsApiImpl.java:391) ~[bundleFile:?]
        at org.openhab.binding.ecovacs.internal.api.impl.EcovacsApiImpl.sendIotCommand(EcovacsApiImpl.java:289) ~[bundleFile:?]
        at org.openhab.binding.ecovacs.internal.api.impl.EcovacsIotMqDevice.sendCommand(EcovacsIotMqDevice.java:97) ~[bundleFile:?]
        at org.openhab.binding.ecovacs.internal.api.impl.EcovacsIotMqDevice.connect(EcovacsIotMqDevice.java:123) ~[bundleFile:?]
        at org.openhab.binding.ecovacs.internal.handler.EcovacsVacuumHandler.lambda$14(EcovacsVacuumHandler.java:561) ~[bundleFile:?]
        at org.openhab.binding.ecovacs.internal.handler.EcovacsVacuumHandler.doWithDevice(EcovacsVacuumHandler.java:798) ~[bundleFile:?]
        at org.openhab.binding.ecovacs.internal.handler.EcovacsVacuumHandler.connectToDevice(EcovacsVacuumHandler.java:560) ~[bundleFile:?]
        at org.openhab.binding.ecovacs.internal.api.util.SchedulerTask.run(SchedulerTask.java:95) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
        at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.util.concurrent.ExecutionException: java.util.concurrent.RejectedExecutionException: HttpClient@270fb9bd{STOPPED} is stopped
        at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[bundleFile:9.4.52.v20230823]
        at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[bundleFile:9.4.52.v20230823]
        at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:732) ~[bundleFile:9.4.52.v20230823]
        at org.openhab.binding.ecovacs.internal.api.impl.EcovacsApiImpl.executeRequest(EcovacsApiImpl.java:385) ~[bundleFile:?]
        ... 13 more
Caused by: java.util.concurrent.RejectedExecutionException: HttpClient@270fb9bd{STOPPED} is stopped
        at org.eclipse.jetty.client.HttpDestination.send(HttpDestination.java:355) ~[bundleFile:9.4.52.v20230823]
        at org.eclipse.jetty.client.HttpDestination.send(HttpDestination.java:323) ~[bundleFile:9.4.52.v20230823]
        at org.eclipse.jetty.client.HttpClient.send(HttpClient.java:627) ~[bundleFile:9.4.52.v20230823]
        at org.eclipse.jetty.client.HttpRequest.sendAsync(HttpRequest.java:780) ~[bundleFile:9.4.52.v20230823]
        at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:767) ~[bundleFile:9.4.52.v20230823]
        at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:728) ~[bundleFile:9.4.52.v20230823]
        at org.openhab.binding.ecovacs.internal.api.impl.EcovacsApiImpl.executeRequest(EcovacsApiImpl.java:385) ~[bundleFile:?]
        ... 13 more

maniac103 commented 8 months ago

Hmm, the binding fetches the HttpClientFactory via injection and uses it to fetch the common HTTP client, which it then passes it to the EcovacsApiHandler (here), which in turn passes it to the created API instances (here), which then use it for communication. In your case, that client obviously is stopped. I see two possible causes for this:

Some other binding fetches that common HTTP client instance and (wrongly) stops it. That would be a bug in that other binding, but it's a bit hard to debug which binding might be the culprit. Do you use any 3rd party binding?
The HttpClient instance isn't meant to be cached, but meant to be re-fetched from the factory everytime it's used. Really unsure whether that's the case though, especially given I have never seen such behavior in my environment.

@lolodomo @jlaur @J-N-K Do you have any suggestions on how to debug this, and/or a definitive answer on the second bullet point? Is there any case where the common HTTP client is expected to be stopped during normal operation?

mueller-ma commented 8 months ago

The only addon that I use which isn't from this repo is https://github.com/ConnectorIO/connectorio-addons/tree/master/bundles/org.connectorio.addons.ui.iconify.

lsiepel commented 1 month ago

The HttpClient instance isn't meant to be cached, but meant to be re-fetched from the factory everytime it's used. Really unsure whether that's the case though, especially given I have never seen such behavior in my environment.

not sure if that is true. Many bindings cache the http client. Cached or not it should not be stopped.

@mueller-ma can you confirm this issue still exist in 4.2.1 ?

mueller-ma commented 4 weeks ago

I'm on 4.2.1 and only have official addons now. I had a rule for several months that disabled the ecovacs thing and enabled it a few seconds later. That was a good workaround, but now I disabled it to see if the issue appears again.

mueller-ma commented 2 weeks ago

Robot went offline with the state:

Status: OFFLINE
COMMUNICATION_ERROR 
Failed to parse response '{"ret":"fail","errno":3,"error":{"error":"check token error","es":{"action":"checkToken","error":{"errno":3000,"error":"TokenExpiredError","es":{"action":"jwt.verify","error":{"name":"TokenExpiredError","message":"jwt expired","expiredAt":"2024-08-20T17:00:34.000Z"}}},"debug":{"token":"<redacted>"}}}}' as data class PortalIotCommandXmlResponse

maniac103 commented 2 weeks ago

Thanks, I'll check this.

maniac103 commented 2 weeks ago

@mueller-ma Test binding built off #17333 (rename to .jar)

Please give it a try and see whether token refresh now works correctly.

mueller-ma commented 2 weeks ago

Where exactly do I need to place the jar?

openhab / openhab-addons