Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Rules refuse to load at startup due to jars in addons folder #3676

Closed
morph166955 opened this issue Jun 30, 2023 · 40 comments · Fixed by #3683
Closed

Rules refuse to load at startup due to jars in addons folder #3676

morph166955 opened this issue Jun 30, 2023 · 40 comments · Fixed by #3683
Labels
bug An unexpected problem or unintended behavior of the Core

Comments

@morph166955
Copy link

Upgraded from 3485 to 3519. I have 4 jars in my addons folder, and have for some time now. Since upgrading, at start the rules never fire. I let it sit for over 15 minutes at one point. Thinking I had a bad jar (which was unlikely as they all worked on 3485) I moved them out of the addons folder and immediately saw:

2023-06-30 15:03:00.153 [INFO ] [nal.ScriptEngineFactoryBundleTracker] - All automation bundles ready.

After further testing, moving ANY jar out of the addons folder seems to clear out the issue. It is irrelevant which jar is moved, it seems that the identification that a change happened is enough to break it free. I can move the jar right back in and everything works as expected.

@morph166955 morph166955 added the bug An unexpected problem or unintended behavior of the Core label Jun 30, 2023
@openhab-bot
Copy link
Collaborator

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

https://community.openhab.org/t/openhab-4-0-snapshot-discussion/142322/387

@lolodomo
Copy link
Contributor

lolodomo commented Jul 2, 2023

After installing the snapshot 3519 with almost nothing setup except few items, one DSL rule and one sitemap, I encountered a case where my feeling was that the rule was no more executed. My scenario was very different from yours (I updated Basic UI with bundle:update) but the result was apparently the same. So there may be a severe bug with rules recently introduced. I will have to investigate more to provide a reproducible scenario and confirm that the problem is really about rules.

At the same time, I upgraded my production openHAB server to that version without any problem.

@J-N-K
Copy link
Member

J-N-K commented Jul 2, 2023

Can you please check if bundle:list shows any bundle that is NOT active? And also please set org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker to DEBUG and check what messages are posted. Please also check the system start-level.

@morph166955
Copy link
Author

I'm not near it today, but can probably pull logs tomorrow.

@openhab-bot
Copy link
Collaborator

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

https://community.openhab.org/t/openhab-4-0-milestone-discussion/145133/490

@helmar74
Copy link

helmar74 commented Jul 2, 2023

Same Problem here, I don't have any addons in the addon folder:
image

@J-N-K
Copy link
Member

J-N-K commented Jul 2, 2023

Is there any bundle not "Active" when you list them?

@helmar74
Copy link

helmar74 commented Jul 2, 2023

Yes:

openhab> bundle:list | grep Reso
245 │ Active   │  80 │ 4.1.92.Final           │ Netty/Resolver
278 │ Resolved │  80 │ 4.0.0.M4               │ openHAB Add-ons :: Bundles :: Telegram Binding
292 │ Resolved │  80 │ 4.0.0.M4               │ openHAB Add-ons :: Bundles :: IO :: openHAB Cl
openhab>

@J-N-K
Copy link
Member

J-N-K commented Jul 2, 2023

If you uninstall them (instead of stopping them), do you have the same issue?

@helmar74
Copy link

helmar74 commented Jul 2, 2023

No as soon as all bundles are "Active" OH 4.0.0M4 starts up normally.
If I uninstall the Resolved bundles it startups normal.
Until 4.0.0M3 I was able to stop bundles and the restart of Openhab worked.

@morph166955
Copy link
Author

Lots o logs...

I tried to run date/time when commands executed to line it up to the logs.

System started at 17:10:22.188

System was basically loaded at 17:10:39.980 (Everything was Active by this point including the 4x jar addons as seen below):

296 │ Active │ 80 │ 4.0.0.202305151551 │ org.openhab.binding.ring
298 │ Active │ 80 │ 4.0.0.202306301807 │ org.openhab.binding.androidtv
301 │ Active │ 80 │ 4.0.0.202305251907 │ org.openhab.binding.rainsoft
302 │ Active │ 80 │ 4.0.0.202305171828 │ org.openhab.binding.rachio

At 17:15:50 I moved the rachio jar out of the addons folder

At 17:15:59.091 system notes All automation bundles ready.

At 17:16:07.833 system notes Rule engine started.

I reran the test by moving the androidtv jar out instead of rachio, same effect. androidtv is merged in at this point, that jar is almost identical to what's merged, it just includes the two current pending PRs which shouldn't have any impact.

