Problems with publishMQTT after Update from OH2.4 to 2.5.0.M5

Hi,

I have a problem with MQTT Binding since i have updated from 2.4 stable to 2.5.0.M5:

Foreword:
I’m using it for communicating with my vacuum cleaner inspired by this post:

Everything worked fine on OH 2.4 stable. Now I updated to 2.5.0.M5 and the solution stopped working correctly. :frowning:

What I have:

OH 2.5.0.M5 running on a Windows machine

Things file:

Bridge mqtt:broker:roomba "Roomba" @ "Cleaner" [ clientID="MyClientId", host="192.168.178.44", port=8883, secure=true,
                                                 username="MyClientId", password="MyPassword",
                                                 certificatepin=true, publickeypin=true ]
{
  Thing topic state "Roomba state" @ "Cleaner" {
    Channels:
      Type string : wifistat "WiFi"    [ stateTopic="wifistat" ]
      Type string : shadow   "Status"  [ stateTopic="$aws/things/3162831022440790/shadow/#" ]
  }
}

Items:

String RoombaWifistatJSON "Roomba WiFi [%s]"   { channel="mqtt:topic:roomba:state:wifistat" }
String RoombaShadowJSON   "Roomba State [%s]" { channel="mqtt:topic:roomba:state:shadow" }

String RoombaBinPresent "Bin present [%s]" (G_Roomba, G_RrEvCh, G_RrEvMin, G_JdEvCh)
String RoombaBinFull    "Bin full [%s]" <cistern> (G_Roomba, G_RrEvCh, G_RrEvMin, G_JdEvCh)
Switch RoombaDocked     "Roomba docked [%s]" <switch> (G_Roomba, G_RrEvCh, G_RrEvMin, G_JdEvCh)
Switch RoombaDock       "Dock Roomba [%s]" <switch> (G_Roomba, G_RrEvCh, G_RrEvMin, G_JdEvCh)
Switch RoombaClean      "Roomba StartStop [%s]" <switch> (G_Roomba, G_RrEvCh, G_RrEvMin, G_JdEvCh)
String RoombaCleaningPhase "Roomba cleaning phase [MAP(CleaningPhase_DE.map):%s]" (G_Roomba, G_RrEvCh, G_RrEvMin, G_JdEvCh)
Dimmer RoombaBatLevel   "Roomba BatLevel [%d]" <dimmer> (G_Roomba, G_RrEvCh, G_RrEvMin, G_JdEvCh)

And in the rules file for outgoing commands

val RoombaActions = getActions("mqtt", "mqtt:broker:roomba")

// Commands: "start", "stop", "pause", "resume", "dock"
val GetCommandJSON = [ String command |
  String::format("{\"command\":\"%s\",\"time\":%d,\"initiator\":\"localApp\"}", command, now.millis / 1000)
]


rule "RoombaDockReceivedCommand"
when
  Item RoombaDock received command ON
then
  RoombaActions.publishMQTT("cmd", GetCommandJSON.apply("dock"))
end

There are also rules for incoming info, but i don’t list it here, because everything seems to be fine with that.

Now the problem:

The way from my vacuum cleaner to OpenHAB works as expected. Data (JSON String) is delivered to item RoombaShadowJSON or RoombaWifistatJSON and processed in my “incoming” rules.
But when I set an item for outgoing commands like RoombaDock it is processed in my “outgoing” rule correctly but the command publishMQTT fails.

In the logs:

2019-12-05 13:51:38.563 [WARN] [nhab.binding.mqtt.action.MQTTActions] - MQTT publish to cmd failed!

Now I have no idea what’s the cause.

Already done:

  • Restarted OH
  • Uninstalled and reinstalled MQTT Binding
  • Edited *.items, *.rules and *.things files in order to be reinitialized
  • cleared tmp and Cache Folders

Is there a way to better debug this? I set log Level to [DEBUG] for mqtt. But there is no more info in openhab.log.

M5 is a testing release. Have you tried Milestone 6? We are moving rapidly toward a stable release this month.

Oh. I thougth I’m uptodate with M5. :slightly_smiling_face:
I will update. Would be nice if that would fix it.

1 Like

I think rc1 (Release Candidate 1) is next.

If it doesn’t work, please report back ASAP, I‘ll provide further instructions for debugging.

1 Like

Updated to M6. Problem remains. :frowning:

Please turn on debug logging on the karaf console

log:set TRACE org.eclipse.smarthome.io.transport.mqtt
log:set TRACE org.openhab.binding.mqtt

and try again. You can later reset that with

log:set DEFAULT org.eclipse.smarthome.io.transport.mqtt
log:set DEFAULT org.openhab.binding.mqtt

Hi,
I switched logging to TRACE like you discribed.

The part of openhab.log:
mqtt_debug_log.txt (16.6 KB)

I started with refreshing the *.things-file so the connection to the broker was re-established.

2019-12-06 20:48:30.202 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'roomba.things'
2019-12-06 20:48:30.216 [TRACE] [.transport.mqtt.MqttBrokerConnection] - Closing the MQTT broker connection '192.168.178.44'
2019-12-06 20:48:30.230 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '192.168.178.44' with clientid 3162831022440790

The incoming data is processed correctly afterwards. Until I send a command to an item which causes a rule to

  RoombaActions.publishMQTT("cmd", GetCommandJSON.apply("dock"))

One of the last lines is

