Lambda randomly fails with 'Script execution of rule with UID ... failed: null in

Setup, Configuration and Use Scripts & Rules
1

Hi there,

since upgrading to openhab 3.x I have spotted a weird issue. Some of my rules which are using lambdas randomly fail with null access errors like this:
2021-07-27 19:05:00.253 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'tradfri-45' failed: null in tradfri

I have created some lambdas to reuse common code accross many triggers like this:

val Functions.Function4<GenericItem, OnOffType, Boolean, String, String> execStd = [ item, onOff, autoAwayMode, modeSuffix |
	val loggroup = "tradfri.script"

	if (item.type.equals("Switch")) {
		val modeItemName = item.name + modeSuffix
		logDebug(loggroup, "Search for modeItem: '"+ modeItemName + "'.")
		val modeItem = gTradfri_Mode.members.filter[dt|dt.name == modeItemName].head as SwitchItem

		if(modeItem !== null) {
			logDebug(loggroup, "modeItem '"+ modeItem.label + "' found.")
			if(modeItem.state == ON || (autoAwayMode && Max_Alarmanlage.state == ON)) {
        		logDebug(loggroup, "Schedule '"+ item.label + "' Auto - Mode")
    			item.sendCommand(onOff)
        		logDebug(loggroup, "Schedule '"+ item.label + "': " + onOff.toString)
	    	} else {
        		logDebug(loggroup, "Schedule '"+ item.label + "' NOOP - Mode")
			}
		} else {
			logWarn(loggroup, "Mode Item '" + modeItemName + "' could not be found in group 'gTradfri_Mode'")
		}

	} else {
		logDebug(loggroup, "unsupported item type: " + item.type)
    }

    "done"
]

My triggers are rather simple then:

rule "Lampe Kind Garten Decke Abend  ON"
when
    Channel 'astro:sun:lampe_kz:set#event' triggered END
then
	execStd.apply(TRADFRI_Lampe_Kind_Garten_Decke, ON, true, "_Mode_Abend")
end

My log now looks like this:

2021-07-27 19:05:00.244 [DEBUG] [hab.core.model.script.tradfri.script] - Search for modeItem: 'TRADFRI_Lampe_Kind_Strasse_Mode_Abend'.
2021-07-27 19:05:00.244 [DEBUG] [hab.core.model.script.tradfri.script] - Search for modeItem: 'TRADFRI_Lampe_Kind_Strasse_Decke_Mode_Abend'.
2021-07-27 19:05:00.244 [DEBUG] [hab.core.model.script.tradfri.script] - Search for modeItem: 'TRADFRI_Lampe_Kind_Garten_Decke_Mode_Abend'.
2021-07-27 19:05:00.253 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'tradfri-45' failed: null in tradfri
2021-07-27 19:05:00.266 [DEBUG] [hab.core.model.script.tradfri.script] - modeItem 'Lampe Kind Strasse (Auto Abend)' found.
...
2021-07-27 19:05:00.283 [DEBUG] [hab.core.model.script.tradfri.script] - modeItem 'Lampe Strasse Decke (Auto Abend)' found.
...

I assume that this is a concurrency issue because it always happens when multiple rules execute at the same time as in this example.
The failing statement most like is this one:
val modeItem = gTradfri_Mode.members.filter[dt|dt.name == modeItemName].head as SwitchItem

I do not understand why this can be null?

Maybe someone could help me to understand what I need to fix here. Thanks in advance!

2

Just from the timestamps here, you’ve got concurrency. Lambdas are not thread-safe, may trample on each other’s variables.
Concurrency locks are available, but as general advice, you will build fragile, hard to debug, code. Best to avoid lambdas altogether, it can usually be coded a different way.

Curious though why your single sunset event is leading to multiple runs?
I suspect you can re-code in a rule using Group and Member of triggers, avoid the whole lambda problem.

Completely different theory, just to add confusion -

Iterating over a Group while it may also be getting updates has always been an issue, resulting in unexpected null returns.

While many things have changed in OH3, this has not.

One circumvention approach, if you know that the Group will be churning about when the rule is triggered, is to run a short delay and let it settle down before your code.

