openHAB on raspberry starting problems

Setup, Configuration and Use Scripts & Rules
1

I have some problems starting my openHAB on a raspberry PI. System is starting without any exceptions/errors etc. but mostly after startup UI is updated only once and no more change after that. UI is no more responsive. F.e. changing a switch has no effect and normally after a few minutes UI is no more available and even no events are logged/processed any more, so a restart is required. Normally it takes me 15-20 times restarting the openHAB system to get it running properly. I tried several things, delaying the openHAB start on booting for example, but no real effect. Seems to be in the openHAB system itself and not depending on any environment. Removing the homematic binding normally helps to start openHAB properly, but this can’t be the solution. I put that binding into debug but even on starting the system properly or if it fails -> same successfull log messages from that binding. So i tried to analyse the startup process of openHAB and attached you will find 4 logs. 2 successfull starts and 2 failed starts. What is conspicuous to me in that files is, that on the successful starts the rules are loaded very late in the startup process compared to the failed startups.
Any ideas how to workaround this annoying issue?

running1.txt
INFO o.o.c.internal.CoreActivator[:61]- openHAB runtime has been started (v1.7.1). INFO o.o.i.s.i.DiscoveryServiceImpl[:93]- mDNS service has been started INFO o.o.i.s.i.DiscoveryServiceImpl[:53]- Service Discovery initialization completed. WARN o.a.c.DefaultAnnotationProcessor[:178]- Unable to detect annotations. Application may fail to deploy. INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.sitemap' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'rrd4j.persist' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.script' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.items' INFO o.o.io.rest.RESTApplication[:144]- Started REST API at /rest INFO o.o.u.w.i.s.WebAppServlet[:79]- Started Classic UI at /openhab.app INFO o.o.b.h.i.bus.HomematicBinding[:92]- HomematicConfig[host=XXX,callbackHost=XXX,callbackPort=XXXX,aliveInterval=300,reconnectInterval=disabled] INFO o.o.b.h.i.c.HomematicCommunicator[:74]- Starting Homematic communicator INFO o.o.b.h.i.c.HomematicCommunicator[:84]- Homematic ServerId[name=Homegear,version=0.5.25] INFO o.o.b.h.i.c.c.HomegearClient[:59]- Starting HomegearClient INFO o.o.b.h.i.c.StateHolder[:83]- Loading Homematic datapoints INFO o.o.b.h.i.c.StateHolder[:91]- Finished loading 93 Homematic datapoints INFO o.o.b.h.i.c.StateHolder[:187]- Loading Homematic Server variables INFO o.o.c.s.AbstractActiveService[:169]- HTTP Refresh Service has been started INFO o.o.b.h.i.c.StateHolder[:196]- Finished loading 0 Homematic server variables INFO o.o.b.h.i.c.s.BinRpcCallbackServer[:44]- Starting BinRpcCallbackServer at port 9123 INFO o.o.b.h.i.c.HomematicCommunicator[:114]- Scheduling one datapoint reload job in one minute INFO o.o.c.s.AbstractActiveService[:169]- Homematic server connection tracker has been started INFO o.o.b.a.i.bus.AstroBinding[:70]- AstroConfig[latitude=XXX,longitude=XXX,interval=120,systemTimezone=Europe/Berlin (CET +0100),daylightSavings=false] INFO o.o.c.s.AbstractActiveService[:169]- Exec Refresh Service has been started INFO o.o.c.s.AbstractActiveService[:169]- NTP Refresh Service has been started INFO o.o.b.a.i.job.JobScheduler[:150]- Scheduled a daily job at midnight for astro calculation INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'steckdosen.rules' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'fbh.rules' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'alarm.rules'

