search

openhab / openhab1-addons

Add-ons for openHAB 1.x
Eclipse Public License 2.0
3.43k stars 1.7k forks source link

Get FileNotFoundException for one or two rule files when openHAB starts up #736

Closed sumnerboy12 closed 7 years ago

sumnerboy12 commented 10 years ago

Sometimes when I restart openHAB I get a FileNotFoundException in the logs and any rules in that file do not load. A simple 'touch' on that rule file forces openHAB to load the rules and everything is fine after that.

See log output below.

It is a bit strange as maybe 1 in 10 restarts everything runs through fine, with no errors. About 7 in 10 times I get the exception for just the heating.rules file. And maybe 2 in 10 times I get it for a couple of files (usually one of them is the heating.rules file).

I have checked the heating.rules file many times and there is nothing wrong with it. As I said earlier, if I 'touch' the file it is successfully parsed and loaded every time.

I am guessing it is something to do with the startup sequence causing some file IO issues. At it just so happens that the blip happens when the heating.rules file is being loaded each time and that is why it always shows up then.

I think I have seen this reported elsewhere in the forums a while ago but I couldn't find any mention of it. Wanted to log it here so it wasn't forgotten.

2014-01-13 22:50:40 INFO o.o.c.internal.CoreActivator[:92]- openHAB runtime has been started (v1.4.0). 2014-01-13 22:50:41 INFO o.o.c.s.AbstractActiveService[:189]- Google Calender Event-Downloader has been started 2014-01-13 22:50:42 INFO o.o.i.s.i.DiscoveryServiceImpl[:92]- mDNS service has been started 2014-01-13 22:50:43 INFO o.o.i.r.i.RESTApplication[:158]- Started REST API at /rest 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'demo.sitemap' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'housesitter.sitemap' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'renee.sitemap' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'home.sitemap' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'lights_off.script' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'wakeup_kitchen.script' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'irrigation_off.script' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'get_weather_today.script' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'lights_on.script' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'get_weather_tomorrow.script' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'wakeup_master.script' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'logging.persist' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'rrd4j.persist' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'db4o.persist' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'av.items' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'sun.items' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'chart.items' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'sensor.items' 2014-01-13 22:50:51 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'weather.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'scene.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'security.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'demo.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'appliance.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'heating.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'irrigation.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'zwave.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'energy.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'network.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'lights.items' 2014-01-13 22:50:52 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'presence.items' 2014-01-13 22:50:53 INFO o.o.u.w.i.s.WebAppServlet[:99]- Started Classic UI at /openhab.app 2014-01-13 22:50:56 INFO o.o.a.t.i.TwitterActionService[:127]- TwitterAction has been successfully authenticated > awaiting your Tweets! 2014-01-13 22:50:57 INFO o.o.c.s.AbstractActiveService[:189]- HTTP Refresh Service has been started 2014-01-13 22:50:57 INFO o.o.c.s.AbstractActiveService[:189]- NetworkHealth Refresh Service has been started 2014-01-13 22:50:57 INFO o.o.c.s.AbstractActiveService[:189]- Exec Refresh Service has been started 2014-01-13 22:50:58 INFO o.o.a.x.internal.XMPPConnect[:122]- Connection to XMPP as 'xxx@gmail.com' has been established. 2014-01-13 22:50:59 INFO o.o.i.s.SqueezeServer[:313]- Squeeze Server connection established. 2014-01-13 22:50:59 INFO o.o.c.s.AbstractActiveService[:189]- ZWave Refresh Service has been started 2014-01-13 22:50:59 INFO o.o.c.s.AbstractActiveService[:189]- PiFace Watchdog Service has been started 2014-01-13 22:51:02 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'demo.rules' 2014-01-13 22:51:02 WARN o.o.m.c.i.ModelRepositoryImpl[:78]- Configuration model 'demo.rules' is either empty or cannot be parsed correctly! 2014-01-13 22:51:02 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'scene.rules' 2014-01-13 22:51:03 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'sensor.rules' 2014-01-13 22:51:04 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'security.rules' 2014-01-13 22:51:05 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'av.rules' 2014-01-13 22:51:05 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'appliance.rules' 2014-01-13 22:51:05 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'network.rules' 2014-01-13 22:51:05 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'presence.rules' 2014-01-13 22:51:07 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'heating.rules' 2014-01-13 22:51:07 ERROR o.e.x.r.i.DefaultResourceDescription[:75]- heating.rules (No such file or directory) java.io.FileNotFoundException: heating.rules (No such file or directory) at java.io.FileInputStream.open(Native Method) at java.io.FileInputStream.(FileInputStream.java:138) at org.eclipse.emf.ecore.resource.impl.FileURIHandlerImpl.createInputStream(FileURIHandlerImpl.java:99) at org.eclipse.emf.ecore.resource.impl.ExtensibleURIConverterImpl.createInputStream(ExtensibleURIConverterImpl.java:354) at org.eclipse.emf.ecore.resource.impl.ResourceImpl.load(ResourceImpl.java:1256) at org.eclipse.xtext.resource.impl.DefaultResourceDescription.computeExportedObjects(DefaultResourceDescription.java:73) 2014-01-13 22:51:07 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'irrigation.rules' 2014-01-13 22:51:07 WARN o.o.m.c.i.ModelRepositoryImpl[:78]- Configuration model 'irrigation.rules' is either empty or cannot be parsed correctly! 2014-01-13 22:51:07 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'sun.rules' 2014-01-13 22:51:07 ERROR o.e.x.r.i.DefaultResourceDescription[:75]- irrigation.rules (No such file or directory) java.io.FileNotFoundException: irrigation.rules (No such file or directory) at java.io.FileInputStream.open(Native Method) at java.io.FileInputStream.(FileInputStream.java:138) at org.eclipse.emf.ecore.resource.impl.FileURIHandlerImpl.createInputStream(FileURIHandlerImpl.java:99) at org.eclipse.emf.ecore.resource.impl.ExtensibleURIConverterImpl.createInputStream(ExtensibleURIConverterImpl.java:354) at org.eclipse.emf.ecore.resource.impl.ResourceImpl.load(ResourceImpl.java:1256) at org.eclipse.xtext.resource.impl.DefaultResourceDescription.computeExportedObjects(DefaultResourceDescription.java:73) 2014-01-13 22:51:07 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'zwave.rules' 2014-01-13 22:51:07 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'weather.rules' 2014-01-13 22:51:07 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'energy.rules' 2014-01-13 22:51:07 INFO o.o.m.c.i.ModelRepositoryImpl[:99]- Loading model 'lights.rules'