For that particular search code though, if you know that there is an Item to find, you could avoid searching Group altogether and go direct.

	val modeItem = ScriptServiceUtil.getItemRegistry.getItem(modeItemName)
3

Thanks for your hints.
I do not think that the group changes as this only holds items which are just manually changed. This did not happen here. But of course the lambdas are called from many triggers and sometimes also in parallel.

So if it is not thread safe what is the alternative if I want to reuse code fragments across multiple triggers?

4

Depends what you are trying to do

5

So the situation is as follows:
I have a lot of lights in my house. Those lights should be turned on/off in morning and afternoon/evening.
For me it does not make sense to switch on (or off) all lights at the same time thus I have a dedicated trigger rule for each light. Some triggers have a fixed time and some depend on Astro events.

Each light has 2 virtual items which control if automatic behaviour should be applied or not. This is already covered by the lambda. In addition the automatic mode can be enforced while nobody is at home. This is it basically.

My Lambda approach worked fine for a long time in openhab 2. Most likely the issue was already there but I did never see that error message. I checked the “Separation of Behaviour” DP but I do not understand how I could apply it to my use case.

6

It is what it is. OH3 most definitely has a new rule engine for DSL rules that handles threading in a different way, and this will affect concurrency issues. Some go away, some are highlighted.

Would it be fair to say that you want to send some complicated instruction, associated with a particular light. Not an actual command direct to the light, because you want to pick up ‘variables’ from some other associated Items.

Something like 

“LightA, turn on for NN minutes as specified in Item LightA_duration, but only if XX”
“LightB, turn on with brightness specified in LightB_brightness, with no timing, but only if YY”

You might create a LightA_command dummy Item, and send it a text string (ON, true, "_Mode_Abend")
All xx_command Items can be in a Group, and a rule triggered from Member_of
The rule can analyse the instruction, find associated Items from triggeringItem.name, do whatever it needs to do to real LightA.

That would essentially be reconstructing your lambda as a rule. The advantage of that is that openHAB now manages concurrency via its events bus and the normal rule management, which works more reliably. In the OH3 engine in particular, a single rule will only run one instance at a time, and further triggers neatly queued. “Auto concurrency lock”, if you like.

Tip - if you dislike proliferation of Items, remember you can separate command from state.
If you disable autoupdate on an Item, you can send it commands to trigger and be processed by rules, that do not affect Item state at all.
So some Item like LightA_duration, containing only a reference state, could be exploited as the vehicle for commands too.
The limitation is that commands must be of same type e.g. number for Number type Item.

Example use;
LightA_duration.sendCommand(1)
where LightA_duration state is 30.
A rule can trigger from command, turn on Light A and set up a timer to turn it off again in 30 minutes.
Sending command 0 could turn Light A off immediately and cancel the timer.
Sending command -1 could turn the light on with no timer.
When you are home or away, some other process can still adjust the timing value with postUpdate()

7

As @rossko57 indicates, lambdas are not thread safe. And you’ve not provided your Group Item’s definition so it is certainly possible that it’s churning through the series of updates when the Group anyway. For every one change to a single member of a Group, the Group itself will receive N-1 updates where N is the number of members. So it certainly is possible that the error is that the Group is processing an update when the rule runs. Such errors tend to be intermittent and depends on timing.

Without seeing the actual code, the lambdas and the rules that use them, it’s hard to provide good recommendations for ways to proceed. Some comments with the lambda you did post:

  • It’s more concise to define the lambda as
val execStd = [GenericItem item, OnOffType onOff, Boolean autoAwayMode, String modeSuffix |
]

Get rid of the "done" when defined this way because this is properly a Procedure, not a Function and therefore has no meaningful return value. So why force it? The engine is smart enough to figure out what you want without being explicit in this case.

  • Use findFirst instead of filter
head.

    gTradfri_Mode.members.findFirst[dt | dt.name == modeItemName] as SwitchItem

  • Because the Group search might be the actual problem, use the Item Registry to access the Item instead (see the Item Registry section of Design Pattern: Associated Items).

  • In general rossko’s advice is spot on. Global lambdas in Rules DSL is a code smell in my opinion. They are really only useful in a few rare circumstances. A better approach is to write the one rule to handle your lights and use things like Associated Items DP to figure out what to do.

  • If you can’t figure out a way to make this into one rule, perhaps it’s time to move to one of the other rules based languages which do support functions and classes and libraries and such.