2019-12-06 20:49:09.154 [WARN ] [nhab.binding.mqtt.action.MQTTActions] - MQTT publish to cmd failed!

After that the binding seems to stop working. The Incoming data is not processed anymore and there are no more logging entries.
The broker thing still shows online in PaperUI.

To get it working again I have to refresh *.things-file.

This all worked without issues on 2.4.0.

What is before that line?

I attached the complete log file above

The lines before the failure are all related to incoming data I think.

Hi,

I seem to have a similar or related problem running OH 2.5.0-M5 docker container. Same scenario wrt Roomba vaccum robot. MQTT incoming messages stop being processed after some time.

I’ve captured the following error while tinkering with things and items trying to reestablish the connection:

2019-12-07 09:40:20.429 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'Runnable.run()' on 'org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$$Lambda$785/1515908452@6007ef60': org.openhab.binding.mqtt.generic.internal.handler.GenericMQTTThingHandler cannot be cast to org.openhab.binding.mqtt.handler.AbstractBrokerHandler
java.lang.ClassCastException: org.openhab.binding.mqtt.generic.internal.handler.GenericMQTTThingHandler cannot be cast to org.openhab.binding.mqtt.handler.AbstractBrokerHandler
        at org.openhab.binding.mqtt.internal.MqttBrokerHandlerFactory.lambda$0(MqttBrokerHandlerFactory.java:83) ~[?:?]
        at java.util.WeakHashMap.forEach(WeakHashMap.java:1025) ~[?:1.8.0_222]
        at java.util.Collections$SynchronizedMap.forEach(Collections.java:2649) ~[?:1.8.0_222]
        at org.openhab.binding.mqtt.internal.MqttBrokerHandlerFactory.removeHandler(MqttBrokerHandlerFactory.java:83) ~[?:?]
        at org.eclipse.smarthome.core.thing.binding.BaseThingHandlerFactory.unregisterHandler(BaseThingHandlerFactory.java:259) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl.lambda$5(ThingManagerImpl.java:794) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_222]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_222]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_222]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_222]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?: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]

Also I see this warnings:

2019-12-07 09:40:22.157 [WARN ] [.incoming.MqttIncomingPublishService] - No publish flow registered for MqttStatefulPublish{stateless=MqttPublish{topic=wifistat, payload=50byte, qos=AT_MOST_ONCE, retain=false}, packetIdentifier=-1, dup=false, topicAlias=0, subscriptionIdentifiers=[]}.
2019-12-07 09:40:22.181 [WARN ] [.incoming.MqttIncomingPublishService] - No publish flow registered for MqttStatefulPublish{stateless=MqttPublish{topic=$aws/things/<ClientId>/shadow/update, payload=40byte, qos=AT_MOST_ONCE, retain=false}, packetIdentifier=-1, dup=false, topicAlias=0, subscriptionIdentifiers=[]}.

Will collect more logs…

The error is unrelated and will be fixed by https://github.com/openhab/openhab2-addons/pull/6505.

I copied your rule code and testes with latest master. I can publish all day long without any error, even after a connection loss. There must be something strange with your setup.

Thank you for investing some time on this!

I tried the following:

  • Complete new installation of latest snapshot Build 1771.
  • Installed mqtt binding via PaperUI.
  • Imported my things-file, items-file and rules-file.

Result: The same as my original problem.

I even updated my Java version and deactivated my firewall. No change.

I have no idea what could be wrong and why it worked with 2.4.0 without any problems. :worried:

Plase install https://janessa.me/esh/org.openhab.binding.mqtt-debug.jar (instructions: option #2 from https://janessa.me/esh). The bundle number you are looking for is bundle:list -s | grep org.openhab.binding.mqtt (the one without further extension) and try again. It may be that you need a restart.

Hi Jan,

thanks, will give 2.5.0-RC1 a try once it becomes available.

Yet besides that error while manually triggering a reconnect, I’m facing an issue where the MQTT bridge apparently looses the connection to the broker. The bridge stays “online” and so does the MQTT client, yet no data is transmitted anymore. There is no related error message in the log, even when TRACE is enabled. I can see on the vacuum robot the connection is gone as all lights turn off on it while they stay on all the time when the connection to the MQTT bridge is established. The connection just drops after a few hours of OH being started. There is apparently no re-connect attempt by the MQTT bridge. I’m pretty sure this was working fine on 2.5.0-M4.

Thanks!

Thank you very much!
I will try it but it may take a few days. I will report!

Hello everybody,

i can confirm both bugs with current 2.5.0-M6: Bridge loose the connection to broker after couple of hours. There are no updates anymore. And try to send command leads in
[WARN] [nhab.binding.mqtt.action.MQTTActions] - MQTT publish to cmd failed!.
Additionally, binding reports
[WARN] [.incoming.MqttIncomingPublishService] - No publish flow registered for MqttStatefulPublish{stateless=MqttPublish{topic=wifistat, payload=55byte, qos=AT_MOST_ONCE, retain=false}, packetIdentifier=-1, dup=false, topicAlias=0, subscriptionIdentifiers=[]}

As far i can remember 2.5.0-M4 worked. Openhab runs on Raspberry.

Kind regards,

Alexander

Why does it lose connection? There must be something in the log. And which broker? And please use the debug-bundle.

Hi,

setup is described here. I installed debug version provided. As far more information is available, i’ll post it.

Kind regards,

Alexander

EDIT: Trying to send command leads in:

EDIT2: Some related information can be found here.