OH3: migrated rules to from OH2 throwing random script errors

  • openHABian 3.3.0 on rPi4 4GB

I have a rule migrated from OH2, modified to fit the OH3 calls; however, it throws a script error as it feels like. It runs for a few days without an error, and then has a day where it throws an error.
The rule runs to completion.

The error is:

2022-12-05 11:26:11.091 [INFO ] [.core.model.script.Irrigation1.07.07] - ... Valve 4 deltaVolume is.............. 48
2022-12-05 11:26:11.098 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'irrigation1-8' failed: null in irrigation1
2022-12-05 11:26:25.061 [INFO ] [.core.model.script.Irrigation1.06.11] - Irrigation1: group finished.

This is the rule:

rule "Irrigation 1: Irrigation valves OFF"
    when
        Member of gIrrigation1 received command OFF
    then
        // figure out which valve was shut OFF
        // e.g. Irrigation1_1
        val nameParts   = triggeringItem.name.split('_')
        val valveNumber = nameParts.get(1)
        val valveFlow   = PumpStation1_Flow.state as Number
        val pumpMeter   = PumpStation1_Meter.state as Number

        // subtract the memorised meter reading at valve ON event
        // from the current meter reading
        val valveVolume = pumpMeter - g_MemoriseMeterRead


        // ----- update valve flow
        // get current flow rate from irrigation controller as update via MQTT;
        // should be reflective of mean at end of valve duration
        // and send flow rate for this session to item
        if (PUBLISH == 1) mqttActions.publishMQTT(mqttTopicRoot + "Flow" + valveNumber, valveFlow.toString)

        if (DEBUG == 2)
        {
            logInfo(logPrefix + "80", "... Valve {} is now OFF - flow was....... {}", valveNumber, valveFlow.toString)
        }


        // ----- update volumes
        // send valve volume to valve volume item for site map display
        // we are updating the item via MQTT! Why? Why not postUpdate()?
        if (PUBLISH == 1) mqttActions.publishMQTT(mqttTopicRoot + "Volume" + valveNumber, valveVolume.toString)

        if (DEBUG == 1)
        {
            logInfo(logPrefix + "07.01", "... Valve {} volume is................... {}", valveNumber, valveVolume.toString)
        }


        // 20210429 added on the suspicion of things not updating fast enough
        Thread::sleep(500)

        if (DEBUG == 1)
        {
            logInfo(logPrefix + "07.02", "... Valve {} volume is (after delay)..... {}", valveNumber, valveVolume.toString)
        }


        // update SessionMemory by ading this valve's volume to it
        var sessionMemory = (PumpStation1_LastSessionMemory.state as Number) + valveVolume

        if (DEBUG == 1)
        {
            logInfo(logPrefix + "07.03", "... new sessionMemory is (prev+current). {}", sessionMemory)
        }

        PumpStation1_LastSessionMemory.postUpdate(sessionMemory)
        // 20210429 added on the suspicion of things not updating fast enough
        Thread::sleep(500)

        if (DEBUG == 1)
        {
            logInfo(logPrefix + "07.04", "... updated LastSessionMemory is (=83).. {}", PumpStation1_LastSessionMemory.state.toString)
        }

        // check for valve volume out of tolerance and send email
        // e.g. Irrigation1_1_BaseVolume
        // build the item name
        // next line from https://community.openhab.org/t/rules-dsl-get-item-from-string-name/48279
        val baseVolumeItem = ScriptServiceUtil.getItemRegistry.getItem("Irrigation1_" + valveNumber + "_BaseVolume") as GenericItem

        // e.g.           320
        val baseVolume = (baseVolumeItem.state as Number).intValue

        // e.g.     -22 = 298                  - 320
        val deltaVolume = valveVolume.intValue - baseVolume

        if (DEBUG == 1)
        {
            logInfo(logPrefix + "07.05", "... Valve {} baseVolume is set to........ {}", valveNumber, baseVolume)
            logInfo(logPrefix + "07.06", "... Valve {} valveVolume is.............. {}", valveNumber, valveVolume.intValue)
            logInfo(logPrefix + "07.07", "... Valve {} deltaVolume is.............. {}", valveNumber, deltaVolume)
        }

        // e.g. 15 litres plus/minus
        val toleranceVolume = (PumpStation1_ToleranceVolume.state as Number).intValue

        // Generate email message
        var mailSubject = "OH3 Irrigation1: Valve " + valveNumber + " is " + Math::abs(deltaVolume)

        if (Math::abs(deltaVolume) > toleranceVolume)
        {
            if (deltaVolume > 0)
            {
                mailSubject = mailSubject + " litres more"
            }
            else
            {
                mailSubject = mailSubject + " litres less"
            }

            mailSubject = mailSubject + " than the baseline of " + baseVolume + " litres."
            mailActions.sendMail(
                emailToMax,
                mailSubject,
                "Please check sprinklers attached to valve " + valveNumber + "..."
            )
        }
end

Now, before I get grief for this weird item update via MQTT; I thought about it today, Why I would do such a thing. The only answer I could come up with was: I did back then (not even today) figure out how to build an item name.
This rule is switching off a number of valves.

Any hints appreciated.

