search

openhab / openhab-addons

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

[netatmo] Strange startup behavior and status transitions #12809

Closed jlaur closed 2 years ago

jlaur commented 2 years ago

When starting the binding, there are too many status transitions and possibly also requests. It seems that an additional cycle is triggered.

Here is a distilled log for one weather station with one additional indoor module:

2022-05-25 17:08:28.355 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - Initializing Netatmo API bridge handler.
2022-05-25 17:08:28.367 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - Connecting to Netatmo API.
2022-05-25 17:08:28.371 [TRACE] [mo.internal.handler.ApiBridgeHandler] - executeUri POST  https://api.netatmo.com/oauth2/token
2022-05-25 17:08:28.482 [DEBUG] [tatmo.internal.handler.DeviceHandler] - Initializing handler for bridge netatmo:weather-station:home:main
2022-05-25 17:08:28.616 [DEBUG] [tatmo.internal.handler.ModuleHandler] - Initializing handler for thing netatmo:indoor:home:main:indoor
2022-05-25 17:08:28.500 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:account:home' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2022-05-25 17:08:28.551 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:account:home' changed from INITIALIZING to UNKNOWN
2022-05-25 17:08:28.607 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:indoor:home:main:indoor' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-05-25 17:08:28.638 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:weather-station:home:main' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2022-05-25 17:08:28.680 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:indoor:home:main:indoor' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-05-25 17:08:28.703 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:indoor:home:main:indoor' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2022-05-25 17:08:31.749 [TRACE] [mo.internal.handler.ApiBridgeHandler] - executeUri returned : code [200 OK] body [this station]
2022-05-25 17:08:28.795 [DEBUG] [tatmo.internal.handler.DeviceHandler] - bridgeStatusChanged for bridge netatmo:weather-station:home:main to ONLINE
2022-05-25 17:08:28.795 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:account:home' changed from UNKNOWN to ONLINE
2022-05-25 17:08:29.118 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:account:home' changed from ONLINE to UNKNOWN
2022-05-25 17:08:28.803 [DEBUG] [tatmo.internal.handler.ModuleHandler] - bridgeStatusChanged for thing netatmo:indoor:home:main:indoor to UNKNOWN
2022-05-25 17:08:31.807 [DEBUG] [tatmo.internal.handler.ModuleHandler] - bridgeStatusChanged for thing netatmo:indoor:home:main:indoor to ONLINE
2022-05-25 17:08:28.810 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:weather-station:home:main' changed from OFFLINE (BRIDGE_OFFLINE) to UNKNOWN
2022-05-25 17:08:29.112 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - Shutting down Netatmo API bridge handler.
2022-05-25 17:08:29.115 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - Initializing Netatmo API bridge handler.
2022-05-25 17:08:29.118 [DEBUG] [tatmo.internal.handler.DeviceHandler] - bridgeStatusChanged for bridge netatmo:weather-station:home:indoor to UNKNOWN
2022-05-25 17:08:29.118 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - Connecting to Netatmo API.
2022-05-25 17:08:29.121 [TRACE] [mo.internal.handler.ApiBridgeHandler] - executeUri POST  https://api.netatmo.com/oauth2/token
2022-05-25 17:08:29.150 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:weather-station:home:main' changed from UNKNOWN to OFFLINE (BRIDGE_OFFLINE)
2022-05-25 17:08:29.260 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:account:home' changed from UNKNOWN to ONLINE
2022-05-25 17:08:29.279 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:weather-station:home:main' changed from OFFLINE (BRIDGE_OFFLINE) to UNKNOWN
2022-05-25 17:08:31.892 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:indoor:home:main:indoor' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2022-05-25 17:08:32.088 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:indoor:home:main:indoor' changed from ONLINE to UNKNOWN
2022-05-25 17:08:42.268 [TRACE] [mo.internal.handler.ApiBridgeHandler] - executeUri returned : code [200 OK] body [this station]
2022-05-25 17:08:42.333 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:indoor:home:main:indoor' changed from UNKNOWN to ONLINE

