Issue of the topic:
Hi there i have sometimes a problem with a item that recieves sometimes fast updates through MQTT and
only the last change is seen by the rule.
The item is a general recieved MQTT message from a 433Mhz to MQTT Gateway. I have several Sensors in and outside the house which send their payload via 433Mhz messages to this Gateway and the Gateway sends the MQTT messages to the Broker on which Openhab also listen.
Items configuration related to the issue
Number MQTT_Trigger_Dummy "[%.1f]" {mqtt="<[openhabian:home/433toMQTT:state:default]", expire="60m, 999999"}
Rules code related to the issue
import java.util.concurrent.locks.ReentrantLock
var long changedItemDummy
var Number mqtt_calc_dummy
val ReentrantLock lock = new ReentrantLock()
rule "MQTT_Transform"
when
Item MQTT_Trigger_Dummy changed
then
if(!lock.isLocked){
lock.lock()
try {
if (MQTT_Trigger_Dummy.state < 999900) { // Value is not error
if ((MQTT_Trigger_Dummy.state >= 110000) && (MQTT_Trigger_Dummy.state <= 119999)) {
// a humidity value from sensor 1 identified
mqtt_calc_dummy = MQTT_Trigger_Dummy.state
//logInfo("Bath", "raw value: " + mqtt_calc_dummy)
mqtt_calc_dummy = mqtt_calc_dummy - 110000
//logInfo("Bath", "value minus 110000: " + mqtt_calc_dummy)
mqtt_calc_dummy = mqtt_calc_dummy / 10
// having the calculation in one line magical doesn't work
logInfo("Bath", "Humidity calculated value: " + mqtt_calc_dummy)
if (mqtt_calc_dummy >= 0) { // if value < 0 something fishy
FF_Bath_Humidity.postUpdate(mqtt_calc_dummy)
}
lock.unlock();
return;
}
// Some more if's that check for certain values
// after that the error handling code
} else {
logInfo("Sensor", "Sensor send error code " + MQTT_Trigger_Dummy.state)
if (MQTT_Trigger_Dummy.state == 999901) {
logInfo("Sensor", "Bath: reading DHT22 failed")
}
lock.unlock();
return;
}
} finally {
lock.unlock()
}
}
end
If logs where generated please post these here using code fences:
2018-05-13 18:06:35.177 [vent.ItemStateChangedEvent] - MQTT_Trigger_Dummy changed from 999901 to 155548
2018-05-13 18:06:36.886 [vent.ItemStateChangedEvent] - MQTT_Trigger_Dummy changed from 155548 to 110800
2018-05-13 18:06:37.890 [vent.ItemStateChangedEvent] - MQTT_Trigger_Dummy changed from 110800 to 130611
Now my big question is:
Is this behaviour the issue with the java ram cleanup, which i read in some other posts?
Or could i do something to get it working?
Strange side note:
If the sensor could not be read correct it resends the values after one minute. This than seems to work, sometimes.
Any help or inside would be great.
If you have any questions, feel free to ask
you may add another logInfo (maybe just putting out the raw value) to actually make sure if your rules triggers or not; you did not post all code, but it is easy with a lot of if statements to miss some ranges of numbers
you did not state whether or not you receive any error messages
you can add another statement to get a logInfo if your rule cannot get a lock fast enough: here an example how I use it:
import java.util.concurrent.locks.ReentrantLock;
import java.util.concurrent.TimeUnit;
var ReentrantLock lock = new ReentrantLock()
rule "VoiceCMD"
when
// trigger condition
then
// logInfo("Notifications","Notifications rule got triggered")
var gotLock = lock.tryLock(1000, TimeUnit.MILLISECONDS)
try {
if (gotLock) {
// do stuff
}
else logInfo("VoiceCMD", "re-entry lock activated")
}
catch(Exception e){
logError("VoiceCMD", "error in VoiceCMD: " + e)
lock.unlock
}
finally {
if(gotLock){
lock.unlock()
}
}
end
A couple of remarks, I had issues with getting a lock in another rule and the extended version of lock.tryLock gives the system some more time to catch up. But notice the logInfo statement towards the end that indicates if the rule latched already a lock and the system tried to activate it a second time. The only time I have this happening is when I use a group as rule trigger, as per design, OH tries then to trigger the rule as many times as there are members to the group.
the 1s interval is only sometimes a cause of the problem, so it seems. Often the 1s time gap between the change if the items is not a problem at all. But if the rule problem happens, it is in a 1s time interval, or lets say nearly 1s.
regarding not posting all the code, this is not a real problem, i did it mainly for readability of the code for other people.
The code covers all possible sensor boards with all sensors (at least one sensor per board with a maximum of 3 sensors per board).
As far as i could see in the log files the code really covers all values which are legal to be received.
sorry i forgot to state this: No, i did not receive any error messages. If i have the effect i get three times the Item.state of the last change.
It only happens rarely, but it happens.
i will try the log info variant to see if my rule couldnāt get the lock fast enough. Thank you for this info!
Greetings
Marc
Edit:
here is a event log with the added info if the rule is entered at all:
Just as another thought: you may want to check all your rules for use of long (>100ms) thread:sleep statements or other reasons for your rules to run a long time. OH2 only runs a few rules in parallel, the thread pool assigned is very small (5?). If the system is out of threads no more rules will run.
This is not how I think a lock should be used.
A lock should stop, the thread till the resource is free again and then continue. See this post for example.
At the beginning of your rule you test the lock and skip if it is locked, but then you loose the call, so when the calculation is still ongoing you loose the next value.
Secondly I donāt see a reason why you need a lock at all. There is no shared resource or anything else which obviously needs to be locked.
I agree with a lot of what has already been said. You are throwing out events because you donāt do anything if the lock is locked. And even if you were using the lock, it would only exacerbate the problem because when you call MQTT_Trigger_Dummy.state, you get the current value of the Item in the Item registry. If you lock the Rule and the messages are coming in fast then the later runs of the Rule will run using the most recent value the Item has received. So the first thing to do is to absolutely eliminate the lock.
Add some logInfos so you can figure out how often the Rule is triggering.
1s should not be a problem. That is plenty of time to run a Rule like this.
Elaborate on this a bit. Letās say you get the value 1, 2, and 3 one second apart. The Rule triggers three times with the value 1 or triggers three times with the value 3?
What are the QOS settings for the sensor publishing the data? Again, this shouldnāt be a problem with 1s times but if it is 0 then MQTT makes a best try to deliver the message but if the messages are coming in really fast the broker can drop the older messages.
Thank you for your opinions and insides.
I added the whole lock part because the rule was executed multiple times before finishing.
As a example:
I got three values for the MQTT_Dummy in a fast order, i saw three times the starting of the rule but it took āto longā and never finished the first run.
But i will definitly try to deactivate the lock again and see what happens.
Regarding the elaborate 1, 2, 3 the rule triggers and i see three times the value 3, which would correspond to your response.
Regarding the question of the QOS, it is set to 0, but i think that this is here no problem, as the state change in the Item is seen in the Events.log.
Edit:
Log after remove of the complete lock part in my rule:
So the first value here is ignored again. The first value is the voltage value of the sensor (155521 transforms to 5521mV) and only the second state change of MQTT_Dummy is read (110504 transform to a humidity of 50.4%).
And shortly after the above log this log:
2018-05-14 21:10:22.075 [vent.ItemStateChangedEvent] - MQTT_Trigger_Dummy changed from 155521 to 110517
==> /var/log/openhab2/openhab.log <==
2018-05-14 21:10:22.090 [INFO ] [eclipse.smarthome.model.script.Rules] - MQTT_Transform entered
2018-05-14 21:10:22.128 [INFO ] [.eclipse.smarthome.model.script.Bath] - Humidity calculated value: 51.70000000
==> /var/log/openhab2/events.log <==
2018-05-14 21:10:22.151 [vent.ItemStateChangedEvent] - FF_Bath_Humidity changed from 50.40000000 to 51.70000000
2018-05-14 21:10:22.174 [vent.ItemStateChangedEvent] - FF_Bath_Dht_Update changed from 2018-05-14T21:10:20.779+0200 to 2018-05-14T21:10:22.162+0200
2018-05-14 21:10:23.280 [vent.ItemStateChangedEvent] - MQTT_Trigger_Dummy changed from 110517 to 130627
==> /var/log/openhab2/openhab.log <==
2018-05-14 21:10:23.283 [INFO ] [eclipse.smarthome.model.script.Rules] - MQTT_Transform entered
2018-05-14 21:10:23.309 [INFO ] [.eclipse.smarthome.model.script.Bath] - Temperature calculated value: 22.70000000
==> /var/log/openhab2/events.log <==
2018-05-14 21:10:23.325 [vent.ItemStateChangedEvent] - FF_Bath_Temperature_dht changed from 22.80000000 to 22.70000000
So one time it does not work and another time it works. If you look at the time difference between the state change for the MQTT_Trigger_Dummy:
Does not work: (20:59:12.770 - 20:59:11.375 = 1.395)
Does work: (21:10:23.280 - 21:10:22.075 = 1.205)
So my first conclusion: It is not the time between the state changes!
Then either there is a command in your rule that is taking longer than expected to complete or the events are coming in much faster than one per second.
What is it in your rule that is taking a long time to complete. As I read the Rule it shouldnāt be taking longer than a dozen milliseconds to complete. You should never have a case where more than one instance of it is running at the same time for events that take place over a second apart.
Looking at the time stamps here is what Iām willing to bet money is happening.
You have some Thread::sleeps or calls to actions that take a long time to complete (executeCommandLine, sendHttp*Request, etc).
The Rules Engine only gives you 5 execution threads. This means only 5 rules can run at the same time. When you have Rules that take a long time to complete you have a high likelihood that you run out of execution threads. When that happens no new Rule can run until one of these running Rules exits.
So Iām going to guess that you are running out of Rules threads which is delaying the time when your Rules can execute in response to the change. By the time the Rule does execute, the MQTT_Trigger_Dummy has already changed state so the Rule ends up running twice with the same value.
MQTT_Trigger_Dummy changes to 155548
MQTT_Trigger_Dummy changes to 110806
More than a second later the Rule triggers in response to event 1. But the Item has already changed state to 110806 so that is what the Rule runs with.
The Rule triggers again in response to event 2 and processes with 110806.
So iām back after a day,
i checked my whole rules:
not a single delay
one cron entry (checks every hour if one of the sensor updates is older then one hour, if so send telegram message with the sensor not sending info)
And also sometimes i see very fast MQTT Updates like these:
2018-05-15 12:52:01.760 [vent.ItemStateChangedEvent] - MQTT_Trigger_Dummy changed from 130617 to 155521
2018-05-15 12:52:01.809 [vent.ItemStateChangedEvent] - MQTT_Trigger_Dummy changed from 155521 to 110459
2018-05-15 12:52:01.827 [vent.ItemStateChangedEvent] - MQTT_Trigger_Dummy changed from 110459 to 130618
Without the lock these lead to changes during the exection of the rule, in the above example -13000.0 Degrees. Sadly after the check if the value is in legal range g. But i can secure the code a little bit more.
Like reading the state of the item in the beginning of the rule into a extra variable and later only work with the variable and not with the item.state. This should make the code a little bit safer against state changes during rule exection.
Also I will look into the gateway and see if i can limit the mqtt message send per time to something about 1 message per second.
A little bit. But if you use received command for your trigger then the receivedCommand implicit variable will be populated. Does it really matter if older values are skipped for something like humidity values? The value is unlikly to be that different if the messages are arriving fast enough to be causing this problem.
The sensors sends their value between 10 minutes and 60 minutes. (Depends where they are and what they measure). So if in one intervall 2 of lets say 3 values are missed and the next send is 60 minutes away then it indeed does matter if the values are ālostā.
As a explanation: All the sensors send their data via 433Mhz and i use a NodeMcu ESP8266 with OpenMQTTGateway to recieve all 433Mhz messages and transfer these to a MQTT Messages.
But if you receive three values within a few seconds, those previous two will only be in the system for a few seconds before they get replaced by the last value anyway. Unless you have code you havenāt posted, it is only processing data for the FF_Bath_Humidity. So I just donāt see the impact if your FF_Bath_Humidity loses a few values that would only have been set to the FF_Bath_Humidity Item for a few seconds at the most anyway.
FF_Bath_Humidity will always be set to the most recent value received in all cases. So it doesnāt matter if it will be 60 minutes until the next update.
As i posted in the very first posting, the rule above is not complete,
i shortened it to show a example (here humidity).
You couldnāt know there are a lot more Items and values analysed:
Some example from the easiest sensor board in the bath:
It sends three values: Voltage of battery, humidity and temperature.
This looks like the following for the MQTT_Trigger_Dummy.state
155521: 15 says first sensorboard, voltage with 5521mV
110459: 11 says first sensorboard, humidity with 45.9%
130618: 13 says first sensorboard, temperature with 21,8 Degree
And so on for different sensorboards. Additional to above we have x2nnnn in co2 ppm, x4nnnn rain in mliter, x6nnnn pressure in hPa, x7nnnn water level in percent and x8nnnn light level in lumen.
Hopefully this explains why missing a MQTT_Trigger_Dummy with the rule is bad, it is a lost sensor value.
I totally understand, that it looked from the code given in my first post like it only misses a value for humidity, but sadly this is not the case.
If after our discussions the result is, that the rule system is not fitting for a transformation like this, then i have to go the other way: i have to change for every sensor the gateway. So to say make the gateway intelligent and the not need the rules. With the downside to having to go to the gateway everytime something on the sensors have to be changed.
Or you can change your MQTT config on the Items to use command instead of state (assuming that you are not already) and change the Rule trigger to received command and use the receivedCommand implicit variable instead of MQTT_Trigger_Dummy.state.
receivedCommand doesnāt depend on the Itemās actual state so even if the Item changes state while the Rule is processing receivedCommand wonāt change on you.
Maybe it is jsut the way you try to process this values which makes it slow, you could try somthing different like in this post.
So my idea would be to distribute the received value to an other item and then you can process this items with a other rule. You can then put all e.g. all voltages into one group and have a rule triggered by this group to process the value.
Not tested but something like this.
rule "433MHz RX"
when
Item MQTT_Trigger_Dummy changed
then
// keep upper values, remove lower part only
switch Integer.parseInt(triggeringItem.state) & 0xfffC000 {
...
// only send lower values to item to update.
case 150000: Sensor_volt_1.postUpdate(triggeringItem.state & 0x3fff )
case 130000: Sensor_temp_1.postUpdate(triggeringItem.state & 0x3fff )
case 110000: Sensor_hum_1.postUpdate(triggeringItem.state & 0x3fff )
...
}
end
One thing to consider is interference on the radio channel. Iāve had to ditch most of my 433MHz stuff due to local radio noise from things such as weather stations. I used to have 2 RFM69 devices that broadcast every 5 seconds and IIRC only about 65% of the messages got through which was a worry as I was using them to load shed to protect the mains fuse.
I moved to Adafruit Huzzah ESP8266 development boards running ESPEasy connected ito the serial port of the Arduinos in the power monitors and itās no longer a problem. From memory there was no collision detection on 433MHz, so if any transmissions overlapped nothing got through
Hi rikoshak,
i tried to switch to to the command instead of the state.
Or to be more precise i added a second item and added a second rule, so that i could easier test the behavior.
But i did not get the item to recieve a single command.
I mainly found informations how to configure a item as a switch, so i tried the following as the item config:
Number MQTT_Trigger_Dummy2 "[%.1f]" {mqtt="<[openhabian:home/433toMQTT:command:*:default]"}
So apperently this is wrong, any idea how to correct it or if you have a example which is not a switch command (on off) i would be thankfull.
For the rule is started like this:
rule "MQTT_Transform2"
when
Item MQTT_Trigger_Dummy2 received command
then
logInfo("MQTT", "Transform 2 entered")
mqtt_safe_state2 = MQTT_Trigger_Dummy2.receivedCommand.toLong
if (mqtt_safe_state2 < 999900) { // Value is not error
@kevin So far iām lucky: Here i only see 1 or 2 values not from my sensors a week from a different source. So iām very confident to say that there are nearly no interferences.
Okay the first part seems to work,
the rule gets triggered, but the MyItem2.recievedcommand is not working.
The logfile says āreceivedCommandā is not a member of āorg.eclipse.smarthome.core.library.items.NumberItemā
Could it be, that receivedcommand is only available for say switch items?
Sorry to asking again simple questions, but i really want to try the alternative solution you proposed.
