I’m running the following rule since quite some time already and it occasionaly throws the following exception:
20:45:29.182 [ERROR] [.eclipse.smarthome.model.script.Error] - Some bad stuff happened in my Buffer rule: java.lang.IllegalStateException
The rule itself is this
rule "Buffer Energy"
when
Item Energy_Buf received update
then
for (buffer : Energy_Buf?.members) {
try {
val energyItem = Energy_Log.members.findFirst[name.equals(buffer.name.substring(0, buffer.name.lastIndexOf("_")))]
if(buffer.state != NULL && energyItem != NULL) {
if(energyItem.state == NULL) {
//logError(energyItem.name, "Updating to " + buffer.state)
postUpdate(energyItem, buffer.state)
} else if((energyItem.state as DecimalType).floatValue < (buffer.state as DecimalType).floatValue && ((buffer.state as DecimalType).floatValue - (energyItem.state as DecimalType).floatValue) < 15.0) {
//logError(energyItem.name, "Updating to " + buffer.state)
postUpdate(energyItem, buffer.state)
} else {
if(energyItem.state != buffer.state)
logError(energyItem.name, "Bad value " + buffer.state + ", current is " + energyItem.state)
}
}
} catch(Throwable t) {
logError("Error", "Some bad stuff happened in my Buffer rule: " + t.toString)
}
}
end
The rule is responsible for filtering values that shouldn’t be in there. Did I miss anything that could cause this exception? I checked for null values there so I can’t think about where the issue might come from.
I made them LogError on purpose as I have about 10-20 values updated per second, not marking this red makes it very difficult to find the appropriate lines in log:tail
I have added a few more debug outputs so it looks like this now:
rule "Buffer Energy"
when
Item Energy_Buf received update
then
for (buffer : Energy_Buf?.members) {
try {
//val energyItem = Energy_Log.members.findFirst[name.equals(buffer.name.split("_").get(0))]
val energyItem = Energy_Log.members.findFirst[name.equals(buffer.name.substring(0, buffer.name.lastIndexOf("_")))]
logError(energyItem.name, "Got item!")
if(buffer.state !== null && energyItem !== null) {
logError(energyItem.name, "Item is not null!")
if(energyItem.state === null) {
logError(energyItem.name, "Updating to " + buffer.state)
postUpdate(energyItem, buffer.state)
} else if ( ((energyItem.state as Number) < (buffer.state as Number)) && (((buffer.state as Number) - (energyItem.state as Number)) < 15.0) ) {
logError(energyItem.name, "Updating to " + buffer.state)
postUpdate(energyItem, buffer.state)
} else {
if(energyItem.state != buffer.state)
logError(energyItem.name, "Bad value " + buffer.state + ", current is " + energyItem.state)
}
} else {
logError("EnergyRule", "Either buffer is null or no destination found!")
}
} catch(Throwable t) {
logError("Error", "Some bad stuff happened in my Buffer rule: " + t.toString)
}
}
end
And I am getting this now:
21:34:18.959 [ERROR] [home.model.script.Energy_Office_Total] - Got item!
21:34:18.962 [ERROR] [home.model.script.Energy_Office_Total] - Item is not null!
21:34:18.967 [ERROR] [.eclipse.smarthome.model.script.Error] - Some bad stuff happened in my Buffer rule: java.lang.IllegalStateException
21:34:18.980 [ERROR] [smarthome.model.script.Energy_Heating] - Got item!
I think the issue is caused by the comparison? But why would that cause an IlegalStateException?
If this Rule is getting run so frequently that you have more than one instance of it running at the same time there can sometimes be strange interactions between the various instances. I usually see the problem most frequently when the two are working on members of a Group or the like, Certain parts of Rules DSL are not terrible thread safe.
If the fix Vincent makes doesn’t solve things then tell us some more about how this Rule gets triggered.
I added a Lock for now and it looks like this fixed it, seems like there was an issue that reading and writing on the same variable at the same time caused. Shouldn’t the structure under this (OpenHAB itself) take care of this to prevent issues like this (lock item before writing/reading and unlock after writing/reading)?
If this rule is being called that frequently, you might be better off using JSR223 Rules which support this sort of rule better. However, you should consider only triggering the rule on charges if that is possible. If not, try the rule using Member of trigger. When you use received update with a Group item the rule gets triggered N-1 times where N in the number of members for every update.
In short, this rule is spending a while lot of time running when it didn’t need to. I see nothing in the logic that would make Member of changed inappropriate. Though Member of received update would still probably fix the original problem without the need for locks. If you have 5 members, the rule triggers and runs 4 times every time any one of the 5 members updates.
Error occurs “sometimes” on (sometimes means: once per dozens of rule execuitions).
var lastupdate_item = gLastUpdate.members.findFirst[name.equals(triggeringItem.name + "_LastUpdate")]
It looks like findFirst function returns exception when it iterates through group of items and finds during iteration non-initialized item in the group.
It occurs on stable 2.4.0 and trunc 2.5.0 versions (as I’ve checked).
How frequently does this Rule run? Does it every run more than once at the same time?
There are some threading issues that look a whole lot like the error you report when you are iterating over a Group’s members and the state of one of those members changes while the Rule is running.
That’s may be a point. But in fact this is an error. I am not interested in changes of other members. For this specific rule I just want to organize Items in collection easy to maintain in rules and UI.
Can you consider to i.e. add ability to find item with i.e. flag dirtyread to ignore potential changes in items? Otherwise I’ll have to organize some synchronized procedure to make access to this group sequential.
As I see this is known issue and that’s can be the compromise between overall data coherency and specific usage.
I can’t do anything. I’m not a developer on OH. But you can file an issue and perhaps one of them will be able to address the issue.
Those isn’t something that you will be able to fix with a lock because the changes are taking place outside if the roles and therefore outside of your control.
It might be the case that this error doesn’t occur in JSR223 Rules but I can’t guarantee it. The last time I saw something like this, I used a different approach (for this and other reasons) which side street the issue.
I have the same error with some of my rules.
These rules based on the iCloud binding, so multiple devices gets updated together and a rule runs for each device (and also there is other item queries from other groups like above). So I think this causes the error, but not every time, only a few times per day, however this rule runs every 5 min. But it might happen that at that time one rule finishes earlier than another is finished with quering the members…