Script throws exception on openHAB startup, sometimes

You shouldn’t have to. What is the error you are seeing? The only think I can think of is that holidayName is still null when you call postUpdate. That wouldn’t work. But if holidayName is any sort of String that will work.

Sorry for not posting the complete syntax:

snipped
else if (dayOfYear==parse(year+"-12-31").getDayOfYear) {
    holidayName = "new_years_eve" // Silvester
    holiday = false
}
else {
    holidayName = "no_special_day"
    holiday = false
}

SpecialDay.postUpdate(holidayName)

But the problem only comes on restart of OH, not if I start the rule manually or via cron.

We need to see the whole rule. These few lines do not give any context. For example, what the heck is dayOfYear and how is it populated? What do you do with holiday? Are any of these Items, local variables, global variables? If variables, are they populated from Items?

Hi Rich,

there is a parallel post here with all details:

I have the same error with the same script. But i didn’t find any solution in the other thread.
If i update openhab to the newest snapshot (i do that once a week or so) the first startup takes way longer than usual and the openhab.log is filled with the same errors. My script is called feestdag.script, but it is the exact same holiday.script from the same tutorial.
feestdag.txt (3.7 KB)

rule "Feestdagen"
when
	Time cron "0 0 0 * * ?" or
	System started
then
	callScript("feestdag")
end 
//partial stack trace: 
2019-08-25 21:00:31.814 [ERROR] [xbase.resource.BatchLinkableResource] - resolution of uriFragment '|::0.0.18.2.7.0.6::0::/2' failed.
java.lang.IllegalStateException: ON uses unsupported uri fragment tmp_feestdag.script#/1/@members.6
	at org.eclipse.xtext.xbase.typesystem.internal.ScopeProviderAccess.getCandidateDescriptions(ScopeProviderAccess.java:158) ~[?:?]
	at org.eclipse.xtext.xbase.typesystem.internal.AbstractTypeComputationState.getLinkingCandidates(AbstractTypeComputationState.java:409) ~[?:?]
	at org.eclipse.xtext.xbase.typesystem.computation.XbaseTypeComputer._computeTypes(XbaseTypeComputer.java:1112) ~[?:?]
	at org.eclipse.xtext.xbase.typesystem.computation.XbaseTypeComputer.computeTypes(XbaseTypeComputer.java:101) ~[?:?]
	at org.eclipse.smarthome.model.script.jvmmodel.ScriptTypeComputer.computeTypes(ScriptTypeComputer.java:39) ~[?:?]
	at org.eclipse.xtext.xbase.typesystem.internal.AbstractTypeComputationState.doComputeTypes(AbstractTypeComputationState.java:121) ~[?:?]
	at org.eclipse.xtext.xbase.typesystem.internal.AbstractTypeComputationState.computeTypes(AbstractTypeComputationState.java:109) ~[?:?]
	at org.eclipse.xtext.xbase.typesystem.internal.AbstractLinkingCandidate.resolveArgumentType(AbstractLinkingCandidate.java:627) ~[?:?]

There are known problems with rules becoming active before other parts of openHAB have completely initialized. Especially when it is a more long winded startup, such as after an upgrade or cache deletion.

Thinks, i might work something out with a timer as workaround. Do you know if there is some github issue/discussion? Maybe i can add this as an example to get a fix?
Because the script is not using any binding/addon/ui/io/action/persistence etc. It must be some core stuff that is not initialized yet. Without really knowing all the inner workings of openHAB, it seems wrong to start a rule while the core is not yet ready to start anything.

I believe this is the most general case

I have no real idea if your symptom is another manifestation of the general boot-order problem, it just feels like it.
Even if it is, it may need something else to be taken account in any eventual fix.

I would suggest it is worth opening a new github issue - I would guess against openhab core.

Sure. It’s a non-trivial mess to sort out though.

Hi,

I’m getting the same error message since updating to 2.5.0 M2. The script is also the same but in my case adapted to german language. feiertag.script.txt (3.6 KB)

I did some tests and it seems not being related to the rule which is calling the script is triggered before everything is loaded. I removed the call to my script and still get the issue.
Hence it seems this error occurs already when the script file is loaded. The only solution I found is to completely remove the script file from openhab.

If I readd the file once openhab is up and running the error doesn’t occure.

Is there any idea, what I can do to solve this issue, since it is completely blocking openhab from completing startup?

Well spotted; this rang a bell. Files in the /scripts folder are parsed at load time (and edit/save), so you don’t need to call them to trigger an error.
Delaying rule execution doesn’t help, sorry.