kaikreuzer commented 10 years ago

I can confirm this problem, I have seen the same. Just checked the JavaDoc of FileInputStream. It states that a FileNotFoundException is thrown "[...] for some other reason cannot be opened for reading". So it does not even want to say that the file does not exist. Some users claimed that it is related to startup rules - files which do not contain startup rules do not seem to be concerned.

sumnerboy12 commented 10 years ago

Hmmm - interestingly heating.rules is one of the rule files I have without any startup rules. Probably 1/3 of my rules files have startup rules and the majority of those load fine. The irrigation.rules file does have a startup rule and that is the second-most frequent file to fail.

kaikreuzer commented 10 years ago

Ok, so that's no explanation then... :-(

jarlebh commented 10 years ago

I have the same behaviour on Linux, I have not seen this on Windows. Also renaming the file with problem only moves it to another rule file. I cannot see any pattern, also tried JDK 6 and 7

JSurf commented 10 years ago

Same here. Maybe too many open files or something like that ?

JSurf commented 10 years ago

Does this only happen on small devices like the raspberry or also on fast powerful servers ? I have a raspberry

jarlebh commented 10 years ago

For me it happens on a 3 year old dell server running ubuntu. I have no issues on windows.

  1. mai 2014 21:37 skrev "JSurf" notifications@github.com følgende:

Does this only happen on small devices like the raspberry or also on fast powerful servers ?

— Reply to this email directly or view it on GitHubhttps://github.com/openhab/openhab/issues/736#issuecomment-43546519 .

JSurf commented 10 years ago

Copied my configuration to a more powerful server, and it fails there regularly on startup. Seems to be timing related. I tried to debug inside the ModelRepositoryImpl addOrRefresh method, but then it does not fail, maybe because debugging slows down the loading to a later time

without debugging it fails every time

sumnerboy12 commented 10 years ago

Kai committed a fix recently which has pretty much resolved this issue for me now (after I was seeing it after every single restart). Try the latest v1.5.0 SNAPSHOT build and see if things improve.

kaikreuzer commented 10 years ago

My fix was not about the FileNotFoundException, but about registering actions at startup - so I am not sure, if this can be really related? If so, even better :-)

sumnerboy12 commented 10 years ago

Yep - all my start up issues have gone - although I did just remember I moved all my startup rules into a single file/rule which I now trigger manually after a restart. So that may have something to do with it as well. Either way, my system is much more stable now!

JSurf commented 10 years ago

I just ran my config on a 1.5 nightly build runtime. This issue is NOT fixed with the mentioned patch

sumnerboy12 commented 10 years ago

Ok - try removed all rules with System started triggers. I moved them into a rule which is triggered by a virtual item - i.e. just a switch with no binding which I manually switch via the UI once openHAB has started.

JSurf commented 10 years ago

Currently i'm fine with touching the failed files after startup. I'm more interested to find the reason for this behaviour so this can be fixed in the code.

JSurf commented 10 years ago

So after some more debugging i have found something. I have enabled the thread name in the logging an found something interesting. The FileNotFoundException is thrown from a thread named after the last rule in my first rules file.

FolderObserver 15:35:24.858 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'hwr_cwl.rules'
FolderObserver 15:35:25.511 INFO  runtime.busevents[:22] - HWR_CWL received command 2
FolderObserver 15:35:25.524 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'muell.rules'
FolderObserver 15:35:25.580 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'network.rules'
FolderObserver 15:35:25.581 WARN  o.o.m.c.i.ModelRepositoryImpl[:58] - Configuration model 'network.rules' is either empty or cannot be parsed correctly!
FolderObserver 15:35:25.583 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'persons.rules'
CWL Profiles to Homematic commands 15:35:25.590 ERROR o.e.x.r.i.DefaultResourceDescription[:75] - network.rules (No such file or directory)
java.io.FileNotFoundException: network.rules (No such file or directory)
        at java.io.FileInputStream.open(Native Method)dd

Why is there a thread named after my rule trying to load another rules file ??

But if i remove the last rule of hwr_cwl.rules everything is fine. That last rule is an "item changed" rule on a "virtual" item with no binding that is changed on startup with a startup rule. So maybe it is right that the error is related to startup rules in rules files but it might cause other files to fail. If i remove the last rule of hwr_cwl.rules i currently cannot reproduce the loading error

Here are my rules:

hwr_cwl.rules:

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*

rule "CWL Startup"
when
   System started or
   Item HwrCwlSwUnreach changed from ON to OFF
then
   if (now.getHourOfDay >= 22 || now.getHourOfDay <= 7) {
      sendCommand(HWR_CWL, 1)
   } else {
      sendCommand(HWR_CWL, 2)
   }
end

//rule "CWL Unreachable"
//when
//   Item HwrCwlSwUnreach changed from OFF to ON
//then
//   sendCommand(HWR_CWL, -1)
//end

rule "CWL Nacht reduziert"
when
    Time cron "0 0 22 * * ?" // 22:00 reduziert
then
   sendCommand(HWR_CWL, 1)
end

rule "CWL Tags normal"
when
    Time cron "0 0 7 * * ?" // 8:00 normal
then
   sendCommand(HWR_CWL, 2)
end

rule "CWL Profiles to Homematic commands"
when
       Item HWR_CWL changed
then
              sendCommand(HwrCWLSw1,OFF)
              sendCommand(HwrCWLSw2,OFF)
              sendCommand(HwrCWLSw3,OFF)
              sendCommand(HwrCWLSw4,OFF)

        switch(HWR_CWL.state) {
                     case 0 : sendCommand(HwrCWLSw1,ON)
            case 2 : sendCommand(HwrCWLSw2,ON)
            case 3 : sendCommand(HwrCWLSw3,ON)

        }
end

network.rules:

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*