The two requests with ~11 seconds between them are identical and receives the same response payloads. The line "Shutting down Netatmo API bridge handler." is from ApiBridgeHandler.dispose(), which could indicate a configuration update: https://github.com/openhab/openhab-core/blob/cabb3f73150d13f44d647f46af8362e396684b92/bundles/org.openhab.core.thing/src/main/java/org/openhab/core/thing/binding/BaseThingHandler.java#L105-L107

Expected Behavior

One initial request and one set of status transitions towards ONLINE.

Current Behavior

Too many status updates:

2022-05-25 21:06:38.064 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:indoor:home:main:indoor' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2022-05-25 21:07:19.322 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:indoor:home:main:indoor' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2022-05-25 21:07:19.550 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:indoor:home:main:indoor' changed from ONLINE to UNKNOWN
2022-05-25 21:07:28.565 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'netatmo:indoor:home:main:indoor' changed from UNKNOWN to ONLINE

Possible Solution

Steps to Reproduce

ssh openhab@localhost -p8101 'bundle:restart org.openhab.binding.netatmo'

refreshToken is stored in a .things file.

Your Environment

openHAB 3.3.0M5, binding compiled from main branch May 25th 2022.

lolodomo commented 2 years ago

If the thing is disposed/initialized, this is very probably because the thing configuration was updated and this should happen only if the the "refreshToken" parameter is not set in your thing. https://github.com/openhab/openhab-addons/blob/main/bundles/org.openhab.binding.netatmo/src/main/java/org/openhab/binding/netatmo/internal/handler/ApiBridgeHandler.java#L130 So yes, this will happen the first when you authenticate.

jlaur commented 2 years ago

If the thing is disposed/initialized, this is very probably because the thing configuration was updated and this should happen only if the the "refreshToken" parameter is not set in your thing.

The problem is that in fact it is stored in my thing - in a file (shortened):

Bridge netatmo:account:home "Netatmo API" [ clientId="xxx", clientSecret="yyy", refreshToken="zzz" ] {
        Bridge weather-station main [ id="xx:xx:xx:xx:xx:xx" ] {
                indoor indoor [ id="yy:yy:yy:yy:yy:yy" ]
        }
}
lolodomo commented 2 years ago

I have setup it like you.

If I restart the binding, I cannot reproduce your problem with "Shutting down Netatmo API bridge handler".

But for my outside module and rain gauge module, I can see your pattern OFFLINE/BRIDGE_OFFLINE => ONLINE => UNKNOWN => ONLINE.

lolodomo commented 2 years ago

Ok, bridgeStatusChanged is correctly overriden. So that means there is a call to setThingStatus with ONLINE for these things run too early (before or during bridgeStatusChanged is called), maybe here: https://github.com/openhab/openhab-addons/blob/main/bundles/org.openhab.binding.netatmo/src/main/java/org/openhab/binding/netatmo/internal/handler/CommonInterface.java#L148

lolodomo commented 2 years ago

Verified, this is the only place that sets the thing status to ONLINE. So the only explanation I can find is that setNewData is called for this thing before the call to bridgeStatusChanged => commonInitialize. Probably by the bridge handler of this thing (weather station in our case).

Probably something done in this method (class RestCapability<T extends RestManager>):

    @Override
    protected void updateNADevice(Device newData) {
        super.updateNADevice(newData);
        NAObjectMap<Module> modules = newData.getModules();
        handler.getActiveChildren().forEach(child -> {
            Module childData = modules.get(child.getId());
            if (childData != null) {
                child.setNewData(childData);
            }
        });
    }
lolodomo commented 2 years ago

Maybe if getActiveChildren() filters things that are in status OFFLINE/BRIDGE_OFFLINE, it could resolve the problem.