I would still say this is to do with boot order, parsing scripts before all Items are available, and I’m not surprised if timing does change between versions.

That I do not know.

Okay. Thanks for your input.
So at least my observations make sense.

My main Problem is that the error is triggered continuously and blocking start-up.

I guess I’ll copy my code from script to the rule. Not nice but should solve it for the time being

This does not seem right at all. I just tried a nonsense script in 2.4.0 and it loads without complaint. Perhaps you could try this in 2.5 to see if it shows something up.

/scripts/nonsense.script

postUpdate(nonsenseItem, "rubbish")

openhab.log

2019-08-28 23:05:49.618 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nonsense.script'

That loads properly you are right. However there seems to be something wired at the moment.

I copied the script back to /etc/openhab2/scripts while openhab2 is up and running fine and it was loaded properly.
When changing the rule file back so it is called I get the following error:

==> /var/log/openhab2/openhab.log <==
2019-08-29 07:18:33.740 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'Tageszeit berechnen': null
2019-08-29 07:18:33.886 [ERROR] [xbase.resource.BatchLinkableResource] - resolution of uriFragment '|::0.0.0.0::1::/0' failed.
org.eclipse.xtext.util.RuntimeIOException: java.io.FileNotFoundException: /var/lib/openhab2/zeit.rules (No such file or directory)

That looks like a big clue. Sorry I do not have OH2.5 to confirm.

That’s obviously wrong folder, I’m guessing that is the correct filename for the rule that calls the script. Like the script return messing up.
It’s quite possible that not many people use scripts to expose a bug here.

I suggest if this is repeatable you create a simple example and a github issue.

Maybe I’ve found a solution!
I changed all the if {} else if {} statements to single if-statements.
Now the script is starting without any errors.

I’m using the same script for a year now, but after at least the update to 2.5.3 a normal system startup is no longer possible. As with the other posters the log is flooded with the Java exception, which causes the system so busy, that the initialization will not complete.

