search

openhab / openhab-core

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

WatchService: Detected invalid event (hash must not be null for CREATE/MODIFY) #3680

Closed lolodomo closed 1 year ago

lolodomo commented 1 year ago

Install from scratch of snapshot 3524 on Windows, just by unzipping the ZIP file. After initial setup steps (creating an account, installing Basic UI and RRD4j bindings), everything looks good:

12:54:57.428 [INFO ] [org.openhab.core.Activator           ] - Starting openHAB 4.0.0 (build Build #3524)
12:55:02.543 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
12:55:38.685 [WARN ] [e.io.rest.auth.internal.TokenResource] - Couldn't find a user with a session matching the provided refresh_token
12:55:38.687 [WARN ] [e.io.rest.auth.internal.TokenResource] - Token issuing failed: invalid_grant
12:55:53.887 [INFO ] [tp.auth.internal.AuthorizePageServlet] - First user account created: lolodomo
12:55:57.169 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Paris'.
12:55:57.170 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Locale set to 'fr_FR'.
12:56:20.274 [INFO ] [rnal.ScriptEngineFactoryBundleTracker] - All automation bundles ready.
12:56:22.644 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.

All bundles are active and start level is 100.

Now I copy/paste in my conf folder items, sitemap and rule and I got an unexpected warning for each file:

12:57:33.550 [WARN ] [ore.internal.service.WatchServiceImpl] - Detected invalid event (hash must not be null for CREATE/MODIFY): DirectoryChangeEvent{eventType=CREATE, isDirectory=false, path=D:\Domotique\openHAB\OH4\conf\items\test.items, count=1, rootPath=D:\Domotique\openHAB\OH4\conf, hash=(null)}
12:57:34.576 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
12:58:21.373 [WARN ] [ore.internal.service.WatchServiceImpl] - Detected invalid event (hash must not be null for CREATE/MODIFY): DirectoryChangeEvent{eventType=CREATE, isDirectory=false, path=D:\Domotique\openHAB\OH4\conf\sitemaps\test.sitemap, count=1, rootPath=D:\Domotique\openHAB\OH4\conf, hash=(null)}
12:58:22.423 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
12:58:40.459 [WARN ] [ore.internal.service.WatchServiceImpl] - Detected invalid event (hash must not be null for CREATE/MODIFY): DirectoryChangeEvent{eventType=CREATE, isDirectory=false, path=D:\Domotique\openHAB\OH4\conf\rules\test.rules, count=1, rootPath=D:\Domotique\openHAB\OH4\conf, hash=(null)}
12:58:41.515 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'

Note that paths displayed by the logs are correct. All bundles are still active and start level is still 100.

lolodomo commented 1 year ago

If I restart OH, I don't have these warnings. All bundles are active.

openhab> bundle:list -s | grep -v Active
START LEVEL 100 , List Threshold: 50
 ID │ State  │ Lvl │ Version                │ Symbolic name
────┼────────┼─────┼────────────────────────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
openhab>

But start level is only 20:

{
  "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": 88587520,
    "totalMemory": 227540992,
    "startLevel": 20
  }
}

Nothing special in logs:

