[SOLVED] Binding restart via rule in Docker: executeCommandLine "/openhab/runtime/bin/client bunde:restart ###" only works WITHOUT time-out value

Hi,

I am using OpenHAB 2.5 Milestone 3 in a docker container on a x86_64 NAS. I have sometimes issues that the docker containers starts too quick before the Zwave stick gets initialized. Hence I want to restart the zwave binding when it detects that the zwave things are “offline” at system start.

Based on previous topics I created the follwing rule:

Remind that in the docker container the path to karaf console is /openhab/runtime/bin/client

rule "Do what I want"

  when
    Item restart_zwave changed to 2

  then

    // val String results = executeCommandLine("/openhab/conf/restartzw.sh", 5000)
    val String results = executeCommandLine("/openhab/runtime/bin/client 'bundle:restart org.openhab.binding.zwave' ", 8000)

    logInfo("FILE", "***** RESTARTING: >" + results + "< *****")

end

When running the command from the docker command line it works:

# /openhab/runtime/bin/client 'bundle:restart org.openhab.binding.zwave'

When running the rule I receive the following log entry and the binding is not restarted:

17:28:15.963 [DEBUG] [clipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/openhab/runtime/bin/client 'bundle:restart org.openhab.binding.zwave' '
17:28:17.818 [DEBUG] [clipse.smarthome.io.net.exec.ExecUtil] - exit code '1', result 'Closed'
17:28:17.819 [INFO ] [g.eclipse.smarthome.model.script.FILE] - ***** RECYCLING: >Closed< *****

Alternatively I have created a small script /openhab/conf/restartzw.sh that runs the above command string from command line. When running the script from the command line it works but running it from the rule creates the error:

#!/bin/sh
/openhab/runtime/bin/client 'bundle:restart org.openhab.binding.zwave'

This creates the following error log entry when calling this script from the rule (see above):

17:29:37.446 [DEBUG] [clipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/openhab/conf/scripts/restartzw.sh'
17:29:39.302 [DEBUG] [clipse.smarthome.io.net.exec.ExecUtil] - exit code '1', result 'Closed'
17:29:39.303 [INFO ] [g.eclipse.smarthome.model.script.FILE] - ***** RECYCLING: >Closed< *****

I think the problem is the exit code: 1 respectively the command result Closed which are most likely the reason/explanation for the problem. But I do not understand what this means …

I would kindly appreciate any hint to get this solved.
There can be no big problem as the command works fine when I run it from command line.

Thank you
Justus

1 Like

Needed to rephrase my findings. I thought that I had it solved the problem by moving my script to /openhab/conf/scripts/ but I was wrong.

As I am running the OpenHAB docker container I am not easily able to install ssh and hence I need a solution without ssh

Give it a try. I do not know if it works

rule "Do what I want"

  when
    Item restart_zwave changed to 2

  then
    val String results = executeCommandLine("docker exec -it openhab /openhab/runtime/bin/client 'bundle:restart org.openhab.binding.zwave' ", 8000)

    logInfo("FILE", "***** RESTARTING: >" + results + "< *****")

end

This won’t definitely not work as the docker command runs online outside of the container but the executeCommandLine command runs inside the container :frowning:

When I either start the script manually from the command line:

root@openhab-2:/openhab/conf/scripts# ./restartzw.sh

or run the command directly on the command line:

root@openhab-2:/openhab/conf/scripts# /openhab/runtime/bin/client bundle:restart 232

(232 is the number of the zwave binding)

The it works:

root@openhab-2:/openhab/conf/scripts# /openhab/runtime/bin/client bundle:restart 232
Logging in as openhab
root@openhab-2:/openhab/conf/scripts#

And here the output of the karaf log:

19:20:18.372 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from ONLINE: Node initialising: REQUEST_NIF to UNINITIALIZED
19:20:18.388 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
19:20:18.388 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from ONLINE: Node initialising: REQUEST_NIF to UNINITIALIZED
19:20:18.403 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
19:20:18.404 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from ONLINE: Node initialising: REQUEST_NIF to UNINITIALIZED
19:20:18.416 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
19:20:18.416 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:564c8ec1' changed from ONLINE to UNINITIALIZED
19:20:21.474 [INFO ] [ding.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
19:20:21.479 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:564c8ec1' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
19:20:27.083 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
19:20:27.083 [INFO ] [.zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
19:20:27.145 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:564c8ec1' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
19:20:27.151 [INFO ] [ding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
19:20:27.157 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:564c8ec1' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
19:20:27.163 [INFO ] [ding.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
19:20:27.165 [INFO ] [ave.internal.protocol.ZWaveController] - Starting ZWave controller
19:20:27.165 [INFO ] [ave.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
19:20:27.174 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
19:20:27.175 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
19:20:27.179 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
19:20:27.183 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
19:20:27.187 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
19:20:27.188 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
19:20:30.348 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:564c8ec1' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
19:20:30.349 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
19:20:30.351 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
19:20:30.352 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
19:20:30.352 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:serial_zstick:564c8ec1' has been updated.
19:20:30.364 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF
19:20:30.366 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF
19:20:30.367 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

It just does not work when calling either the script or the command via executeCommandLine ???

But thank your for your response!!!

Perhaps?

rule "Do what I want"

  when
    Item restart_zwave changed to 2

  then
    val String results = executeCommandLine("bash /openhab/runtime/bin/client 'bundle:restart org.openhab.binding.zwave' ", 8000)

    logInfo("FILE", "***** RESTARTING: >" + results + "< *****")

end

No :frowning: the same output like without bash :

19:31:35.130 [DEBUG] [clipse.smarthome.io.net.exec.ExecUtil] - executed commandLine 'bash /openhab/runtime/bin/client 'bundle:restart org.openhab.binding.zwave' '
19:31:37.035 [DEBUG] [clipse.smarthome.io.net.exec.ExecUtil] - exit code '1', result 'Closed'
19:31:37.036 [INFO ] [g.eclipse.smarthome.model.script.FILE] - ***** RECYCLING: >Closed< *****

I am wondering why the command returns “Closed”?

I am currently testing with this rule:

  • no time out value for executeCommandLine
    and
  • leaving bundle:restart org.openhab.binding.zwave without quotes)
rule "Do what I want"

when Item restart_zwave changed to 2

then

  val String results = executeCommandLine("/openhab/runtime/bin/client bundle:restart org.openhab.binding.zwave")
  logInfo("FILE", "***** RESTARTING: >" + results + "< *****")

end

This does something … I have to figure out if it really restarts the binding but it looks promising.
This is the log output:

20:06:23.059 [INFO ] [clipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/openhab/runtime/bin/client bundle:restart org.openhab.binding.zwave'
20:06:23.061 [INFO ] [g.eclipse.smarthome.model.script.FILE] - ***** RECYCLING: >null< *****
20:06:25.006 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from ONLINE to UNINITIALIZED
20:06:25.070 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
20:06:25.071 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from ONLINE: Node initialising: REQUEST_NIF to UNINITIALIZED
20:06:25.085 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
20:06:25.086 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from ONLINE: Node initialising: REQUEST_NIF to UNINITIALIZED
20:06:25.101 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
20:06:25.101 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:564c8ec1' changed from ONLINE to UNINITIALIZED
20:06:28.296 [INFO ] [ding.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
20:06:28.303 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:564c8ec1' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
20:06:36.105 [INFO ] [.zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
20:06:36.110 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
20:06:36.194 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:564c8ec1' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
20:06:36.204 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:564c8ec1' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
20:06:36.213 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
20:06:36.235 [INFO ] [ding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
20:06:36.266 [INFO ] [ding.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
20:06:36.269 [INFO ] [ave.internal.protocol.ZWaveController] - Starting ZWave controller
20:06:36.270 [INFO ] [ave.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
20:06:36.290 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
20:06:36.290 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
20:06:36.291 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
20:06:36.301 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
20:06:36.304 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
20:06:39.492 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:564c8ec1' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
20:06:39.494 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node5' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
20:06:39.496 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
20:06:39.497 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
20:06:39.497 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:serial_zstick:564c8ec1' has been updated.
20:06:39.507 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node4' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF
20:06:39.511 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:564c8ec1:node2' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

… Investigating … :thinking:

If you only have it at startup, maybe it helps to execute a script before the runtime is started that sleeps a few seconds?

There’s also an issue for adding serial port reconnection logic to the ZWave binding:

1 Like

Is this a bug or a feature???

When leaving the time-out value and the quotes in the executeCommandLine command then it works !!!

rule "Do what I want"

when Item restart_zwave changed to 2

then

  val String results = executeCommandLine("/openhab/runtime/bin/client bundle:restart org.openhab.binding.zwave")
  logInfo("FILE", "***** RESTARTING: >" + results + "< *****")

end

I am wondering if this shouldn’t also work with quotes and the time-out value???

IME, using the client script through executeCommandLine is unreliable. But ssh works every time.

Hi Scott,

thanks for your advice. I found your tutorial already but I cannot easily use it in docker as the openhab docker image does not contain ssh. I would have to craft my own openhab docker image and maintain it and I would like to prevent that and use the default one.
Hence I try to solve problems with the exiting functionality. I will keep your advice in mind and when current solution turns out to be unacceptable, I will consider switching to ssh with all the dependencies coming along. But for now I am satisfied. Thank you!

1 Like