2020-05-24 16:12:55.795 [ERROR] [xbase.resource.BatchLinkableResource] - resolution of uriFragment '|::0.0.4.0::1::/0' failed.
java.lang.NullPointerException: null
        at org.eclipse.smarthome.model.script.ScriptServiceUtil.getActionServices(ScriptServiceUtil.java:111) ~[?:?]
        at org.eclipse.smarthome.model.script.scoping.ActionClassLoader.loadClass(ActionClassLoader.java:37) ~[?:?]
        at java.lang.Class.forName0(Native Method) ~[?:1.8.0_152]
        at java.lang.Class.forName(Class.java:348) ~[?:1.8.0_152]
        at org.eclipse.xtext.common.types.access.impl.ClassFinder.forName(ClassFinder.java:41) ~[?:?]
        at org.eclipse.xtext.common.types.access.impl.ClassFinder.forName(ClassFinder.java:15) ~[?:?]
        at org.eclipse.xtext.common.types.access.impl.AbstractClassFinder.forName(AbstractClassFinder.java:43) ~[?:?]
        at org.eclipse.xtext.common.types.access.reflect.ReflectionTypeProvider.findClassByName(ReflectionTypeProvider.java:155) ~[?:?]
        at org.eclipse.xtext.common.types.access.reflect.ReflectionTypeProvider.doFindTypeByName(ReflectionTypeProvider.java:116) ~[?:?]
        at org.eclipse.xtext.common.types.access.reflect.ReflectionTypeProvider.findTypeByName(ReflectionTypeProvider.java:109) ~[?:?]
        at org.eclipse.xtext.common.types.xtext.AbstractTypeScope.getSingleElement(AbstractTypeScope.java:59) ~[?:?]
        at org.eclipse.xtext.common.types.xtext.AbstractTypeScope.getSingleElement(AbstractTypeScope.java:54) ~[?:?]
        at org.eclipse.xtext.common.types.xtext.AbstractTypeScope.getElements(AbstractTypeScope.java:73) ~[?:?]
        at org.eclipse.xtext.linking.impl.ImportedNamesAdapter$WrappingScope$1.iterator(ImportedNamesAdapter.java:79) ~[bundleFile:?]
        at org.eclipse.xtext.scoping.impl.ImportScope.getLocalElementsByName(ImportScope.java:156) ~[bundleFile:?]
        at org.eclipse.xtext.scoping.impl.ImportScope.getSingleLocalElementByName(ImportScope.java:142) ~[bundleFile:?]
        at org.eclipse.xtext.scoping.impl.AbstractScope.getSingleElement(AbstractScope.java:105) ~[bundleFile:?]
        at org.eclipse.xtext.scoping.impl.AbstractScope.getSingleElement(AbstractScope.java:108) ~[bundleFile:?]
        at org.eclipse.xtext.linking.impl.DefaultLinkingService.getLinkedObjects(DefaultLinkingService.java:114) ~[bundleFile:?]
        at org.eclipse.xtext.linking.lazy.LazyLinkingResource.getEObject(LazyLinkingResource.java:265) ~[bundleFile:?]
        at org.eclipse.xtext.xbase.resource.BatchLinkableResource.getEObject(BatchLinkableResource.java:119) ~[bundleFile:?]
        at org.eclipse.emf.ecore.resource.impl.ResourceSetImpl.getEObject(ResourceSetImpl.java:223) ~[bundleFile:?]
        at org.eclipse.emf.ecore.util.EcoreUtil.resolve(EcoreUtil.java:199) ~[bundleFile:?]
        at org.eclipse.emf.ecore.util.EcoreUtil.resolve(EcoreUtil.java:259) ~[bundleFile:?]
        at org.eclipse.emf.ecore.impl.BasicEObjectImpl.eResolveProxy(BasicEObjectImpl.java:1477) ~[bundleFile:?]
        at org.eclipse.xtext.common.types.impl.JvmTypeReferenceImplCustom.eResolveProxy(JvmTypeReferenceImplCustom.java:31) ~[?:?]
        at org.eclipse.xtext.common.types.impl.JvmParameterizedTypeReferenceImpl.getType(JvmParameterizedTypeReferenceImpl.java:111) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.references.LightweightTypeReferenceFactory.getType(LightweightTypeReferenceFactory.java:242) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.references.LightweightTypeReferenceFactory.doVisitParameterizedTypeReference(LightweightTypeReferenceFactory.java:173) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.references.LightweightTypeReferenceFactory.doVisitParameterizedTypeReference(LightweightTypeReferenceFactory.java:52) ~[?:?]
        at org.eclipse.xtext.common.types.impl.JvmParameterizedTypeReferenceImplCustom.accept(JvmParameterizedTypeReferenceImplCustom.java:53) ~[?:?]
        at org.eclipse.xtext.common.types.util.AbstractTypeReferenceVisitor.visit(AbstractTypeReferenceVisitor.java:34) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.references.LightweightTypeReferenceFactory.toLightweightReference(LightweightTypeReferenceFactory.java:83) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.references.StandardTypeReferenceOwner.toLightweightTypeReference(StandardTypeReferenceOwner.java:117) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.computation.XbaseTypeComputer._computeTypes(XbaseTypeComputer.java:524) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.computation.XbaseTypeComputer.computeTypes(XbaseTypeComputer.java:152) ~[?:?]
        at org.eclipse.smarthome.model.script.jvmmodel.ScriptTypeComputer.computeTypes(ScriptTypeComputer.java:38) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.AbstractTypeComputationState.doComputeTypes(AbstractTypeComputationState.java:121) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.AbstractTypeComputationState.computeTypes(AbstractTypeComputationState.java:109) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.computation.XbaseTypeComputer._computeTypes(XbaseTypeComputer.java:483) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.computation.XbaseTypeComputer.computeTypes(XbaseTypeComputer.java:118) ~[?:?]
        at org.eclipse.smarthome.model.script.jvmmodel.ScriptTypeComputer.computeTypes(ScriptTypeComputer.java:38) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.AbstractTypeComputationState.doComputeTypes(AbstractTypeComputationState.java:121) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.AbstractTypeComputationState.computeTypes(AbstractTypeComputationState.java:109) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.AbstractRootTypeComputationState.computeTypes(AbstractRootTypeComputationState.java:32) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.LogicalContainerAwareReentrantTypeResolver._computeTypes(LogicalContainerAwareReentrantTypeResolver.java:827) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.LogicalContainerAwareReentrantTypeResolver.computeTypes(LogicalContainerAwareReentrantTypeResolver.java:711) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.LogicalContainerAwareReentrantTypeResolver.computeMemberTypes(LogicalContainerAwareReentrantTypeResolver.java:897) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.LogicalContainerAwareReentrantTypeResolver._computeTypes(LogicalContainerAwareReentrantTypeResolver.java:886) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.LogicalContainerAwareReentrantTypeResolver.computeTypes(LogicalContainerAwareReentrantTypeResolver.java:705) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.LogicalContainerAwareReentrantTypeResolver.computeTypes(LogicalContainerAwareReentrantTypeResolver.java:697) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.DefaultReentrantTypeResolver.resolve(DefaultReentrantTypeResolver.java:164) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.DefaultReentrantTypeResolver.reentrantResolve(DefaultReentrantTypeResolver.java:139) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.CachingBatchTypeResolver$LazyResolvedTypes.resolveTypes(CachingBatchTypeResolver.java:80) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.CachingBatchTypeResolver$2.process(CachingBatchTypeResolver.java:57) ~[?:?]
        at org.eclipse.xtext.xbase.typesystem.internal.CachingBatchTypeResolver$2.process(CachingBatchTypeResolver.java:53) ~[?:?]
        at org.eclipse.xtext.util.concurrent.IUnitOfWork$Void.exec(IUnitOfWork.java:37) ~[bundleFile:?]
        at org.eclipse.xtext.util.OnChangeEvictingCache.execWithoutCacheClear(OnChangeEvictingCache.java:128) ~[bundleFile:?]
        at org.eclipse.xtext.xbase.typesystem.internal.CachingBatchTypeResolver.doResolveTypes(CachingBatchTypeResolver.java:53) ~[bundleFile:?]
        at org.eclipse.xtext.xbase.typesystem.internal.AbstractBatchTypeResolver.resolveTypes(AbstractBatchTypeResolver.java:69) ~[bundleFile:?]
        at org.eclipse.xtext.xbase.resource.BatchLinkingService.resolveBatched(BatchLinkingService.java:60) ~[bundleFile:?]
        at org.eclipse.xtext.xbase.resource.BatchLinkingService.resolveBatched(BatchLinkingService.java:41) ~[bundleFile:?]
        at org.eclipse.xtext.xbase.resource.BatchLinkableResource.getEObject(BatchLinkableResource.java:117) ~[bundleFile:?]
        at org.eclipse.emf.ecore.resource.impl.ResourceSetImpl.getEObject(ResourceSetImpl.java:223) ~[bundleFile:?]
        at org.eclipse.emf.ecore.util.EcoreUtil.resolve(EcoreUtil.java:199) ~[bundleFile:?]
        at org.eclipse.emf.ecore.util.EcoreUtil.resolve(EcoreUtil.java:259) ~[bundleFile:?]
        at org.eclipse.emf.ecore.impl.BasicEObjectImpl.eResolveProxy(BasicEObjectImpl.java:1477) ~[bundleFile:?]
        at org.eclipse.xtext.xbase.impl.XAbstractFeatureCallImplCustom.getFeature(XAbstractFeatureCallImplCustom.java:48) ~[?:?]
        at org.eclipse.xtext.xbase.impl.XAbstractFeatureCallImplCustom.isStatic(XAbstractFeatureCallImplCustom.java:151) ~[?:?]
        at org.eclipse.xtext.xbase.impl.XAbstractFeatureCallImplCustom.getActualArguments(XAbstractFeatureCallImplCustom.java:180) ~[?:?]
        at org.eclipse.xtext.xbase.impl.XAbstractFeatureCallImplCustom.getActualArguments(XAbstractFeatureCallImplCustom.java:174) ~[?:?]
        at org.eclipse.xtext.xbase.impl.XBinaryOperationImplCustom.getActualArguments(XBinaryOperationImplCustom.java:37) ~[?:?]
        at org.eclipse.xtext.xbase.controlflow.DefaultEarlyExitComputer._exitPoints(DefaultEarlyExitComputer.java:244) ~[?:?]
        at org.eclipse.xtext.xbase.controlflow.DefaultEarlyExitComputer.exitPoints(DefaultEarlyExitComputer.java:308) ~[?:?]
        at org.eclipse.xtext.xbase.controlflow.DefaultEarlyExitComputer.getExitPoints(DefaultEarlyExitComputer.java:65) ~[?:?]
        at org.eclipse.xtext.xbase.controlflow.DefaultEarlyExitComputer._exitPoints(DefaultEarlyExitComputer.java:190) ~[?:?]
        at org.eclipse.xtext.xbase.controlflow.DefaultEarlyExitComputer.exitPoints(DefaultEarlyExitComputer.java:330) ~[?:?]
        at org.eclipse.xtext.xbase.controlflow.DefaultEarlyExitComputer.getExitPoints(DefaultEarlyExitComputer.java:65) ~[?:?]
        at org.eclipse.xtext.xbase.controlflow.DefaultEarlyExitComputer.isEarlyExit(DefaultEarlyExitComputer.java:48) ~[?:?]
        at org.eclipse.xtext.xbase.validation.EarlyExitValidator.checkDeadCode(EarlyExitValidator.java:105) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_152]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_152]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_152]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_152]
        at org.eclipse.xtext.validation.AbstractDeclarativeValidator$MethodWrapper.invoke(AbstractDeclarativeValidator.java:127) ~[bundleFile:?]
        at org.eclipse.xtext.validation.AbstractDeclarativeValidator.internalValidate(AbstractDeclarativeValidator.java:318) ~[bundleFile:?]
        at org.eclipse.xtext.validation.AbstractInjectableValidator.validate(AbstractInjectableValidator.java:71) ~[bundleFile:?]
        at org.eclipse.xtext.validation.CompositeEValidator.validate(CompositeEValidator.java:150) ~[bundleFile:?]
        at org.eclipse.emf.ecore.util.Diagnostician.doValidate(Diagnostician.java:171) ~[bundleFile:?]
        at org.eclipse.emf.ecore.util.Diagnostician.validate(Diagnostician.java:158) ~[bundleFile:?]
        at org.eclipse.emf.ecore.util.Diagnostician.validate(Diagnostician.java:137) ~[bundleFile:?]
        at org.eclipse.emf.ecore.util.Diagnostician.validate(Diagnostician.java:108) ~[bundleFile:?]
        at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.lambda$2(ModelRepositoryImpl.java:290) ~[bundleFile:?]
        at org.eclipse.smarthome.model.core.internal.SafeEMFImpl.call(SafeEMFImpl.java:30) [bundleFile:?]
        at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.validateModel(ModelRepositoryImpl.java:290) [bundleFile:?]
        at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.addOrRefreshModel(ModelRepositoryImpl.java:103) [bundleFile:?]
        at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.checkFile(FolderObserver.java:247) [bundleFile:?]
        at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.processWatchEvent(FolderObserver.java:310) [bundleFile:?]
        at org.eclipse.smarthome.core.service.WatchQueueReader.run(WatchQueueReader.java:240) [bundleFile:?]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_152]