2023-07-02 17:10:22.188 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 4.0.0 (build Build #3519)
2023-07-02 17:10:22.509 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'America/Chicago'.
2023-07-02 17:10:22.516 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '34.7316754,-86.7368729'.
2023-07-02 17:10:22.517 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_US'.
2023-07-02 17:10:22.518 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'US'.
2023-07-02 17:10:23.078 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : BundleComponentActivator : ComponentHolder created.
2023-07-02 17:10:23.105 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : Dependency Manager created $000interface=org.openhab.core.service.ReadyService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=service, parameter=0
2023-07-02 17:10:23.106 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : Dependency Manager created $001interface=org.openhab.core.service.StartLevelService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=service, parameter=1
2023-07-02 17:10:23.108 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2023-07-02 17:10:23.109 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : Component created: DS=DS14, implementation=org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker, immediate=true, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker]
2023-07-02 17:10:23.110 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : Component Services: scope=singleton, services=[org.openhab.core.service.ReadyService$ReadyTracker]
2023-07-02 17:10:23.111 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2023-07-02 17:10:23.113 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : Querying state disabled
2023-07-02 17:10:23.114 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : Querying state disabled
2023-07-02 17:10:23.115 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : Component can not be activated since it is in state disabled
2023-07-02 17:10:23.116 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker] : Querying state disabled
2023-07-02 17:10:23.117 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Updating target filters
2023-07-02 17:10:23.118 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : No change in target property for dependency $000: currently registered: false
2023-07-02 17:10:23.119 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] :  No existing service listener to unregister for dependency $000
2023-07-02 17:10:23.120 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Setting target property for dependency $000 to null
2023-07-02 17:10:23.121 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.service.ReadyService), initialReferenceFilter (objectClass=org.openhab.core.service.ReadyService)
2023-07-02 17:10:23.122 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm $000 tracker reset (closed)
2023-07-02 17:10:23.123 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.service.ReadyService}={service.id=191, service.bundleid=149, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.internal.service.ReadyServiceImpl, component.id=38} (enter)
2023-07-02 17:10:23.124 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false
2023-07-02 17:10:23.125 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.service.ReadyService}={service.id=191, service.bundleid=149, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.internal.service.ReadyServiceImpl, component.id=38} (exit)
2023-07-02 17:10:23.126 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm $000 tracker opened
2023-07-02 17:10:23.127 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : registering service listener for dependency $000
2023-07-02 17:10:23.128 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : No change in target property for dependency $001: currently registered: false
2023-07-02 17:10:23.128 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] :  No existing service listener to unregister for dependency $001
2023-07-02 17:10:23.129 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Setting target property for dependency $001 to null
2023-07-02 17:10:23.130 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : New service tracker for $001, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.service.StartLevelService), initialReferenceFilter (objectClass=org.openhab.core.service.StartLevelService)
2023-07-02 17:10:23.131 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm $001 tracker reset (closed)
2023-07-02 17:10:23.132 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.service.StartLevelService}={service.id=205, service.bundleid=149, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.service.StartLevelService, component.id=46, 80=things:handler, 70=dsl:sitemap, 50=ruleengine:start, 40=dsl:rules,managed:rule,rules:refresh,rules:dslprovider, 30=persistence:restore,automation:scriptEngineFactories, service.pid=org.openhab.startlevel, 20=dsl:items,managed:item,dsl:things,managed:thing,managed:itemchannellink,dsl:persist,managed:metadata} (enter)
2023-07-02 17:10:23.133 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm $001 tracking 2 SingleStatic active: false trackerOpened: false optional: false
2023-07-02 17:10:23.135 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.service.StartLevelService}={service.id=205, service.bundleid=149, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.service.StartLevelService, component.id=46, 80=things:handler, 70=dsl:sitemap, 50=ruleengine:start, 40=dsl:rules,managed:rule,rules:refresh,rules:dslprovider, 30=persistence:restore,automation:scriptEngineFactories, service.pid=org.openhab.startlevel, 20=dsl:items,managed:item,dsl:things,managed:thing,managed:itemchannellink,dsl:persist,managed:metadata} (exit)
2023-07-02 17:10:23.136 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm $001 tracker opened
2023-07-02 17:10:23.136 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : registering service listener for dependency $001
2023-07-02 17:10:23.137 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2023-07-02 17:10:23.138 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2023-07-02 17:10:23.139 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2023-07-02 17:10:23.139 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2023-07-02 17:10:23.140 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm osgi.ds.satisfying.condition tracking 3 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2023-07-02 17:10:23.141 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm osgi.ds.satisfying.condition tracking 3 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2023-07-02 17:10:23.142 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : dm osgi.ds.satisfying.condition tracker opened
2023-07-02 17:10:23.143 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : registering service listener for dependency osgi.ds.satisfying.condition
2023-07-02 17:10:23.144 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Changed state from disabled to unsatisfiedReference
2023-07-02 17:10:23.145 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Component enabled
2023-07-02 17:10:23.146 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : ActivateInternal
2023-07-02 17:10:23.147 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state unsatisfiedReference
2023-07-02 17:10:23.148 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state unsatisfiedReference
2023-07-02 17:10:23.149 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Activating component from state unsatisfiedReference
2023-07-02 17:10:23.150 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state unsatisfiedReference
2023-07-02 17:10:23.151 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state unsatisfiedReference
2023-07-02 17:10:23.151 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Changed state from unsatisfiedReference to satisfied
2023-07-02 17:10:23.152 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : registration change queue [registered]
2023-07-02 17:10:23.156 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Checking constructor public org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(org.openhab.core.service.ReadyService,org.openhab.core.service.StartLevelService,org.osgi.framework.BundleContext)
2023-07-02 17:10:23.157 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.service.ReadyService through loader of org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker
2023-07-02 17:10:23.161 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : getClassFromComponentClassLoader: Found class org.openhab.core.service.ReadyService
2023-07-02 17:10:23.162 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.service.StartLevelService through loader of org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker
2023-07-02 17:10:23.164 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : getClassFromComponentClassLoader: Found class org.openhab.core.service.StartLevelService
2023-07-02 17:10:23.165 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Found constructor with 3 arguments : public org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(org.openhab.core.service.ReadyService,org.openhab.core.service.StartLevelService,org.osgi.framework.BundleContext)
2023-07-02 17:10:23.166 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : This thread collected dependencies
2023-07-02 17:10:23.167 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : getService (single component manager) dependencies collected.
2023-07-02 17:10:23.167 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state satisfied
2023-07-02 17:10:23.168 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state satisfied
2023-07-02 17:10:23.169 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.service.ReadyService}={service.id=191, service.bundleid=149, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.internal.service.ReadyServiceImpl, component.id=38}] service: [null]]]
2023-07-02 17:10:23.170 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : For dependency $001, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.service.StartLevelService}={service.id=205, service.bundleid=149, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.service.StartLevelService, component.id=46, 80=things:handler, 70=dsl:sitemap, 50=ruleengine:start, 40=dsl:rules,managed:rule,rules:refresh,rules:dslprovider, 30=persistence:restore,automation:scriptEngineFactories, service.pid=org.openhab.startlevel, 20=dsl:items,managed:item,dsl:things,managed:thing,managed:itemchannellink,dsl:persist,managed:metadata}] service: [null]]]
2023-07-02 17:10:23.171 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2023-07-02 17:10:23.174 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - Added org.openhab.core.model.script.runtime: RESOLVED
2023-07-02 17:10:23.175 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : getting activate: activate
2023-07-02 17:10:23.176 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Locating method activate in class org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker
2023-07-02 17:10:23.177 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Declared Method org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-07-02 17:10:23.177 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Locating method activate in class org.osgi.util.tracker.BundleTracker
2023-07-02 17:10:23.178 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Declared Method org.osgi.util.tracker.BundleTracker.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-07-02 17:10:23.179 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Locating method activate in class java.lang.Object
2023-07-02 17:10:23.179 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-07-02 17:10:23.180 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : activate method [activate] not found, ignoring
2023-07-02 17:10:23.180 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Set implementation object for component
2023-07-02 17:10:23.181 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Changed state from satisfied to active
2023-07-02 17:10:30.139 [WARN ] [server.session.ServerUserAuthService] - handleUserAuthRequestMessage(ServerSessionImpl[null@/10.255.0.80:57613]) Failed (SshException) to authenticate using factory method=publickey: EdDSA provider not supported

