openhab / openhab-addons

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

[mqtt] Cannot connect to TheThingsNetwork because of HomeAssistant discovery #8056

Closed TheNetStriker closed 3 years ago

TheNetStriker commented 4 years ago

Expected Behavior

OpenHab can directly connect to TheThingsNetwork via MQTT.

Current Behavior

OpenHab cannot connect to the ThingsNetwork via MQTT because the client seems to get kicked from the server because of the HomeAssistant discovery. There is also a thead in the community forum about this problem: https://community.openhab.org/t/connecting-openhab-thethingsnetwork/96936/9

Possible Solution

Add an option to the MQTT broker to disable HomeAssistant discovery.

Steps to Reproduce (for Bugs)

Create a test application in TheThingsNetwork and try to connect to it: https://www.thethingsnetwork.org/docs/applications/mqtt/

Your Environment

OpenHabian with OpenHab 2.5.6.

Logs

2020-07-02 23:38:38.921 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'eu.thethings.network' with clientid f5a7fe71-2a0e-8fd3-9a23-0ee2e254f857
2020-07-02 23:38:39.077 [WARN ] [.transport.mqtt.MqttBrokerConnection] - Failed subscribing to topic homeassistant/#
java.util.concurrent.CompletionException: com.hivemq.client.mqtt.mqtt3.exceptions.Mqtt3SubAckException: SUBACK contains only Error Codes
        at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:593) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[?:1.8.0_222]
        at com.hivemq.client.internal.mqtt.mqtt3.Mqtt3AsyncClientView.lambda$handleSubAck$0(Mqtt3AsyncClientView.java:64) ~[?:?]
        at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760) [?:1.8.0_222]
        at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) [?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) [?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) [?:1.8.0_222]
        at com.hivemq.client.rx.FlowableWithSingle$SingleFutureSubscriber.onError(FlowableWithSingle.java:395) [bundleFile:?]
        at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber.onError(FlowableWithSingleCombine.java:178) [bundleFile:?]
        at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.checkTerminated(FlowableObserveOn.java:197) [bundleFile:?]
        at io.reactivex.internal.operators.flowable.FlowableObserveOn$ObserveOnConditionalSubscriber.runAsync(FlowableObserveOn.java:641) [bundleFile:?]
        at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:176) [bundleFile:?]
        at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) [bundleFile:?]
        at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
Caused by: com.hivemq.client.mqtt.mqtt3.exceptions.Mqtt3SubAckException: SUBACK contains only Error Codes
2020-07-02 23:50:30.266 [WARN ] [.transport.mqtt.MqttBrokerConnection] - Failed subscribing to topic sample_application/devices/sample_device/up
java.util.concurrent.CompletionException: com.hivemq.client.mqtt.exceptions.MqttSessionExpiredException: Session expired as connection was closed.
        at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:593) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[?:1.8.0_222]
        at com.hivemq.client.internal.mqtt.mqtt3.Mqtt3AsyncClientView.lambda$handleSubAck$0(Mqtt3AsyncClientView.java:64) ~[?:?]
        at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760) [?:1.8.0_222]
        at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) [?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) [?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) [?:1.8.0_222]
        at com.hivemq.client.rx.FlowableWithSingle$SingleFutureSubscriber.onError(FlowableWithSingle.java:395) [bundleFile:?]
        at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber.onError(FlowableWithSingleCombine.java:178) [bundleFile:?]
        at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.checkTerminated(FlowableObserveOn.java:197) [bundleFile:?]
        at io.reactivex.internal.operators.flowable.FlowableObserveOn$ObserveOnConditionalSubscriber.runAsync(FlowableObserveOn.java:641) [bundleFile:?]
        at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:176) [bundleFile:?]
        at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) [bundleFile:?]
        at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
Caused by: com.hivemq.client.mqtt.exceptions.MqttSessionExpiredException: Session expired as connection was closed.
Caused by: com.hivemq.client.mqtt.mqtt3.exceptions.Mqtt3DisconnectException: Client sent DISCONNECT
No3x commented 4 years ago

I do have the same issue and (almost same) stacktrace trying to connect to the mqtt.thingspeak.com broker with 2.5.6-2 (Release Build).