Today I updated to 2.5.5-1 and took some time in investigating. As here and in other threats already mentioned I figured out it is related to timing. After updating openHAB it looks like, that the items used in the postUpdate() are not available at the time the script is loaded.

if (holidayName!==null) {
    postUpdate(SpecialDay,holidayName)
} else {
    holidayName = "none"
    postUpdate(SpecialDay,holidayName)
}

Updates are applied to my installation as part of an “apt upgrade”. During the update the openhab2.service is stopped, but not restarted. My solution for the issue is to comment out the part of the script, which is updating the items, start the openhab2.service and let the system initialize. After half an hour I uncomment the part containing the postUpdate() and the script loads without any error.

/*
if (holidayName!==null) {
    postUpdate(SpecialDay,holidayName)
} else {
    holidayName = "none"
    postUpdate(SpecialDay,holidayName)
}
*/

Usually I would expect, that rules and scripts are loaded after things and items. I’m not familiar in posting bugs on github, but if someone could give me a hint how-to, I’ll do.

Jan

Could you post your log with an example of these errors? Are you possibly experiencing some of the issues in this topic?

Hi Scott,
the update from 2.4 to 2.5 had not produced the issue, it started on one of the minor updates within 2.5. I think it was 2.5.2 to 2.5.3 but I’m not sure.

I’ve attached the complete openhab.log beginning with the startup after the update from 2.5.4-1 to 2.5.5-1 until it run without errors. I’ve only masked my coordinates in the Location settings. (it’s a tarball, but have to have a known extension to allow the upload. Please remove .txt from the filename to allow proper processing) openhab.log.tgz.txt (261.5 KB)

*Update: Clearing the cache only slowed down startup, but hadn’t helped to avoid the Java exeptions.

regards Jan

Yes, that’s an action that would be expected to make it worse (and is performed anyway as part of an upgrade)
Reportedly, it can two or three restarts to properly rebuild the cache, so see what’s left after that.

Your log looks to have rules loading before the Items are ready. I suggest scrapping the clunky old rules DSL and using scripted automation with Jython and the helper libraries, where you will not have this issue. If you want to stay with the rules DSL, then you should setup a way to delay the rules from loading.