running2.txt
INFO o.o.c.internal.CoreActivator[:61]- openHAB runtime has been started (v1.7.1). INFO o.o.i.s.i.DiscoveryServiceImpl[:93]- mDNS service has been started INFO o.o.i.s.i.DiscoveryServiceImpl[:53]- Service Discovery initialization completed. WARN o.a.c.DefaultAnnotationProcessor[:178]- Unable to detect annotations. Application may fail to deploy. INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.sitemap' INFO o.o.io.rest.RESTApplication[:144]- Started REST API at /rest INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'rrd4j.persist' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.script' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.items' INFO o.o.u.w.i.s.WebAppServlet[:79]- Started Classic UI at /openhab.app INFO o.o.b.h.i.bus.HomematicBinding[:92]- HomematicConfig[host=XXX,callbackHost=XXX,callbackPort=XXX,aliveInterval=300,reconnectInterval=disabled] INFO o.o.b.h.i.c.HomematicCommunicator[:74]- Starting Homematic communicator INFO o.o.b.h.i.c.HomematicCommunicator[:84]- Homematic ServerId[name=Homegear,version=0.5.25] INFO o.o.b.h.i.c.c.HomegearClient[:59]- Starting HomegearClient INFO o.o.b.h.i.c.StateHolder[:83]- Loading Homematic datapoints INFO o.o.c.s.AbstractActiveService[:169]- HTTP Refresh Service has been started INFO o.o.b.h.i.c.StateHolder[:91]- Finished loading 93 Homematic datapoints INFO o.o.b.h.i.c.StateHolder[:187]- Loading Homematic Server variables INFO o.o.b.h.i.c.StateHolder[:196]- Finished loading 0 Homematic server variables INFO o.o.b.h.i.c.s.BinRpcCallbackServer[:44]- Starting BinRpcCallbackServer at port 9123 INFO o.o.b.h.i.c.HomematicCommunicator[:114]- Scheduling one datapoint reload job in one minute INFO o.o.c.s.AbstractActiveService[:169]- Homematic server connection tracker has been started INFO o.o.b.a.i.bus.AstroBinding[:70]- AstroConfig[latitude=XXX,longitude=XXX,interval=120,systemTimezone=Europe/Berlin (CET +0100),daylightSavings=false] INFO o.o.c.s.AbstractActiveService[:169]- Exec Refresh Service has been started INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'steckdosen.rules' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'fbh.rules' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'alarm.rules' INFO o.o.c.s.AbstractActiveService[:169]- NTP Refresh Service has been started INFO o.o.b.a.i.job.JobScheduler[:150]- Scheduled a daily job at midnight for astro calculation

failed1.txt
INFO o.o.c.internal.CoreActivator[:61]- openHAB runtime has been started (v1.7.1). INFO o.o.i.s.i.DiscoveryServiceImpl[:93]- mDNS service has been started INFO o.o.i.s.i.DiscoveryServiceImpl[:53]- Service Discovery initialization completed. WARN o.a.c.DefaultAnnotationProcessor[:178]- Unable to detect annotations. Application may fail to deploy. INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.sitemap' INFO o.o.io.rest.RESTApplication[:144]- Started REST API at /rest INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'rrd4j.persist' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.script' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.items' INFO o.o.u.w.i.s.WebAppServlet[:79]- Started Classic UI at /openhab.app INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'steckdosen.rules' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'fbh.rules' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'alarm.rules' INFO o.o.b.h.i.bus.HomematicBinding[:92]- HomematicConfig[host=XXX,callbackHost=XXX,callbackPort=XXX,aliveInterval=300,reconnectInterval=disabled] INFO o.o.b.h.i.c.HomematicCommunicator[:74]- Starting Homematic communicator INFO o.o.b.h.i.c.HomematicCommunicator[:84]- Homematic ServerId[name=Homegear,version=0.5.25] INFO o.o.b.h.i.c.c.HomegearClient[:59]- Starting HomegearClient INFO o.o.b.h.i.c.StateHolder[:83]- Loading Homematic datapoints INFO o.o.b.h.i.c.StateHolder[:91]- Finished loading 93 Homematic datapoints INFO o.o.b.h.i.c.StateHolder[:187]- Loading Homematic Server variables INFO o.o.b.h.i.c.StateHolder[:196]- Finished loading 0 Homematic server variables INFO o.o.b.h.i.c.s.BinRpcCallbackServer[:44]- Starting BinRpcCallbackServer at port 9123 INFO o.o.b.h.i.c.HomematicCommunicator[:114]- Scheduling one datapoint reload job in one minute INFO o.o.c.s.AbstractActiveService[:169]- Homematic server connection tracker has been started INFO o.o.b.a.i.bus.AstroBinding[:70]- AstroConfig[latitude=XXX,longitude=XXX,interval=120,systemTimezone=Europe/Berlin (CET +0100),daylightSavings=false] INFO o.o.c.s.AbstractActiveService[:169]- NTP Refresh Service has been started INFO o.o.c.s.AbstractActiveService[:169]- HTTP Refresh Service has been started INFO o.o.c.s.AbstractActiveService[:169]- Exec Refresh Service has been started INFO o.o.b.a.i.job.JobScheduler[:150]- Scheduled a daily job at midnight for astro calculation

