[Solved] Exec Command only Executed on Item Change

Platform information:

  • Hardware: Raspberry Pi 3B
  • OS: Raspbian Buster
  • Java Runtime Environment: Zulu (openjdk version “1.8.0_152”)
  • openHAB version: 2.4.0 (Build)

In order to test the exec-binding I use a simple setup:

Item:

String execTestItem {channel="exec:command:execTestThing:input"}

Thing:

Thing exec:command:execTestThing "execThing" [command="sudo /etc/openhab2/scripts/execTestScript.sh %2$s", interval=0, autorun=true, timeout=5, transform="REGEX((.*?))"]

Rule:

rule "rule_exec_test"
        when
            Time cron "0 * * * * ?"                // every minute
        then
            var Number reading = (nWaterMeterReading.state as DecimalType).floatValue
            var String execArgument = String::format("%1$.3f", reading)
            execTestItem.sendCommand(execArgument)
            logWarn("rule_exec_test", "update Logfile: " + execArgument)
    end

This setup basically works, the log files don’t show errors.
With this setup I expect that the data is written to a file every minute when the rule is executed.

When the data is written to a file the logs show this:

2019-09-07 17:50:00.034 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 298,793
2019-09-07 17:50:00.040 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 298,793
2019-09-07 17:50:00.060 [vent.ItemStateChangedEvent] - execTestItem changed from 298,792 to 298,793
==> /var/log/openhab2/openhab.log <==
2019-09-07 17:50:00.037 [WARN ] [marthome.model.script.rule_exec_test] - update Logfile: 298,793

However the data only is written to a file when the item has changed before.
When the item has not changed the file is not updated by the exec-command and the log shows this:

2019-09-07 17:46:00.047 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 298,785
2019-09-07 17:46:00.050 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 298,785
==> /var/log/openhab2/openhab.log <==
2019-09-07 17:46:00.046 [WARN ] [marthome.model.script.rule_exec_test] - update Logfile: 298,785

So how do I force the exec-command to be executed independent of an item change?

Thanks for any help!

The “prediction” is openHAB’s autoupdate feature at work. autoupdate is enabled by default on each Item. When an Item receives a command, it guesses/predicts the likely outcome of that command and updates the Item to that new state.
Example, command OFF to a Dimmer Item and autoupdate will update state to 0%.

By default, Item state changes are logged.

By default, updates to the same state are NOT logged.

So everything is normal and as expected so far.

The exec binding takes no notice at all of the state of your Item linked to the input channel. It is only interested in the commands that you send to the Item.

What makes you think that your script doesn’t run?

Thanks for this explanation. This helps me to understand the openHab log output.
The script that should be executed adds a timestamp and appends the argument to a file. Looking at the timestamps I see that the script only writes to the file when the value of the execArgument has changed.
So instead of adding one line per minute the script ony seems to be exectuted only once for each item value.
Also the file’s timestamp for write access is not updated every minute but ony when the items has changed.

The output file looks like this:

08.09.2019; 09:45:00; 299,066;
08.09.2019; 09:48:00; 299,067;

but because the rule is triggered every minute it was expected to look like this:

08.09.2019; 09:45:00; 299,066;
08.09.2019; 09:46:00; 299,066;
08.09.2019; 09:47:00; 299,066;
08.09.2019; 09:48:00; 299,067;
08.09.2019; 09:49:00; 299,067;
08.09.2019; 09:50:00; 299,067;

@Automark
What exactly are you trying to achieve?
It looks like you are trying to reinevent the wheel. In this case the persistence services.

This is what I am thinking as well.
You can see in your events.log if commands are issued every minute, apparently they are.
With autorun=true, the binding should call the script every time.
If it didn’t, that is a bug.

The info that is missing here is whether your script ran but decided not to make an update (because it already has run for that value, say)
Look to add a message or something at the head of your script to see when it runs.