var Number mediaPcFullNotify = 0

rule "media-PC nicht erreichbar"
when
   Item Net_MediaPC changed to OFF
then
   sendMail("some@mail.com", "[OPENHAB] Media-PC nicht erreichbar", "Media-PC per PING nicht zu erreichen")
end

rule "media-PC full"
when
   Item Net_MediaPC_HDD changed
then
   if (Net_MediaPC_HDD.state > 90) {
      //if (mediaPcFullNotify == 0) {
      //   mediaPcFullNotify = 1
         sendMail("some@mail.com", "[OPENHAB] Media-PC HDD fast voll", "Media-PC HDD ist fast voll "+Net_MediaPC_HDD.state+ " % belegt")
      //}
   } else {
     // mediaPcFullNotify = 0
   }
end
JSurf commented 10 years ago

I could reduce the hwr_cwl.rules file to a minimum:

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*

rule "CWL Startup"
when
   System started
then
      sendCommand(HWR_CWL, 1)
end

rule "CWL Profiles to Homematic commands"
when
       Item HWR_CWL changed
then
   logInfo("CWL","changed");
end

Now another rules file failed:

FolderObserver 16:07:10.862 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'hwr_cwl.rules'
FolderObserver 16:07:11.481 INFO  runtime.busevents[:22] - HWR_CWL received command 2
FolderObserver 16:07:11.485 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'muell.rules'
CWL Profiles to Homematic commands 16:07:11.495 ERROR o.e.x.r.i.DefaultResourceDescription[:75] - muell.rules (No such file or directory)
java.io.FileNotFoundException: muell.rules (No such file or directory)
        at java.io.FileInputStream.open(Native Method)
CWL Profiles to Homematic commands 16:07:11.523 INFO  org.openhab.model.script.CWL[:53] - yo
FolderObserver 16:07:11.560 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'network.rules'
FolderObserver 16:07:11.572 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'persons.rules'

Actually it seems it is not important what is inside the file that fails

Hope this Info helps in tracking down this bug.

lostcontrol commented 10 years ago

