Exec Binding: executeCommandLine stops working and forces openHAB to restart

Add-ons Bindings
1

Since a few days my installation (2.4.0) is very unstable without any changes on the system.
Today i figured out that if i’am using executeCommandLine in a rule, opebHAB restarts without any reason. There are no errors in the log.

Rule

rule “Xiaomi HeardBeat”
when
Time cron “0/30 * * * * ?”
then
logInfo(“Xiaomi.rule”, “Xiaomi Heartbeat”)
var String xiaomiHeardBeat = executeCommandLine(“/openhab/conf/scripts/HeartBeat/checkXiaomi.sh”, 5000)
var String xiaomiReachable = “OFF”
if (xiaomiHeardBeat.length > 0)
{
xiaomiReachable = “ON”
}
sendCommand(Xiaomi_Dustcloud_Connection, xiaomiReachable)
end

Log:

2019-02-17 17:34:00.002 [INFO ] [arthome.model.script.Helligkeit.rule] - Check Helligkeit im Treppenaufgang EGOG
2019-02-17 17:34:00.004 [INFO ] [.smarthome.model.script.Heizung.rule] - Zusatzheizung Bad: Temperatur ist auf 23.5 °C
2019-02-17 17:34:00.005 [INFO ] [.smarthome.model.script.Heizung.rule] - Zusatzheizung Bad ist eingeschalten
2019-02-17 17:34:00.005 [INFO ] [.smarthome.model.script.Heizung.rule] - Zusatzheizung Bad:5 7 17 20 26.0
2019-02-17 17:34:00.653 [INFO ] [e.smarthome.model.script.Xiaomi.rule] - Xiaomi Heartbeat
2019-02-17 17:34:00.655 [INFO ] [.smarthome.model.script.Zentral.rule] - Cron läuft
2019-02-17 17:34:01.439 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Deleting weatherJob-home-OWM
2019-02-17 17:34:01.608 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been shut down
2019-02-17 17:34:01.777 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2019-02-17 17:34:01.969 [INFO ] [b.core.service.AbstractActiveService] - Expire Refresh Service has been shut down
2019-02-17 17:34:12.811 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2019-02-17 17:34:12.847 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - QueuedThreadPool[ESH-httpClient-common]@38ec4ad1{STOPPING,10<=10<=40,i=0,q=6}[org.eclipse.jetty.util.thread.TryExecutor$$Lambda$314/388146529@77619a9a] Couldn’t stop Thread[ESH-httpClient-common-111,5,main]
2019-02-17 17:34:12.848 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - QueuedThreadPool[ESH-httpClient-common]@38ec4ad1{STOPPING,10<=10<=40,i=0,q=6}[org.eclipse.jetty.util.thread.TryExecutor$$Lambda$314/388146529@77619a9a] Couldn’t stop Thread[ESH-httpClient-common-112,5,main]
2019-02-17 17:34:12.903 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard

Any ideas?

2

I would start troubleshooting by cleaning the cache.

sudo systemctl stop openhab2

sudo openhab-cli clean-cache

sudo systemctl start openhab2

3

Sorry, forget to mention that i’am running openHAB in docker

4

Deleted tmp and cache folder but without any differences

2019-02-17 18:53:00.003 [INFO ] [.smarthome.model.script.Heizung.rule] - Zusatzheizung Bad:5 7 17 20 26.0
2019-02-17 18:53:00.506 [INFO ] [e.smarthome.model.script.Xiaomi.rule] - Xiaomi Heartbeat
2019-02-17 18:53:00.507 [INFO ] [.smarthome.model.script.Zentral.rule] - Cron läuft
2019-02-17 18:53:01.193 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Deleting weatherJob-home-OWM
2019-02-17 18:53:01.352 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been shut down
2019-02-17 18:53:01.496 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2019-02-17 18:53:02.075 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule ‘Xiaomi HeardBeat’: null
2019-02-17 18:53:02.134 [INFO ] [b.core.service.AbstractActiveService] - Expire Refresh Service has been shut down
2019-02-17 18:53:11.923 [ERROR] [org.openhab.core.model.core ] - bundle org.openhab.core.model.core:2.5.0.201902130920 (160)[org.eclipse.smarthome.folder(41)] : The removeModelParser method has thrown an exception
java.lang.NullPointerException: null
at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.removeModelParser(FolderObserver.java:101) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:228) ~[42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) ~[42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:664) ~[42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:510) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.inject.methods.BindMethod.invoke(BindMethod.java:42) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:1927) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.DependencyManager.close(DependencyManager.java:1682) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:417) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:163) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:831) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:805) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.DependencyManager.deactivateComponentManager(DependencyManager.java:2332) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.DependencyManager.access$400(DependencyManager.java:56) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:401) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:302) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1242) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1137) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.untrack(ServiceTracker.java:997) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1176) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:125) [42:org.apache.felix.scr:2.1.14]
at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:920) [?:?]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:222) [?:?]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:927) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:892) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:135) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterService(AbstractComponentManager.java:969) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:823) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:805) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:584) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:716) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:511) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:428) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.Activator.access$300(Activator.java:49) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:291) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.AbstractExtender$1.run(AbstractExtender.java:216) [42:org.apache.felix.scr:2.1.14]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at org.apache.felix.scr.impl.AbstractExtender.destroyExtension(AbstractExtender.java:238) [42:org.apache.felix.scr:2.1.14]
at org.apache.felix.scr.impl.AbstractExtender.bundleChanged(AbstractExtender.java:132) [42:org.apache.felix.scr:2.1.14]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908) [?:?]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) [?:?]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) [?:?]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) [?:?]
at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:168) [?:?]
at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) [?:?]
at org.eclipse.osgi.container.Module.doStop(Module.java:634) [?:?]
at org.eclipse.osgi.container.Module.stop(Module.java:498) [?:?]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1675) [?:?]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1594) [?:?]
at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:270) [?:?]
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:147) [?:?]
at org.eclipse.osgi.container.Module.doStop(Module.java:636) [?:?]
at org.eclipse.osgi.container.Module.stop(Module.java:498) [?:?]
at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:202) [?:?]
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:165) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2019-02-17 18:53:12.119 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2019-02-17 18:53:12.128 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - QueuedThreadPool[ESH-httpClient-common]@d24666c{STOPPING,10<=10<=40,i=2,q=7}[org.eclipse.jetty.util.thread.TryExecutor$$Lambda$363/2026691236@a29f9f] Couldn’t stop Thread[ESH-httpClient-common-189,5,main]
2019-02-17 18:53:12.129 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - QueuedThreadPool[ESH-httpClient-common]@d24666c{STOPPING,10<=10<=40,i=0,q=7}[org.eclipse.jetty.util.thread.TryExecutor$$Lambda$363/2026691236@a29f9f] Couldn’t stop Thread[ESH-httpClient-common-188,5,]
2019-02-17 18:53:12.130 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - QueuedThreadPool[ESH-httpClient-common]@d24666c{STOPPING,10<=10<=40,i=0,q=7}[org.eclipse.jetty.util.thread.TryExecutor$$Lambda$363/2026691236@a29f9f] Couldn’t stop Thread[ESH-httpClient-common-191,5,main]
2019-02-17 18:53:12.165 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard

There is a NPE but this is probably a follow up error

5

So do it manually /var/lib/openhab2/cache and /var/lib/openhab2/tmp folders

6

You deleted the cache and tmp files or just the contents of the files?

7

deleted both directories

8

You might need to use mkdir and recreate them.

9

openHAB recreated them on restart

10

There is an other error in the console

openHAB | Launching the openHAB runtime…
openHAB |
openHAB | __ _____ ____
openHAB | ____ ____ ___ ____ / / / / | / __ )
openHAB | / __ / __ / _ / __ / // / /| | / __ |
openHAB | / // / // / __/ / / / __ / ___ |/ // /
openHAB | _/ ./_// /// /// |/___/
openHAB | /_/ 2.5.0-SNAPSHOT
openHAB | Build #1522
openHAB |
openHAB | Hit ‘’ for a list of available commands
openHAB | and ‘[cmd] --help’ for help on a specific command.
openHAB | Hit ‘’ or type ‘system:shutdown’ or ‘logout’ to shutdown openHAB.
openHAB |
openhab> Loading class com.mysql.jdbc.Driver'. This is deprecated. The new driver class is com.mysql.cj.jdbc.Driver’. The driver is automatically registered via the SPI and manual loading of the driver class is generally unnecessary.
openHAB |
openHAB | Error executing command: java.io.IOException: Resource temporarily unavailable

But without further infos

Btw, i tried also the latest snapshot

11

Good to know.:+1:

In the future you can use the commands below as it will not delete the file.

sudo service openhab2 stop && sudo rm -rf /var/lib/openhab2/cache/* 

&& sudo rm -rf /var/lib/openhab2/tmp/* && sudo reboot   ( all one line for doing the below )
12

Have you tried uninstalling the Exec binding, cleaning the cache, then reinstalling the binding?

13

no, but i will

14

Seeing how this is a strange issue it may also help to completely remove the binding then reinstall. To do this first uninstall it using whatever method used to install it. Next you will want to stop OH and edit /var/lib/openhab2/config/org/openhab/addons.config to remove the Exec binding and save the change. Since OH is already stopped go ahead and clean the cache again and reboot. After everything is back up and running then reinstall the Exec binding.

15

not working…really weird
have to think about an alternative to the exec binding

16

Both logs shown have this message immediately after the Xiaomi one. Cause or effect, I don’t know.

17

[INFO ] [.smarthome.model.script.Zentral.rule] - Cron läuft

is just antoher rule (working rule)

18

Some new infos, seems depending on kind of exec call:

Working exec

rule “Check Handy in WLAN”
when
Time cron “0 0/1 * * * ?”
then
logInfo(“Zentral.rule”, “Check Handy in WLAN”)
var String client1 = executeCommandLine(“tail /openhab/conf/data/stefanAnwesend.txt”, 5000)
var String client1Connected = “OFF”
if (client1.length > 0)
client1Connected = “ON”
logDebug(“Zentral.rule”, "client1: " + client1Connected)
sendCommand(Anwesenheit_Stefan, client1Connected)
end

Not working exec:

rule “Xiaomi HeardBeat”
when
Time cron “0/30 * * * * ?”
then
logInfo(“Xiaomi.rule”, “Xiaomi Heartbeat”)
var String xiaomiHeardBeat = executeCommandLine(“/openhab/conf/scripts/HeartBeat/test.sh”, 5000)
var String xiaomiReachable = “OFF”
if (xiaomiHeardBeat.length > 0)
{
xiaomiReachable = “ON”
}
sendCommand(Xiaomi_Dustcloud_Connection, xiaomiReachable)
end

test.sh

#!/bin/bash
echo “1”

Seems to a problem with bash calls?!?!?