Binding not yet ready in startup sequence, how to detect

Peter_Novotny · February 26, 2023, 11:42am

When migrating from OH2 to OH3 startup is not executed. In openhab log is

2023-02-26 11:51:52.905 [INFO ] [.thing.internal.GenericThingProvider] - No ThingHandlerFactory found for thing exec:command:arduino_send (thing-type is exec:command). Deferring initialization.
2023-02-26 11:51:52.909 [INFO ] [.thing.internal.GenericThingProvider] - No ThingHandlerFactory found for thing exec:command:persistence (thing-type is exec:command). Deferring initialization.

skipping log garbage from startup

2023-02-26 11:52:03.902 [INFO ] [rg.openhab.core.model.script.STARTUP] - Startup finished...

In events log is

2023-02-26 11:52:05.084 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:arduino_send' changed from UNINITIALIZED to INITIALIZING
2023-02-26 11:52:05.104 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:arduino_send' changed from INITIALIZING to ONLINE
2023-02-26 11:52:05.112 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:persistence' changed from UNINITIALIZED to INITIALIZING
2023-02-26 11:52:05.128 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:persistence' changed from INITIALIZING to ONLINE

Startup needs the bindings, but as you see the bindings have started cca 2 seconds after startup finished, all exec commands in startup returned NULL.

Searching this forum gets me to idea of waiting for needed exec bindings to be ONLINE and I have created this code:

var ThingStatus = Java.type("org.openhab.core.thing.ThingStatus")
var Thing_exec_binding = Java.type("org.openhab.core.model.script.actions.Things")
var persistence_binding_status = Thing_exec_binding.getThingStatusInfo("exec:command:persistence")
var arduino_binding_status = Thing_exec_binding.getThingStatusInfo("exec:command:arduino_send")
rule "Startup"
  when 
    System started
  then
    logInfo ("STARTUP", "System Starting...")
    auto_runner_lock.lock()
    while ((persistence_binding_status != ThingStatus.ONLINE) || (arduino_binding_status != ThingStatus.ONLINE)) {
      logInfo ("STARTUP", "Waiting for exec bindings to start, currently persistence: "+persistence_binding_status+" arduino:"+arduino_binding_status)
      Thread::sleep (1234)
      persistence_binding_status = Thing_exec_binding.getThingStatusInfo("exec:command:persistence")
      arduino_binding_status = Thing_exec_binding.getThingStatusInfo("exec:command:arduino_send")
    }

When uploaded to OH3 there is following error:

2023-02-26 12:10:53.237 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'rollershutter.rules', using it anyway:
The field Tmp_rollershutterRules.Thing_exec_binding refers to the missing type Object
The field Tmp_rollershutterRules.Thing_exec_binding refers to the missing type Object
The field Tmp_rollershutterRules.persistence_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.arduino_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.persistence_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.arduino_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.persistence_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.Thing_exec_binding refers to the missing type Object
The field Tmp_rollershutterRules.arduino_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.Thing_exec_binding refers to the missing type Object
2023-02-26 12:11:09.134 [WARN ] [e.runtime.internal.RuleContextHelper] - Variable 'Thing_exec_binding' on rule file 'rollershutter.rules' cannot be initialized with value '<XFeatureCallImplCustom>.type(<XStringLiteralImpl>)': The name 'Java' cannot be resolved to an item or type; line 16, column 26, length 4
2023-02-26 12:11:09.140 [WARN ] [e.runtime.internal.RuleContextHelper] - Variable 'persistence_binding_status' on rule file 'rollershutter.rules' cannot be initialized with value '<XFeatureCallImplCustom>.getThingStatusInfo(<XStringLiteralImpl>)': 'getThingStatusInfo' is not a member of 'Object'; line 17, column 34, length 65
2023-02-26 12:11:09.145 [WARN ] [e.runtime.internal.RuleContextHelper] - Variable 'arduino_binding_status' on rule file 'rollershutter.rules' cannot be initialized with value '<XFeatureCallImplCustom>.getThingStatusInfo(<XStringLiteralImpl>)': 'getThingStatusInfo' is not a member of 'Object'; line 18, column 30, length 66