I upgraded from 1.3.1 to a 1.5.0 CI snapshot (#656) yesterday and can also confirm this issue. I have to check if I have "System started" triggers in my rules.

JSurf commented 10 years ago

I think the cause is that rules get executed before all rules are loaded in proper models. Would it be possible to postpone any rule execution (including startup rules) until ALL rules files are loaded ?

From the log above i would say that the threads "FolderObserver" and "CWL Profiles..." try to load the same model at the same time, with the "CWL Profiles..." thread maybe not having enough information to properly load the model.

From a user perspective the easiest workaround could be to put all rules into one big spaghetti-rules file, which i would prefer not to do for easier maintainance of configuration.

JSurf commented 10 years ago

Some more stuff, i hink i have tracked it down to two functions.

ModelRepositoryImpl.addOrRefreshModel(String name, InputStream inputStream) RuleEngine.executeRule(Rule rule, RuleEvaluationContext context)

From a timing perspective the ScriptExecutionThread in RuleEngine runs in between ModelRepositoryImpl:77 resource = resourceSet.createResource(URI.createURI(name)); and before the resource is actually loaded

so now the model is alread in the resource set but not loaded. Somehow the ScriptExecutionThread does access all rules models in an uncontrolled way NOT through the ModelRepositoryImpl where everything is properly synchronized.

Finally found the full stack after wondering for some time that there is no openhab-class involved. stdout only shows part of the stack trace, here is the full one:

java.io.FileNotFoundException: muell.rules (No such file or directory)
        at java.io.FileInputStream.open(Native Method)
        at java.io.FileInputStream.<init>(FileInputStream.java:106)
        at org.eclipse.emf.ecore.resource.impl.FileURIHandlerImpl.createInputStream(FileURIHandlerImpl.java:99)
        at org.eclipse.emf.ecore.resource.impl.ExtensibleURIConverterImpl.createInputStream(ExtensibleURIConverterImpl.java:354)
        at org.eclipse.emf.ecore.resource.impl.ResourceImpl.load(ResourceImpl.java:1256)
        at org.eclipse.xtext.resource.impl.DefaultResourceDescription.computeExportedObjects(DefaultResourceDescription.java:73)
        at org.eclipse.xtext.resource.DerivedStateAwareResourceDescriptionManager$1.getLookUp(DerivedStateAwareResourceDescriptionManager.java:61)
        at org.eclipse.xtext.resource.impl.AbstractResourceDescription.getExportedObjects(AbstractResourceDescription.java:32)
        at org.eclipse.xtext.resource.DerivedStateAwareResourceDescriptionManager.internalGetResourceDescription(DerivedStateAwareResourceDescriptionManager.java:45)
        at org.eclipse.xtext.resource.impl.DefaultResourceDescriptionManager$1.get(DefaultResourceDescriptionManager.java:60)
        at org.eclipse.xtext.resource.impl.DefaultResourceDescriptionManager$1.get(DefaultResourceDescriptionManager.java:1)
        at org.eclipse.xtext.util.OnChangeEvictingCache.get(OnChangeEvictingCache.java:75)
        at org.eclipse.xtext.resource.impl.DefaultResourceDescriptionManager.getResourceDescription(DefaultResourceDescriptionManager.java:58)
        at org.eclipse.xtext.resource.impl.ResourceSetBasedResourceDescriptions.getResourceDescription(ResourceSetBasedResourceDescriptions.java:97)
        at org.eclipse.xtext.resource.impl.ResourceSetBasedResourceDescriptions$1$1.computeNext(ResourceSetBasedResourceDescriptions.java:61)
        at org.eclipse.xtext.resource.impl.ResourceSetBasedResourceDescriptions$1$1.computeNext(ResourceSetBasedResourceDescriptions.java:1)
        at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:141)
        at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:136)
        at com.google.common.collect.Iterators$7.computeNext(Iterators.java:643)
        at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:141)
        at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:136)
        at com.google.common.collect.Iterators$8.hasNext(Iterators.java:777)
        at com.google.common.collect.Iterables$3.hasNext(Iterables.java:501)
        at com.google.common.collect.Iterators$5.hasNext(Iterators.java:539)
        at org.eclipse.xtext.common.types.access.impl.IndexedJvmTypeAccess.getIndexedJvmType(IndexedJvmTypeAccess.java:64)
        at org.eclipse.xtext.common.types.access.impl.IndexedJvmTypeAccess.getIndexedJvmType(IndexedJvmTypeAccess.java:53)
        at org.eclipse.xtext.common.types.access.impl.ClasspathTypeProvider.findTypeByName(ClasspathTypeProvider.java:77)
        at org.openhab.model.script.scoping.ScriptScopeProvider.createItemFeatures(ScriptScopeProvider.java:87)
        at org.openhab.model.script.scoping.ScriptScopeProvider.createSimpleFeatureCallScope(ScriptScopeProvider.java:64)
        at org.eclipse.xtext.xbase.scoping.XbaseScopeProvider.createFeatureCallScope(XbaseScopeProvider.java:331)
        at org.eclipse.xtext.xbase.scoping.XbaseScopeProvider.getScope(XbaseScopeProvider.java:179)
        at org.eclipse.xtext.xbase.linking.XbaseLinkingScopeProvider.getScope(XbaseLinkingScopeProvider.java:42)
        at org.eclipse.xtext.linking.impl.DefaultLinkingService.getScope(DefaultLinkingService.java:59)
        at org.eclipse.xtext.linking.impl.DefaultLinkingService.getLinkedObjects(DefaultLinkingService.java:119)
        at org.eclipse.xtext.linking.lazy.LazyLinkingResource.getEObject(LazyLinkingResource.java:179)
        at org.eclipse.xtext.xbase.resource.XbaseResource.access$0(XbaseResource.java:1)
        at org.eclipse.xtext.xbase.resource.XbaseResource$2.exec(XbaseResource.java:239)
        at org.eclipse.xtext.xbase.resource.XbaseResource$2.exec(XbaseResource.java:1)
        at org.eclipse.xtext.util.OnChangeEvictingCache.execWithoutCacheClear(OnChangeEvictingCache.java:124)
        at org.eclipse.xtext.xbase.resource.XbaseResource.getEObject(XbaseResource.java:237)
        at org.eclipse.emf.ecore.resource.impl.ResourceSetImpl.getEObject(ResourceSetImpl.java:223)
        at org.eclipse.emf.ecore.util.EcoreUtil.resolve(EcoreUtil.java:197)
        at org.eclipse.emf.ecore.util.EcoreUtil.resolve(EcoreUtil.java:257)
        at org.eclipse.emf.ecore.impl.BasicEObjectImpl.eResolveProxy(BasicEObjectImpl.java:1473)
        at org.eclipse.xtext.xbase.impl.XAbstractFeatureCallImpl.getFeature(XAbstractFeatureCallImpl.java:175)
        at org.eclipse.xtext.xbase.impl.XAbstractFeatureCallImpl.eGet(XAbstractFeatureCallImpl.java:434)
        at org.eclipse.xtext.xbase.impl.XFeatureCallImpl.eGet(XFeatureCallImpl.java:224)
        at org.eclipse.emf.ecore.impl.BasicEObjectImpl.eGet(BasicEObjectImpl.java:1011)
        at org.eclipse.emf.ecore.impl.BasicEObjectImpl.eGet(BasicEObjectImpl.java:1003)
        at org.eclipse.emf.ecore.impl.BasicEObjectImpl.eGet(BasicEObjectImpl.java:998)
        at org.eclipse.xtext.xbase.resource.XbaseResource.trackResolution(XbaseResource.java:202)
        at org.eclipse.xtext.xbase.resource.XbaseResource.getFeature(XbaseResource.java:187)
        at org.eclipse.xtext.xbase.resource.LinkingAssumptions.getFeature(LinkingAssumptions.java:120)
        at org.eclipse.xtext.xbase.impl.FeatureCallToJavaMapping.getFeature(FeatureCallToJavaMapping.java:60)
        at org.eclipse.xtext.xbase.impl.FeatureCallToJavaMapping.getActualReceiver(FeatureCallToJavaMapping.java:44)
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:656)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291)
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218)
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291)
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218)
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204)
        at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59)
        at org.openhab.core.scriptengine.ScriptExecutionThread.run(ScriptExecutionThread.java:44)

So the "DefaultResourceDescriptionManager" somehow accesses the not fully loaded model. This happens in the ScriptExecutionThread

kaikreuzer commented 10 years ago

Thanks for your very detailed analysis. Looks indeed like a race condition when starting the rules. We had discussed similar issues here: https://bugs.eclipse.org/bugs/show_bug.cgi?id=423516 The suggested solution is to only start executing rules when a certain start level is reached; all files should be loaded initially at a lower start level. I guess, this would prevent this issue here as well.

JSurf commented 10 years ago

yes from my analysis i would also think this would solve the issue

petrklus commented 10 years ago

Confirmed with 1.5 release.

Running on ODROID U3, Ubuntu 14.04 Server (headless, no X), Oracle's Java 7. Nothing else running on the machine, it has heaps of power left. Also running of eMMC for the OS, which means that IO should be pretty snappy too.

juelicher commented 9 years ago

With 1.6 it seems as if this problem got worse. I get the "file not found exception" on every startup, with older versions after 2-3 tries openHAB started without an exception.

Worse: In older versions touching the files which caused the problem was a good workaround. In 1.6 this workaround does not always work. Below is an extract from my log. After the fish touch there was the error "2014-11-26 18:10:13.801 WARN o.o.m.c.i.ModelRepositoryImpl[:58]- Configuration model 'operatinghours.rules' is either empty or cannot be parsed correctly!"

The second touch, without changing the file, worked as expected.

