My OpenHAB2 Server just stop working from time to time:
cupro@Bunker-Kubuntu:/var/log/openhab2⟫ tail -50 openhab.log
[…INFO about ab.binding.exec.internal.ExecBinding which runs every 15seconds…]
2017-05-15 10:34:39.547 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
cupro@Bunker-Kubuntu:/var/log/openhab2⟫ sudo service openhab2 status
status: Ignoring predefined value for KARAF_HOME
Not Running …
1 cupro@Bunker-Kubuntu:/var/log/openhab2⟫ sudo service openhab2 start
Starting openHAB2 server openhab2
…done.
I have no idea.
It doesn’t run on an RPI, which is the most common failure here I have found.
Its an older desktop client, with Kubuntu.
You need a lot more than just the last line from the logs do diagnose this. All that logging statement says is that it shutdown. And it looks like it shutdown normally. At least it didn’t crash.
I have more examples:
Here is also a problem with a rule, I have since months, without crashes.
2017-05-16 16:07:00.108 [INFO ] [ab.binding.exec.internal.ExecBinding] - executed commandLine 'curl https://api.particle.io/v1/devices/XXX/PoolFilter?access_token=YYY -d args=2'
2017-05-16 16:07:15.120 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule BunkerLuft: org.eclipse.smarthome.core.library.types.DecimalType
2017-05-16 16:07:15.130 [INFO ] [ab.binding.exec.internal.ExecBinding] - executed commandLine 'curl https://api.particle.io/v1/devices/XXX/PoolFilter?access_token=YYY -d args=2'
2017-05-16 16:07:30.103 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule BunkerLuft: org.eclipse.smarthome.core.library.types.DecimalType
2017-05-16 16:07:30.118 [INFO ] [ab.binding.exec.internal.ExecBinding] - executed commandLine 'curl https://api.particle.io/v1/devices/XXX/PoolFilter?access_token=YYY -d args=2'
2017-05-16 16:07:45.131 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule BunkerLuft: org.eclipse.smarthome.core.library.types.DecimalType
2017-05-16 16:07:45.192 [INFO ] [ab.binding.exec.internal.ExecBinding] - executed commandLine 'curl https://api.particle.io/v1/devices/XXX/PoolFilter?access_token=YYY -d args=2'
2017-05-16 16:08:00.197 [INFO ] [ab.binding.exec.internal.ExecBinding] - executed commandLine 'curl https://api.particle.io/v1/devices/XXX/PoolFilter?access_token=YYY -d args=2'
2017-05-16 16:08:00.210 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule BunkerLuft: org.eclipse.smarthome.core.library.types.DecimalType
2017-05-16 16:08:06.731 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2017-05-16 16:24:37.615 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dragonlair.items'
2017-05-16 16:24:38.370 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2017-05-16 16:24:42.837 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dragonlair.rules'
2017-05-16 16:24:45.445 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dragonlair.script'
2017-05-16 16:24:47.006 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
There is another example today with more infos?
2017-05-16 07:50:30.099 [INFO ] [ab.binding.exec.internal.ExecBinding] - executed commandLine 'curl https://api.particle.io/v1/devices/XXX/PoolFilter?access_token=YYY -d args=2'
2017-05-16 07:50:45.116 [INFO ] [ab.binding.exec.internal.ExecBinding] - executed commandLine 'curl https://api.particle.io/v1/devices/XXX/PoolFilter?access_token=YYY -d args=2'
2017-05-16 07:51:00.078 [INFO ] [ab.binding.exec.internal.ExecBinding] - executed commandLine 'curl https://api.particle.io/v1/devices/XXX/PoolFilter?access_token=YYY -d args=2'
2017-05-16 07:51:15.091 [INFO ] [ab.binding.exec.internal.ExecBinding] - executed commandLine 'curl https://api.particle.io/v1/devices/XXX/PoolFilter?access_token=YYY -d args=2'
2017-05-16 07:51:26.244 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2017-05-16 07:51:30.127 [INFO ] [ab.binding.exec.internal.ExecBinding] - executed commandLine 'curl https://api.particle.io/v1/devices/XXX/PoolFilter?access_token=YYY -d args=2'
2017-05-16 07:51:35.940 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Deleting weatherJob-home
2017-05-16 07:51:36.001 [INFO ] [penhab.io.transport.mqtt.MqttService] - Stopping broker connection 'rack'
2017-05-16 07:51:36.157 [INFO ] [b.core.service.AbstractActiveService] - Exec Refresh Service has been shut down
2017-05-16 07:51:36.479 [ERROR] [.eclipse.smarthome.model.persistence] - [org.eclipse.smarthome.model.persistence.manager(105)] The unsetModelRepository method has thrown an exception
java.lang.NullPointerException
at org.eclipse.smarthome.model.persistence.internal.PersistenceModelManager.unsetModelRepository(PersistenceModelManager.java:67)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_121]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_121]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_121]
at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_121]
at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod$NotResolved.invoke(BaseMethod.java:576)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BindMethod.invoke(BindMethod.java:655)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:1837)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.DependencyManager.close(DependencyManager.java:1600)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:352)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:152)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:813)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:579)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:706)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:523)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:452)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator.access$300(Activator.java:54)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:306)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)[32:org.apache.felix.scr:2.0.6]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121]
at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:186)[32:org.apache.felix.scr:2.0.6]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1623)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1542)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:248)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:144)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.doStop(Module.java:626)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:186)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:159)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-05-16 07:51:36.517 [INFO ] [assic.internal.servlet.WebAppServlet] - Stopped Classic UI
2017-05-16 07:51:36.578 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been shut down
2017-05-16 07:51:36.623 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2017-05-16 07:51:39.824 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2017-05-16 07:51:39.866 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2017-05-16 07:51:39.889 [INFO ] [.dashboard.internal.DashboardService] - Stopped dashboard
2017-05-16 09:59:41.369 [WARN ] [eclipse.jetty.servlet.ServletHandler] -
javax.servlet.ServletException: java.lang.IllegalStateException: Request scope has been already shut down.
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:489)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76)[10:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)[81:org.eclipse.jetty.servlet:9.2.19.v20160908]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)[81:org.eclipse.jetty.servlet:9.2.19.v20160908]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71)[172:org.ops4j.pax.web.pax-web-jetty:4.3.0]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)[80:org.eclipse.jetty.server:9.2.19.v20160908]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)[79:org.eclipse.jetty.security:9.2.19.v20160908]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)[80:org.eclipse.jetty.server:9.2.19.v20160908]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)[80:org.eclipse.jetty.server:9.2.19.v20160908]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:287)[172:org.ops4j.pax.web.pax-web-jetty:4.3.0]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)[81:org.eclipse.jetty.servlet:9.2.19.v20160908]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)[80:org.eclipse.jetty.server:9.2.19.v20160908]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)[80:org.eclipse.jetty.server:9.2.19.v20160908]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)[80:org.eclipse.jetty.server:9.2.19.v20160908]
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)[172:org.ops4j.pax.web.pax-web-jetty:4.3.0]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)[80:org.eclipse.jetty.server:9.2.19.v20160908]
at org.eclipse.jetty.server.Server.handle(Server.java:499)[80:org.eclipse.jetty.server:9.2.19.v20160908]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)[80:org.eclipse.jetty.server:9.2.19.v20160908]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)[80:org.eclipse.jetty.server:9.2.19.v20160908]
at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[72:org.eclipse.jetty.io:9.2.19.v20160908]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[83:org.eclipse.jetty.util:9.2.19.v20160908]
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[83:org.eclipse.jetty.util:9.2.19.v20160908]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
Caused by: java.lang.IllegalStateException: Request scope has been already shut down.
at jersey.repackaged.com.google.common.base.Preconditions.checkState(Preconditions.java:173)[153:org.glassfish.jersey.bundles.repackaged.jersey-guava:2.22.2]
at org.glassfish.jersey.process.internal.RequestScope.retrieveCurrent(RequestScope.java:239)[157:org.glassfish.jersey.core.jersey-common:2.22.2]
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:314)[157:org.glassfish.jersey.core.jersey-common:2.22.2]
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)[158:org.glassfish.jersey.core.jersey-server:2.22.2]
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)[158:org.glassfish.jersey.core.jersey-server:2.22.2]
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
... 26 more
2017-05-16 09:59:48.678 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dragonlair.items'
2017-05-16 09:59:49.345 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2017-05-16 09:59:54.321 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dragonlair.rules'
2017-05-16 09:59:57.962 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dragonlair.script'
2017-05-16 09:59:59.341 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
BasicUI is stopping but then it is acting like it is restarting, at least enough to reload your configs.
Look at your syslogs to see if the karaf console is writing out something. What ever is happening is either not being logged by openHAB or is happening outside of openHAB logging.
Well, OH isn’t even in the list. Not sure where to go from here. Maybe try a reinstall. OH. I’m out of ideas. There is nothing seen thus far that shows any indication why it’s crashing.
A programmer-friend think it could be a memory leak. I have checked the java process … it is growing and growing. Maybe one of the new rules. But he doesn’t know much enough about openHAB. Maybe I create variables which I didn’t destroy … how to destroy variables in openhab?
I use a global Variable for a DMXDATA string.
Than I check the different items for RGB, White, Amber, UV, Dimmer and build a string.
If the string is different to the last one I send it to my DMX Sender.
var String DMXDATAhexcurrent = ""
rule "DMXHexPar"
when
Time cron "* * * * * ?"
then
var HSBType HSBhex1
var DMXDATAhex = ""
HSBhex1 = hexGroup1.state as HSBType
var string hex1redValue = (HSBhex1.red.floatValue * 2.55).intValue.toString
var string hex1greenValue = (HSBhex1.green.floatValue * 2.55).intValue.toString
var string hex1blueValue = (HSBhex1.blue.floatValue * 2.55).intValue.toString
//hex1redValue = "0"
//hex1greenValue = "0"
//hex1blueValue = "0"
var DMXhexdimmer1 = (hex1dimmer.state as DecimalType * 2.55).intValue.toString
var DMXhex1A = (hex1A.state as DecimalType * 2.55).intValue.toString
var DMXhex1W = (hex1W.state as DecimalType * 2.55).intValue.toString
var DMXhex1UV = (hex1UV.state as DecimalType * 2.55).intValue.toString
DMXDATAhex = "200," + hex1redValue + "," + hex1greenValue + "," + hex1blueValue + "," + DMXhex1W + "," + DMXhex1A + "," + DMXhex1UV + "," + DMXhexdimmer1 + ",255,0,0,0,0"
if(DMXDATAhexcurrent!=DMXDATAhex){
DMX.postUpdate(DMXDATAhex)
executeCommandLine("/home/cupro/scripts/particle_dmux.py " + DMXDATAhex)
DMXDATAhexcurrent=DMXDATAhex
}
end
Destroying variables when you are done with them is not something you do in rules.
If it does have a memory leak, it needs to be fixed in oh code. The problem is that it has really hard to find unless you know what you are looking for. The only way I know of to Barrie it down is to uninstall bindings one by one until OH stops growing until it crashes. Then you will know which binding to file an issue against.
Thanks … I have not solved it until yet … I am not able to uninstall any bindings in the moment. I will install a new server during this year. Than I can test the old server.
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3940 openhab 20 0 484820 253940 11604 S 23.9 13.1 295:08.47 java
3940 openhab 20 0 485844 254804 11604 S 20.9 13.2 325:14.50 java
3940 openhab 20 0 500176 268532 11760 S 19.9 13.9 558:50.50 java
3940 openhab 20 0 505236 273292 10788 S 21.9 14.1 617:42.4 java
Grad eben hatte ich wieder nen Absturz. Beim Start 8% MEM … nach 4 Minuten 10%.
Teilweise hatte ich jetzt Wochenlang keinen Absturz und dann wieder jeden zweiten Tag, echt faszinierend.
