[ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule <rulename>': null

Hi there!

Currently I’m looking for errors in my openhab.log to track down anything which does not belong there – for eliminating another problem.

I see errors like

[ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Determine number of activated lights': null 

during regular operation.

Here’s my rule which is causing this behavior. I use this rules to prepare charting of active light counts (afaik there’s no way to get a Group:Switch into a chart).

import org.eclipse.xtext.xbase.lib.Functions

val Functions$Function2<GroupItem, GroupItem, Boolean> updateNumberItem= [ groupItem, associationGroup |

    val groupItemName = groupItem.name
    logInfo("counters", "updateNumberItem=" + groupItemName)
    val numberItemName = "I" + groupItemName.substring(1)
    val numberItem = associationGroup.members.findFirst[ ni | ni.name == numberItemName ]

    var count = groupItem.allMembers.filter(l|(l.state > 0 || l.state==ON)).size
    logInfo("counters", "update to " + numberItem.name + " for group " + groupItem.name + ": " + count)
    numberItem.postUpdate(count)

    true
]

rule "Determine number of activated lights"
when
    Item GlightsSfCounter received update or
    Item GlightsSfWrCounter received update or
    Item GlightsSfBarCounter received update or
    Item GlightsSfLrCounter received update or
    Item GlightsSfBerCounter received update or
    Item GlightsSfCorCounter received update or
    Item GswitchablesSfCounter received update or
    Item GswitchablesSfWrCounter received update or
    Item GswitchablesSfBerCounter received update
then
    logInfo("counters", "rule execution")
    logInfo("counters", "rule execution: item=" + triggeringItem.name)
    val triggeringGroup = (triggeringItem as GroupItem)
    updateNumberItem.apply(triggeringGroup, GassociatedCounters)
end

To get an understanding what happens when I execute the rule, here’s an excerpt of the openhab.log:

2018-07-15 15:25:39.494 [INFO ] [clipse.smarthome.model.script.motion] - No more motion in second floor living room: switching lights off
2018-07-15 15:25:39.536 [INFO ] [ipse.smarthome.model.script.counters] - rule execution
2018-07-15 15:25:39.542 [INFO ] [ipse.smarthome.model.script.counters] - rule execution
2018-07-15 15:25:39.556 [INFO ] [ipse.smarthome.model.script.counters] - rule execution: item=GlightsSfLrCounter
2018-07-15 15:25:39.561 [INFO ] [ipse.smarthome.model.script.counters] - rule execution: item=GlightsSfCounter
2018-07-15 15:25:39.573 [INFO ] [ipse.smarthome.model.script.counters] - updateNumberItem=GlightsSfCounter
2018-07-15 15:25:39.573 [INFO ] [ipse.smarthome.model.script.counters] - updateNumberItem=GlightsSfLrCounter
2018-07-15 15:25:39.665 [INFO ] [ipse.smarthome.model.script.counters] - update to IlightsSfLrCounter for group GlightsSfLrCounter: 0
2018-07-15 15:25:39.706 [INFO ] [ipse.smarthome.model.script.counters] - update to IlightsSfCounter for group GlightsSfCounter: 0
2018-07-15 15:25:49.603 [INFO ] [ipse.smarthome.model.script.counters] - rule execution
2018-07-15 15:25:49.614 [INFO ] [ipse.smarthome.model.script.counters] - rule execution: item=GlightsSfLrCounter
2018-07-15 15:25:49.607 [INFO ] [ipse.smarthome.model.script.counters] - rule execution
2018-07-15 15:25:49.621 [INFO ] [ipse.smarthome.model.script.counters] - rule execution: item=GlightsSfCounter
2018-07-15 15:25:49.634 [INFO ] [ipse.smarthome.model.script.counters] - updateNumberItem=GlightsSfLrCounter
2018-07-15 15:25:49.634 [INFO ] [ipse.smarthome.model.script.counters] - updateNumberItem=GlightsSfCounter
2018-07-15 15:25:49.656 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Determine number of activated lights': null
2018-07-15 15:25:49.679 [INFO ] [ipse.smarthome.model.script.counters] - update to IlightsSfLrCounter for group GlightsSfLrCounter: 0 

I read [SOLVED] Error: Rule '<rulename>': null and grasped that I should use the triggeringItem which I now did.

Can this be a concurrency issue? (Only speculation since I do not have yet a decent understanding about how openHAB works internally)

Almost always null errors are caused by type problems. This means you are trying to use an Object in a way that is not valid for that type of Object. Most of the time this is caused by , for example, trying to do a comparison operator with an Item’s whose state is NULL.

I’d be willing to bet that one of your members of groupItem is NULL which means l.state > 0 is an error.

Sorry for the late reply, I can only work on my home automation on weekends…

The group GassociatedCounters consists of static items only, as well as the groups in the triggeringItem, so I wonder how they could be null. I’ve now implemented a check for invalid casts by verifying groupItem !== null.

But I think I’m missing your point. I stumbled about Is there a difference between null and NULL?.

I guess you mean that

var count = groupItem.allMembers.filter(l|(l.state > 0 || l.state==ON)).size

does not work in all cases. Do you say it will fail if state is NULL? Should it be like this:

var count = groupItem.allMembers.filter(l|((l.state != NULL) && (l.state > 0 || l.state==ON))).size

Yes, that is what I meant. NULL is a special state, not to be confused with null which is different, and that state doesn’t support the > operation.

I tried to fix it that way, but I’m still getting these null errors. Maybe there’s another reason? Perhaps something concurrency related?

Can you judge from the following log paired with the code?

2018-07-21 12:12:55.085 [INFO ] [ipse.smarthome.model.script.counters] - rule execution
2018-07-21 12:12:55.096 [INFO ] [ipse.smarthome.model.script.counters] - rule execution: item=GlightsSfWrCounter
2018-07-21 12:12:55.106 [INFO ] [ipse.smarthome.model.script.counters] - rule execution
2018-07-21 12:12:55.109 [INFO ] [marthome.model.script.counters-debug] - updateNumberItem 1=GlightsSfWrCounter
2018-07-21 12:12:55.115 [INFO ] [ipse.smarthome.model.script.counters] - rule execution: item=GlightsSfCounter
2018-07-21 12:12:55.119 [INFO ] [marthome.model.script.counters-debug] - updateNumberItem 2=GlightsSfWrCounter
2018-07-21 12:12:55.124 [INFO ] [marthome.model.script.counters-debug] - updateNumberItem 1=GlightsSfCounter
2018-07-21 12:12:55.116 [INFO ] [ipse.smarthome.model.script.counters] - update to IlightsSfWrCounter for group GlightsSfWrCounter: 0
2018-07-21 12:12:55.129 [INFO ] [marthome.model.script.counters-debug] - updateNumberItem 2=GlightsSfCounter
2018-07-21 12:12:55.137 [INFO ] [marthome.model.script.counters-debug] - updateNumberItem 3=GlightsSfCounter
2018-07-21 12:12:55.136 [INFO ] [ipse.smarthome.model.script.counters] - rule execution
2018-07-21 12:12:55.140 [INFO ] [ipse.smarthome.model.script.counters] - rule execution: item=GlightsSfCounter
2018-07-21 12:12:55.136 [INFO ] [marthome.model.script.counters-debug] - updateNumberItem 3=GlightsSfWrCounter
2018-07-21 12:12:55.148 [INFO ] [marthome.model.script.counters-debug] - updateNumberItem 1=GlightsSfCounter
2018-07-21 12:12:55.149 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Determine number of activated items': null
2018-07-21 12:12:55.154 [INFO ] [marthome.model.script.counters-debug] - updateNumberItem 2=GlightsSfCounter
2018-07-21 12:12:55.162 [INFO ] [marthome.model.script.counters-debug] - updateNumberItem 3=GlightsSfCounter
2018-07-21 12:12:55.175 [INFO ] [ipse.smarthome.model.script.counters] - update to IlightsSfCounter for group GlightsSfCounter: 0
2018-07-21 12:12:55.179 [INFO ] [ipse.smarthome.model.script.counters] - update to IlightsSfWrCounter for group GlightsSfWrCounter: 0

… and the rules:

val Functions$Function2<GroupItem, GroupItem, Boolean> updateNumberItem= [ groupItem, associationGroup |

    if (groupItem !== null) {
        val groupItemName = groupItem.name
        logInfo("counters-debug", "updateNumberItem 1=" + groupItemName)
        val numberItemName = "I" + groupItemName.substring(1)
        logInfo("counters-debug", "updateNumberItem 2=" + groupItemName)
        val numberItem = associationGroup.members.findFirst[ ni | (ni.name != NULL) && (ni.name == numberItemName) ]
        logInfo("counters-debug", "updateNumberItem 3=" + groupItemName)

        var count = groupItem.allMembers.filter(l|((l.state != NULL) && (l.state > 0 || l.state==ON))).size
        logInfo("counters", "update to " + numberItem.name + " for group " + groupItem.name + ": " + count)
        numberItem.postUpdate(count)
    }

    true
]

rule "Determine number of activated items"
when
    Item GlightsSfCounter received update or
    Item GlightsSfWrCounter received update or
    Item GlightsSfBarCounter received update or
    Item GlightsSfLrCounter received update or
    Item GlightsSfBerCounter received update or
    Item GlightsSfCorCounter received update or
then
    logInfo("counters", "rule execution")
    logInfo("counters", "rule execution: item=" + triggeringItem.name)
    val triggeringGroup = (triggeringItem as GroupItem)
    updateNumberItem.apply(triggeringGroup, GassociatedCounters)
end

It can be a concurrency issue. When you trigger using received update on a group, the rule triggers n-1 times for every single update to one of its members, where n is the number of members.

So if the Group has five members, this role will trigger 4 times all within milliseconds of each other when one Item changes.

You don’t say how you defined these Groups but if all you need is the number of ON Items, you don’t need any rules at all.

Group:Number:SUM

With this the Group’s state will be the number of its members that are ON. No rules required.

At a minimum you should use the Member of rule trigger so the rule only triggers once per change.

Do you see a way how such a concurrency issue could cause that behavior?

But let me show you how I defined the groups:

Group:Number:SUM GlightsSfCounter "Lichter aktiv [%d]" <light> (Gsf)
Group:Switch:OR(ON, OFF) GlightsSfWrCounter "Lichter aktiv [%d]" <light> (GlightsSfCounter)
Group:Switch:OR(ON, OFF) GlightsSfBarCounter "Lichter aktiv [%d]" <light> (GlightsSfCounter)
Group:Switch:OR(ON, OFF) GlightsSfLrCounter "Lichter aktiv [%d]" <light> (GlightsSfCounter)
Group:Switch:OR(ON, OFF) GlightsSfLrSideboardCounter "Lichter aktiv [%d]" <light> (GlightsSfLrCounter)
Group:Switch:OR(ON, OFF) GlightsSfBerCounter "Lichter aktiv [%d]" <light> (GlightsSfCounter)
Group:Switch:OR(ON, OFF) GlightsSfCorCounter "Lichter aktiv [%d]" <light> (GlightsSfCounter)
Group:Switch:OR(ON, OFF) GlightsSfSrCounter "Lichter aktiv [%d]" <light> (GlightsSfCounter)

You’re saying that I don’t need this logic, but I did not find any other way around it. as within the BasicUI the groups are usable to show the active light counts, but I cannot use the values for charting. In order to persist active light counts, I had to update the items. – Is there another way to achieve this?

Best regards!

I have similar error, but instead of null, it’s written 4 :

[ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'RFLink IN': 4

What is the meaning of 4? What I should looking for into my rule RFLink IN?

There is the rule triggering this error:

rule "RFLink IN"
when
   Item RFLinkRaw received update
then
logInfo(logName, "raw data received: " + RFLinkRaw.state)

// split the message into parts on the ';'
val RFbuffer = RFLinkRaw.state.toString.split(';')
//	val RFprefix = RFbuffer.get(0)
//	val RFstamp = RFbuffer.get(1)
val RFvendor = RFbuffer.get(2)
val RFidLong = RFbuffer.get(3)
val RFdata_1 = RFbuffer.get(4)
val RFdata_2 = RFbuffer.get(5)
val RFidHex = transform("REGEX", "ID=([0-9a-fA-F]*)", RFidLong)


// look at the fifth part of the message to see which type of message it is and parse accordingly    
switch (RFvendor + " " + RFidHex) {

    // process a TEMP message
    case "LacrosseV4 0001" : { //sonde Lacrosse extérieure
    	val tempHex = RFdata_1.replace("TEMP=", '')
        val rawTemp = new java.math.BigDecimal(Integer::parseInt(tempHex, 16))            
        val adjustedNegTemp = (rawTemp-32768)/-10.0
        val adjustedPosTemp = rawTemp / 10.0
         
        if (rawTemp > 32768) {
        	Lacrosse_OUT_Temperature.postUpdate(adjustedNegTemp)
        	logInfo(logName, "some data received from " + RFvendor + ":Temp=" + adjustedNegTemp + "C" )
        }
        else {
        	Lacrosse_OUT_Temperature.postUpdate(adjustedPosTemp)
        	logInfo(logName, "some data received from " + RFvendor + ":Temp=" + adjustedPosTemp + "C" )
        }
    }    
}
// process a RollerShutter message
switch (RFvendor) {
    case "BrelMotor" : {
		switch (RFdata_1) {
			case ("SWITCH=05") : {
				logInfo(logName, "Command confirmation from " + RFvendor + " chambre:" + RFdata_2)
			}
			case ("SWITCH=a0") : {
				logInfo(logName, "Command confirmation from " + RFvendor + " All living:" + RFdata_2)
			}
			case ("SWITCH=a1") : {
				logInfo(logName, "Command confirmation from " + RFvendor + " Living1:" + RFdata_2)
			}
			case ("SWITCH=a2") : {
				logInfo(logName, "Command confirmation from " + RFvendor + " Living2:" + RFdata_2)
			}
			case ("SWITCH=a3") : {
				logInfo(logName, "Command confirmation from " + RFvendor + " Living3:" + RFdata_2)
			}
			case ("SWITCH=a4") : {
				logInfo(logName, "Command confirmation from " + RFvendor + " Living4:" + RFdata_2)
			}
			default : logInfo(logName, "completely irrelevant data received from " + RFvendor)
		}
	}
	case "LacrosseV4" : {
	}
	default : logInfo(logName, "completely irrelevant data received from " + RFvendor)
 }
end

Wild guess that is your culprit. The unhelpful message is sometimes due to array index being out of range.
I would modify your rule to see if the array resulting from the message split is as long as you expected.

I see… You are perfectly right. When I received RF data from my devices, it fit all the buffer. After sending information to take action, confirmation received from device is only 3 bytes…

2020-06-29 08:00:01.325 [INFO ] [e.smarthome.model.script.RFLinkLogMM] - raw data received: 20;B3;OK;

2020-06-29 08:00:01.336 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'RFLink IN': 4

My understanding is that isn’t causing any issue but that error log. Is there a way to manage that kind of data not always of the same length?

Yes of course.
Your array-of-strings variable RFbuffer has a length property, to tell you how long it is.

if ( RFbuffer.length > 5) {
   // do stuff
} else {
   // short message, do something else
}

Problem fixed. Thanks a lot!

 // Do something only if RFbuffer have at least 5 bytes. If I received 3 bytes, it's an acknowledge message, exit.
if (RFbuffer.length < 5) {
	return;
}
else {
    // Do normal stuff

Note that, if your message happens to be 5 elements long,
val RFdata_2 = RFbuffer.get(5)
will still error because it counts elements from 0, (5) is the sixth element.

Good point. Thanks. I’ll make modification.