(items load)
(persistence load)

2023-07-02 17:10:39.974 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: STARTING
2023-07-02 17:10:39.980 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: ACTIVE

(things load)
(rules load)

2023-07-02 17:11:18.544 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state active
2023-07-02 17:12:01.690 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state active
2023-07-02 17:12:10.201 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state active
2023-07-02 17:12:30.606 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state active
2023-07-02 17:14:59.494 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state active


openhab> shell:date && bundle:list -s | grep -v Active
Jul Sun 2 17:12:30 2023
START LEVEL 100 , List Threshold: 50
 ID │ State  │ Lvl │ Version                │ Symbolic name
────┼────────┼─────┼────────────────────────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
openhab> shell:date && bundle:list -s | grep -v Active
Jul Sun 2 17:14:59 2023
START LEVEL 100 , List Threshold: 50
 ID │ State  │ Lvl │ Version                │ Symbolic name
────┼────────┼─────┼────────────────────────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────


ubuntu@ubuntu:/raid/docker/openhab/addons$ date && sudo mv org.openhab.binding.rachio-4.0.0-SNAPSHOT-f5c3431.jar ..
Sun Jul  2 17:15:50 CDT 2023


2023-07-02 17:15:59.080 [INFO ] [internal.handler.RachioBridgeHandler] - RachioCloud: Shutting down
2023-07-02 17:15:59.091 [INFO ] [nal.ScriptEngineFactoryBundleTracker] - All automation bundles ready.
2023-07-02 17:16:00.402 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(101)] : Querying state active