2014-11-26 18:10:13.618 ERROR o.e.x.r.i.DefaultResourceDescription[:75]- operatinghours.rules (No such file or directory) java.io.FileNotFoundException: operatinghours.rules (No such file or directory) at java.io.FileInputStream.open(Native Method) at java.io.FileInputStream.(FileInputStream.java:146) at org.eclipse.emf.ecore.resource.impl.FileURIHandlerImpl.createInputStream(FileURIHandlerImpl.java:99) at org.eclipse.emf.ecore.resource.impl.ExtensibleURIConverterImpl.createInputStream(ExtensibleURIConverterImpl.java:354) at org.eclipse.emf.ecore.resource.impl.ResourceImpl.load(ResourceImpl.java:1256) at org.eclipse.xtext.resource.impl.DefaultResourceDescription.computeExportedObjects(DefaultResourceDescription.java:73) 2014-11-26 18:10:13.801 INFO o.o.m.c.i.ModelRepositoryImpl[:97]- Refreshing model 'operatinghours.rules' 2014-11-26 18:10:13.801 WARN o.o.m.c.i.ModelRepositoryImpl[:58]- Configuration model 'operatinghours.rules' is either empty or cannot be parsed correctly! 2014-11-26 18:10:18.470 INFO o.o.m.script.measurement rules[:53]- Patio_Light_Bright changed to OFF 2014-11-26 18:10:18.897 INFO o.o.a.prowl.internal.Prowl[:132]- API call succeeded. 998 api calls left. 2014-11-26 18:10:33.815 INFO o.o.m.c.i.ModelRepositoryImpl[:79]- Loading model 'operatinghours.rules' 2014-11-26 18:10:34.029 INFO o.o.m.s.operating hours rules[:53]- Initialized Counters

sumnerboy12 commented 9 years ago

I found something interesting the other day, which was prompted by someones comment on the forum about startup issues on a Pi. They increased the 'folder watch interval' from the default 10s to 180s or something to give openHAB time to startup on their Pi before loading all the config.

I tried setting the interval for all my file types (items, rules, sitemaps, scripts etc) to 30s and saw an immediate improvement when starting up. We the default value of 10s I think openHAB is still in the middle of starting up when all of a sudden all the item and rule files are read, causing issues with concurrency and file access.

In my case I found leaving the items interval at 10s was best, then making rules 25s and scripts 30s. This means each part of the system initialises at a different time and I have been seeing a much more stable start up.

Might be worth trying and seeing it helps in your case?

JSurf commented 9 years ago

Tried with the suggested values on 1.5.1, this did not help in my case

petrklus commented 9 years ago

Same here - still experiencing the issue (still on 1.5 - will upgrade soon), need to "touch" the rule files after every restart. Did not try adjusting the values all the way to 180s, would be a bit of a pain to debug/develop any new rules.

Was the root cause of this identified or is it all still in the air?

petrklus commented 9 years ago

Just upgraded to 1.6.1 (only moved the settings to ensure I start fresh - all rrd4j is clean etc.) First run OK, on a second restart I got pretty much the same errors as on 1.5. Please see log: https://gist.github.com/petrklus/c1deacbbd598db07d6a2 (around line 131).

"Touching" the files afterwards fixes the issue as before and they load properly. I am running on quad-core ARM with nothing else running (server variant of the Ubuntu OS), so it's idling most of the time.

petrklus commented 9 years ago

Reproduced this with java8 as well. Sometimes I need to "touch" the file multiple times for get it loaded. Is anyone looking into this?

petrklus commented 9 years ago

Reproduced this with java8 as well. Sometimes I need to "touch" the file multiple times for get it loaded. Is anyone looking into this?

