OpenHAB 3: System started issue with random errors => solved

Matthias_Kaufmann · January 4, 2021, 2:46pm

Dear all,

I upgraded to OH 3 and combined this to move my installation from RP4 to Docker on Synology.
I experienced kind of a random behavior in some rules. For example I have a own booting routine to ensure a deterministic boot order of my rules. When booting OH3, I get randomly errors for the identical script. If I just reload the same rule file again, it might work or might not work.
Is there anything known?

Error message (not quite helpful, no line of code etc)

Script execution of rule with UID ‘boot-2’ failed: sleep interrupted in boot

var boot_onetime_finished = 0

rule "Boot"

when

    System started

then

    BootFinished.sendCommand(OFF)

end

rule "Boot via Cron"

when

    Item BootStart received command ON or

    Time cron "0/30 * * ? * * *" // Alle 30 Sekunden

then

    if (boot_onetime_finished == 0) {

        boot_onetime_finished = 1

        BootStart.sendCommand (OFF)

        BootFinished.sendCommand(OFF)

        BootUIStart.sendCommand(OFF)

        BootUIFinished.sendCommand(OFF)

        BootGoogleHomeStart.sendCommand(OFF)

        BootGoogleHomeFinished.sendCommand(OFF)

        BootAnwesenheitStart.sendCommand(OFF)

        BootAnwesenheitFinished.sendCommand(OFF)

        BootSpeedTestStart.sendCommand(OFF)

        BootSpeedTestFinished.sendCommand(OFF)

        BootTimeOfTheDayStart.sendCommand(OFF)

        BootTimeOfTheDayFinished.sendCommand(OFF)

        BootZigbeeStart.sendCommand(OFF)

        BootZigbeeFinished.sendCommand(OFF)

        val mailActions = getActions("mail","mail:smtp:gmail")

        mailActions.sendMail("xxx", "OpenHAB Boot gestartet","OpenHAB Boot gestartet")

        logInfo("Boot: ","Start")

        BootStatus.sendCommand("Start")

        // Persistance

        logInfo("Boot: ","Persistance Laden: Warten")

        BootStatus.sendCommand("Persistance Laden: Warten")

        while (BootPersistanceFinished.state != ON) {

        }

        Thread::sleep(10*1000)

        logInfo("Boot: ","Persistance Laden: Abgeschlossen")

        BootStatus.sendCommand("Persistance Laden: Abgeschlossen")

        

        // UI

        logInfo("Boot: ","UI: Gestartet, warten")

        BootStatus.sendCommand("UI: Gestartet, warten")

        BootUIFinished.sendCommand(OFF)

        BootUIStart.sendCommand(ON)

        while (BootUIFinished.state != ON) {

        }

        Thread::sleep(10*1000)

        logInfo("Boot: ","UI: Abgeschlossen")

        BootStatus.sendCommand("UI: Abgeschlossen")

        // Google home

        logInfo("Boot: ","Google Home: Gestartet, warten")

        BootStatus.sendCommand("Google Home: Gestartet, warten")

        BootGoogleHomeFinished.sendCommand(OFF)

        BootGoogleHomeStart.sendCommand(ON)

        while (BootGoogleHomeFinished.state != ON) {

        }

        Thread::sleep(10*1000)

        logInfo("Boot: ","Google Home: Abgeschlossen")

        BootStatus.sendCommand("Google Home: Abgeschlossen")

        // Time Of The Day

        logInfo("Boot: ","Time Of The Day: Gestartet, warten")

        BootStatus.sendCommand("Time Of The Day: Gestartet, warten")

        BootTimeOfTheDayFinished.sendCommand(OFF)

        BootTimeOfTheDayStart.sendCommand(ON)

        while (BootTimeOfTheDayFinished.state != ON) {

        }

        Thread::sleep(10*1000)

        logInfo("Boot: ","Time Of The Day: Abgeschlossen")

        BootStatus.sendCommand("Time Of The Day: Abgeschlossen")

        // Anwesenheit

        logInfo("Boot: ","Anwesenheit: Gestartet, warten")

        BootStatus.sendCommand("Anwesenheit: Gestartet, warten")

        BootAnwesenheitFinished.sendCommand(OFF)

        BootAnwesenheitStart.sendCommand(ON)

        while (BootAnwesenheitFinished.state != ON) {

        }

        Thread::sleep(10*1000)

        logInfo("Boot: ","Anwesenheit: Abgeschlossen")

        BootStatus.sendCommand("Anwesenheit: Abgeschlossen")

        // Speed Test  

        logInfo("Boot: ","Speed Test: Gestartet, warten")

        BootStatus.sendCommand("Speed Test: Gestartet, warten")

        BootSpeedTestFinished.sendCommand(OFF)

        BootSpeedTestStart.sendCommand(ON)

        while (BootSpeedTestFinished.state != ON) {

        }

        Thread::sleep(10*1000)

        logInfo("Boot: ","Speed Test: Abgeschlossen")

        BootStatus.sendCommand("Speed Test: Abgeschlossen")

        // Zigbee

        logInfo("Boot: ","Zigbee: Gestartet, warten")

        BootStatus.sendCommand("Zigbee: Gestartet, warten")

        BootZigbeeFinished.sendCommand(OFF)

        BootZigbeeStart.sendCommand(ON)

        while (BootZigbeeFinished.state != ON) {

        }

        Thread::sleep(10*1000)

        logInfo("Boot: ","Zigbee: Abgeschlossen")

        BootStatus.sendCommand("Zigbee: Abgeschlossen")

        BootStatus.sendCommand("Abgeschlossen")

        BootFinished.sendCommand(ON)

        mailActions.sendMail("xxx", "OpenHAB Boot beendet","OpenHAB Boot beendet")

    }

