[mqtt] Availability Topics are not subscribed to on Restart

[albrechtf]

Expected Behavior

When configuring an Availability Topic for a Generic MQTT Thing and e.g. unplugging that thing, I expect openHAB to report this Thing as "OFFLINE" even after a restart of openHAB.

Current Behavior

With openHAB 3.0 (and also with previous versions), the availability topics are not correctly subscribed to, so that my device is reported as ONLINE although it is not available.

I traced this down to a potential "race condition", combined with, ahem, not ideal design in classes AbstractMQTTThingHandler and GenericMQTTThingHandler. When starting up in normal speed, the following things happen (among other, non-MQTT related things), in this order:

• Configuration for the MQTT Thing and Availability Topic is loaded (in GenericMQTTThingHandler.initialize()), and Availability Topic ChannelState is prepared (in AbstractMQTTThingHandler.addAvailabilityTopic()). As no MQTT connection is yet available, nothing else happens. The ChannelStates would be started by AbstractMQTTThingHandler.bridgeStatusChanged() as soon as connection is available.
• The MQTT Bridge starts up.
• The MQTT Bridge reports "OFFLINE" immediately (as connection is not yet established).
• This invokes AbstractMQTTThingHandler.bridgeStatusChanged(), which calls stop(), which removes all ChannelStates for the Availability Topics!
• The MQTT Bridge reports "ONLINE" as soon as connection is established.
• This invokes AbstractMQTTThingHandler.bridgeStatusChanged(), which tries to start the ChannelStates of the Availability Topics, but the Map is now empty...

Note that this bug in principle also applies when the Bridge itself REALLY turns OFFLINE, then ONLINE later. Afterwards, no (valid) Availability info would be present for Generic MQTT Things.

Here is the output of some log entries I temporarily added to the code, to prove this OFFLINE-ONLINE order on startup:

13:52:20.889 [OH-safeCall-1] WARN  o.o.b.m.g.AbstractMQTTThingHandler:235 - Bridge found, status info is OFFLINE
13:52:20.945 [-thingManager-4] WARN  o.o.b.m.g.AbstractMQTTThingHandler:175 - Bridge is now ONLINE

Possible Solution

There are at least two possible fixes for this:

• Just re-load configuration in GenericMQTTThingHandler.start(). This is not completely clean, as it makes many assumptions about the concrete implementation in AbstractMQTTThingHandler, but I already tried this solution, and it worked for me. There are some corner cases where a failure in subscribing to the availability topics may not be reported correctly.
• Clean up all the logic and the split between GenericMQTTThingHandler and AbstractMQTTThingHandler. Logic should be symmetrical (creation and removal of availability topic in same class), and currently, it is highly assymetrical. Also, all the explicit calls of stop(), along with the implicit calls from the framework, look very unclean. This would be a rather huge rework of both classes - nevertheless, may be worth the effort.

Note that there are no Unit Tests for Availability Topics at all yet.

Steps to Reproduce (for Bugs)

Race-condition variant:

• Configure openHAB with at least one configured Generic MQTT Thing with Availability Topic (LWT)
• Stop openHAB
• Disconnect the physical Thing (e.g. smart socket) from power
• Startup openHAB
• Check Web UI - Thing will be reported ONLINE.

Slow-mo variant:

• Configure openHAB with at least one configured Generic MQTT Thing with Availability Topic (LWT)
• Stop MQTT Broker (e.g. Mosquitto), wait for Log entry to state MQTT Client disonnect
• Start MQTT Broker
• Disconnect the physical Thing (e.g. smart socket) from power
• Check Web UI - Thing will be reported ONLINE.

Your Environment

• Version used: 3.0.0 Release Build and latest GitHub Master (d6364ac for MQTT Generic)
• Environment name and version: Chrome 87.0.4280.141; Eclipse 2020-12
• Operating System and version: Ubuntu Linux 20.04