failed2.txt
INFO o.o.c.internal.CoreActivator[:61]- openHAB runtime has been started (v1.7.1). INFO o.o.i.s.i.DiscoveryServiceImpl[:93]- mDNS service has been started INFO o.o.i.s.i.DiscoveryServiceImpl[:53]- Service Discovery initialization completed. WARN o.a.c.DefaultAnnotationProcessor[:178]- Unable to detect annotations. Application may fail to deploy. INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.sitemap' INFO o.o.io.rest.RESTApplication[:144]- Started REST API at /rest INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'rrd4j.persist' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.script' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'demo.items' INFO o.o.u.w.i.s.WebAppServlet[:79]- Started Classic UI at /openhab.app INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'steckdosen.rules' INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'fbh.rules' INFO o.o.b.h.i.bus.HomematicBinding[:92]- HomematicConfig[host=XXX,callbackHost=XXX,callbackPort=XXX,aliveInterval=300,reconnectInterval=disabled] INFO o.o.b.h.i.c.HomematicCommunicator[:74]- Starting Homematic communicator INFO o.o.m.c.i.ModelRepositoryImpl[:80]- Loading model 'alarm.rules' INFO o.o.b.h.i.c.HomematicCommunicator[:84]- Homematic ServerId[name=Homegear,version=0.5.25] INFO o.o.b.h.i.c.c.HomegearClient[:59]- Starting HomegearClient INFO o.o.b.h.i.c.StateHolder[:83]- Loading Homematic datapoints INFO o.o.b.h.i.c.StateHolder[:91]- Finished loading 93 Homematic datapoints INFO o.o.b.h.i.c.StateHolder[:187]- Loading Homematic Server variables INFO o.o.b.h.i.c.StateHolder[:196]- Finished loading 0 Homematic server variables INFO o.o.b.h.i.c.s.BinRpcCallbackServer[:44]- Starting BinRpcCallbackServer at port 9123 INFO o.o.b.h.i.c.HomematicCommunicator[:114]- Scheduling one datapoint reload job in one minute INFO o.o.c.s.AbstractActiveService[:169]- Homematic server connection tracker has been started INFO o.o.b.a.i.bus.AstroBinding[:70]- AstroConfig[latitude=XXX,longitude=XXX,interval=120,systemTimezone=Europe/Berlin (CET +0100),daylightSavings=false] INFO o.o.c.s.AbstractActiveService[:169]- HTTP Refresh Service has been started INFO o.o.c.s.AbstractActiveService[:169]- Exec Refresh Service has been started INFO o.o.c.s.AbstractActiveService[:169]- NTP Refresh Service has been started INFO o.o.b.a.i.job.JobScheduler[:150]- Scheduled a daily job at midnight for astro calculation

2

I can’t suggest a workaround since the cause of the problem is unknown. You might get more information if you run with the DEBUG logging configuration for everything (logback_debug.xml). Is the openHAB process still running after you see the behavior you describe? If so, you could use the Java tool jstack to get a thread dump of the stopped process. This may give some clues about what the process is doing when it’s not responding. Using the top command might give a hit about whether the process is actually blocked or is running in a tight loop.