Can someone please guide me what I’m doing wrong. I’m not very good at the specific language used in openhab rules.

Thank you

Wolfgang_S · February 26, 2023, 12:50pm

You imported the rule into OH3 ? Which scripting language did you select ?

Peter_Novotny · February 26, 2023, 1:00pm

I’m using file named rollershutter.rules that I put into /etc/openhab/rules/.
There is no special language identification, adapting file from OH2 it is/was named DSL if I’m right.

To complete information: Running on Raspberry pi 3B+ with Raspbian 11 and zulu java

Wolfgang_S · February 26, 2023, 1:09pm

Isn’t your script content using JavaScript syntax while it should be DSL ?
An example for DSL rule can be found here

Peter_Novotny · February 26, 2023, 1:35pm

You are right, I have looked in the manual and google but can not see the link you posted. Modified my code in following way:

var persistence_binding_status = getThingStatusInfo("exec:command:persistence")
var arduino_binding_status = getThingStatusInfo("exec:command:arduino_send")

rule "Startup"
  when 
    System started
  then
    logInfo ("STARTUP", "System Starting...")
    auto_runner_lock.lock()
    logInfo ("STARTUP", "Before binding wait loop: "+persistence_binding_status.getStatus().toString()+" arduino:"+arduino_binding_status.getStatus().toString())
    while (((persistence_binding_status == null) || (persistence_binding_status.getStatus().toString() != "ONLINE")) || ((arduino_binding_status == null) || (arduino_binding_status.getStatus().toString() != "ONLINE"))) {
      logInfo ("STARTUP", "Waiting for exec bindings to start, currently persistence: "+persistence_binding_status.getStatus().toString()+" arduino:"+arduino_binding_status.getStatus().toString())
      Thread::sleep (1234)
      persistence_binding_status = getThingStatusInfo("exec:command:persistence")
      arduino_binding_status = getThingStatusInfo("exec:command:arduino_send")
    }
    logInfo ("STARTUP", "After binding wait loop "+persistence_binding_status.getStatus().toString()+" arduino:"+arduino_binding_status.getStatus().toString())

In log is

2023-02-26 14:27:36.741 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rollershutter.rules'
2023-02-26 14:28:10.506 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'rollershutter.rules', using it anyway:
The field Tmp_rollershutterRules.persistence_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.arduino_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.persistence_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.persistence_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.arduino_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.arduino_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.persistence_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.arduino_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.persistence_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.arduino_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.persistence_binding_status refers to the missing type Object
The field Tmp_rollershutterRules.arduino_binding_status refers to the missing type Object
2023-02-26 14:28:27.261 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
2023-02-26 14:28:40.591 [INFO ] [rg.openhab.core.model.script.STARTUP] - System Starting... home_away status: OFF
2023-02-26 14:28:40.606 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'rollershutter-1' failed: cannot invoke method public org.openhab.core.thing.ThingStatus org.openhab.core.thing.ThingStatusInfo.getStatus() on null in rollershutter
2023-02-26 14:28:40.611 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.

Made one more attempt adding

import org.openhab.core.thing.ThingStatus

as first line of my code, but error is the same. Anything I miss?

Peter_Novotny · February 26, 2023, 8:27pm

With help of this post submitted by nyholm I have made following modification and reached working state even when it is definitely very bad workaround.

Added one new item:

// STARTUP DELAYER
Switch LATE_STARTUP "Swith to delay startup"

And modified rules like this

rule "System_Startup_Delayer"
  when
    System started
  then
    Thread::sleep(5000)
// please repeat previous line 24x I have removed from this code to make it more readable  
// see original poster explanation that loop does not work and I can confirm it
    LATE_STARTUP.sendCommand(ON)
end
rule "RealStartup"
  when 
    Item LATE_STARTUP received command ON
  then
    logInfo ("STARTUP", "System Starting...")
// normal startup actions here
    LATE_STARTUP.sendCommand(OFF)

There is one problem with this workaround, as some inputs are fed to system via api, it is possible that input will arrive earlier than startup is made. This can not be resolved as any assignment, lock or other action will trigger error during startup.
I feel very bad about this workaround, but hope it will not cause too much trouble.