8

Thanks again for your useful hints.
I think I got an idea how to change my rules. I will give it a try and report back.

9

Ok, I managed to implement the new approach. The result is a little bit more complex as I have included some additional functionality

rule "Switch And Scene Command" when
    Item SwitchAndSceneCommand received command
then
    val loggroup = "command.switchandscene"

    // command parsing
    logDebug(loggroup + ".trigger", "[TRIGGER] '" + triggeringItemName + "' received command: '"+ receivedCommand.toFullString() + "'.")
    val String[] commandTokens = receivedCommand.toFullString().split(",")
    var Boolean   validCommand      = true
    var String    switchItemName    = null
    var OnOffType onOff             = null
    var Boolean   autoAwayMode      = false
    var String    modeSuffix        = null
    var Integer   scene             = null
    var Boolean   checkVacationDay  = false
    var OnOffType runOnVacationDay  = null

    if (commandTokens.size >= 3) {
        switchItemName   = commandTokens.get(0)
        onOff            = OnOffType.valueOf(commandTokens.get(1))
        modeSuffix       = commandTokens.get(2)
    } else {
        validCommand     = false
    }

    if (commandTokens.size >= 4) {
        autoAwayMode     = Boolean.valueOf(commandTokens.get(2))
        modeSuffix       = commandTokens.get(3)

        if (commandTokens.size == 5) {
            if(commandTokens.get(4).matches("\\d+")) {
                scene            = Integer.valueOf(commandTokens.get(4))
            } else {
                checkVacationDay = true
                runOnVacationDay = OnOffType.valueOf(commandTokens.get(4))
            }
        } else if (commandTokens.size == 6) {
            scene            = Integer.valueOf(commandTokens.get(4))
            checkVacationDay = true
            runOnVacationDay = OnOffType.valueOf(commandTokens.get(5))
        } else if (commandTokens.size > 6) {
            validCommand     = false
        }
    }


    // command processing
    if(validCommand) {
        logDebug(loggroup, "parsed Command onOff: '" + onOff + "', autoAwayMode: '" + autoAwayMode + "', modeSuffix: '" + modeSuffix + "', scene: '" + scene + "', checkVacationDay: '" + checkVacationDay + "', runOnVacationDay: '" + runOnVacationDay + "'.")

        val checkExpression = "!" + checkVacationDay + " || " + VacationDay.state + " == " + runOnVacationDay
        if(!checkVacationDay || VacationDay.state == runOnVacationDay) {
            if(checkVacationDay) {
                logDebug(loggroup, "checkVacationDay passed (" + checkExpression + ")")
            } else {
                logDebug(loggroup, "checkVacationDay inactive")
            }

            // check switch item
            logDebug(loggroup, "Search for switchItem: '"+ switchItemName + "'.")
            val switchItem = ScriptServiceUtil.getItemRegistry.getItem(switchItemName) as SwitchItem
            logDebug(loggroup, "switchItem '" + switchItemName + "' (" + switchItem.label + ") found.")

            // check mode item
            val modeItemName = switchItemName + modeSuffix
            logDebug(loggroup, "Search for modeItem: '"+ modeItemName + "'.")
            val modeItem = ScriptServiceUtil.getItemRegistry.getItem(modeItemName) as SwitchItem
            logDebug(loggroup, "modeItem '" + modeItemName + "' (" + modeItem.label + ") found.")

            // check scene item (optional)
            var NumberItem sceneItem = null
            if (scene !== null) {
                val sceneItemName = switchItemName + "_Scene"
                logDebug(loggroup, "Search for sceneItem: '"+ sceneItemName + "'.")
                sceneItem = ScriptServiceUtil.getItemRegistry.getItem(sceneItemName) as NumberItem
                logDebug(loggroup, "sceneItem '" + sceneItemName + "' (" + sceneItem.label + ") found.")
            }

            // determine if item should receive a command
            if(modeItem.state == ON || (autoAwayMode && Max_Alarmanlage.state == ON)) {

                // send the optional scene command
                if (scene !== null) {
                    sceneItem.sendCommand(scene)
        			logInfo(loggroup, "Command sent: " + String::format("%-5s", "'" + scene.toString + "'") + " ["+ sceneItem.label +"]")
                    Thread::sleep(500)
                }
                // send the switch command
                switchItem.sendCommand(onOff)
                logInfo(loggroup, "Command sent: " + String::format("%-5s", "'" + onOff.toString + "'") + " ["+ switchItem.label +"]")


            // all the else logging goes here
            } else {
                logDebug(loggroup, "Command '" + switchItemName + "' (" + switchItem.label + "): SKIPPED - Mode")
            }
        } else {
            logDebug(loggroup, "checkSpecialDay blocked execution (" + checkExpression + ")")
        }
    } else {
        logWarn(loggroup, "receivedCommand '" + receivedCommand + "' could not be parsed")
    }
