[SOLVED] Item changed rule not firing

I have created a Thing with an MQTT binding which appears to work correctly - it subscribes to a topic published by a temperature sensor (every 5 seconds). I can see events corresponding to these messages in the event log:

2018-12-29 23:17:19.651 [vent.ItemStateChangedEvent] - mqtt_topic_aab8b45e_Studytemp changed from 14.31 to 14.38
2018-12-29 23:17:25.473 [vent.ItemStateChangedEvent] - mqtt_topic_aab8b45e_Studytemp changed from 14.38 to 14.31
2018-12-29 23:17:31.299 [vent.ItemStateChangedEvent] - mqtt_topic_aab8b45e_Studytemp changed from 14.31 to 14.38
2018-12-29 23:18:47.024 [vent.ItemStateChangedEvent] - mqtt_topic_aab8b45e_Studytemp changed from 14.38 to 14.31
2018-12-29 23:18:52.851 [vent.ItemStateChangedEvent] - mqtt_topic_aab8b45e_Studytemp changed from 14.31 to 14.38

I have created a rule to trigger on the change, but it never does:

rule "radiator on"
when item mqtt_topic_aab8b45e_Studytemp changed
then
sendCommand(mqtt_topic_ce4868c7_Sonoff1Switch,OFF)
end

What am I doing wrong? I know the rule would not do anything very useful. I am just taking baby steps trying to understand how rules work.

openHAB 2.4.0-1 (Release Build) openhabian on Pi 3

Have you checked the openhab.log file? it seems you have a syntax error in your rule, it should be
when Item mqtt_topic_aab8b45e_Studytemp changed
Note the capital in Item.
Furthermore, I would suggest to use sendCommand as a method like so:
mqtt_topic_ce4868c7_Sonoff1Switch.sendCommand(OFF)

Thanks very much. I do still have an issue - the rule fires twice (or am I mis-reading the log?):

2018-12-30 00:28:41.069 [vent.ItemStateChangedEvent] - mqtt_topic_aab8b45e_Studytemp changed from 14.31 to 14.38
2018-12-30 00:28:41.090 [ome.event.ItemCommandEvent] - Item 'mqtt_topic_ce4868c7_Sonoff1Switch' received command ON
2018-12-30 00:28:41.099 [nt.ItemStatePredictedEvent] - mqtt_topic_ce4868c7_Sonoff1Switch predicted to become ON
2018-12-30 00:28:41.995 [ome.event.ItemCommandEvent] - Item 'mqtt_topic_ce4868c7_Sonoff1Switch' received command ON
2018-12-30 00:28:42.004 [nt.ItemStatePredictedEvent] - mqtt_topic_ce4868c7_Sonoff1Switch predicted to become ON

To check that, you might want to add a line to log what is happening. Before the line with sendCommand, put something like:

logInfo("radiator.test", "Studytemp changed to " + mqtt_topic_aab8b45e_Studytemp.state)

These logs should appear in openhab.log, so then you can check if the rule is triggered twice or not. Based on that, you can look further.

OK the rule is only firing once for each temp change - but why are there double sets of events in the log?

2018-12-30 00:54:13.094 [INFO ] [smarthome.model.script.radiator.test] - Studytemp changed to 14.31
==> /var/log/openhab2/events.log <==
2018-12-30 00:54:13.110 [ome.event.ItemCommandEvent] - Item 'mqtt_topic_ce4868c7_Sonoff1Switch' received command ON
2018-12-30 00:54:13.120 [nt.ItemStatePredictedEvent] - mqtt_topic_ce4868c7_Sonoff1Switch predicted to become ON
2018-12-30 00:54:14.066 [ome.event.ItemCommandEvent] - Item 'mqtt_topic_ce4868c7_Sonoff1Switch' received command ON
2018-12-30 00:54:14.071 [nt.ItemStatePredictedEvent] - mqtt_topic_ce4868c7_Sonoff1Switch predicted to become ON
2018-12-30 00:54:18.903 [vent.ItemStateChangedEvent] - mqtt_topic_aab8b45e_Studytemp changed from 14.31 to 14.38

The rule you showed us sends an OFF, maybe post what you have now?

This is the current version of the rule:

rule "radiator on"
when Item mqtt_topic_aab8b45e_Studytemp changed
then
logInfo("radiator.test", "Studytemp changed to " + mqtt_topic_aab8b45e_Studytemp.state)
mqtt_topic_ce4868c7_Sonoff1Switch.sendCommand(ON)
end

Any other rules related to mqtt_topic_ce4868c7_Sonoff1Switch?

No other rules at all.

Then it might be related to how the MQTT binding works, but I have no knowledge on that whatsoever, I’m afraid.
Might be worth a separate topic specifically related to this issue. :wink:

A useful step would be to comment out the sendCommand line in this rule, and see if commands still appear in the log. I’m doubtful it’s a genuine doubling.

Yep. That would be it - it was due to the MQTT state topic in the configuration of the channel for the MQTT thing. When the MQTT command is sent to the device it obligingly responds with its status which is what led to my confusion.

Many thanks for your help with this and all the best for 2019.

Correct - not genuine doubling. Thanks for your help.