FWIW, I also run openHAB on a RPi and I’ve never seen this behavior.

3

Thx for your quick reply. The openHAB process is still running.

As you adviced i used jstack when there was that blocking Situation. There is a deadlock, but i don’t know yet how to interpret it. Here is the result (removed some lines because of posting Limit and can’t upload a file):
`Found one Java-level deadlock:

“qtp6016868-190”:
waiting to lock monitor 0x014bf5c8 (object 0x6c294528, a org.openhab.model.rule.internal.engine.RuleEngine),
which is held by “EventAdmin Async Event Dispatcher Thread”
“EventAdmin Async Event Dispatcher Thread”:
waiting to lock monitor 0x01622d00 (object 0x6c294590, a org.eclipse.xtext.xbase.resource.XbaseResource),
which is held by “Open/Close FBH Erdgeschoß”
“Open/Close FBH Erdgeschoß”:
waiting to lock monitor 0x01621a30 (object 0x6c350a08, a org.eclipse.xtext.xbase.resource.XbaseResource),
which is held by “Alarm detection”
“Alarm detection”:
waiting to lock monitor 0x01622d00 (object 0x6c294590, a org.eclipse.xtext.xbase.resource.XbaseResource),
which is held by “Open/Close FBH Erdgeschoß”`

4

OK, great. So that’s the problem. Are the “Alarm detection” and “Open/Close FBH Erdgeschoß” thread names also names of two of your rules?

5

Yes, they are. But they did not seem very special or complicated to me or even that they are able to block each other or something.
rule "Open/Close FBH Erdgeschoß" when Item t1TempTo changed or Item t1TempCurr changed then if(t1TempCurr.state>t1TempTo.state) { if (brenn_B.state==ON && EG_FBH_comfort.state==OFF) { sendCommand(brenn_B, OFF) } } else { if (brenn_B.state==OFF) { sendCommand(brenn_B, ON) } } end

rule "Alarm detection" when Item corMotion changed to ON or Item corSab changed to ON or Item alarmOn changed to OFF then if(alarmOn.state==ON) { //ALARM!!!! for one minute sendCommand(ALARM, ON) if(alarmTimer!=null) { logDebug("RULE","alarmTimer was still active! cancel()") alarmTimer.cancel() alarmTimer = null } alarmTimer = createTimer(now.plusSeconds(60)) [| logDebug("RULE","alarmTimer fired!") sendCommand(ALARM, OFF) ] } else { sendCommand(ALARM, OFF) } end

6

I’m using a workaround at the moment running quite well so far. I modified my openHAB init.d startup script and renaming all rule files to .tmp before starting openHAB and after 90 seconds (when openHAB has already been started) i rename them to .rules again and openHAB is loading the rules.
Thank you for pointing me to the right direction.

7

You may be able to do something similar by delaying the rule loading through a configuration in the openhab.cfg file.This is often done to avoid race condition between persistence state restoration and rule execution, but it may apply to your case as well. I agree with you that the rules seem straightforward.

1 Like
8

Hi there…

I had almost the same issue as devUBi described in the first post. My personal workaround was to start openhab without any rules and after startup I was putting the files one by another into the rules folder.
According to the linked thread I´ve set the following parameters to my openhab.cfg file:

folder:items=10,items
folder:sitemaps=20,sitemap
folder:persistence=30,persist
folder:scripts=35,script
folder:rules=60,rules

As far as I can say, its working great now - no more starting issues since then. So many thanks for the advice! :smile:

best regards
Daniel

9

Hi There,
i had exactly the same problem and therefore I wanna thank you steve1 for your suggestion with the delay!
I changed it like Daniel to 60 sec. and it is now working fine.
Finally everything is working as i should.

10

I’m having a similar issue with my Roomba 860 robotic vacuum and Roomba 880. I believe that the integration with OpenHAB is a bit buggy and needs fixing.

11

Please note that this is a 2 years old thread and refers to openHAB1, not openHAB2.
If you have any issues please open a new thread, provide your details (server hardware, openHAB version installed, errors in log files, configuration files if any, …)

1 Like