openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.86k stars 3.58k forks source link

[mqtt] Generic MQTT thing channel trigger stops calling rule after postupdate #5913

Closed bccrew closed 5 years ago

bccrew commented 5 years ago

System: Ubuntu 18.04 with Openhabian repo Openhab: Zulu Java + latest OH snapshot openHAB 2.5.0 Build #1656 MQTT binding

Hi all,

I have a pulse counter running on ESPEeasy which sends payload '1' to a local mosquitto broker running on the same system as OH. I have configured a broker connection and a generic MQTT thing which checks a certain topic for input.

As my gasmeter is sending a pulse for every 0.01m³ of gas, I have written a rule that adds 0.01 to the counted value. Every night I'm resetting the counter to 0 with another rule:

rule "countgasmeterpulses" when Time is midnight then postUpdate(GasMeter_Daily,0) end

After this reset, the following rule doesn't work anymore:

rule "countgasmeterpulses" when Channel "mqtt:systemBroker:LocalMosquitto:WM" triggered 1 then GasMeter_Daily.postUpdate((GasMeter_Daily.state as Number) + 0.01) end

Only when I change something to the rule (for example the description of the rule or whatever text) and the model is refreshed by the system, the rule takes effect. Testing with sending payload 1 via mqtt-spy to the mosquitto broker.

`==> /var/log/openhab2/events.log <== 12:58:00.023 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.09 to 0 13:01:59.732 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered 1 13:02:04.381 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered 1 13:02:05.021 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered 1 13:02:05.508 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered 1

==> /var/log/openhab2/openhab.log <== 13:02:30.436 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'countgasmeterpulses.rules'

==> /var/log/openhab2/events.log <== 13:02:33.741 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered 1 13:02:33.760 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0 to 0.01 13:02:34.796 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered 1 13:02:34.801 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.01 to 0.02`

bccrew commented 5 years ago

If I change the rule to just "triggered", meaning that I can send whatever I want, the rule also doesn't work.

rule "countgasmeterpulses" when Channel "mqtt:systemBroker:LocalMosquitto:WM" triggered

after the refresh of the rule model, it keeps working and counting:

[vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered testpayload [vent.ItemStateChangedEvent] - WaterMeter_Daily changed from 0 to 0.01 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered testpayload [vent.ItemStateChangedEvent] - WaterMeter_Daily changed from 0.01 to 0.02 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered testpayload [vent.ItemStateChangedEvent] - WaterMeter_Daily changed from 0.02 to 0.03 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered testpayload [vent.ItemStateChangedEvent] - WaterMeter_Daily changed from 0.03 to 0.04

But when I reset the Number with postupdate to 0 again, the rule stops working

[vent.ItemStateChangedEvent] - WaterMeter_Daily changed from 0.04 to 0 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered testpayload [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered testpayload [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered testpayload [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:WM triggered testpayload

Rossko57 commented 5 years ago

At the least, you should add a logInfo or similar to the beginning of the rule in order to establish if the issue is about rule triggering or postUpdate failing. Maybe that could log out the current state of the Item. e.g. what happens if GasMeter_Daily has state NULL

bccrew commented 5 years ago

When using a loginfo like this:

    logInfo("countgasmeterpulses.rules", "this is a log before postupdate")
    GasMeter_Daily.postUpdate((GasMeter_Daily.state as Number) + 0.01)

Nothing is logged...

The channel triggers, but nothing happens.

[vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:GasMeterBroker triggered 1 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:GasMeterBroker triggered 1 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:GasMeterBroker triggered 1

When I use a time cron to reset the status to NULL the channel still triggers but nothing happens.

rule "countgasmeterpulses" when Time cron "0 49 19 1/1 ? " then postUpdate(WaterMeter_Daily,"NULL") end

2019-08-13 19:49:00.024 [vent.ItemStateChangedEvent] - WaterMeter_Daily changed from 1 to NULL 2019-08-13 19:49:10.089 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:GasMeterBroker triggered 1 2019-08-13 19:49:11.265 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:LocalMosquitto:GasMeterBroker triggered 1

Also, if you add a connection to an MQTT broker for example mosquitto (add thing manually through Paper UI) you can set a payload condition on the Publish Trigger. If you enter value 1 or even leave it empty, the channel is always triggered anyhow, seems like another bug?

Rossko57 commented 5 years ago

You might usefully look into openhab.log

bccrew commented 5 years ago

Ofcourse... My logging is working for other rules.. :)

rule "countgasmeterpulsesreset.rules" when Time cron "0 00 20 1/1 ? " then logInfo("countgasmeterpulsesreset.rules", "this is a log entry of type INFO") postUpdate(GasMeter_Daily,"NULL") end

2019-08-13 20:00:00.028 [INFO ] [cript.countgasmeterpulsesreset.rules] - this is a log entry of type INFO

2019-08-13 20:00:00.031 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 1 to NULL

bccrew commented 5 years ago

Something is seriously wrong. I have this Gasmeter thing with a Number Value channel. When I fill in a Delta value of 0,01 and I keep sending payload INCREASE via mqtt-spy to my broker, the count is wrong.

2019-08-13 23:02:25.242 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 7.0 to 0.01
2019-08-13 23:02:26.330 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.01 to 8
2019-08-13 23:02:26.331 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 8.0 to 0.02
2019-08-13 23:02:27.074 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.02 to 9
2019-08-13 23:02:27.077 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 9.0 to 0.03
2019-08-13 23:02:27.649 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.03 to 10
2019-08-13 23:02:27.651 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 10.0 to 0.04
2019-08-13 23:02:28.299 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.04 to 11
2019-08-13 23:02:28.300 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 11.0 to 0.05
2019-08-13 23:02:28.931 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.05 to 12
2019-08-13 23:02:28.932 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 12.0 to 0.06
2019-08-13 23:02:29.530 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.06 to 13
2019-08-13 23:02:29.530 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 13.0 to 0.07
2019-08-13 23:02:37.907 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.07 to 14
2019-08-13 23:02:37.911 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 14.0 to 0.08
2019-08-13 23:02:38.690 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.08 to 15
2019-08-13 23:02:38.691 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 15.0 to 0.09
2019-08-13 23:02:39.323 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.09 to 16
2019-08-13 23:02:39.324 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 16.0 to 0.10
2019-08-13 23:02:43.747 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 0.10 to 17
2019-08-13 23:02:43.747 [vent.ItemStateChangedEvent] - GasMeter_Daily changed from 17.0 to 0.11
davidgraeff commented 5 years ago

You should know that the mqtt binding keeps its own states to implement increase/decrease. And postUpdate only updates item states, not the internal binding state.

The way how the binding is used here will not work unfortunately. One way would be to post to the mqtt topic instead to update the bindings internal state.

Rossko57 commented 5 years ago

I wonder if the postCommand channel option should be used here, as that is essentially what the user is trying to do. Rules are easily triggered from command.

J-N-K commented 5 years ago

I woudl vote for won't fix.