2023-07-02 17:16:07.833 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.



@J-N-K
Copy link
Member

J-N-K commented Jul 3, 2023

I think I know the cause of this issue. Is anyone able to reproduce it for sure? I can provide a bundle that should fix it.

@helmar74
Copy link

helmar74 commented Jul 3, 2023

I think I know the cause of this issue. Is anyone able to reproduce it for sure? I can provide a bundle that should fix it.

If I stop one of the bundles in console, the Rule Engine doesn't start and event.log stays empty...
So, if your changes fixes it, I can try it...

@morph166955
Copy link
Author

I think I know the cause of this issue. Is anyone able to reproduce it for sure? I can provide a bundle that should fix it.

It happens every start for me. Easy enough to recreate.

@J-N-K
Copy link
Member

J-N-K commented Jul 3, 2023

Install the fixed bundle with

update org.openhab.core.automation.module.script https://janessa.me/esh/org.openhab.core.automation.module.script-4.0.0-SNAPSHOT.jar

and restart. Is everything working now?

@morph166955
Copy link
Author

morph166955 commented Jul 3, 2023

So a weird thing happened when I tried it. The upgrade worked:

openhab> bundle:list -s | grep script
158 │ Active │  80 │ 4.0.0.202306251610     │ org.openhab.core.automation.module.script
159 │ Active │  80 │ 4.0.0.202306251611     │ org.openhab.core.automation.module.script.rulesupport
199 │ Active │  80 │ 4.0.0.202306251612     │ org.openhab.core.model.script
200 │ Active │  80 │ 4.0.0.202306251612     │ org.openhab.core.model.script.ide
201 │ Active │  80 │ 4.0.0.202306251612     │ org.openhab.core.model.script.runtime
openhab> update org.openhab.core.automation.module.script https://janessa.me/esh/org.openhab.core.automation.module.script-4.0.0-SNAPSHOT.jar
openhab> bundle:list -s | grep script
158 │ Active  │  80 │ 4.0.0.202307031825     │ org.openhab.core.automation.module.script
159 │ Waiting │  80 │ 4.0.0.202306251611     │ org.openhab.core.automation.module.script.rulesupport
199 │ Active  │  80 │ 4.0.0.202306251612     │ org.openhab.core.model.script
200 │ Active  │  80 │ 4.0.0.202306251612     │ org.openhab.core.model.script.ide
201 │ Waiting │  80 │ 4.0.0.202306251612     │ org.openhab.core.model.script.runtime