openhab> log:tail
13:07:48.820 [INFO ] [org.openhab.core.Activator           ] - Starting openHAB 4.0.0 (build Build #3524)
13:07:49.138 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Paris'.
13:07:49.139 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Locale set to 'fr_FR'.
13:07:51.680 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
13:07:52.116 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
13:07:54.010 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
13:07:54.098 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'
lolodomo commented 1 year ago

After enabling DEBUG logs for org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker and restarting OH:

13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Setting target property for dependency $001 to null
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : New service tracker for $001, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.service.StartLevelService), initialReferenceFilter (objectClass=org.openhab.core.service.StartLevelService)
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : dm $001 tracker reset (closed)
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.service.StartLevelService}={service.id=188, service.bundleid=149, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.service.StartLevelService, component.id=33, 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)
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : dm $001 tracking 2 SingleStatic active: false trackerOpened: false optional: false
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.service.StartLevelService}={service.id=188, service.bundleid=149, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.service.StartLevelService, component.id=33, 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)
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : dm $001 tracker opened
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : registering service listener for dependency $001
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : 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))
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : dm osgi.ds.satisfying.condition tracker reset (closed)
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : 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)
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : 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)
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : dm osgi.ds.satisfying.condition tracker opened
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : registering service listener for dependency osgi.ds.satisfying.condition
13:18:00.342 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Changed state from disabled to unsatisfiedReference
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Component enabled
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : ActivateInternal
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Querying state unsatisfiedReference
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Querying state unsatisfiedReference
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Activating component from state unsatisfiedReference
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Querying state unsatisfiedReference
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Querying state unsatisfiedReference
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Changed state from unsatisfiedReference to satisfied
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : registration change queue [registered]
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : 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)
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.service.ReadyService through loader of org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : getClassFromComponentClassLoader: Found class org.openhab.core.service.ReadyService
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.service.StartLevelService through loader of org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker
13:18:00.347 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : getClassFromComponentClassLoader: Found class org.openhab.core.service.StartLevelService
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : 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)
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : This thread collected dependencies
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : getService (single component manager) dependencies collected.
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Querying state satisfied
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Querying state satisfied
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.service.ReadyService}={service.id=173, 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=25}] service: [null]]]
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : For dependency $001, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.service.StartLevelService}={service.id=188, service.bundleid=149, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.service.StartLevelService, component.id=33, 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]]]
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : 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]]]
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Added org.openhab.core.model.script.runtime: RESOLVED
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : getting activate: activate
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Locating method activate in class org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (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
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Locating method activate in class org.osgi.util.tracker.BundleTracker
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (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
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Locating method activate in class java.lang.Object
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : activate method [activate] not found, ignoring
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Set implementation object for component
13:18:00.352 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - bundle org.openhab.core.automation.module.script:4.0.0.202307021027 (158)[org.openhab.core.automation.module.script.internal.ScriptEngineFactoryBundleTracker(88)] : Changed state from satisfied to active
13:18:02.423 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
13:18:02.763 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: STARTING
13:18:02.768 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: ACTIVE
13:18:02.861 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
13:18:05.029 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
13:18:05.122 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'
lolodomo commented 1 year ago

If I remove my test.rules file and restarts OH, then it works well and start level is 100:

13:23:59.153 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
13:23:59.480 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: STARTING
13:23:59.492 [DEBUG] [rnal.ScriptEngineFactoryBundleTracker] - Modified org.openhab.core.model.script.runtime: ACTIVE
13:23:59.591 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
13:24:01.618 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
13:24:02.068 [INFO ] [rnal.ScriptEngineFactoryBundleTracker] - All automation bundles ready.
13:24:06.987 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
lolodomo commented 1 year ago

The problem is really the DSL rule file. Without any DSL rule files, it works. I then tried with just one simplified file test2.rules like that and same failure (start level 20):

rule "Test Input"
when
    Item TestCommand received command
then
    logInfo("Rule","TestCommand received " + receivedCommand.toString)
end
lolodomo commented 1 year ago

I am not sure but maybe there is a link with bug #3671 about WatchService.

lolodomo commented 1 year ago

Regarding the warnings, they were added in #3633 by @J-N-K . Maybe the root cause was not identified?

J-N-K commented 1 year ago

This is not related. You mix different issues. The start-level 20 bug is #3676 which has nothing to do with the watch service at all. #3671 is IMO not a bug and for sure not related to the issues you report here.

Is this a dockerized environment? I guess I the file is created with a file size 0, the hash probably is null which leads to the issue you report here.

lolodomo commented 1 year ago

It is on a Windows 10 PC. No docker. My file contains text (a rule) so should not have a size 0.

lolodomo commented 1 year ago

The start-level 20 bug is #3676 which has nothing to do with the watch service at all.

Note that in my scenario, I am locked at start level 20 but I never updated any bundle and I never added/removed any jar file in/from the addon folder.

J-N-K commented 1 year ago

Yes, but the cause is a race condition: if the scripting bundles are active before startlevel 20 is reached, then the ready marker is not set. In most cases startlevel 20 is reached before all scripting bundles are loaded, then it works. It seems that stopped bundles (or jars in the addon-folder) favor the occurrence of this issue, but it can also happen on other setups, depending on configuration and system.

lolodomo commented 1 year ago

Ok, thank you for the explanation. I will test your fix this evening. Then we will have to merge it quickly because I am now fully blocked to make progress on my pending subjects.

lolodomo commented 1 year ago

To come back to the original issue, I will trace to check if method is called only once with null hash or if it is called twice including one with a valid hash.

lolodomo commented 1 year ago

@J-N-K : come back to the original issue. I added a log at the entry of onEvent and here is the logs when I add a rule file:

08:39:33.181 [INFO ] [ore.internal.service.WatchServiceImpl] - onEvent DirectoryChangeEvent{eventType=CREATE, isDirectory=false, path=D:\Domotique\openHAB\OH4\conf\rules\test.rules, count=1, rootPath=D:\Domotique\openHAB\OH4\conf, hash=(null)}
08:39:33.186 [WARN ] [ore.internal.service.WatchServiceImpl] - Detected invalid event (hash must not be null for CREATE/MODIFY): DirectoryChangeEvent{eventType=CREATE, isDirectory=false, path=D:\Domotique\openHAB\OH4\conf\rules\test.rules, count=1, rootPath=D:\Domotique\openHAB\OH4\conf, hash=(null)}
08:39:33.215 [INFO ] [ore.internal.service.WatchServiceImpl] - onEvent DirectoryChangeEvent{eventType=MODIFY, isDirectory=false, path=D:\Domotique\openHAB\OH4\conf\rules\test.rules, count=2, rootPath=D:\Domotique\openHAB\OH4\conf, hash=rQDqV/UeDlR1WPCIBfVVIw==}
08:39:34.223 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'

So the method is called twice, first with a null hash and then with a proper hash.

I would propose to just reduce the log to DEBUG level. WDYT ? And add a comment explaining the strange behaviour in Windows.

lolodomo commented 1 year ago

What is important to consider is that this warning is a wrong warning, the new file is properly detected and handled.

If I then update the file content, only 1 MODIFY event occurred, as expected.

I will submit a fix changing the log level to DEBUG if eventType is CREATE and adding a comment explaining the strange behaviour on Windows OS. @J-N-K : let me know if you do not agree.

lolodomo commented 1 year ago

@J-N-K : I fixed the problem. In fact, the test and log were not at the right place. It can still occur that the warning log is displayed when not expected in case the Windows file explorer takes an unexpected long time to copy a file. One option would be to increase the constant PROCESSING_TIME which is currently set to 1s. WDYT ? But at least now, the warning is now relatively rare on Windows and the new or updated files are apparently never ignored now.