I do not understand the reasoning.
The rule engine runs into some kind of exception, without a proper error message. That’s all we know. This could be an indicator of a postponed rule execution as well as an indicator of the rule not being run at all. Or something completly different.
No. We know that this error is always related to a problem with the type of an object being used in that Rule. That can be forgetting to cal .state, the Item’s state is NULL, and the like.
Running out of execution threads can not cause this by itself unless you have gone out of your way to set up some sort of inter-dependency between the timing and order that your Rules execute, in which case you would have seen problems long before now.
Not unless somehow the postponed rule execute somehow causes an Item’s state to not be what is expected (e.g. NULL) or something like that. And if this were the case, then honestly that is a bigger problem that needs to be fixed than these null exceptions.
tl;dr: These types of null errors are ALWAYS about type.
Following your object/type reason, how would you explain that this rule run about every 10 minutes with 30 sets of items and usually works fine. But every once in a while the rule throws this error. With the same set of items, the rule worked fine a few minutes ago.
What are the states of all 30 Items and all the variables when the rule throws the error?
Without that information I can’t tell you what the cause is buying the fact that it is NOT because you have run out of execution threads. When that happens the rules don’t run or there is a delay between when the rule is triggered and it runs. It does not generate this or any other error in the logs.
@rlkoshak, it’s about 30 sets of 3 items each. The rule is quite simple it just substracts the set temperature from the current temperature and stores result in another NumberItem.
I have about 30 thermostats, each sends the current temperature every 5-10 minutes. The error occurs about 3 times a day.
If your reason of this error is correct, the error should disappear, because i added a guard before the item state calculation (if(actitem.state !== null && setitem.state !== null)). And additionally the message of an undefined state should appear.
This is the latest version of the rule. All these comments are from trying to track this error down.
rule "calc diff temp"
when
Member of gActTemp changed
then
// logInfo(logger, "[ERROR] calc diff temp: trigger: " + triggeringItem.name)
Thread::sleep(100)
val NumberItem actitem = triggeringItem as NumberItem
// logInfo(logger, "[ERROR] calc diff temp: number: " + actitem.name)
if (actitem !== null)
{
val NumberItem setitem = gSetTemp.members.filter[ i | i.name==String::format("%s_SETTEMP",actitem.name.split("_").get(0)) ].last
// logInfo(logger, "[ERROR] calc diff temp: set: " + setitem.name)
val NumberItem diffitem = gDiffTemp.members.filter[ i | i.name==String::format("%s_DIFFTEMP",actitem.name.split("_").get(0)) ].last
// logInfo(logger, "[ERROR] calc diff temp: diff: " + diffitem.name)
if (setitem !== null && diffitem !== null)
{
if(actitem.state !== null && setitem.state !== null) {
var Number diff = (actitem.state as DecimalType) - (setitem.state as DecimalType)
diffitem.postUpdate(diff)
}
else
{
logInfo(logger, String::format("state undefined: %s", actitem.name) )
}
}
else
{
logError(logger, String::format("SET or DIFF undefined: %s", actitem.name))
}
} else {
logError(logger, "ACT undefined.")
}
end
This is one set of items (Believe me, all sets are similar defined):
Number AZHK_SETTEMP "AZHK (Soll)[%.1f °C]" <temperature> (gAZTemp,gSetTemp,gRestoreOnStartup,gPersist,gPersistNumber) { channel = "homematic:HG-HM-CC-RT-DN:homegear:NEQ0172836:4#SET_TEMPERATURE" }
Number AZHK_ACTUALTEMP "AZHK (Ist)[%.1f °C]" <temperature> (gAZTemp,AZHK_Heizung,gActTemp,gRestoreOnStartup,gPersist,gPersistNumber) { channel = "homematic:HG-HM-CC-RT-DN:homegear:NEQ0172836:4#ACTUAL_TEMPERATURE" }
Number AZHK_DIFFTEMP "Diff AZHK [%.1f °C]" <temperature> (gDiffTemp,gRestoreOnStartup,gPersist,gPersistNumber)
Here is the relevant log excerpt:
cat /var/log/openhab2/openhab.log | grep calc\ diff\ temp
2018-05-31 18:57:16.246 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-01 04:41:14.212 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-01 19:30:15.238 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-02 12:00:20.159 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-02 14:18:39.369 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-02 15:36:30.317 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-03 16:04:27.650 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-03 16:58:23.334 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-03 17:14:08.848 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-03 17:36:16.809 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-04 03:22:53.376 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-04 18:45:14.969 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-05 13:26:17.763 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-05 19:33:17.097 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-05 22:19:35.485 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-05 22:24:22.034 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-06 01:20:35.159 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-06 17:54:14.138 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-07 01:09:16.948 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-07 09:02:20.435 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-07 13:53:44.907 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-08 02:41:16.037 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-08 05:14:15.048 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-08 14:33:16.683 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
NULL
null != NULL
NULL is a special state indicating the Item has an uninitialized state. And you would get the null error above if you tried to actitem.state as Number if actitem.state == NULL.
Scanning throught the Rule… (not everything below is relevant to the error).
Why the Thread::sleep?
val NumberItem actitem = triggeringItem as NumberItem
Are all the members of gActTemp of type NumerItem?
if (actitem !== null)
This will never happen. triggeringItem will always be set to the Item that triggered the Rule. Since this Rule can only be triggered by a change to an Item, triggeringItem will never be null.
val NumberItem setitem = gSetTemp.members.filter[ i | i.name==String::format("%s_SETTEMP",actitem.name.split("_").get(0)) ].last
This is more a matter of style, but it would be shorter to use findFirst and string concatination:
val NumberItem setitem = gSetTemp.members.findFirst[ i | i.name = actitem.name.split("_").get(0) + "_SETTEMP" ]
if(actitem.state !== null && setitem.state !== null) {
This also can never be the case. If you have a not null Item, the Item will always have a State. But that State may be NULL which cannot be cast to a DecimalType.
Again, NULL != null. They are not the same thing.
Over all, this Rule could be simplified using Design Pattern: How to Structure a Rule.
rule "calc diff temp"
when
Member of gActTemp changed
then
val actitem = triggeringItem // we don't really need to cast this to a NumberItem
val setitem = gSetTemp.members.findFirst[ i | i.name == actitem.name.split("_").get(0) + "_SETTEMP" ]
val diffitem = gDiffTemp.members.findFirst[ i | i.name == actitem.name.split("_").get(0) + "_DIFFTEMP"]
// skip the rule if the actitem changed to NULL
if(actitem.state == NULL){
logInfo(logger, "%s's state is NULL!", actitem.name)
return;
}
// skip the rule if setitem or diffitem were not found in their respective Groups
if(setitem === null || diffitem == null){
logInfo(logger, "Could not find setitem and/or diffitem")
return;
}
// skip the rule if either the associated setitem and diffitem's states are NULL
if(setitem.state == NULL || diffitem.state == NULL){
logInfo(logger, "One of setitem or diffitem's state is NULL:\n setitem = %s\n diffitem = %s", setitem.state, diffitem.state)
return;
}
// at this point we have all three relevant Items and know their states are not NULL
var Number diff = actitem.state - setitem.state // it should be able to do this without casting
diffitem.postUpdate(diff)
end
Thanks, @rlkoshak.
All the ifs & log statements were never intended to be there it was just a result of the errors i was getting and tracking them down. And i didn’t knew or didn’t think about the return statement. 
This NULL / null stuff is pure genius. I am quite sure next time i wil have forgotten this. 
I am now using your variant of the rule, let’s see what happens.
First thing what happens, you cannot substract states, the last cast is necessary.
Humph. I hate the inconsistency with Numbers. You CAN do boolean operators without casting (e.g. setitem.state > diffitem.state).
Hope it solves the problem or at least shows you where the problem occurs. The checks should catch them all and log.
It occurs to me though that you probably don’t need to or want to skip the rule when diffitem.state == NULL. You are not using the state of diffitem in this Rule, you are calculating the new state for diffitem, so it doesn’t matter if it is NULL.
Thanks, I have also added a few null checks in my rule and now am waiting to see which item is the culprit. But even if we identify null items and NULL states, how do we investigate further? Before I condensed my repetitive rules using “Member of” etc I never had this problem, and every rule executed 100% of the time without any null errors. Think of critical rules like heating where I am updating a room’s setpoint at 6am - it’s great to catch nulls and exit so I have a clean log but if the rule is not updating the setpoint, then this will definitely fail the WAT (wife acceptance test) come winter!
Also the sporadic nature of the null error is intriguing - one of the rules giving me a headache runs every 20 seconds, yet I get null errors maybe once or twice a day - an error rate of roughly 0.04%…
The error is still existing, but it occured only once since the change of code. Nothing else is logged at 10:23 in openhab.log, all these logInfos didn’t have any effect.
2018-06-10 10:23:35.630 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
It happened when two temperatures changed at almost the same time:
2018-06-10 10:23:30.890 [vent.ItemStateChangedEvent] - LM3_Spannung changed from 228.40 to 228.80
2018-06-10 10:23:35.193 [vent.ItemStateChangedEvent] - F2WT_RSSI changed from -74 to -72
2018-06-10 10:23:35.282 [vent.ItemStateChangedEvent] - F2WT_ACTUALTEMP changed from 24.20 to 24.30
2018-06-10 10:23:35.345 [vent.ItemStateChangedEvent] - ArWT_ACTUALTEMP changed from 25.60 to 25.70
2018-06-10 10:23:35.450 [GroupItemStateChangedEvent] - gActTemp changed from 25.10 to 25.11 through F2WT_ACTUALTEMP
2018-06-10 10:23:35.872 [GroupItemStateChangedEvent] - gDiffTemp changed from 9.29 to 9.30 through F2WT_DIFFTEMP
2018-06-10 10:23:35.878 [vent.ItemStateChangedEvent] - F2WT_DIFFTEMP changed from 3.20 to 3.30
2018-06-10 10:23:41.648 [vent.ItemStateChangedEvent] - AZWT_ACTUALTEMP changed from 25.40 to 25.50
This is my current rule:
rule "calc diff temp"
when
Member of gActTemp changed
then
val actitem = triggeringItem // we don't really need to cast this to a NumberItem
val setitem = gSetTemp.members.findFirst[ i | i.name == actitem.name.split("_").get(0) + "_SETTEMP" ]
val diffitem = gDiffTemp.members.findFirst[ i | i.name == actitem.name.split("_").get(0) + "_DIFFTEMP"]
// skip the rule if the actitem changed to NULL
if(actitem.state == NULL)
{
logInfo("calc diff temp", "%s's state is NULL!", actitem.name)
return;
}
// skip the rule if setitem or diffitem were not found in their respective Groups
if(setitem === null)
{
logInfo("calc diff temp", "Could not find setitem for %s", actitem.name)
return;
}
if(diffitem == null)
{
logInfo("calc diff temp", "Could not find diffitem for %s", actitem.name)
return;
}
// skip the rule if either the associated setitem and diffitem's states are NULL
if(setitem.state == NULL)
{
logInfo("calc diff temp", "%s's state is NULL!", setitem.name)
return;
}
// at this point we have all three relevant Items and know their states are not NULL
var Number diff = (actitem.state as DecimalType) - (setitem.state as DecimalType) // it should be able to do this without casting
diffitem.postUpdate(diff)
end
Once you know what item is unexpectedly NULL you start looking into why that item is NULL at that point. If there sooner other rule interacting with this item? Was the .items file it’s in reload? Is the binding doing something unexpected? Are some of the items used by this rule changing while this rule runs?
The key thing is the error is not in this particular rule. This rule is just where the symptom is seen.
The logInfos have no effect. They just help to tell us what is going on.
Since the error occurs when two change at almost the same time I suspect the items are changing state or in process of changing state in the middle of the rule execution.
Add more logging to find exactly what line it is failing on.
In addition, set everything you use, including the states of the items, to variables at the top of the rule even before the if statements checking if the states are NULL. If you capture the states up front any changes that occur while the rule is running behind the scenes may not impact the rule.
Like I said above, the symptom is appearing in this rule but the problem lies elsewhere.
What did the logs from your rule show at this time?
It’s all above, quoted again. First excerpt is openhab.log, 2nd is events.log
cat /var/log/openhab2/openhab.log | grep 2018-06-10\ 10:23
cat /var/log/openhab2/events.log | grep 2018-06-10\ 10:23 (result is cut, two messages before and one after)
OK, that is what I was trying to confirm… there were no log entries that actually came from your rule to determine which line caused the exception. See if you get some logging with this…
rule "calc diff temp"
when
Member of gActTemp changed
then
logInfo("calc diff temp", "{}: state changed to {}",triggeringItem.name,triggeringItem.state)
val setitem = gSetTemp.members.findFirst[ i | i.name == actitem.name.split("_").get(0) + "_SETTEMP" ]
if (setitem === null) {
logInfo("calc diff temp", "{}: Could not find setitem",triggeringItem.name)
}
else {
logInfo("calc diff temp", "{}: setitem.name=[{}]",triggeringItem.name,setitem.name)
if (setitem.state == NULL) {
logInfo("calc diff temp", "{}: setitem state is NULL {}",triggeringItem.name,setitem.name)
}
else {
logInfo("calc diff temp", "{}: setitem.state=[{}]",triggeringItem.name,setitem.state)
val diffitem = gDiffTemp.members.findFirst[ i | i.name == actitem.name.split("_").get(0) + "_DIFFTEMP" ]
if (diffitem === null) {
logInfo("calc diff temp", "{}: Could not find diffitem",triggeringItem.name)
}
else {
logInfo("calc diff temp", "{}: diffitem.name=[{}]",triggeringItem.name,diffitem.name)
if (diffitem.state == NULL) {
logInfo("calc diff temp", "{}: diffitem state is NULL {}",triggeringItem.name,diffitem.name)
}
else {
logInfo("calc diff temp", "{}: diffitem.state=[{}]",triggeringItem.name,diffitem.state)
var Number diff = (triggeringItem.state as DecimalType) - (setitem.state as DecimalType)
logInfo("calc diff temp", "{}: diff=[{}]",triggeringItem.name,diff)
diffitem.postUpdate(diff)
}
}
}
}
end
The failing line of code for me is:
val isHomeItem = gIsHome.members.findFirst[ t|t.name == isHomeName ]
and all other .findFirst / .filter lines where you are getting the item from the group. My null checks are not catching this but the logs immediately above these lines are working and the ones immediately below are not.
OK, this is some progress.
First, log/test everything on that line.
logInfo("test", gIsHome)
logInfo("test", gIsHome.members.size)
logInfo("test", isHomeName)
Do these all make sense?
I thought a bit about my case:
My guess would be, the rule engine (instance ArWT) cannot access a group (gDiffTemp or gActTemp), while a group member is being changed (by instance F2WT) or while the group average is being calculated by openHAB.
This is my combined (openhab.log+events.log) log put into sequence by time:
2018-06-10 10:23:30.890 [vent.ItemStateChangedEvent] - LM3_Spannung changed from 228.40 to 228.80
2018-06-10 10:23:35.193 [vent.ItemStateChangedEvent] - F2WT_RSSI changed from -74 to -72
2018-06-10 10:23:35.282 [vent.ItemStateChangedEvent] - F2WT_ACTUALTEMP changed from 24.20 to 24.30
2018-06-10 10:23:35.345 [vent.ItemStateChangedEvent] - ArWT_ACTUALTEMP changed from 25.60 to 25.70
2018-06-10 10:23:35.450 [GroupItemStateChangedEvent] - gActTemp changed from 25.10 to 25.11 through F2WT_ACTUALTEMP
2018-06-10 10:23:35.630 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'calc diff temp': null
2018-06-10 10:23:35.872 [GroupItemStateChangedEvent] - gDiffTemp changed from 9.29 to 9.30 through F2WT_DIFFTEMP
2018-06-10 10:23:35.878 [vent.ItemStateChangedEvent] - F2WT_DIFFTEMP changed from 3.20 to 3.30
2018-06-10 10:23:41.648 [vent.ItemStateChangedEvent] - AZWT_ACTUALTEMP changed from 25.40 to 25.50
It’s really fast but I don’t know we can make that assumption. One would have to review the Item Registry code to verify that is the case.
That might very well be the case. You might be able to test for that. Check to see if the Group is null before the findFirst line. If it is, that could be evidence that it is the problem.
Given your reasoning, the gDiffTemp would be the Group that would be changing while this Rule is running since you say gSetTemp doesn’t change. So focus on that Group.
The member of gActTemp definitely changed. But I suspect the state of gActTemp itself is still being calculated in the background when this Rule triggers. Also, the state of gDiffTemp is also potentially being recalculated from the previous run of this Rule, depending on how close together new ActTemps come in.
I think we need to gather more evidence before we file an issue, but if your guess is right, then there will likely need to be an issue filed. It will probably be a major pain to correct though so we should also look for a work-around.
This is also an assumption that we may not be able to make. We know it is not NULL at the time of checking it in the if statement. But the actual line where we use it occurs some milliseconds later and the state could have changed out from under us. It’s unlikely but if you have enough Items updating all at once it might occur, though rarely.
We can eliminate this possibility as well:
rule "calc diff temp"
when
Member of gActTemp changed
then
val actitem = triggeringItem // we don't really need to cast this to a NumberItem
val act = actitem.state
// skip the rule if the actitem changed to NULL
if(act == NULL)
{
logInfo("calc diff temp", "%s's state is NULL!", actitem.name)
return;
}
val setitem = gSetTemp.members.findFirst[ i | i.name == actitem.name.split("_").get(0) + "_SETTEMP" ]
// skip the rule if setitem or diffitem were not found in their respective Groups
if(setitem === null)
{
logInfo("calc diff temp", "Could not find setitem for %s", actitem.name)
return;
}
val set = setitem.state
if(set == NULL)
{
logInfo("calc diff temp", "%s's state is NULL!", setitem.name)
return;
}
val diffitem = gDiffTemp.members.findFirst[ i | i.name == actitem.name.split("_").get(0) + "_DIFFTEMP"]
if(diffitem == null)
{
logInfo("calc diff temp", "Could not find diffitem for %s", actitem.name)
return;
}
// at this point we have all three relevant Items and know their states are not NULL
var Number diff = (act as DecimalType) - (set as DecimalType)
diffitem.postUpdate(diff)
end
The big change is we save the state to a val and then only use the val in the Rule. This will prevent any changes taking place behind the scenes from impacting the Rule. Based on the observed behavior and your reasoning I don’t think this is the problem. But it will eliminate it as a possiblity.
I can think of a number of mitigations for the observed behavior but we need more info before I’ll know which one is most appropriate. But they include:
postUpdate(actitem.name.split("_").get(0) + "_DIFFTEMP", diff). Since gDiffTemp is the only one that we think is causing problems, if we avoid trying to findFirst on the Group then the error should not appear.I have tried doing that in my code but it has not helped - I think this has to do with the way we extract the item from the group.
postUpdate(actitem.name.split("_").get(0) + "_DIFFTEMP", diff)
I will try this version on mine and report back.
Hopefully we are getting somewhere!
Thanks
No, it’s a fact defined by my devices. The don’t publish the temperature in miliseconds, they publish the current temperature sometimes between 5 and 10 minutes. (IIRC roughly every 8 minutes).
I will make the change regarding the elimination of the findfirst for diffitem, this is the most promising change in my opinion. Thanks. Let’s see what happens.
Edit:
This will be difficult from now on. This error occured only twice after the rule change (on 2018-06-08). The rate went down from three times a day to once every three days. 