end

Instead of creating one Command-Item as Associate-Item for each “real” item I decided to go for a single Command item. All parameters are passed as a String. I tested it for more than one week and it seems that the errors are gone now.

10

Some coding style advice that might make this rule shorter and easier to understand.

  • Fail fast. Rather than setting a flag and having an if(validCommand), as soon as you know you don’t have a valid command return;. That will drop your levels of indentation (which is one measure of code complexity) by one. So you can something like:

  • You don’t need to nest all those if tests for cases where the number of tokens is > 3. Just put them in series.

if(commandTokens.size < 3 || commandTokens.size > 6){
    logWarn(loggroup, "receivedCommand '" + receivedCommand + "' could not be parsed")
    return;
}

// We already know the size is at least 3
switchItemName = commandTokens.get(0)
onOff = OnOffType.valueOf(commandTokens.get(1))
modeSuffix = commandTokens.get(2)

if(commandTokens.size >= 4){
   autoAwayMode = Boolean.valueOf(commandTokens.get(2))
   modeSuffix = commandTokens.get(3)
}
if(commandTokens.size == 5){
    if(commandTokens.get(4).matches("\\d+")) {
        scene = Integer.valueOf(commandTokens.get(4))
    }
    else {
        checkVacationDay = true
        runOnVacationDay = OnOffType.valueOf(commandTokens.get(4))
    }
}
else if(commandTokens.size == 6){
    scene = Integer.valueOf(commandTokens.get(4))
    checkVacationDay = true
    runOnVacationDay = OnOffType.valueOf(commandTokens.get(5))
}

// We already handled the case where size > 6

// If we made it to here we know already that it's a valid command
logDebug(loggroup, "parsed Command onOff: '" + onOff + "', autoAwayMode: '" + autoAwayMode + "', modeSuffix: '" + modeSuffix + "', scene: '" + scene + "', checkVacationDay: '" + checkVacationDay + "', runOnVacationDay: '" + runOnVacationDay + "'.")
...

That drops the indents by two in some places.

  • Move the vacation day up and fail fast.
...
// If we made it to here we know already that it's a valid command
logDebug(loggroup, "parsed Command onOff: '" + onOff + "', autoAwayMode: '" + autoAwayMode + "', modeSuffix: '" + modeSuffix + "', scene: '" + scene + "', checkVacationDay: '" + checkVacationDay + "', runOnVacationDay: '" + runOnVacationDay + "'.")

if(checkVacationDay && VacationDay.state != runOnVacationDay){
    logDebug(loggroup, "checkSpecialDay blocked execution (" + checkExpression + ")")
    return;
}

// If we make it to this point we know we need to run the command.
...

That eliminates another indentation

  • You don’t need to pull the Item from the Item registry to send it a command. Just use the sendCommand Action. sendCommand(sceneItemName, scene). You only need to pull it to check its current state or access other stuff like it’s label (is that logDebug really important? I wouldn’t bother to pull the Item just to debug log out it’s label).

I think you get the idea. If you reorder some things and fail fast long complex rules like these can become significantly simpler.

1 Like