When I restarted, it was back to the original version (all I did was turn the docker off and back on, I didn't clear any caches). However, when it came up it loaded like it was going to jam, then about 30 seconds later it sent:

2023-07-03 13:47:48.584 [INFO ] [nal.ScriptEngineFactoryBundleTracker] - All automation bundles ready.
2023-07-03 13:47:48.612 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
2023-07-03 13:47:48.667 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: STOPPING
2023-07-03 13:47:48.667 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: RESOLVED
2023-07-03 13:47:48.671 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(236)] : Querying state active
2023-07-03 13:47:48.672 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(236)] : Deactivating component
2023-07-03 13:47:48.673 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(236)] : registration change queue [unregistered]
2023-07-03 13:47:48.673 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(236)] : getting deactivate: deactivate
2023-07-03 13:47:48.674 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(236)] : Locating method deactivate in class org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker
2023-07-03 13:47:48.674 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(236)] : Declared Method org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker.deactivate([interface org.osgi.service.component.ComponentContext]) not found
2023-07-03 13:47:48.675 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(236)] : Found deactivate method: public void org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker.deactivate() throws java.lang.Exception
2023-07-03 13:47:48.675 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202306251610 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(236)] : invoking deactivate: deactivate: parameters []
2023-07-03 13:47:48.676 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - Removed org.openhab.core.model.script.runtime
2023-07-03 13:47:48.676 [INFO ] [nal.ScriptEngineFactoryBundleTracker] - All automation bundles ready.
2023-07-03 13:47:48.854 [INFO ] [nal.ScriptEngineFactoryBundleTracker] - All automation bundles ready.
2023-07-03 13:47:48.856 [DEBUG] [nal.ScriptEngineFactoryBundleTracker] - Added org.openhab.core.model.script.runtime: ACTIVE

And then it loaded my rules for a second time. At that point, they started working.

@J-N-K
Copy link
Member

J-N-K commented Jul 3, 2023

That's really strange. Does it happen again when you restart again? Which bundle is now shown by bundle:list?

@morph166955
Copy link
Author

It shows the original that came with the image. 4.0.0.202306251610. Maybe it's a docker thing?

@J-N-K
Copy link
Member

J-N-K commented Jul 3, 2023

Maybe. I don't use docker. Always trouble with things like that.

@morph166955
Copy link
Author

Is there a cleaner way to reload/restart from inside karaf? Any chance it's because these are sitting at Waiting?

openhab> bundle:list -s | grep script
158 │ Active │ 80 │ 4.0.0.202307031825 │ org.openhab.core.automation.module.script
159 │ Waiting │ 80 │ 4.0.0.202306251611 │ org.openhab.core.automation.module.script.rulesupport
199 │ Active │ 80 │ 4.0.0.202306251612 │ org.openhab.core.model.script
200 │ Active │ 80 │ 4.0.0.202306251612 │ org.openhab.core.model.script.ide
201 │ Waiting │ 80 │ 4.0.0.202306251612 │ org.openhab.core.model.script.runtime

@J-N-K
Copy link
Member

J-N-K commented Jul 3, 2023

No, they are waiting because they depend on the update bundle. This is why you need to restart. But of course, if everything is reverted, it'll not work.

@morph166955
Copy link
Author

I was able to catch it early on the restart. It looks like it dumped the update...

openhab> bundle:list -s | grep script
158 │ Waiting │ 80 │ 4.0.0.202307031825 │ org.openhab.core.automation.module.script
159 │ Active │ 80 │ 4.0.0.202306251611 │ org.openhab.core.automation.module.script.rulesupport
199 │ Resolved │ 80 │ 4.0.0.202306251612 │ org.openhab.core.model.script
200 │ Resolved │ 80 │ 4.0.0.202306251612 │ org.openhab.core.model.script.ide
201 │ Resolved │ 80 │ 4.0.0.202306251612 │ org.openhab.core.model.script.runtime
openhab> bundle:list -s | grep script
158 │ Waiting │ 80 │ 4.0.0.202306251610 │ org.openhab.core.automation.module.script
159 │ Active │ 80 │ 4.0.0.202306251611 │ org.openhab.core.automation.module.script.rulesupport
199 │ Waiting │ 80 │ 4.0.0.202306251612 │ org.openhab.core.model.script
200 │ Active │ 80 │ 4.0.0.202306251612 │ org.openhab.core.model.script.ide
201 │ Waiting │ 80 │ 4.0.0.202306251612 │ org.openhab.core.model.script.runtime

@morph166955
Copy link
Author

Maybe push it and I'll just update the snapshot when it runs?

@J-N-K
Copy link
Member

J-N-K commented Jul 4, 2023

@lolodomo Since you seem to experience the same issue: Can you try if the fix resolves the start level 20 issue for you?

@lolodomo
Copy link
Contributor

lolodomo commented Jul 4, 2023

Yes, I plan to test this evening.

@lolodomo
Copy link
Contributor

