[Solved] MQTT publishing duplicate messages

Add-ons Bindings
,
1

I turned on debug binding for mqtt and it shows that for certain events that the binding is publishing the same message 10-20 times to my mqtt broker. I had originally had QOS=2 but even after changing it to 0 I’m still seeing the occurrence of multiple publish events. I don’t see any errors in my regular openhab logs.

Here is the mqtt debug log example:

11-Sep-2017 12:31:10.628 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:13.856 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:13.895 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:14.033 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:14.048 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:14.131 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:14.179 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:14.271 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:14.455 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:14.503 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:14.584 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:14.632 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:15.143 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:16.353 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:16.417 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:16.580 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:16.760 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:16.817 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:18.385 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:18.473 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:18.544 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:18.618 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:18.734 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
11-Sep-2017 12:31:18.833 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight

Here is my mqtt.cfg:

mqttloc.url=tcp://localhost:1883
mqttloc.clientId=openhab
mqttloc.user=openhab
mqttloc.pwd=**********
mqttloc.qos=0
mqttloc.retain=false
mqttloc.lwt=client/openhab/status:offline:2:true

And here is the item definition:

Dimmer  Light_SF_MasterBath_NorthSink  "Masterbath North Sink Light"  <Dimmablelight>  (SF_Lights, SF_Masterbath)  ["iss:room:Master Bathroom", "iss:type:DevDimmer"]  {channel="zwave:device:c96128c0:node15:switch_dimmer",  mqtt="<[mqttloc:home/masterBathroom/masterbathNorthSinkLight/set:command:default],>[mqttloc:home/masterBathroom/masterbathNorthSinkLight:state:*:default]"}
2

So just to test to make sure this wasn’t something being triggered outside of OpenHAB, I just turned off my other software that publishes to my MQTT broker and am continuing to see random publishing of multiple messages from OpenHAB. I’ve yet to see any correlations to any other activity in my log files.

So I was able to capture a much more detailed log showing the multiple postings. Maybe someone above my paygrade can troubleshoot from this activity.

Here is the MQTT activity:

12-Sep-2017 14:34:47.213 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookWallLight
12-Sep-2017 14:34:47.302 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookWallLight
12-Sep-2017 14:34:47.441 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookWallLight
12-Sep-2017 14:34:47.646 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookWallLight
12-Sep-2017 14:34:47.795 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookWallLight
12-Sep-2017 14:34:47.946 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookWallLight
12-Sep-2017 14:34:48.037 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookWallLight
12-Sep-2017 14:34:48.106 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookWallLight
12-Sep-2017 14:34:49.574 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookMainLight
12-Sep-2017 14:34:49.633 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state OFF to home/mainFloor/mainFloorLights
12-Sep-2017 14:34:49.687 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookMainLight
12-Sep-2017 14:34:49.734 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state OFF to home/mainFloor/mainFloorLights
12-Sep-2017 14:34:49.752 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookMainLight
12-Sep-2017 14:34:49.815 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state OFF to home/mainFloor/mainFloorLights
12-Sep-2017 14:34:49.829 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookMainLight
12-Sep-2017 14:34:49.896 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state OFF to home/mainFloor/mainFloorLights
12-Sep-2017 14:34:50.040 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookMainLight
12-Sep-2017 14:34:50.077 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state OFF to home/mainFloor/mainFloorLights
12-Sep-2017 14:34:50.144 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/kitchenNook/kitchenNookMainLight
12-Sep-2017 14:34:50.179 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state OFF to home/mainFloor/mainFloorLights

And here is the corresponding OH activity showing the attempts,

https://drive.google.com/open?id=0B77VHtwPft8ebXpZSnV5a205dVE

3

@chris as per my other post, here is a multi-update from this morning:

23-Sep-2017 08:24:26.722 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathBathLight
23-Sep-2017 08:24:27.763 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathBathLight
23-Sep-2017 08:24:27.975 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathBathLight
23-Sep-2017 08:24:28.542 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathBathLight

And the associated Zwave debug log (Node 14): https://drive.google.com/open?id=0B77VHtwPft8eWHYzVVdvSUFWRWc

Let me know any other info I can provide to try to help trouble shoot. Thanks!!

4

Looks ok to me from the binding perspective - it’s only sent one message (well, two, but for different reasons) and it’s received multiple responses from the device.

image
image.png868×748 134 KB

5

Oh, so it’s an issue with the device sending back the four responses to a single status request?

Since these are Cooper devices that have the hail class would it be fine if I went to 1 poll per day on them? Or even better, is there any way of adding in a do not poll option? Or am I wasting our time worrying about this?

Thanks.

6

Yes - this might just be the network, or maybe the device. It’s not completely uncommon, and can happen more often if the device is not having the best comms with the controller since it can miss the acks… Or, it might be something else, but it’s coming from the device in any case…

Probably it’s ok.

I’ve not provided this option as I believe that it’s important to periodically poll - otherwise you can’t tell if a device has just not been used, or it’s died if it stops sending data.

IMHO - yes :wink: . I would ignore it unless it’s causing you a bit problem. If we thought it was the binding, then I would want to know why. Since it looks from this log at least that it’s the device, I would ignore this.

7

Thanks. That may make sense since the devices with the most duplicates are furthest from the controller and one of my in between nodes close to them seems to have failed.