search

openhab / openhab-core

Core framework of openHAB
https://www.openhab.org/
Eclipse Public License 2.0
925 stars 424 forks source link

Startup order rules vs io - sendBroadcastNotification not loading until after system start rules fire #1991

Open morph166955 opened 3 years ago

morph166955 commented 3 years ago

I believe this is an issue with the new startup order and not the binding itself, hence putting it here versus addons.

When OH3 loads org.openhab.io.* seems to be very far down in the startup process (almost at the bottom on mine). It looks like my rules load before org.openhab.io.openhabcloud has a chance to completely load. This causes errors like:

2020-12-22 16:48:16.611 [ERROR] [module.script.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'startup-3' failed: The name 'sendBroadcastNotification' cannot be resolved to an item or type; line 180, column 4, length 71 in startup

It also has a by-product that my startup rule notifications are not sent and the startup rules end up crashing (which is also confusing because they are in a "try {} finally {}" but that's another story).

morph166955 commented 3 years ago

Let me add some more info on this based on watching logs through restarts. "system started" rules trigger before the rules engine starts. This seems to cause a problem because the system isn't fully up at that point. All 4 below are "system started" triggers.

2020-12-23 12:57:54.450 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'startup-3' is executed. 2020-12-23 12:57:56.195 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'samsungtv_adfd-4' is executed. 2020-12-23 12:57:57.916 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'samsungtv_a4a4-4' is executed. 2020-12-23 12:57:59.553 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'samsungtv_b47c-4' is executed. 2020-12-23 12:57:59.553 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.

cweitkamp commented 3 years ago

@morph166955 With #2222 in place may I ask you to test if this issue is still present?

morph166955 commented 3 years ago

Sure, I haven't been following that one, anything specific I need to do to my scripts? Also to confirm, it looks like S2267 includes this as well as #2241 so I'll be loading that.

morph166955 commented 3 years ago

Running S2267 stock with no changes to my rules. It looks like trigger 2 for startup-3 is actually a cron job that runs once a minute. It also looks like the three samsung rules that are executed are item triggers caused by the startup-3 rule running. Why any are running before the rule engine started, not sure. Also same issue that sendBroadcastNotification is still not loaded at that point.

EDIT: trigger 2 is not a cron job. Sorry, I forgot that it counts at 0. trigger 2 is an item changing (which I'm actually not sure what is causing that item to change either, the only rule that actually changes that item is startup-3). 

2021-03-16 16:56:07.373 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'startup-3' is triggered.
2021-03-16 16:56:07.373 [DEBUG] [e.automation.internal.RuleEngineImpl] - Rule engine not yet started - not executing rule 'startup-3',
2021-03-16 16:56:07.375 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'startup-3' failed: The name 'sendBroadcastNotification' cannot be resolved to an item or type; line 197, column 4, length 71 in startup
javax.script.ScriptException: The name 'sendBroadcastNotification' cannot be resolved to an item or type; line 197, column 4, length 71 in startup
        at org.openhab.core.model.script.runtime.internal.engine.DSLScriptEngine.eval(DSLScriptEngine.java:135) ~[?:?]
        at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:62) [bundleFile:?]
        at java.util.Optional.ifPresent(Optional.java:183) [?:?]
        at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:59) [bundleFile:?]
        at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1179) [bundleFile:?]
        at org.openhab.core.automation.internal.RuleEngineImpl.runNow(RuleEngineImpl.java:1028) [bundleFile:?]
        at org.openhab.core.automation.internal.RuleEngineImpl.lambda$6(RuleEngineImpl.java:1441) [bundleFile:?]
        at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183) [?:?]
        at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177) [?:?]
        at java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1603) [?:?]
        at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484) [?:?]
        at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) [?:?]
        at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150) [?:?]
        at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173) [?:?]
        at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) [?:?]
        at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497) [?:?]
        at org.openhab.core.automation.internal.RuleEngineImpl.lambda$4(RuleEngineImpl.java:1441) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
2021-03-16 16:56:07.377 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'startup-3' is executed.
2021-03-16 16:56:09.505 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'samsungtv_adfd-4' is executed.
2021-03-16 16:56:11.646 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'samsungtv_a4a4-4' is executed.
2021-03-16 16:56:13.833 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'samsungtv_b47c-4' is executed.
2021-03-16 16:56:13.833 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
jpg0 commented 3 years ago

Something I just realised: the changes in #2222 pertain to the ScriptFileWatcher which I believe is only used for jsr233 scripts, so may not help startup issues for DSL rules.

cweitkamp commented 3 years ago

Thanks for testing. The differences to my case are that I am using JSR223 Python rules and the error message (see https://github.com/openhab/openhab-core/issues/1983#issuecomment-800570712) occurred while parsing the rule. You are trying to use the System started method in a DSL rule with trigger "System started". We probably cannot solve this easily unless implementing startlevel trigger for DSL rules.

morph166955 commented 3 years ago

No problem. Is it possible to load IO before the rules engne fires System started?