lolodomo commented Jul 5, 2023

@J-N-K : unfortunately, it does not solve the start level 20 I encounter in the issue #3680 with a OH server running in Windows 10.

06:29:39.821 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Added org.openhab.core.model.script.runtime: RESOLVED
...
06:29:41.932 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
06:29:42.292 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: STARTING
06:29:42.297 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: ACTIVE
06:29:42.386 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
06:29:44.434 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
06:29:44.530 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test2.rules'

I updated the bundle org.openhab.core.automation.module.script with the one compiled from your PR #3683:

openhab> bundle:list | grep -v Active
START LEVEL 100 , List Threshold: 50
 ID │ State  │ Lvl │ Version                │ Name
────┼────────┼─────┼────────────────────────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
openhab> bundle:list -s | grep script
158 │ Active │  80 │ 4.0.0.202307050426     │ org.openhab.core.automation.module.script
159 │ Active │  80 │ 4.0.0.202307021028     │ org.openhab.core.automation.module.script.rulesupport
199 │ Active │  80 │ 4.0.0.202307021028     │ org.openhab.core.model.script
200 │ Active │  80 │ 4.0.0.202307021029     │ org.openhab.core.model.script.ide
201 │ Active │  80 │ 4.0.0.202307021029     │ org.openhab.core.model.script.runtime
openhab>
{
  "systemInfo": {
    "configFolder": "D:\\Domotique\\openHAB\\OH4\\conf",
    "userdataFolder": "D:\\Domotique\\openHAB\\OH4\\userdata",
    "logFolder": "D:\\Domotique\\openHAB\\OH4\\userdata\\logs",
    "javaVersion": "17.0.6",
    "javaVendor": "Eclipse Adoptium",
    "javaVendorVersion": "Temurin-17.0.6+10",
    "osName": "Windows 10",
    "osVersion": "10.0",
    "osArchitecture": "amd64",
    "availableProcessors": 4,
    "freeMemory": 98327056,
    "totalMemory": 185597952,
    "startLevel": 20
  }
}

@J-N-K
Copy link
Member

J-N-K commented Jul 5, 2023

Did you restart?

@lolodomo
Copy link
Contributor

lolodomo commented Jul 5, 2023

@J-N-K : I added a log at the beginning of the checkReady method:

