Simple rule changes behavior when logInfo is used (openHAB 2 beta 5)

Setup, Configuration and Use Runtime
, ,
1

Hello,

I’m running the latest openHAB 2 beta 5 on a pine64.

I have been experimenting with openHAB and seven Z-Wave devices that I bought to play with. I am now venturing into making rules and got a few extremely trivial rules working. Then I made the following simple rule and it is exhibiting a strange behavior that I don’t understand.

The rule looks at the state of a simple Z-Wave binary power switch and toggles it every 10 seconds. Here’s the rule, which I wrote manually in a text editor (nano):

rule "scare children and old people"
when
    Time cron "0/10 * * * * ?"
then
    logInfo("FILE", "state is: " + zwave_device_controller_node18_switch_binary.state)
    if
        zwave_device_controller_node18_switch_binary.state==ON
    then
        zwave_device_controller_node18_switch_binary.sendCommand(OFF)
        // logInfo("FILE", "turned christmas lights off")
    else
        zwave_device_controller_node18_switch_binary.sendCommand(ON)
        // logInfo("FILE", "turned christmas lights on")
end

When run exactly as shown above, the rule works great and here is its output in openhab.log:

2016-12-27 20:40:45.581 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'myrule.rules'
2016-12-27 20:40:50.304 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:41:00.015 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: ON
2016-12-27 20:41:10.014 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:41:20.017 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: ON
2016-12-27 20:41:30.016 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF

Problem is, when I uncomment those two logInfo lines in the rule, the rule starts misbehaving. The power switch stays off and the log shows:

2016-12-27 20:43:01.428 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'myrule.rules'
2016-12-27 20:43:10.298 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:43:10.303 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:43:20.019 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:43:20.027 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:43:30.016 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:43:30.031 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:43:40.017 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:43:40.026 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:43:50.015 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:43:50.027 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:44:00.044 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: ON
2016-12-27 20:44:00.050 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:44:10.014 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:44:10.022 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:44:20.015 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:44:20.022 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:44:30.014 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:44:30.023 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:44:40.014 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:44:40.021 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:44:50.014 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:44:50.030 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:45:00.048 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: ON
2016-12-27 20:45:00.054 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off
2016-12-27 20:45:10.019 [INFO ] [.eclipse.smarthome.model.script.FILE] - state is: OFF
2016-12-27 20:45:10.027 [INFO ] [.eclipse.smarthome.model.script.FILE] - turned christmas lights off

Note that it occasionally says that the “state is: ON”. This is a lie. The switch is definitely off as confirmed physically. Even the control switch in the Paper UI control section stays in the off position, so it doesn’t even appear that the underlying system believes that the state is ON.

Also note that even though the rule thinks the state is off, it still tries to turn the switch off, which seems virtually impossible given the rule code.

The most curious thing about this is that simple logging actions seems to be modifying the behavior of the rule!

I have a feeling I’m missing something simple. Can anyone help?

Here’s some theories:

  • The state attribute of the item has side effects I would not have anticipated.
  • I’m posing my conditional wrongly.
  • I have a syntax error.
  • There’s a bug related to the logInfo action.
2

More information. I can’t make any sense of it, but I noticed this in the event log while the rule is misbehaving:

2016-12-27 21:16:00.032 [ItemStateChangedEvent     ] - zwave_device_controller_node18_switch_binary changed from OFF to ON

Again, though, the switch is not actually being turned on, as confirmed physically.

3

Could it be that you are misssing {} if you are inserting the logInfo to achieve the same behavior.

if
    zwave_device_controller_node18_switch_binary.state==ON
then {
    zwave_device_controller_node18_switch_binary.sendCommand(OFF)
    // logInfo("FILE", "turned christmas lights off")
      }
else{
    zwave_device_controller_node18_switch_binary.sendCommand(ON)
    // logInfo("FILE", "turned christmas lights on")    if
    zwave_device_controller_node18_switch_binary.state==ON
     }

…

1 Like
4

It might be better to make the code more readable, but I’m a C++ guy so this is just better to me, your mileage may vary:

if(zwave_device_controller_node18_switch_binary.state==ON)
{
    zwave_device_controller_node18_switch_binary.sendCommand(OFF)
    // logInfo("FILE", "turned christmas lights off")
}
else
{
    zwave_device_controller_node18_switch_binary.sendCommand(ON)
    // logInfo("FILE", "turned christmas lights on") 
}
5

Nailed it. The key was the braces. For future reference, here’s what worked:

rule "scare children and old people"
when
    Time cron "0/10 * * * * ?"
then
    logInfo("FILE", "state is: " + zwave_device_controller_node18_switch_binary.state)
    if
        zwave_device_controller_node18_switch_binary.state==ON
    then {
        zwave_device_controller_node18_switch_binary.sendCommand(OFF)
        logInfo("FILE", "turned christmas lights off")
    }
    else {
        zwave_device_controller_node18_switch_binary.sendCommand(ON)
        logInfo("FILE", "turned christmas lights on")
    }
end

I’m kind of disappointed that openHAB will happily load a rule which has improper syntax without giving any kind of indication that something’s wrong.

6

Are you using the Smarthome Designer? It’s exactly for this purpose and it would have given you an error message:

I replaced zwave_device_controller_node18_switch_binary with one of my existing items to not get even more error indications.

7

Point taken.

8

What miracles have you done to make designer come to life.
In my case designer is both not working under macOS and Windows.

It is starting but then I am receive false error everywhere.
All tests are done using version 0.8

9

Actually it was quite straight forward:
On my Win 64Bit I installed Java 32Bit, downloaded Designer 0.8 for Win 32Bit, pointed to my config directory (Samba share on RPi) and that’s all.
I’ve read several times in other posts that users had to map their share to a drive letter to make it work. This was not the case in my setup.
Good luck.