21:31:44.132 ERROR o.e.x.r.i.DefaultResourceDescription[:75]- christmas.rules (No such file or directory)
java.io.FileNotFoundException: christmas.rules (No such file or directory)
    at java.io.FileInputStream.open(Native Method)
    at java.io.FileInputStream.<init>(FileInputStream.java:131)
    at org.eclipse.emf.ecore.resource.impl.FileURIHandlerImpl.createInputStream(FileURIHandlerImpl.java:99)
    at org.eclipse.emf.ecore.resource.impl.ExtensibleURIConverterImpl.createInputStream(ExtensibleURIConverterImpl.java:354)
    at org.eclipse.emf.ecore.resource.impl.ResourceImpl.load(ResourceImpl.java:1256)
    at org.eclipse.xtext.resource.impl.DefaultResourceDescription.computeExportedObjects(DefaultResourceDescription.java:73)
    at org.eclipse.xtext.resource.DerivedStateAwareResourceDescriptionManager$1.getLookUp(DerivedStateAwareResourceDescriptionManager.java:61)
    at org.eclipse.xtext.resource.impl.AbstractResourceDescription.getExportedObjects(AbstractResourceDescription.java:32)
    at org.eclipse.xtext.resource.DerivedStateAwareResourceDescriptionManager.internalGetResourceDescription(DerivedStateAwareResourceDescriptionManager.java:45)
    at org.eclipse.xtext.resource.impl.DefaultResourceDescriptionManager$1.get(DefaultResourceDescriptionManager.java:60)
    at org.eclipse.xtext.resource.impl.DefaultResourceDescriptionManager$1.get(DefaultResourceDescriptionManager.java:1)
    at org.eclipse.xtext.util.OnChangeEvictingCache.get(OnChangeEvictingCache.java:75)
    at org.eclipse.xtext.resource.impl.DefaultResourceDescriptionManager.getResourceDescription(DefaultResourceDescriptionManager.java:58)
    at org.eclipse.xtext.resource.impl.ResourceSetBasedResourceDescriptions.getResourceDescription(ResourceSetBasedResourceDescriptions.java:97)
    at org.eclipse.xtext.resource.impl.ResourceSetBasedResourceDescriptions$1$1.computeNext(ResourceSetBasedResourceDescriptions.java:61)
    at org.eclipse.xtext.resource.impl.ResourceSetBasedResourceDescriptions$1$1.computeNext(ResourceSetBasedResourceDescriptions.java:1)
    at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:141)
    at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:136)
    at com.google.common.collect.Iterators$7.computeNext(Iterators.java:643)
    at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:141)
    at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:136)
    at com.google.common.collect.Iterators$8.hasNext(Iterators.java:777)
    at com.google.common.collect.Iterables$3.hasNext(Iterables.java:501)
    at com.google.common.collect.Iterators$5.hasNext(Iterators.java:539)
    at org.eclipse.xtext.common.types.access.impl.IndexedJvmTypeAccess.getIndexedJvmType(IndexedJvmTypeAccess.java:64)
    at org.eclipse.xtext.common.types.access.impl.IndexedJvmTypeAccess.getIndexedJvmType(IndexedJvmTypeAccess.java:53)
    at org.eclipse.xtext.common.types.access.impl.ClasspathTypeProvider.findTypeByName(ClasspathTypeProvider.java:77)
    at org.openhab.model.script.scoping.ScriptScopeProvider.createItemFeatures(ScriptScopeProvider.java:87)
    at org.openhab.model.script.scoping.ScriptScopeProvider.createSimpleFeatureCallScope(ScriptScopeProvider.java:64)
    at org.eclipse.xtext.xbase.scoping.XbaseScopeProvider.createFeatureCallScope(XbaseScopeProvider.java:331)
    at org.eclipse.xtext.xbase.scoping.XbaseScopeProvider.getScope(XbaseScopeProvider.java:179)
    at org.eclipse.xtext.xbase.linking.XbaseLinkingScopeProvider.getScope(XbaseLinkingScopeProvider.java:42)
    at org.eclipse.xtext.linking.impl.DefaultLinkingService.getScope(DefaultLinkingService.java:59)
    at org.eclipse.xtext.linking.impl.DefaultLinkingService.getLinkedObjects(DefaultLinkingService.java:119)
    at org.eclipse.xtext.linking.lazy.LazyLinkingResource.getEObject(LazyLinkingResource.java:179)
    at org.eclipse.xtext.xbase.resource.XbaseResource.access$0(XbaseResource.java:1)
    at org.eclipse.xtext.xbase.resource.XbaseResource$2.exec(XbaseResource.java:239)
    at org.eclipse.xtext.xbase.resource.XbaseResource$2.exec(XbaseResource.java:1)
    at org.eclipse.xtext.util.OnChangeEvictingCache.execWithoutCacheClear(OnChangeEvictingCache.java:124)
    at org.eclipse.xtext.xbase.resource.XbaseResource.getEObject(XbaseResource.java:237)
    at org.eclipse.emf.ecore.resource.impl.ResourceSetImpl.getEObject(ResourceSetImpl.java:223)
    at org.eclipse.emf.ecore.util.EcoreUtil.resolve(EcoreUtil.java:197)
    at org.eclipse.emf.ecore.util.EcoreUtil.resolve(EcoreUtil.java:257)
    at org.eclipse.emf.ecore.impl.BasicEObjectImpl.eResolveProxy(BasicEObjectImpl.java:1473)
    at org.eclipse.xtext.xbase.impl.XAbstractFeatureCallImpl.getFeature(XAbstractFeatureCallImpl.java:175)
    at org.eclipse.xtext.xbase.impl.XAbstractFeatureCallImpl.eGet(XAbstractFeatureCallImpl.java:434)
    at org.eclipse.xtext.xbase.impl.XFeatureCallImpl.eGet(XFeatureCallImpl.java:224)
    at org.eclipse.emf.ecore.impl.BasicEObjectImpl.eGet(BasicEObjectImpl.java:1011)
    at org.eclipse.emf.ecore.impl.BasicEObjectImpl.eGet(BasicEObjectImpl.java:1003)
    at org.eclipse.emf.ecore.impl.BasicEObjectImpl.eGet(BasicEObjectImpl.java:998)
    at org.eclipse.xtext.xbase.resource.XbaseResource.trackResolution(XbaseResource.java:202)
    at org.eclipse.xtext.xbase.resource.XbaseResource.getFeature(XbaseResource.java:187)
    at org.eclipse.xtext.xbase.resource.LinkingAssumptions.getFeature(LinkingAssumptions.java:120)
    at org.eclipse.xtext.xbase.impl.FeatureCallToJavaMapping.getFeature(FeatureCallToJavaMapping.java:60)
    at org.eclipse.xtext.xbase.impl.FeatureCallToJavaMapping.getActualReceiver(FeatureCallToJavaMapping.java:44)
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:656)
    at sun.reflect.GeneratedMethodAccessor49.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291)
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218)
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321)
    at sun.reflect.GeneratedMethodAccessor63.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291)
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218)
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204)
    at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59)
    at org.openhab.model.rule.internal.engine.ExecuteRuleJob.execute(ExecuteRuleJob.java:55)
    at org.quartz.core.JobRunShell.run(JobRunShell.java:213)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557)
DocZoid commented 9 years ago

Why is this still open? This is so annoying to me... I switched from a singlecore Synology NAS to a odroid XU3-lite octacore and from java 7 to 8 and still the same behaviour. It even got worse now: using exactly the same files, on the NAS all the items got loaded before the rules (always, and the items never had errors), now the rules are loaded before, which gives a lot of errors because of unknown items, and also the item files get this error sometimes.

For those interested: I made a workaround on my NAS which at least helped with the rules files (only leaving the .persist files to the error, but those failed every time they were read after the items). The trick is this:

rule "power alive" when Time cron "40 0/6 * * * ?" or System started then executeCommandLine("touch /tmp/power.rules") end

rule Startup when System started then
executeCommandLine("/usr/bin/sudo cp /share/OpenHAB/configurations/rules/* /tmp") end

!/bin/sh

cd /tmp find ./ -name "*.rules" -mmin +8 -exec touch /share/OpenHAB/configurations/rules/{} ';'

On the odroid, all this doesn't work anymore because like I said, the items get broken, too. On the NAS, I had a CPU monitor, and I found out that this bug only occurred if the cpu load was at max. Touching the .persist files during startup time did not help. After openhab was running and the cpu load dropped, I could touch the .persist files to reload them 100% successfully. Also, the trouble only starts when rules are running (and like I said the cpu is at max). Loading .items and .persist files before the rules is also 100% successful. Does this help?

Please help on this! Thx a lot!

sumnerboy12 commented 9 years ago

I have the following in my openhab.cfg and have found it has made a huge difference to startup reliability;

Configuration folders (must exist as a subdirectory of

"configurations"; the value

tells the number of seconds for the next scan of the directory for

changes. A

value of -1 deactivates the scan).

A comma separated list can follow after the refresh value. This list

defines a filter

for valid file extensions for the models.

folder:items=10,items folder:sitemaps=30,sitemap folder:rules=30,rules folder:scripts=25,script folder:persistence=30,persist