$ git diff   src/main/java/org/openhab/core/automation/module/script/internal/ScriptEngineFactoryBundleTracker.java
diff --git a/bundles/org.openhab.core.automation.module.script/src/main/java/org/openhab/core/automation/module/script/internal/ScriptEngineFactoryBundleTracker.java b/bundles/org.openhab.core.automation.module.script/src/main/java/org/openhab/core/automation/module/script/internal/ScriptEngineFactoryBundleTracker.java
index 11dfe522f..c1a192560 100644
--- a/bundles/org.openhab.core.automation.module.script/src/main/java/org/openhab/core/automation/module/script/internal/ScriptEngineFactoryBundleTracker.java
+++ b/bundles/org.openhab.core.automation.module.script/src/main/java/org/openhab/core/automation/module/script/internal/ScriptEngineFactoryBundleTracker.java
@@ -128,6 +128,7 @@ public class ScriptEngineFactoryBundleTracker extends BundleTracker<Bundle> impl
     private void checkReady() {
         int startLevel = startLevelService.getStartLevel();
         boolean allBundlesActive = allBundlesActive();
+        logger.debug("checkReady ready={} startLevel={} allBundlesActive={}", ready, startLevel, allBundlesActive);

         if (!ready && startLevel >= StartLevelService.STARTLEVEL_MODEL && allBundlesActive) {
             logger.debug("All automation bundles ready: {}", bundles);

And the result is:


06:59:41.540 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.541 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.541 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.545 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.547 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.549 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.550 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.550 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.551 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.552 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.553 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.554 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.555 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.555 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.556 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.557 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.560 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.562 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.564 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.565 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.566 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.567 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.568 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.569 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.570 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.571 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.572 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.573 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.576 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.577 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.580 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.582 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.583 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.584 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.585 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.586 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.587 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.588 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.590 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.593 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.594 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.595 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.596 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.598 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.599 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.600 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.602 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.603 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.604 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.605 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.608 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.609 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.610 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.611 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.611 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.613 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.615 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.616 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.617 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.618 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.619 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.620 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.623 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.625 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.626 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.627 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.628 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.629 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.630 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.632 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.632 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.633 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.634 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.634 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.635 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.638 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.639 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.639 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.640 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.641 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.642 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.642 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.643 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.645 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.646 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.647 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.648 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.649 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.649 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.650 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.651 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.652 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.655 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.656 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.656 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.658 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.659 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.659 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.660 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.661 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.662 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.664 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.664 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.665 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.666 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.666 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.667 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.670 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.672 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.672 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.673 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.674 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.675 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.675 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.676 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.677 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.677 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.678 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.678 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.680 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.681 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.682 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.683 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.684 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.687 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.689 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.690 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.691 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.691 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.692 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.693 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.694 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.694 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.696 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.697 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.698 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.698 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.699 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.702 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.704 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.705 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.705 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.706 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.707 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.707 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.708 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.709 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.709 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.710 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.711 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.711 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.713 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.714 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.715 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.716 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.719 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.721 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.722 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.723 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.724 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.725 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.725 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.726 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.726 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.727 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.727 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.727 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.728 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.729 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.730 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.730 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.731 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.731 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.734 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.735 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.736 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.736 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.736 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.737 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.737 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.738 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.738 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.739 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.739 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.740 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.740 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.741 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.742 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.742 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.743 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.744 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.744 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.745 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.745 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.746 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.747 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.747 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.748 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.751 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.752 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.753 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:41.753 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Added org.openhab.core.model.script.runtime: RESOLVED
06:59:41.754 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.755 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.755 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.755 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.756 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.756 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.757 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.757 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.757 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.758 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.758 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.759 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.759 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.760 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.760 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.761 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.761 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.763 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.764 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.768 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.769 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.769 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.770 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.770 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.771 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.771 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.772 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.773 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.773 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.773 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.774 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.774 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.775 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.776 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.776 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.777 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.777 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.778 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307050457 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : getting activate: activate
06:59:41.778 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307050457 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Locating method activate in class org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker
06:59:41.780 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307050457 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Declared Method org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker.activate([interface org.osgi.service.component.ComponentContext]) not found
06:59:41.784 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307050457 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Locating method activate in class org.osgi.util.tracker.BundleTracker
06:59:41.785 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307050457 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Declared Method org.osgi.util.tracker.BundleTracker.activate([interface org.osgi.service.component.ComponentContext]) not found
06:59:41.786 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307050457 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Locating method activate in class java.lang.Object
06:59:41.787 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307050457 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
06:59:41.787 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307050457 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : activate method [activate] not found, ignoring
06:59:41.788 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307050457 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Set implementation object for component
06:59:41.789 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307050457 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Changed state from satisfied to active
06:59:41.799 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.875 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.877 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.902 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:41.904 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.361 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.392 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.506 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.509 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.512 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.515 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.590 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.592 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.716 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.718 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.728 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.734 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.786 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.788 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.838 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.840 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.847 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.871 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.946 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.949 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.984 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:42.986 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.091 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.093 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.340 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.349 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.448 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.453 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.682 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.684 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.687 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.689 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.694 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.698 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.795 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.797 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.861 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.863 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.867 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.869 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.872 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.875 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.879 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:43.881 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.380 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.382 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.413 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.415 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.467 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.469 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.551 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.553 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.563 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.565 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.570 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:44.572 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:45.859 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
06:59:46.187 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.189 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.193 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.196 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.204 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.206 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.208 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.213 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.308 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.311 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.316 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.318 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.321 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.323 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.360 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.362 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.380 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.381 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.385 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.390 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: STARTING
06:59:46.391 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=false
06:59:46.394 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: ACTIVE
06:59:46.396 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.400 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.404 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.406 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.407 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.409 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.496 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
06:59:46.574 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.577 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.585 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.586 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.587 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.588 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.635 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.637 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.663 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.666 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.676 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:46.694 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:49.390 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:49.393 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:50.478 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
06:59:50.567 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test2.rules'
06:59:51.332 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.343 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.471 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.474 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.683 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.686 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.743 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.745 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.817 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.820 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.892 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.898 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.902 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.903 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.905 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.906 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.907 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.909 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.910 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.913 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.915 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.917 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.918 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.919 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.922 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.924 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.926 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.927 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.931 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.933 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.934 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.936 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.977 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:51.981 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:52.019 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true
06:59:55.842 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - checkReady ready=false startLevel=10 allBundlesActive=true

Looks like my start level is 10 when this method is called while your code is now expecting 20.

@lolodomo
Copy link
Contributor

lolodomo commented Jul 5, 2023

Did you restart?

Of course.
Without a restart, some bundles are not active after my bundle update.

@lolodomo
Copy link
Contributor

lolodomo commented Jul 5, 2023

So previous code with StartLevelService.STARTLEVEL_OSGI was probably better in my case ?

@lolodomo
Copy link
Contributor

lolodomo commented Jul 5, 2023

Or checkReady for rules is not called when my start level is finally 20 ?

@J-N-K
Copy link
Member

J-N-K commented Jul 5, 2023

Level 20 should be correct, I have added some more logging, maybe you can try to update again.

In principle, the ready service should notify the tracker that start level 20 was reached. I also added logging for that.

@lolodomo
Copy link
Contributor

lolodomo commented Jul 5, 2023

I also added logging for that.

I don't find any change in your branch. Did you really push a new commit ?

@J-N-K
Copy link
Member

J-N-K commented Jul 5, 2023

I only updated the download link. Changes pushed.

@lolodomo
Copy link
Contributor

lolodomo commented Jul 5, 2023

With your last changes:


20:39:32.123 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307051837 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Changed state from satisfied to active
20:39:34.592 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
20:39:34.961 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: STARTING
20:39:34.967 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: ACTIVE
20:39:35.059 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
20:39:37.624 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
20:39:37.711 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test2.rules'
20:39:41.912 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Readymarker startlevel=20 added

@lolodomo
Copy link
Contributor

lolodomo commented Jul 5, 2023

With TRACE enabled:

20:43:20.938 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
20:43:21.252 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: STARTING
20:43:21.255 [TRACE] [rnal.ScriptEngineFactoryBundleTracker] - ready: false, startlevel: 10, allActive: false
20:43:21.259 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: ACTIVE
20:43:21.262 [TRACE] [rnal.ScriptEngineFactoryBundleTracker] - ready: false, startlevel: 10, allActive: true
20:43:21.379 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
20:43:23.332 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
20:43:23.424 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test2.rules'
20:43:28.668 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Readymarker startlevel=20 added
20:43:28.671 [TRACE] [rnal.ScriptEngineFactoryBundleTracker] - ready: false, startlevel: 10, allActive: true

@J-N-K
Copy link
Member

J-N-K commented Jul 5, 2023

Uh. That's a neat one. The start-level service still returns 10 when checkReady is called after the ready marker is received. I'll fix that.

@J-N-K
Copy link
Member

J-N-K commented Jul 5, 2023

Updated once again.

@lolodomo
Copy link
Contributor

lolodomo commented Jul 5, 2023

Now it works, start level is 100.


21:15:10.497 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
21:15:10.828 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: STARTING
21:15:10.832 [TRACE] [rnal.ScriptEngineFactoryBundleTracker] - ready: false, startlevel: false, allActive: false
21:15:10.838 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: ACTIVE
21:15:10.839 [TRACE] [rnal.ScriptEngineFactoryBundleTracker] - ready: false, startlevel: false, allActive: true
21:15:10.946 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
21:15:14.380 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
21:15:14.478 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test2.rules'
21:15:17.865 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Readymarker startlevel=20 added
21:15:17.871 [TRACE] [rnal.ScriptEngineFactoryBundleTracker] - ready: false, startlevel: true, allActive: true
21:15:17.873 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Adding ready marker: All automation bundles ready ({org.openhab.core.model.script.runtime=32})
21:15:22.886 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
{
  "systemInfo": {
    "configFolder": "D:\\Domotique\\openHAB\\OH4\\conf",
    "userdataFolder": "D:\\Domotique\\openHAB\\OH4\\userdata",
    "logFolder": "D:\\Domotique\\openHAB\\OH4\\userdata\\logs",
    "javaVersion": "17.0.6",
    "javaVendor": "Eclipse Adoptium",
    "javaVendorVersion": "Temurin-17.0.6+10",
    "osName": "Windows 10",
    "osVersion": "10.0",
    "osArchitecture": "amd64",
    "availableProcessors": 4,
    "freeMemory": 85979016,
    "totalMemory": 171966464,
    "startLevel": 100
  }
}

@morph166955
Copy link
Author

morph166955 commented Jul 6, 2023

Snapshot 3528 looks good! Thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug An unexpected problem or unintended behavior of the Core
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants