MQTT message causes items to update twice

Hello Forum,
I am a new user here although I have been lurking these forums for a while and have been trying to learn how to use openHAB in order to implement it in my now-under-construction house.
Today I faced a strange issue where an MQTT message causes multiple updates items on that topic. I would like to confirm if this is an expected behavior or is it a bug.

The issue appears when configuring a Generic MQTT thing with multiple channels, if 1 channel is defined using wildcard (#) and others using full topic name, then any message to that topic results in updating all the linked items twice, if the message is sent to a different topic then the item with wildcard updates only once. Changing the channel from wildcard to full topic causes all the items to update only once as expected.

This behavior is confirmed using MQTT.fx and KARAF console. (see below)

  • Platform information:
    • Hardware: RPI 3 B
    • OS: openHABian v1.5
    • Java Runtime Environment: java -version (openjdk version “1.8.0_222”)
    • openHAB version: openHAB 2.5.4-1 (Release Build)
  • Issue of the topic: single MQTT message causes multiple updates of items if one of the items is subscribed using wildcard and other items are subscribed to the same topic.
  • Please post configurations (if applicable):
    *Things
    Broker
Bridge mqtt:broker:mosquitto "MQTT Broker: Mosquitto" [ host="localhost", port=1883, secure=false, clientID="openHAB2" ]

*Generic MQTT Thing

    Thing mqtt:topic:mqttTest "mqtt topic test" (mqtt:broker:mosquitto){
    Channels:
        Type string : channel1 "channel 1 test"         [ stateTopic="topic/#", transformationPattern="JSONPATH:$.data1" ]
        Type string : channel2 "channel 2 test"         [ stateTopic="topic/1", transformationPattern="JSONPATH:$.data2" ]
        Type string : channel3 "channel 3 test"         [ stateTopic="topic/1", transformationPattern="JSONPATH:$.data3" ]
        Type string : channel4 "channel 4 test"         [ stateTopic="topic/2", transformationPattern="JSONPATH:$.data2" ]
        Type string : channel5 "channel 5 test"         [ stateTopic="topic/2", transformationPattern="JSONPATH:$.data3" ]
    }

*Items

String channel1Test "item for channel 1 test" <string> { channel = "mqtt:topic:mqttTest:channel1"}
String channel2Test "item for channel 2 test" <string> { channel = "mqtt:topic:mqttTest:channel2"}
String channel3Test "item for channel 3 test" <string> { channel = "mqtt:topic:mqttTest:channel3"}
String channel4Test "item for channel 4 test" <string> { channel = "mqtt:topic:mqttTest:channel4"}
String channel5Test "item for channel 5 test" <string> { channel = "mqtt:topic:mqttTest:channel5"}

on KARAF Console

log:set INFO smarthome.event.ItemStateEvent
log:tail smarthome.event.ItemStateEvent

publishing the below JSON using MQTT.fx and monitoring on KARAF console

{"data1":"chan1test", "data2":"chan2test", "data3":"chan3test"}
  • publishing on topic/1
16:52:54.823 [INFO ] [smarthome.event.ItemStateEvent       ] - channel3Test updated to cahn3test
16:52:54.837 [INFO ] [smarthome.event.ItemStateEvent       ] - channel2Test updated to cahn2test
16:52:54.846 [INFO ] [smarthome.event.ItemStateEvent       ] - channel3Test updated to cahn3test
16:52:54.853 [INFO ] [smarthome.event.ItemStateEvent       ] - channel2Test updated to cahn2test
16:52:54.861 [INFO ] [smarthome.event.ItemStateEvent       ] - channel1Test updated to chan1test
16:52:54.868 [INFO ] [smarthome.event.ItemStateEvent       ] - channel1Test updated to chan1test
  • publishing same JSON on topic/2
16:54:08.586 [INFO ] [smarthome.event.ItemStateEvent       ] - channel5Test updated to cahn3test
16:54:08.601 [INFO ] [smarthome.event.ItemStateEvent       ] - channel5Test updated to cahn3test
16:54:08.610 [INFO ] [smarthome.event.ItemStateEvent       ] - channel4Test updated to cahn2test
16:54:08.620 [INFO ] [smarthome.event.ItemStateEvent       ] - channel4Test updated to cahn2test
16:54:08.629 [INFO ] [smarthome.event.ItemStateEvent       ] - channel1Test updated to chan1test
16:54:08.638 [INFO ] [smarthome.event.ItemStateEvent       ] - channel1Test updated to chan1test
  • publishing same JSON on topic/3
16:55:19.696 [INFO ] [smarthome.event.ItemStateEvent       ] - channel1Test updated to chan1test

As you can see, MQTT is working expected and items are receiving correct values, except that it updates each items twice (except when publishing to a topic with no other channels defined).
If I change the topic for channel1 from topic/# to topic/1 then all the item update happens only once.

The real world usage (and how I noticed it) was by testing Rhasspy voice assistant with openHAB where Rhasspy publishes the information on hermes/intent/INTENTNAME, so I would need to monitor hermes/intent/# with item IntentName to catch all the intents and a rule executing different commands based on the state of IntentName.

I would be happy to share the full real use case if needed.

Not quite sure, but aren’t first three channels all mapped to same topic?

No, first channel is mapped to all subtopics under topic/ with JSONPATH transformation to look for data1 entry,
second and third channels mapped to topic/1 with JSONPATH for data2 and data3 entries respectively.

Maybe a duplicate link or item? I would think the log would show the item but not sure about the link.

Look in /var/lib/openhab2/jsondb/org.eclipse.smarthome.core.thing.link.ItemChannelLink.json and make sure there isn’t an extra Link hanging around. Also, check for duplicate items in: /var/lib/openhab2/jsondb/org.eclipse.smarthome.core.items.Item.json

If you edit either of these files make sure to stop OH first.

Thank you for the reply, however the jsondb is empty as I believe it is used when creating items using PaperUI (above items are with files).
Links were cleared using KARAF smarthome:links clear also if it was a dead link then this behavior should not stop if changing channel1 definition from wildcard to a single topic.

Also note that removing all the channels except channel1 (wildcard) results in updating the item ONLY one time (same as in last test publishing to a topic no other channels are monitoring).

I tried to find the related commands to debug mqtt using Karaf console but did not find the correct commands.

If you’re referring to DEBUG log via karaf console try:

log:set DEBUG org.openhab.binding.mqtt

You may also want to set log to TRACE if DEBUG lacks the info needed.

I have just tested, even with level TRACE, no logs produced for org.openhab.binding.mqtt

Use bundle:list and set DEBUG to everything associated with mqtt.

Did you use MQTTfx to subscribe to those topics and check wether the double reception happens there as well? (Can’t test ATM).

1 Like

Yes, only 1 message is received on MQTT.fx.
Regarding logs of all MQTT bundles, couldnt find anything there, only logs from system startup when subscribing to the topics (log level TRACE on all MQTT related bundles).

one interesting thing is while trying to debug MQTT I also set TRACE to JSONPATH and it seems that the transformation is being applied twice (per item linked to channel) to the MQTT payload.

18:36:49.935 [DEBUG] [nternal.JSonPathTransformationService] - about to transform '{"data1":"chan1test", "data2":"cahn2test", "data3":"cahn3test"}' by the function '$.data3'
18:36:49.935 [DEBUG] [nternal.JSonPathTransformationService] - about to transform '{"data1":"chan1test", "data2":"cahn2test", "data3":"cahn3test"}' by the function '$.data3'
18:36:49.943 [DEBUG] [nternal.JSonPathTransformationService] - transformation resulted in 'cahn3test'
18:36:49.944 [DEBUG] [nternal.JSonPathTransformationService] - transformation resulted in 'cahn3test'
18:36:49.950 [DEBUG] [nternal.JSonPathTransformationService] - about to transform '{"data1":"chan1test", "data2":"cahn2test", "data3":"cahn3test"}' by the function '$.data2'
18:36:49.953 [DEBUG] [nternal.JSonPathTransformationService] - about to transform '{"data1":"chan1test", "data2":"cahn2test", "data3":"cahn3test"}' by the function '$.data2'
18:36:49.964 [DEBUG] [nternal.JSonPathTransformationService] - transformation resulted in 'cahn2test'
18:36:49.962 [DEBUG] [nternal.JSonPathTransformationService] - transformation resulted in 'cahn2test'
18:36:49.970 [DEBUG] [nternal.JSonPathTransformationService] - about to transform '{"data1":"chan1test", "data2":"cahn2test", "data3":"cahn3test"}' by the function '$.data1'
18:36:49.973 [DEBUG] [nternal.JSonPathTransformationService] - about to transform '{"data1":"chan1test", "data2":"cahn2test", "data3":"cahn3test"}' by the function '$.data1'
18:36:49.975 [DEBUG] [nternal.JSonPathTransformationService] - transformation resulted in 'chan1test'
18:36:49.985 [DEBUG] [nternal.JSonPathTransformationService] - transformation resulted in 'chan1test'

This sending the same JSON to topic/1 but sending to topic/3 or any other topic where only item subscribed is the one with wildcard shows the transformation applied only once.

18:43:33.522 [DEBUG] [nternal.JSonPathTransformationService] - about to transform '{"data1":"chan1test", "data2":"cahn2test", "data3":"cahn3test"}' by the function '$.data1'
18:43:33.526 [DEBUG] [nternal.JSonPathTransformationService] - transformation resulted in 'chan1test'

This does jog my memory, that something like this mentioned before. I cannot now find it in forum or github.

EDIT - what is the QoS involved with this message?

QoS 0
I tested also with QoS 1 (publishing side) but it seems not to make any difference, should I also change in the channel definition?

If anybody wants to test use the below configuration to confirm the behavior to know if it is a bug or not in order to know how to escalate it.
To be clear, for this use case (Rhasspy) I can probably change the way from a catch-all rule to something else (one rule per intent), but I thought if it is a bug then maybe I can help fixing it.

mqtttest.things

    Thing mqtt:topic:mqttTest "mqtt topic test" (mqtt:broker:mosquitto){
    Channels:
        Type string : channel1 "channel 1 test"         [ stateTopic="topic/#", transformationPattern="JSONPATH:$.data1" ]
        Type string : channel2 "channel 2 test"         [ stateTopic="topic/1", transformationPattern="JSONPATH:$.data2" ]
        Type string : channel3 "channel 3 test"         [ stateTopic="topic/1", transformationPattern="JSONPATH:$.data3" ]
    }

mqtttest.items

String channel1Test "item for channel 1 test" <string> { channel = "mqtt:topic:mqttTest:channel1"}
String channel2Test "item for channel 2 test" <string> { channel = "mqtt:topic:mqttTest:channel2"}
String channel3Test "item for channel 3 test" <string> { channel = "mqtt:topic:mqttTest:channel3"}

Karaf console

log:set INFO smarthome.event.ItemStateEvent
log:tail smarthome.event.ItemStateEvent

then with MQTT.fx publish a JSON to topic/1 and topic/2 for example

{"data1":"chan1test", "data2":"cahn2test", "data3":"cahn3test"}

And monitor the item update events in Karaf console, whether publishing to topic/1 results in double update and topic/2 single update or not.