This ensures my items are loaded first, then scripts, then the rest.

Worth a try?

DocZoid commented 9 years ago

Yes thank you, I already just now followed your posts and got to a similar result: folder:items=20,items folder:persistence=22,persist folder:scripts=24,script folder:sitemaps=26,sitemap folder:rules=30,rules

this is then exactly the order in which the files are loaded. But I have 7 rules files and as long as they are still loaded all at once, some of them fail. I don't really want to use only one rules file (because all rules would be retriggered after changing the file). I guess I will reinstall my cron-system on the odroid then...

JanLochi commented 9 years ago

I have the same issue. I use "touch" on the files as a workaround.

lewie commented 9 years ago

I HAD same/similar issue.

In my Config I always installed Systeminfo Binding. Since OH Version 1.4 I had this Problem. Errors on startup or while updating rules Files. I blamed it on OpenHAB.

Yesterday I've forgotten to install Systeminfo Binding. Now, all File Issues are over. I verified this effect, it was definitely caused by Systeminfo Binding or its used Hyperic SIGAR API etc..

Hope this helps somebody. I'm really happy now. Could harden my OH Installation vehement.

petrklus commented 9 years ago

I am really happy this solved it for you!

However, I've seen the same issue even on clean installs which I've used for rule development, those had no other extensions installed. Are you sure you did not remove any rule files when you deployed the new system without the systeminfo binding?

On Mon, Apr 20, 2015 at 4:23 PM, lewie notifications@github.com wrote:

I HAD same/similar issue.

In my Config I always installed Systeminfo Binding. Since OH Version 1.4 I had this Problem. Errors on startup or while updating rules Files. I blamed it on OpenHAB.

Yesterday I've forgotten to install Systeminfo Binding. Now, all File Issues are over. I verified this effect, it was definitely caused by Systeminfo Binding or its used Hyperic SIGAR API etc..

Hope this helps somebody. I'm really happy now. Could harden my OH Installation vehement.

— Reply to this email directly or view it on GitHub https://github.com/openhab/openhab/issues/736#issuecomment-94466319.

lewie commented 9 years ago

Thanks, yes I'm happy!

Did not remove any rule file. My System is a virtual Debian 7, now a daily OpenHAB 1.7.0. I have 10 rules Files, 11 Items Files, 7 sitemaps. addons: org.openhab.action.actions-1.7.0-SNAPSHOT.jar org.openhab.action.xmpp-1.4.0_working_whithout_tls.jar org.openhab.action.mail-1.7.0-SNAPSHOT.jar org.openhab.binding.configadmin-1.7.0-SNAPSHOT.jar org.openhab.binding.exec-1.7.0-SNAPSHOT.jar org.openhab.binding.fritzaha-1.7.0-SNAPSHOT.jar org.openhab.binding.fritzbox-1.7.0-SNAPSHOT.jar org.openhab.binding.http-1.7.0-SNAPSHOT.jar org.openhab.binding.knx-1.7.0-SNAPSHOT.jar org.openhab.binding.modbus-1.7.0-SNAPSHOT.jar org.openhab.binding.mqtt-1.7.0-SNAPSHOT.jar org.openhab.binding.networkhealth-1.7.0-SNAPSHOT.jar org.openhab.binding.ntp-1.7.0-SNAPSHOT.jar org.openhab.binding.snmp-1.7.0-SNAPSHOT.jar org.openhab.binding.tcp-1.7.0-SNAPSHOT.jar org.openhab.persistence.mqtt-1.7.0-SNAPSHOT.jar org.openhab.persistence.postgresql-1.7.0-SNAPSHOT.jar

petrklus commented 9 years ago

.. and for the rest of us; @teichsta , @kaikreuzer - is anyone assigned to fix this?

paulianttila commented 9 years ago

@lewie: I doubt that problem is caused by the system binding. Binding removal on your environment most propably change other binding and rules loading timing which then seems to hide the actual problem.

lewie commented 9 years ago

@paulianttila: Maybe, therefore it would be the easiest, if anybody (how has/knows this Problem too) verifies this effect on it's own System?! I doubt that it is a timing problem the effect is too conspicuous.

it's possible that it is a side effect, do not know, is systeminfo Binding monitoring the file system like OpenHab?

bitforker commented 9 years ago

@lewie: I have the exact same issues but no systeminfo binding installed. I am on openhab 1.6.2 on a physical quad-core Core7 with Debian Wheezy and Oracle Java 8. Exceptions on every startup.

sumnerboy12 commented 9 years ago

Have you tried adjusting the auto-load interval configs as explained here? https://github.com/openhab/openhab/issues/736#issuecomment-77769774

Since doing this I only rarely seeing a file load exception - previously I was getting 3-4 every restart.

bitforker commented 9 years ago

indeed, changing the configuration settings as described above helps. still it's a pain for rule development as now I have to wait for 30 seconds before a changed rule file gets loaded. but for the moment this helps. thanks.

twisniew1976 commented 9 years ago

I have the same/similar issue. (openHAB 1.7.0)

No one presented solution work every time for me, so I've builded some workaround which work for me for 100%.

It is no so beautiful solution :-D

I stopped using System started trigger in rules.

I've created virtual item: Switch SystemStarted "System: Started [%s]" { exec="<[/home/pi/openHAB/bin/getItemLockState.sh@@%3$s:60000:REGEX((.*?))] >[*:/home/pi/openHAB/bin/setItemLockState.sh@@%3$s@@%2$s]" }

next I've created special rule:

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*

rule "System_Startup"
when
    Item SystemStarted received update OFF
then

    sendCommand(SystemStarted, ON)

end

and added to startup script line (on begin of the file) rm -f /home/pi/openHAB/lock/SystemStarted.lock

Next I've changed all relations to System started with Item SystemStarted changed from OFF to ON

getItemLockState.sh source:

#!/bin/bash
HAF=/home/pi/openHAB/bin
LOF=/home/pi/openHAB/lock

if [ ! -f $LOF/$1.lock ]; then
        echo "OFF"
else
        echo "ON"
fi
exit 0

setItemLockState.sh source:

#!/bin/bash
HAF=/home/pi/openHAB/bin
LOF=/home/pi/openHAB/lock

if [ "$2" == 'ON' ]; then
        echo "ON" > $LOF/$1.lock
else
        rm -f $LOF/$1.lock
fi
exit 0

Summarizing Item SystemStarted will change state only once from OFF to ON more or less 6 seconds after system have started up.

moutemoute38 commented 9 years ago

I don't know if I'm really with the same exact problem here, but searching for a fix I found this issue, so it might be usefull for someone. I had the same file not found exception on some of my rule and sitemap files.

The problem was in the following rules :

rule bci_startup

when System started

then sendCommand(bci_status , "REST") end

rule bci_status when Item bci_status received command then ... end

So I think that the startup rule is executed while all the rule file is not completely loaded. The weird thing is that it happens only on startup, and not when just changing this specific file (which triggers the startup rule anyway...) The other problem is that when OH fails to load this one rule files, it also fails to load a few others. So by fixing this one file, all the other files were correctly loaded.

The simplest workaround I found so far is to add a timer to all my startup rules, so the previous failing rule is now :

rule bci_startup

when System started

then var Timer t = createTimer(now.plusSeconds(10)) [| sendCommand(bci_status , "REST")] end

With that all the files are loaded correctly on startup with the following cfg

folder:items=3,items folder:sitemaps=3,sitemap folder:rules=3,rules folder:scripts=3,script folder:persistence=3,persist

I don't know if it's really in the topic, but hope that helps someone.

petrklus commented 9 years ago

@twisniew1976 that is amazing - thank you very much. The only modification I did was slight alteration of the scripts to make it a bit more "universal":

Get:

#!/bin/bash
LOF=$( cd "$( dirname "${BASH_SOURCE[0]}" )" && pwd )

if [ ! -f $LOF/lock/$1.lock ]; then
        echo "OFF"
else
        echo "ON"
fi
exit 0

Set:

#!/bin/bash

LOF=$( cd "$( dirname "${BASH_SOURCE[0]}" )" && pwd )

if [ "$2" == 'ON' ]; then
        echo "ON" > $LOF/lock/$1.lock
else
        rm -f $LOF/lock/$1.lock
fi
exit 0

All in all - I wish there was proper way for OH to handle this... I strongly believe there should be a proper sequence to the startup procedure. There are workarounds needed even for the persistence - which does not load before rules start working.. https://github.com/openhab/openhab/wiki/Persistence#startup-behavior

petrklus commented 9 years ago

@twisniew1976 I am afraid I've rejoiced too soon - the removal of the startup rules did decrease the frequency of the issue significantly, however, it is still there. I am using fair amount of cron-triggered rules (most of them every 1-2m), so my guess is that even though startup rules are no longer ran prematurely, the cron-triggers are still loaded too soon.

@teichsta, @kaikreuzer - is there any plan at all to address this? To me it's still quite a fundamental flaw if I cannot restart OH without examination of the logs to finalise the startup.

PS: I've switched from Odroid to Raspberry PI 2 and the issue stays the same.

michal-konopinski commented 9 years ago

1.7.1 and still wrong :(

twisniew1976 commented 9 years ago

@petrklus I build additional "no so beautiful solution" to prevent / workaround our problem: Script looking for problematic files:

openHAB-daemon-watcher-worker.sh

#!/bin/bash

PATH="/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:$PATH"

# openHAB root folder
if [ -z "${openHAB_root}" ] ; then openHAB_root=/home/pi/openHAB ; fi

openHAB_Folder=${openHAB_root}

PreviousCheck="`cat /tmp/openHAB_LastCheck 2> /dev/null`"

if [ -z "$PreviousCheck" ]
then
    PreviousCheck=`date -d -1minute +"%Y-%m-%d %H:%M:%S"`
fi

NewCheck=`date +"%Y-%m-%d %H:%M:%S"`

cd ${openHAB_root}/logs

cat openhab.log | awk -v PreviousCheck="$PreviousCheck" -v openHAB_Folder="$openHAB_Folder" '
/DefaultResourceDescription] - / && /(No such file or directory)/ {

    if($0 >= PreviousCheck ) {

        b = index($0, "DefaultResourceDescription]")
        e = index($0, "(No such file or directory)")
        l = length("DefaultResourceDescription]")

        if(e > (b + l + 3)) {
            FileToReload = substr($0, b + l + 3, e - l - b - 4)

            if(index(FileToReload, ".items") > 0)
                print openHAB_Folder"/configurations/items/"FileToReload

            else if(index(FileToReload, ".persist") > 0)
                print openHAB_Folder"/configurations/persistence/"FileToReload

            else if(index(FileToReload, ".sitemap") > 0)
                print openHAB_Folder"/configurations/sitemaps/"FileToReload

            else if(index(FileToReload, ".script") > 0)
                print openHAB_Folder"/configurations/scripts/"FileToReload

            else if(index(FileToReload, ".rules") > 0)
                print openHAB_Folder"/configurations/rules/"FileToReload

        }

    }

}' > /tmp/openHAB_FilesToReload

IFS=$'\n'
for FileToReload in `cat /tmp/openHAB_FilesToReload` ; do

    echo "${NewCheck}     [INFO ] [Model refresh problem watcher ] - ${FileToReload}" >> openhab.log

    touch "$FileToReload"

done

echo $NewCheck > /tmp/openHAB_LastCheck
rm -f /tmp/openHAB_FilesToReload

and

openHAB-daemon-watcher.sh:

#!/bin/bash

PATH="/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:$PATH"

# openHAB root folder
if [ -z "${openHAB_root}" ] ; then openHAB_root=/home/pi/openHAB ; fi

rm -f /tmp/openHAB_LastCheck

while true
do

    cd ${openHAB_root}

    sleep 120

    ${openHAB_root}/bin/openHAB-daemon-watcher-worker.sh

done

This script is looking for files which are not loaded properly by openHAB and "touch" they to enforce openHAB to reload.

@michal-konopinski: I also have 1.7.1 and problem still exist.

kstaniek commented 9 years ago

Dos it help having one single rule file for all rules?

omatzyo commented 9 years ago

I just split my 2 big rules files into several smaller files and now this error message appears for all of them... and none of them run. I guess I'll have to recombine.