OH3: MQTT somtimes issues after starting

Add-ons Bindings
,
1

Sometimes after a restart of Openhab 3.0 the MQTT binding is not working properly. (Some topics do not get subscribed and some MQTT Things do not start) I found this error in the log after starting Openhab when this is happening:

2021-01-05 23:34:39.028 [WARN ] [org.openhab.core.internal.common.WrappedScheduledExecutorService                                    ] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
        at org.openhab.binding.mqtt.generic.MqttChannelTypeProvider.derive(MqttChannelTypeProvider.java:132) ~[?:?]
        at org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery.publishResults(HomeAssistantDiscovery.java:197) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        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:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]

Also on one MQTT Thing I got the following error message in Main UI:

java.lang.ClassNotFoundException: org.slf4j.LoggerFactory

Disabling and re-enabling the Thing does not solve this error, only a complete restart of Openhab helps solving the problem. (Somtimes I even have to restart twice) I also get the following error about my ESPHome Thing often after a restart:

2021-01-05 23:35:02.848 [WARN ] [org.openhab.core.internal.common.WrappedScheduledExecutorService                                    ] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: Duplicate channels mqtt:homeassistant_500291e9f78b:4ce1d806:500291e9f78b:ESPsensorccs811_5Ftotal_5Fvolatile_5Forganic_5Fcompound#sensor
        at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:152) ~[?:?]
        at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:144) ~[?:?]
        at org.openhab.core.thing.util.ThingHelper.addChannelsToThing(ThingHelper.java:105) ~[?:?]
        at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:292) ~[?:?]
        at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:1) ~[?:?]
        at org.openhab.binding.mqtt.generic.tools.DelayedBatchProcessing.run(DelayedBatchProcessing.java:110) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        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:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]

Is this a known problem or should I report this on Github?

2

Yes.

Make sure you provide your configuration information too, such as what sort of Things these are (Generic, Homie, Home Assistant) and how you configured them (UI, files), and what the configurations look like.

3

Ok, i have a lot of MQTT things in my configuration and the one that makes the most problems also has a lot of channels, so the configuration is pretty big to post on GitHub. Also I guess I should create two issues. One for the startup problem and one for the warning regarding the ESPHome thing. Or is it better to report both in the same issue?

4

One issue per issue!

And donā€™t worry about the size of your configuration: post it all (relevant) in between code fences and the developers can decide what is and isnā€™t useful!

5

Ok thanks for the hint. Iā€™ve created the following two issues for this:

Iā€™ve just had the problem again after a restart of OpenHab and I hope that this can be fixed.

6

Same problem here, ESPHome with 10 dallas sensors.
I can see in Grafana that sometimes some sensor values are not persisted (most of the time the first sensor is missing). MQTT messages are sent correctly.

Hope to see a solution to this soon.

7

Iā€™m still having this issue with Openhab 3.0.2. Iā€™ve now just added trace logging for ā€œorg.openhab.core.io.transport.mqttā€ and found something interesting. It seems that when OpenHab is starting the mqtt binding is subscribing multiple times to the same topics. It also tries to unsubscribe topics. I guess this could be the cause for my problems because the first time it subscribes everything seem to work fine. Then on the second or third time I get error messages. Iā€™ve uploaded a full trace log to the issue on GitHub:

@rlkoshak @Kai Is there someone I could tag to take a look at this?

8

The issue was filed. When a developer volunteers to try to fix this bug Iā€™m sure it will get fixed.

Though note that there are no changes to the binding between OH 3.0.0 and 3.0.1 and 3.0.2. It might already be fixed in OH 3.1.0 M3. Fixes like these are not typically backported to already released versions.

9

Thanks for the quick reply. Iā€™ve just setup an Eclipse development environment and added all my MQTT Things just like in my production Openhab on a Raspberry Pi 4. I also found topics in the log that are subscribed multiple times, but there is no error like on my Raspberry Pi.

Maybe the problem was already fixed in the main version. I hope that 3.1 will be released soon that I can test this.

10

Possibly related, also deals with failed unsubscribes

11

Thanks for the link.

Iā€™ve analyzed the code and the logs an I currently suspect that the availability topic of my devices could cause this problem. I have various homie and homeassistant things which all provide an availability topic to report if they are online or offline. This also changes the thing status in OpenHab. Using the even log I found out that some of the items do change multiple times between online, unknown and offline during the Openhab startup and this seems to trigger an event that unsubscribes and subscribes all topics again.

On my development computer this happens without any major problems, but on my Rasperry Pi I get error messages from the mqtt client after a few re-subscriptions. I guess this could be because the Rasperry Pi is much slower than my development computer or because of some other limitations.

Is there maybe a thread limit or other optimization setting that I could change to solve this problem?

12

My Pull Request 10562 relates to the MQTT Discovery Service, so I suspect that it might not directly be related to the issue described here by the OP. But it might nevertheless be logically related:

The bugs that I found in the discovery classes are due to an imbalance between the number of ā€œunsubscribesā€ and ā€œsubscribesā€ for a particular listener/topic. The PR addresses that issue in the discovery class by a) not making subsequent subscribes if already subscribed, and b) not making unsubscribes if not already subscribed.

So (this is just a guess for the time being) it may be that the author of the binding made the same logical mistake in the startup/shutdown code in the classes for actually instantiated Things, as he did in the classes for discovered but not yet instantiated (Inbox) Things.

=> I will have a look at the code, and report backā€¦

13

Hmm. It seems that my fix is in MqttBrokerHandlerFactory which is used in the creation of both actually instantiated Things, and also discovered but not yet instantiated (Inbox) Things.

So it may be that my fix might already also (unintentionally) solve the OPā€™s issues. But as I donā€™t have the OPā€™s issues on my system I canā€™t actually replicate whether it solves the problem or not.

=> Let me dig into it a bit furtherā€¦

14

Iā€™ve just compiled the org.openhab.binding.mqtt-3.1.0-SNAPSHOT.jar from your ā€œmqtt-unsubscribeā€ branch myself and installed it on my Raspberry Pi. Sadly I still get the same errors when OpenHab starts up. This does not seem to fix my issue.

15

It is not as easy as simply adding my jar to your addons folder; see this [mqtt] Topics not subscribed after OpenHab 3.0 restart on generic MQTT Thing Ā· Issue #9715 Ā· openhab/openhab-addons Ā· GitHub

PS that link also includes a link to the respective dependency filesā€¦

16

Thanks for the info. I just saw the changes in org.openhab.binding.mqtt.

I guess I just found one issue. Iā€™ve configured my Sonoff switches to include a led channel that does not seem to be recognized by OpenHab correctly. I now removed the led channel and I did not have an NoSuchElementException so far.

I also removed the logger in various js transformation scripts and this seems to have fixed the org.slf4j.LoggerFactory exceptions at startup.

I still have the ā€œDuplicate channelsā€ error in the log, but it seems to work better now. Time will tell if this fixes all my problems after some more OpenHab restarts.

17

I think my PR might reduce the quantity of subscribe/unsubscribe messages that you reported in your Trace log. (Please let me know once the modified version has been released). But I donā€™t know if that was in any way the cause of your other reported problems. So I donā€™t know if it might contribute to fixing themā€¦

18

@AndrewFG Iā€™ve installed OpenHab 3.1 a few weeks ago and this seems to have fixed the problem with MQTT topics that are not registred. Iā€™ve just closed the GitHub issue. But the ā€œDuplicate channelsā€ errors at startup still exist.

1 Like
19

My Pull Request is still active, and I suppose it might fix your issueā€¦