You’re going to need to add lots of logging to narrow down where the error is. At this point all we can say is the error happens sometime after the log for deltaVolume.

Most of the time a failed: null error is caused by a type problem. An Item is NULL and you tried to use it in a calculation as if it were a Number for example. Another common example is if an Item is carrying units and you are trying to do math with it with values that do not carry units or carry incompatible units.

The only red flag I see is you appear to have acquired the handle to mailActions outside of the rule. This is a bad idea because if at some point the Thing goes offline after you’ve loaded the rule, that handle will become stale and cease working. Always get the handle on the Thing actions inside the rule just before you use it.

1 Like

Thanks Rich…

This rule actually completes, rather than bailing out after the error.
What puzzled me here is, it complains one day not the other…

Have moved the mailActions before the call…
Have also moved the mqttActions into the individual rules (not seen in my example).
Have fixed all rules WRT action location…

Have also figured how to compose the itemName:

        var itemName = ScriptServiceUtil.getItemRegistry.getItem("Irrigation1_" + valveNumber + "_ValveFlow") as GenericItem
        itemName.postUpdate(valveFlow)

… which is funny, as I had this line elsewhere in this rule (go figure)
Will see how this works instead of using publishMQTT()…

Have removed the Thread::sleep(500) with the reasoning that it does not matter when the item is updated, as it it is not used for any calculations, where a delay in update could cause an issue.

I have marked your reply as solution, but will report back if the error still occurs.

No it doesn’t, but it might have run twice.

Why would it have run twice?
I can’t see evidence of this in the log… here from yesterday and today.
BTW: today ran w/o error; however, I have changed the mqttPublish to ScriptServiceUtil calls.

2022-12-05 11:26:10.064 [INFO ] [.core.model.script.Irrigation1.07.01] - ... Valve 4 volume is................... 198
2022-12-05 11:26:10.566 [INFO ] [.core.model.script.Irrigation1.07.02] - ... Valve 4 volume is (after delay)..... 198
2022-12-05 11:26:10.568 [INFO ] [.core.model.script.Irrigation1.07.03] - ... new sessionMemory is (prev+current). 894
2022-12-05 11:26:11.071 [INFO ] [.core.model.script.Irrigation1.07.04] - ... updated LastSessionMemory is (=83).. 894
2022-12-05 11:26:11.085 [INFO ] [.core.model.script.Irrigation1.07.05] - ... Valve 4 baseVolume is set to........ 150
2022-12-05 11:26:11.088 [INFO ] [.core.model.script.Irrigation1.07.06] - ... Valve 4 valveVolume is.............. 198
2022-12-05 11:26:11.091 [INFO ] [.core.model.script.Irrigation1.07.07] - ... Valve 4 deltaVolume is.............. 48
2022-12-05 11:26:11.098 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'irrigation1-8' failed: null in irrigation1
2022-12-05 11:26:25.061 [INFO ] [.core.model.script.Irrigation1.06.11] - Irrigation1: group finished.
2022-12-05 11:26:25.075 [INFO ] [.core.model.script.Irrigation1.04.02] - Irrigation1: reset Auto Switch
2022-12-05 11:26:25.083 [INFO ] [.core.model.script.Irrigation1.09.01] - Irrigation1: stopping = cancelling timer(s)
2022-12-05 11:26:25.087 [INFO ] [.core.model.script.Irrigation1.09.04] - Irrigation1: turning ON pump failsafe and timer

2022-12-06 11:26:10.113 [INFO ] [.core.model.script.Irrigation1.07.01] - ... Valve 4 volume is................... 194
2022-12-06 11:26:10.116 [INFO ] [.core.model.script.Irrigation1.07.02] - ... Valve 4 volume is (after delay)..... 194
2022-12-06 11:26:10.118 [INFO ] [.core.model.script.Irrigation1.07.03] - ... new sessionMemory is (prev+current). 876
2022-12-06 11:26:10.122 [INFO ] [.core.model.script.Irrigation1.07.04] - ... updated LastSessionMemory is (=83).. 876
2022-12-06 11:26:10.126 [INFO ] [.core.model.script.Irrigation1.07.05] - ... Valve 4 baseVolume is set to........ 150
2022-12-06 11:26:10.128 [INFO ] [.core.model.script.Irrigation1.07.06] - ... Valve 4 valveVolume is.............. 194
2022-12-06 11:26:10.129 [INFO ] [.core.model.script.Irrigation1.07.07] - ... Valve 4 deltaVolume is.............. 44
2022-12-06 11:26:25.107 [INFO ] [.core.model.script.Irrigation1.06.11] - Irrigation1: group finished.
2022-12-06 11:26:25.113 [INFO ] [.core.model.script.Irrigation1.04.02] - Irrigation1: reset Auto Switch
2022-12-06 11:26:25.119 [INFO ] [.core.model.script.Irrigation1.09.01] - Irrigation1: stopping = cancelling timer(s)
2022-12-06 11:26:25.122 [INFO ] [.core.model.script.Irrigation1.09.04] - Irrigation1: turning ON pump failsafe and timer

Only if you got two triggers - we cannot see that, but you can.

If it didn’t run twice, then it didn’t “complete”, however you are deciding that happened. A script error will bail out, is all I am saying.