Searching for item in group while concurrently updating another item causes DSL rule to fail

[CrappyTan]

• Openhab 2.4
• Raspberry Pi 4, buster, fully patched.
• openjdk version "1.8.0_152"
• OpenJDK Runtime Environment (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76)
• OpenJDK Client VM (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 25.152-b76, mixed mode, Evaluation)
• Working example below
• Discussion thread: https://community.openhab.org/t/rule-extractor-fan-sensor-changed-null-another-case/86988

I have a two groups with overlapping items. I have a rule which fires on member change Within the rule I search for related 2 items using members.findFirst Once member is found, it sends a command to a third member The rule gets fired twice, milliseconds apart and repeats the process. During this second call, the rule simply fails with the message "Rule 'Extractor Fan sensor changed': null"

If I stop using members.findFirst but rather search for the items in the registry, it does not fail.

Items:

Group:Number g_SearchGroup
Group:Number g_TriggerGroup
Group:Number g_FakePushGroup


Number Item1    (g_SearchGroup, g_TriggerGroup, g_FakePushGroup)
Number Item2    (g_SearchGroup, g_TriggerGroup, g_FakePushGroup)
Switch Switch1  (g_SearchGroup)

rule

import org.eclipse.smarthome.model.script.ScriptServiceUtil

rule "FFGG"
when Member of g_TriggerGroup changed 
then
    logWarn("PPP", triggeringItem.name + " has changed and is firing")

    // //option 1
    val itemSwitch          = g_SearchGroup.members.findFirst[SwitchItem item | item.name == "Switch1"] as SwitchItem
    val itemItem1           = g_SearchGroup.members.findFirst[NumberItem item | item.name == "Item1"] as NumberItem
    val itemItem2           = g_SearchGroup.members.findFirst[NumberItem item | item.name == "Item2"] as NumberItem


    //option 2
//    val itemSwitch          = ScriptServiceUtil.getItemRegistry.getItem("Switch1")
//    val itemItem1           = ScriptServiceUtil.getItemRegistry.getItem("Item1")
//    val itemItem2           = ScriptServiceUtil.getItemRegistry.getItem("Item2")


    if (itemSwitch === null)        {logWarn("ItemSwitch is null Cannot continue.");return;}
    if (itemItem1 === null)        {logWarn("itemItem1 is null Cannot continue.");return;}
    if (itemItem2 === null)        {logWarn("itemItem2 is null Cannot continue.");return;}


    val Number val1         = (if (itemItem1.state == NULL) 80     else itemItem1.state as Number)
    val Number val2         = (if (itemItem2.state == NULL) 26  else itemItem2.state as Number)

    logWarn("PPP", "val1:" + val1.toString + " val2:" + val2.toString + " Switch:" + itemSwitch.state)

    if (
        (
                val1 > 25 
            ||  val2 > 30
        )
        && itemSwitch.state != ON){
        logWarn("PPP", "Turning on switch")
        itemSwitch.sendCommand(ON)
        return;
    }

    if (
            (
                    val1 <= 25
                &&  val2 < 50
            ) && itemSwitch.state == ON){
        logWarn("PPP", "Turning off switch")
        itemSwitch.sendCommand(OFF)
        return;
    }

end 

To create failure, simply change the value for the fake group rapidly. It will fail within a few attempts.

This is recreatable on my system.

[5iver]

Can you reproduce this on 2.5?

[CrappyTan]

Can you reproduce this on 2.5?

I've not got a 2.5 install to test on but the thread is continuing on https://community.openhab.org/t/solved-rule-extractor-fan-sensor-changed-null-another-case/86988/38 with Rich, Christoph and Rossko57 finding working examples of this.

[Rossko57]

I have reproduced this under both 2.4 and 2.5 release, and captured a stack dump. I estimate I can get it to fail about 5% of the test runs, wouldn't be surprised if this varies a lot by host performance.

items

Group:Number:AVG gBananas "aggregatation"
Number test1 "test one" (gBananas)
...
Number test4 "test four" (gBananas)

Rules to provoke a flurry of member updates alongside searches available on request, most relevant part

try {
		val local1 = gBananas.members.findFirst[ i | i.name=="test1"]
...
		val local4 = gBananas.members.findFirst[ i | i.name=="test4"]
		logInfo("test", "Here {} {} {} {}", local1, local2, local3, local4)
	} catch(Exception e) {
        logError("test", "An exception occurred: {}", e.getMessage(), e)
    }

openhab.log

2019-12-19 20:19:46.996 [ERROR] [.eclipse.smarthome.model.script.test] - An exception occurred: null
java.lang.IllegalStateException: null
	at org.eclipse.xtext.xbase.typesystem.references.UnboundTypeReference.doCopyInto(UnboundTypeReference.java:684) ~[?:?]
	at org.eclipse.xtext.xbase.typesystem.references.UnboundTypeReference.copyInto(UnboundTypeReference.java:440) ~[?:?]
	at org.eclipse.xtext.xbase.typesystem.internal.ResolvedTypes.toOwnedReference(ResolvedTypes.java:599) ~[?:?]
	at org.eclipse.xtext.xbase.typesystem.internal.ResolvedTypes.getExpectedType(ResolvedTypes.java:622) ~[?:?]
	at org.eclipse.xtext.xbase.typesystem.internal.ForwardingResolvedTypes.getExpectedType(ForwardingResolvedTypes.java:90) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:201) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
	at com.sun.proxy.$Proxy241.apply(Unknown Source) ~[?:?]
	at org.eclipse.xtext.xbase.lib.IteratorExtensions.findFirst(IteratorExtensions.java:108) ~[?:?]
	at org.eclipse.xtext.xbase.lib.IterableExtensions.findFirst(IterableExtensions.java:80) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor125.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_181]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1175) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1150) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1136) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1081) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:861) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:231) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:916) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:275) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:458) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:239) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:650) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:271) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:458) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:239) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:201) ~[?:?]
	at org.eclipse.smarthome.model.script.runtime.internal.engine.ScriptImpl.execute(ScriptImpl.java:81) ~[?:?]
	at org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl.lambda$2(RuleEngineImpl.java:313) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [?:1.8.0_181]
	at java.util.concurrent.FutureTask.run(Unknown Source) [?:1.8.0_181]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source) [?:1.8.0_181]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [?:1.8.0_181]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:1.8.0_181]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:1.8.0_181]
	at java.lang.Thread.run(Unknown Source) [?:1.8.0_181]

[openhab-bot]

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/lambda-randomly-fails-with-script-execution-of-rule-with-uid-failed-null-in/124966/2

[J-N-K]

I wasn't able to reproduce this on a recent OH3.3 snapshot build Does anyone still see this error and can provide a complete set of items/rules that reproduces this issue?

[Rossko57]

I have no 3.3 platform to test it

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.