I have a bunch of items using the MQTT binding that look like this:
temps.items: Number Pond_Temp_deep "Pond Temp (deep) [%.0f]" <temperature> (Outdoor, Temperature) {mqtt="<[mqtt87:/env/temp/pondbottom:state:JS(mqtt_var.js)]"}
This has been working well, but once in a while OpenHab would lose touch with the MQTT hub, so I decided to create an item that would match any sensor MQTT message so I could easily detect if updates stopped coming through:
ops.items: String ENV_any "Env message [%s]" {mqtt="<[mqtt87:/env/#:state:JS(isy_message.js)]"}
(there’s more, but this is enough to show this problem)
I soon noticed that both ENV_any and Pond_Temp_deep, and other items with topics that start with /env/, were showing two updates every time a matching message came through:
2016-10-24 22:12:55.824 [INFO ] [runtime.busevents ] - Pond_Temp_deep state updated to 52 2016-10-24 22:12:55.827 [INFO ] [runtime.busevents ] - ENV_any state updated to 52 2016-10-24 22:12:55.830 [INFO ] [runtime.busevents ] - Pond_Temp_deep state updated to 52 2016-10-24 22:12:55.834 [INFO ] [runtime.busevents ] - ENV_any state updated to 52
Notice how all 4 of these updates come within a few ms of each other.
Samples for a few other topics show the same pattern:
2016-10-24 22:12:55.874 [INFO ] [runtime.busevents ] - Basement_Temp state updated to 64 2016-10-24 22:12:55.877 [INFO ] [runtime.busevents ] - ENV_any state updated to 64 2016-10-24 22:12:55.879 [INFO ] [runtime.busevents ] - Basement_Temp state updated to 64 2016-10-24 22:12:55.883 [INFO ] [runtime.busevents ] - ENV_any state updated to 64 2016-10-24 22:12:55.927 [INFO ] [runtime.busevents ] - RainStorm state updated to 0.480 2016-10-24 22:12:55.930 [INFO ] [runtime.busevents ] - ENV_any state updated to 0.480 2016-10-24 22:12:55.934 [INFO ] [runtime.busevents ] - RainStorm state updated to 0.480 2016-10-24 22:12:55.937 [INFO ] [runtime.busevents ] - ENV_any state updated to 0.480
I commented out the ENV_any item in ops.items, and the problem went away (along with my sentinal for last MQTT message):
2016-10-24 22:12:59.482 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'ops.items' 2016-10-24 22:13:30.213 [INFO ] [runtime.busevents ] - ISY_any state updated to 179 2016-10-24 22:13:30.214 [INFO ] [runtime.busevents ] - MQTT_Update state updated to 2016-10-24T22:13:30 2016-10-24 22:13:55.778 [INFO ] [runtime.busevents ] - Outdoor_Temp state updated to 42 2016-10-24 22:13:55.781 [INFO ] [runtime.busevents ] - Davis_Temp_Update state updated to 2016-10-24T22:13:55 2016-10-24 22:13:55.819 [INFO ] [runtime.busevents ] - Pond_Temp state updated to 53 2016-10-24 22:13:55.838 [INFO ] [runtime.busevents ] - Pond_Temp_deep state updated to 53 2016-10-24 22:13:55.898 [INFO ] [runtime.busevents ] - Basement_Temp state updated to 64 2016-10-24 22:13:55.952 [INFO ] [runtime.busevents ] - RainStorm state updated to 0.480 2016-10-24 22:14:20.210 [INFO ] [runtime.busevents ] - ISY_any state updated to 180
I have a similar setup for topics that start with /isy – and get the same behavior for items that start with that string. On that topic, however, there are some messages that don’t have associated Items – and those show a single update to ISY_any (as seen in the above log)
Other than causing more log entries, and more work on updates to ENV_any and ISY_any (which cause a timer to be cleared and then restarted), this isn’t causing me any pain, but it would be nice to not have this extra noise. For now, I’ve left it active on /ISY, which has much less traffic than /ENV (which has about 5-10 messages/minute), but does have one message that typically arrives every minute, giving me the signal that MQTT is OK.
I have verified with mosquitto_sub that the messages are only arriving once on the MQTT bus.