Log ```bash Starting MQTT broker connection to 'mqtt.thingspeak.com' with clientid dcf02d02-5044-4ece-b5c1-XXXXXXXX 2020-07-04 13:03:28.688 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@c5bb96 to discovery topic homeassistant/# on broker mqtt:broker:newmqtt 2020-07-04 13:03:28.710 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@418b2f to discovery topic +/+/$homie on broker mqtt:broker:newmqtt ==> /var/log/openhab2/events.log <== 2020-07-04 13:03:28.726 [hingStatusInfoChangedEvent] - 'mqtt:broker:newmqtt:newmqttitem' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to UNINITIALIZED (HANDLER_CONFIGURATION_PENDING) ==> /var/log/openhab2/openhab.log <== 2020-07-04 13:03:29.125 [TRACE] [.transport.mqtt.MqttBrokerConnection] - subscribeRaw message consumer for topic 'homeassistant/#' from broker 'mqtt.thingspeak.com' 2020-07-04 13:03:29.130 [TRACE] [ternal.client.MqttAsyncClientWrapper] - Trying to subscribe org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@13127cf to topic homeassistant/# 2020-07-04 13:03:29.146 [TRACE] [.transport.mqtt.MqttBrokerConnection] - subscribeRaw message consumer for topic '+/+/$homie' from broker 'mqtt.thingspeak.com' 2020-07-04 13:03:29.158 [TRACE] [ternal.client.MqttAsyncClientWrapper] - Trying to subscribe org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@13127cf to topic +/+/$homie 2020-07-04 13:03:29.178 [TRACE] [ansport.mqtt.internal.ClientCallback] - Received message on topic 'homeassistant/sensor/d0bae463fd06/power/state' : {"power":"20.4"} 2020-07-04 13:03:29.180 [TRACE] [ansport.mqtt.internal.ClientCallback] - No topic match for 'homeassistant/sensor/d0bae463fd06/power/state' using regex channels/916500/subscribe/fields/field1 2020-07-04 13:03:29.289 [WARN ] [.transport.mqtt.MqttBrokerConnection] - Failed subscribing to topic homeassistant/# java.util.concurrent.CompletionException: com.hivemq.client.mqtt.mqtt3.exceptions.Mqtt3SubAckException: SUBACK contains only Error Codes at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[?:1.8.0_252] at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[?:1.8.0_252] at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:607) ~[?:1.8.0_252] at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) ~[?:1.8.0_252] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_252] at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) ~[?:1.8.0_252] at com.hivemq.client.internal.mqtt.mqtt3.Mqtt3AsyncClientView.lambda$handleSubAck$0(Mqtt3AsyncClientView.java:64) ~[?:?] at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:774) [?:1.8.0_252] at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:750) [?:1.8.0_252] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) [?:1.8.0_252] at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) [?:1.8.0_252] at com.hivemq.client.rx.FlowableWithSingle$SingleFutureSubscriber.onError(FlowableWithSingle.java:395) [bundleFile:?] at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber.onError(FlowableWithSingleCombine.java:178) [bundleFile:?] at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.checkTerminated(FlowableObserveOn.java:197) [bundleFile:?] at io.reactivex.internal.operators.flowable.FlowableObserveOn$ObserveOnConditionalSubscriber.runAsync(FlowableObserveOn.java:641) [bundleFile:?] at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:176) [bundleFile:?] at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) [bundleFile:?] at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) [bundleFile:?] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_252] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_252] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252] Caused by: com.hivemq.client.mqtt.mqtt3.exceptions.Mqtt3SubAckException: SUBACK contains only Error Codes 2020-07-04 13:03:29.306 [WARN ] [.transport.mqtt.MqttBrokerConnection] - Failed subscribing to topic +/+/$homie java.util.concurrent.CompletionException: com.hivemq.client.mqtt.mqtt3.exceptions.Mqtt3SubAckException: SUBACK contains only Error Codes at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[?:1.8.0_252] at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[?:1.8.0_252] at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:607) ~[?:1.8.0_252] at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) ~[?:1.8.0_252] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_252] at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) ~[?:1.8.0_252] at com.hivemq.client.internal.mqtt.mqtt3.Mqtt3AsyncClientView.lambda$handleSubAck$0(Mqtt3AsyncClientView.java:64) ~[?:?] at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:774) [?:1.8.0_252] at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:750) [?:1.8.0_252] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) [?:1.8.0_252] at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) [?:1.8.0_252] at com.hivemq.client.rx.FlowableWithSingle$SingleFutureSubscriber.onError(FlowableWithSingle.java:395) [bundleFile:?] at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber.onError(FlowableWithSingleCombine.java:178) [bundleFile:?] at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.checkTerminated(FlowableObserveOn.java:197) [bundleFile:?] at io.reactivex.internal.operators.flowable.FlowableObserveOn$ObserveOnConditionalSubscriber.runAsync(FlowableObserveOn.java:641) [bundleFile:?] at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:176) [bundleFile:?] at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) [bundleFile:?] at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) [bundleFile:?] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_252] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_252] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252] Caused by: com.hivemq.client.mqtt.mqtt3.exceptions.Mqtt3SubAckException: SUBACK contains only Error Codes ```

I did not know that the issue might be related to homie auto-discovery but rather an issue with the specific server/broker but your explanation makes sense to me.

No3x commented 3 years ago

Tested #8077 contained in 2.5.8-SNAPSHOT by replacing release version of the addon with current snaphot-build of the plugin. And setting enableDiscovery=false on my broker of course. Seems to work now! No issues when subscribing and the values are fetched now.