search

openhab / openhab-core

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

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

Closed morph166955 closed 1 year ago

morph166955 commented 1 year ago

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.

openhab-bot commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

openhab-bot commented 1 year ago

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 commented 1 year ago

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

image
J-N-K commented 1 year ago

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

helmar74 commented 1 year ago

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 commented 1 year ago

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

helmar74 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

morph166955 commented 1 year ago

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

J-N-K commented 1 year ago

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

morph166955 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

J-N-K commented 1 year ago

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

lolodomo commented 1 year ago

Yes, I plan to test this evening.

lolodomo commented 1 year ago

@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 commented 1 year ago

Did you restart?

lolodomo commented 1 year ago

@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 commented 1 year ago

Did you restart?

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

lolodomo commented 1 year ago

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

lolodomo commented 1 year ago

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

J-N-K commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

I only updated the download link. Changes pushed.

lolodomo commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

Updated once again.

lolodomo commented 1 year ago

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 commented 1 year ago

Snapshot 3528 looks good! Thank you!