end

Happy for help!

Thanks and best
MatzeMuc86

Sascha_Billian · January 4, 2021, 4:21pm

The problem seems to be caused by the sleep commands within your rule. They are quite long and other processes during the system start could cause issues. That’s at least how I interpret the error message. You should in general avoid waiting so long within a rule.

rossko57 · January 4, 2021, 5:05pm

Your rules are helpfully populated with logging messages; what do they tell you?

The longish sleeps and while-loops in rules make me queasy; having said that there is no obvious problem apart from the cumulative long run time of the whole rule. I wonder if the new engine includes a watchdog (which would most likely hit a sleep).

Matthias_Kaufmann · January 4, 2021, 7:03pm

I had extreme issues with System Started (not the only one) with parallel firing rules etc. Hence I had to come up with a different solution. That’s just the best I had so far - honestly dramatically more stable than OH 2.5. The log is there as too many things went wrong, hence I can “observe” the boot procedure. As said, nothing I like but obviously no trivial alternative has been there.

Anyhow : I took your feedback into account, removed the sleep and almost all while loops, see code attached.

rule "Boot"
when
    System started
then
    BootFinished.sendCommand(OFF)
    BootStart.sendCommand (ON)
end

rule "Boot via Cron"
when
    Item BootStart received command ON
then
    BootStart.sendCommand (OFF)
    BootFinished.sendCommand(OFF)
    BootUIStart.sendCommand(OFF)
    BootUIFinished.sendCommand(OFF)
    BootGoogleHomeStart.sendCommand(OFF)
    BootGoogleHomeFinished.sendCommand(OFF)
    BootAnwesenheitStart.sendCommand(OFF)
    BootAnwesenheitFinished.sendCommand(OFF)
    BootSpeedTestStart.sendCommand(OFF)
    BootSpeedTestFinished.sendCommand(OFF)
    BootTimeOfTheDayStart.sendCommand(OFF)
    BootTimeOfTheDayFinished.sendCommand(OFF)
    BootZigbeeStart.sendCommand(OFF)
    BootZigbeeFinished.sendCommand(OFF)

    val mailActions = getActions("mail","mail:smtp:gmail")
    mailActions.sendMail("xxx@gmail.com", "OpenHAB Boot gestartet","OpenHAB Boot gestartet")

    logInfo("Boot: ","Start")
    BootStatus.sendCommand("Start")

    // Persistance
    logInfo("Boot: ","Persistance Laden: Warten")
    BootStatus.sendCommand("Persistance Laden: Warten")
    while (BootPersistanceFinished.state != ON) {
    }
    logInfo("Boot: ","Persistance Laden: Abgeschlossen")
    BootStatus.sendCommand("Persistance Laden: Abgeschlossen")

    // UI
    logInfo("Boot: ","UI: Gestartet, warten")
    BootStatus.sendCommand("UI: Gestartet, warten")
    BootUIFinished.sendCommand(OFF)
    BootUIStart.sendCommand(ON)
end


rule "Boot UI"
when
    Item BootUIFinished changed to ON
then
    logInfo("Boot: ","UI: Abgeschlossen")
    BootStatus.sendCommand("UI: Abgeschlossen")

    // Google Home
    logInfo("Boot: ","Google Home: Gestartet, warten")
    BootStatus.sendCommand("Google Home: Gestartet, warten")
    BootGoogleHomeFinished.sendCommand(OFF)
    BootGoogleHomeStart.sendCommand(ON)
end

rule "Boot Google Home"
when
    Item BootGoogleHomeFinished changed to ON
then
    logInfo("Boot: ","Google Home: Abgeschlossen")
    BootStatus.sendCommand("Google Home: Abgeschlossen")

    // Time Of The Day
    logInfo("Boot: ","Time Of The Day: Gestartet, warten")
    BootStatus.sendCommand("Time Of The Day: Gestartet, warten")
    BootTimeOfTheDayFinished.sendCommand(OFF)
    BootTimeOfTheDayStart.sendCommand(ON)
end

rule "Boot Time of The Day"
when
    Item BootTimeOfTheDayFinished changed to ON
then
    logInfo("Boot: ","Time Of The Day: Abgeschlossen")
    BootStatus.sendCommand("Time Of The Day: Abgeschlossen")

    // Anwesenheit
    logInfo("Boot: ","Anwesenheit: Gestartet, warten")
    BootStatus.sendCommand("Anwesenheit: Gestartet, warten")
    BootAnwesenheitFinished.sendCommand(OFF)
    BootAnwesenheitStart.sendCommand(ON)
end

rule "Boot Anwesenheit"
when
    Item BootAnwesenheitFinished changed to ON
then
    logInfo("Boot: ","Anwesenheit: Abgeschlossen")
    BootStatus.sendCommand("Anwesenheit: Abgeschlossen")

    // Speed Test  
    logInfo("Boot: ","Speed Test: Gestartet, warten")
    BootStatus.sendCommand("Speed Test: Gestartet, warten")
    BootSpeedTestFinished.sendCommand(OFF)
    BootSpeedTestStart.sendCommand(ON)
end   

rule "Boot SpeedTest"
when
    Item BootSpeedTestFinished changed to ON
then
    logInfo("Boot: ","Speed Test: Abgeschlossen")
    BootStatus.sendCommand("Speed Test: Abgeschlossen")

    // Zigbee
    logInfo("Boot: ","Zigbee: Gestartet, warten")
    BootStatus.sendCommand("Zigbee: Gestartet, warten")
    BootZigbeeFinished.sendCommand(OFF)
    BootZigbeeStart.sendCommand(ON)
end

rule "Boot Zigbee"
when
    Item BootZigbeeFinished changed to ON
then
    logInfo("Boot: ","Zigbee: Abgeschlossen")
    BootStatus.sendCommand("Zigbee: Abgeschlossen")


    BootStatus.sendCommand("Abgeschlossen")
    BootFinished.sendCommand(ON)
    
    val mailActions = getActions("mail","mail:smtp:gmail")
    mailActions.sendMail("xxx", "OpenHAB Boot beendet","OpenHAB Boot beendet")
end

Nevertheless: When the rule is started via “system started”, I get the error as follows:

2021-01-04 19:59:55.693 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID ‘boot-2’ failed: ‘sendMail’ is not a member of ‘org.openhab.core.thing.binding.ThingActions’; line 29, column 5, length 104 in boot

If I start the same rule manually, everything works fine - just a miracle especially as line 29 with the sending the mail command should be independent of the rule logic anyhow!?

rossko57 · January 4, 2021, 7:13pm

This looks exactly like a classic startup OH2 issue, where the rule tries to get hold of an Action that a binding has not yet made available.
I would say back to the drawing board and attempting to delay stuff.

If the “sleep” error is something to do with extended rule run time, you might try spinning off tasks using createTimer() rather than plodding through a long series of tasks in line.

When OH3 was being birthed, there werea few comments along the lines of “all startup races solved!” and I was dubious …

Sascha_Billian · January 5, 2021, 8:56am

You could switch an item with e.g. a expiration time of one minute to ON when system started triggers. Then you can trigger your rule when this item is expired. As a result you have a delayed startup rule which assures that all bindings are initialized

Matthias_Kaufmann · January 5, 2021, 6:39pm

The timer in the System started rule is the solution (3x rebooting = 3x successful). Still wondering why the fresh OH3 needs again manual modifications to ensure rules are only fired once and after the rest of the system is started but anyhow, I have a solution ;-).

Actually 20 seconds would probably be enough. As I restart the system quite rarely I do not care about the duration but still saw some items firing updated (due to persistance!?) even 20 seconds after the system started rule => changed to 60.

rule "Boot"

when

    System started

then

    BootFinished.sendCommand(OFF)

    createTimer(now.plusSeconds(60)) [|

        BootStart.sendCommand (ON)

    ]   

    

end

rule "Boot via Cron"

when

    Item BootStart received command ON

then

    BootStart.sendCommand (OFF)

    BootFinished.sendCommand(OFF)

    BootUIStart.sendCommand(OFF)

    BootUIFinished.sendCommand(OFF)

    BootGoogleHomeStart.sendCommand(OFF)

    BootGoogleHomeFinished.sendCommand(OFF)

    BootAnwesenheitStart.sendCommand(OFF)

    BootAnwesenheitFinished.sendCommand(OFF)

    BootSpeedTestStart.sendCommand(OFF)

    BootSpeedTestFinished.sendCommand(OFF)

    BootTimeOfTheDayStart.sendCommand(OFF)

    BootTimeOfTheDayFinished.sendCommand(OFF)

    BootZigbeeStart.sendCommand(OFF)

    BootZigbeeFinished.sendCommand(OFF)

    val mailActions = getActions("mail","mail:smtp:gmail")

    mailActions.sendMail("xxx", "OpenHAB Boot gestartet","OpenHAB Boot gestartet")

    logInfo("Boot: ","Start")

    BootStatus.sendCommand("Start")

    // Persistance

    logInfo("Boot: ","Persistance Laden: Warten")

    BootStatus.sendCommand("Persistance Laden: Warten")

    while (BootPersistanceFinished.state != ON) {

    }

    logInfo("Boot: ","Persistance Laden: Abgeschlossen")

    BootStatus.sendCommand("Persistance Laden: Abgeschlossen")

    // UI

    logInfo("Boot: ","UI: Gestartet, warten")

    BootStatus.sendCommand("UI: Gestartet, warten")

    BootUIFinished.sendCommand(OFF)

    BootUIStart.sendCommand(ON)

end

rule "Boot UI"

when

    Item BootUIFinished changed to ON

then

    logInfo("Boot: ","UI: Abgeschlossen")

    BootStatus.sendCommand("UI: Abgeschlossen")

    // Google Home

    logInfo("Boot: ","Google Home: Gestartet, warten")

    BootStatus.sendCommand("Google Home: Gestartet, warten")

    BootGoogleHomeFinished.sendCommand(OFF)

    BootGoogleHomeStart.sendCommand(ON)

end

rule "Boot Google Home"

when

    Item BootGoogleHomeFinished changed to ON

then

    logInfo("Boot: ","Google Home: Abgeschlossen")

    BootStatus.sendCommand("Google Home: Abgeschlossen")

    // Time Of The Day

    logInfo("Boot: ","Time Of The Day: Gestartet, warten")

    BootStatus.sendCommand("Time Of The Day: Gestartet, warten")

    BootTimeOfTheDayFinished.sendCommand(OFF)

    BootTimeOfTheDayStart.sendCommand(ON)

end

rule "Boot Time of The Day"

when

    Item BootTimeOfTheDayFinished changed to ON

then

    logInfo("Boot: ","Time Of The Day: Abgeschlossen")

    BootStatus.sendCommand("Time Of The Day: Abgeschlossen")

    // Anwesenheit

    logInfo("Boot: ","Anwesenheit: Gestartet, warten")

    BootStatus.sendCommand("Anwesenheit: Gestartet, warten")

    BootAnwesenheitFinished.sendCommand(OFF)

    BootAnwesenheitStart.sendCommand(ON)

end

rule "Boot Anwesenheit"

when

    Item BootAnwesenheitFinished changed to ON

then

    logInfo("Boot: ","Anwesenheit: Abgeschlossen")

    BootStatus.sendCommand("Anwesenheit: Abgeschlossen")

    // Speed Test  

    logInfo("Boot: ","Speed Test: Gestartet, warten")

    BootStatus.sendCommand("Speed Test: Gestartet, warten")

    BootSpeedTestFinished.sendCommand(OFF)

    BootSpeedTestStart.sendCommand(ON)

end   

rule "Boot SpeedTest"

when

    Item BootSpeedTestFinished changed to ON

then

    logInfo("Boot: ","Speed Test: Abgeschlossen")

    BootStatus.sendCommand("Speed Test: Abgeschlossen")

    // Zigbee

    logInfo("Boot: ","Zigbee: Gestartet, warten")

    BootStatus.sendCommand("Zigbee: Gestartet, warten")

    BootZigbeeFinished.sendCommand(OFF)

    BootZigbeeStart.sendCommand(ON)

end

rule "Boot Zigbee"

when

    Item BootZigbeeFinished changed to ON

then

    logInfo("Boot: ","Zigbee: Abgeschlossen")

    BootStatus.sendCommand("Zigbee: Abgeschlossen")

    BootStatus.sendCommand("Abgeschlossen")

    BootFinished.sendCommand(ON)

    

    val mailActions = getActions("mail","mail:smtp:gmail")

    mailActions.sendMail("xxx@gmail.com", "OpenHAB Boot beendet","OpenHAB Boot beendet")

end

rossko57 · January 7, 2021, 12:54pm

Possibly. I’m sure in the early days that restore-on-startup always completed without generating bus events, but that may have been a fluke of timing.
Many bindings will of course update linked Items at variable times after startup, you would need to look at this in much more detail if you want to understand it.

Matthias_Kaufmann · January 7, 2021, 6:57pm

Makes sense - anyhow it feels like the big “rush” of updating the items right after reboot comes with a few seconds delay after the system started rule has finished. Might also just be my local setup.

system · February 18, 2021, 11:10am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.