What I’m trying to do is to verify that a script is executed e.g. every minute. Writing a timestamp and data to a file seemed to be a good approach to do that. In a next step a different script would take data to manipulate GPIOs and do some more things. So this is just a first step towards the full functionality.

Calling the script manually from the command line with identical arguments appends a new time stamp every time the script is executed.

When I add an echo output to the head of the script, where could I see the ouput of the echo? Would it show in the openHab log output?
Or is there a Linux command to see when the script is accessed for execution?

You will need to do this:

logInfo("TESTING", execTestItem.sendCommand(execArgument))

or

var String myString= execTestItem.sendCommand(execArgument)
logInfo("TESTING", myString) 

I have just confirmed for myself in OH2.4 that an exec Thing with autorun=true will execute every time you send a command to an Item linked to input channel. Even if it is the same command.

xxx.things
// a harmless windows command
Thing exec:command:testecho [command="cmd.exe /c \"echo %2$s\" ", autorun=true]

xxx.items
Switch testSw {channel="exec:command:testecho:run"}
String testString {channel="exec:command:testecho:input"}
String outString {channel="exec:command:testecho:output"}
DateTime testDate {channel="exec:command:testecho:lastexecution"}

xxx.rules
rule "Clock tick"
when
	Time cron "5 0/1 * * * ?"  // each minute, offset by 5secs
then
	outString.postUpdate("wait")    // to prove it ran
	testString.sendCommand("blah")
end

results

2019-09-08 16:34:07.045 [ome.event.ItemCommandEvent] - Item 'testString' received command blah
2019-09-08 16:34:07.049 [vent.ItemStateChangedEvent] - outString changed from blah to wait
2019-09-08 16:34:07.051 [nt.ItemStatePredictedEvent] - testString predicted to become blah
2019-09-08 16:34:30.181 [vent.ItemStateChangedEvent] - testSw changed from OFF to ON
2019-09-08 16:34:30.227 [vent.ItemStateChangedEvent] - testSw changed from ON to OFF
2019-09-08 16:34:30.230 [vent.ItemStateChangedEvent] - outString changed from wait to blah
2019-09-08 16:34:30.231 [vent.ItemStateChangedEvent] - testDate changed from 2019-09-08T16:33:30.172+0100 to 2019-09-08T16:34:30.220+0100
2019-09-08 16:35:07.067 [ome.event.ItemCommandEvent] - Item 'testString' received command blah
2019-09-08 16:35:07.071 [vent.ItemStateChangedEvent] - dt_Systime changed from 2019-09-08T16:34:07.014+0100 to 2019-09-08T16:35:07.005+0100
2019-09-08 16:35:07.072 [vent.ItemStateChangedEvent] - outString changed from blah to wait
2019-09-08 16:35:07.078 [nt.ItemStatePredictedEvent] - testString predicted to become blah
2019-09-08 16:35:30.227 [vent.ItemStateChangedEvent] - testSw changed from OFF to ON
2019-09-08 16:35:30.287 [vent.ItemStateChangedEvent] - testSw changed from ON to OFF
2019-09-08 16:35:30.289 [vent.ItemStateChangedEvent] - testDate changed from 2019-09-08T16:34:30.220+0100 to 2019-09-08T16:35:30.278+0100
2019-09-08 16:35:30.291 [vent.ItemStateChangedEvent] - outString changed from wait to blah

Fires every time.

However … the sharp eyed will spot a mystery 23 second delay from command to “script” run. I’m looking into that, I think it may be something peculiar about Windows rather than a general exec issue.

It’s weird because it isn’t really a delay, it’s a wait for a set clock time thing.
If I trigger at 25 secs past the minute
Time cron "25 0/1 * * * ?"
the “script” still fires at 30 secs past. Same if trigger at 35 secs.

2019-09-08 16:43:25.019 [ome.event.ItemCommandEvent] - Item 'testString' received command blah
...
2019-09-08 16:43:30.610 [vent.ItemStateChangedEvent] - testSw changed from OFF to ON
2019-09-08 16:43:30.654 [vent.ItemStateChangedEvent] - testSw changed from ON to OFF

That is all an aside to the original issue though.

OK, I added this to the rules file and marked every warning with a different number:

        logWarn("rule_exec_test 1", "update Logfile: " + execArgument)
        logWarn("rule_exec_test 2", execTestItem.sendCommand(execArgument))

        var String myString= execTestItem.sendCommand(execArgument)
        logWarn("rule_exec_test 3", myString)

When the scipt updates the logfile the output is this:

2019-09-08 17:42:00.829 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:42:00.844 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:42:00.868 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190
2019-09-08 17:42:00.872 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:42:00.875 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:42:00.877 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:42:00.880 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190
2019-09-08 17:42:00.886 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:42:00.896 [vent.ItemStateChangedEvent] - execTestItem changed from 299,189 to 299,190
2019-09-08 17:42:00.901 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190
2019-09-08 17:42:00.908 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190
2019-09-08 17:42:00.914 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190
2019-09-08 17:42:00.919 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190

==> /var/log/openhab2/openhab.log <==
2019-09-08 17:42:00.834 [WARN ] [rthome.model.script.rule_exec_test 1] - update Logfile: 299,190
2019-09-08 17:42:00.835 [WARN ] [rthome.model.script.rule_exec_test 1] - update Logfile: 299,190
2019-09-08 17:42:00.841 [WARN ] [rthome.model.script.rule_exec_test 2] - null
2019-09-08 17:42:00.841 [WARN ] [rthome.model.script.rule_exec_test 2] - null
2019-09-08 17:42:00.850 [WARN ] [rthome.model.script.rule_exec_test 3] - null
2019-09-08 17:42:00.852 [WARN ] [rthome.model.script.rule_exec_test 3] - null

When the script doesn’t touch the log file the output is this:

2019-09-08 17:43:00.043 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:43:00.053 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190
2019-09-08 17:43:00.065 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:43:00.098 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:43:00.122 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190
2019-09-08 17:43:00.129 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:43:00.142 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190
2019-09-08 17:43:00.160 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:43:00.163 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,190
2019-09-08 17:43:00.172 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190
2019-09-08 17:43:00.175 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190
2019-09-08 17:43:00.187 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,190

==> /var/log/openhab2/openhab.log <==
2019-09-08 17:43:00.043 [WARN ] [rthome.model.script.rule_exec_test 1] - update Logfile: 299,190
2019-09-08 17:43:00.058 [WARN ] [rthome.model.script.rule_exec_test 1] - update Logfile: 299,190
2019-09-08 17:43:00.060 [WARN ] [rthome.model.script.rule_exec_test 2] - null
2019-09-08 17:43:00.073 [WARN ] [rthome.model.script.rule_exec_test 2] - null
2019-09-08 17:43:00.104 [WARN ] [rthome.model.script.rule_exec_test 3] - null
2019-09-08 17:43:00.115 [WARN ] [rthome.model.script.rule_exec_test 3] - null

The main difference is marked bold.
The new debug outputs (number 2 and 3) both resolve to null, not showing helpful information. Or did I miss something?

The bold log message is entirely the result of autoupdate because you happened to change the command. No connection to exec actions.

No, that idea of trying to get a “result” from a sendCommand will not work in rules.

Add a Switch Item to monitor the run channel and/or a String Item to monitor the script output if you have it printing messages.

p.s. we are all assuming the script completes in less than a minute! but that should be a reasonable assumption.

No worries, the script takes ony a few milli seconds.

Now I’ve added a new item:

String execTestOutput {channel="exec:command:execTestThing:output"}

and a new rule:

rule "rule_exec_output"
    when
        Item execTestOutput changed
    then
        logWarn("rule_exec_output", "script echo:" + execTestOutput.state)
end

When the exec argument changes the output shows the echo from the script (the script starts with an echo of the current date and time):

2019-09-08 18:43:00.029 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,222
2019-09-08 18:43:00.039 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,222
2019-09-08 18:43:00.060 [vent.ItemStateChangedEvent] - execTestItem changed from 299,221 to 299,222
2019-09-08 18:43:00.201 [vent.ItemStateChangedEvent] - execTestOutput changed from timestamp = 08.09.2019;18:37:00 to timestamp = 08.09.2019;18:43:00

==> /var/log/openhab2/openhab.log <==
2019-09-08 18:43:00.056 [WARN ] [rthome.model.script.rule_exec_test 1] - update Logfile: 299,222
2019-09-08 18:43:00.210 [WARN ] [rthome.model.script.rule_exec_output] - script echo:timestamp = 08.09.2019;18:43:00

When the exec argument has not changed the output looks like this (the echo is missing):

2019-09-08 18:38:00.024 [ome.event.ItemCommandEvent] - Item ‘execTestItem’ received command 299,221
2019-09-08 18:38:00.029 [nt.ItemStatePredictedEvent] - execTestItem predicted to become 299,221

==> /var/log/openhab2/openhab.log <==
2019-09-08 18:38:00.025 [WARN ] [rthome.model.script.rule_exec_test 1] - update Logfile: 299,221

This looks to me like the script is not executed when the argument has not changed.

Not to me, you are forcing a report only on change. Try -

rule "rule_exec_output"
    when
        Item execTestOutput received update
    then
        logWarn("rule_exec_output", "script echo:" + execTestOutput.state)
end

Also make a Switch Item, linked to run channel. no rule needed as this will be visible in events.log

You are totally right. I changed the rule to be executed on an update. But it is not triggered when the item has not changed.

I’ve never worked with switch items so far. I don’t understand how this should look like.

xxx.items file

Switch myExecRun {channel="exec:command:execTestThing:run"}

You will see in the events.log (because it changes) this switch go to state ON when the script runs, then a few milliseconds later, all being well, to OFF when the script terminates (or times out).

The good news is that you don’t have that silly delay like me - sure it is some Windows host effect.

Sorry for repying just now.
Thanks a lot for showing how a switch item is added.
When the exec argument changes I now get this for the switch item:

2019-09-09 08:54:00.110 [vent.ItemStateChangedEvent] - execTestItem changed from 299,428 to 299,429
2019-09-09 08:54:00.114 [vent.ItemStateChangedEvent] - myExecRun changed from OFF to ON
2019-09-09 08:54:00.247 [vent.ItemStateChangedEvent] - myExecRun changed from ON to OFF

When the exec argument doesn’t change there’s no output about the switch item.

I’m running version 2.4.0 on a Raspberry Pi, the Exec binding has been installed using the Paper UI.

Okay, you are running exactly the same exec binding as me and getting different behaviour.
We’ll need a demo of that, please.

Please set up an additional test exec Thing, very simplistic and expected to “fail”

Thing exec:command:testecho [command="rubbish", autorun=true]

and associated Items

Switch testSw {channel="exec:command:testecho:run"}   // run monitor
String testString {channel="exec:command:testecho:input"}   // input command

and add a trigger to your existing rule

testSw.sendCommand("rhubarb")

Part of the idea here is to eliminate any weird hidden broken Items or things, all fresh moving parts.

Optionally, add an Item you would expect to receive the message complaining about missing filename.

String testResult {channel="exec:command:testecho:output"}

The events.log for the first and second runs would be of interest, i.e. with state changes then without.

rhubarb??
Now that’s random…

Brit thing … traditionally, speech without meaningful words is “Rhubarb rhubarb rhubarb”. :wink:

I think it’s theatrical originally - something for extras at the back of the scene to look and sound like conversation, without having any attention getting sounds. But at least among my elderly age group in ordinary use to describe politician’s speeches etc., just a version of “blah blah blah”

Well, well. I have been living in the country for 25 years now and I still learn something about the language almost everyday.

Nice one. Thanks