(Solution found) Rules are not triggered by "Changed to ON"

No worries, thanks.

I have Paper set for simple and then create my items in HABmin. I did try a test item through my.items file but same results.

If you use the simple mode,PaperUI will automatically link channels for the detected things. By using habmin for the same ( which I don’t use ) those links might be created twice. Which could be the cause of the problem.
In simple mode OFF only those channels that are linked by habmin ( or an .items file) will be created.

Sorry, mispoke. I have simple mode off.

@chris I think there is something going on in how the zwave binding is passing state changes back to OH. I can see the physical changes in HABmin (sometimes requires a refresh) but I can’t get rules using either “received update” or “changed to” checks to pickup the changes. I remember seeing a while back a similar issue with Cooper dimmers (which I’m using), so it might be unique to them. Though I do have a couple of Linear’s that I was having issues with as well (though did not run the same full rule test I did above, but could do so if that would help).

Let me know your thoughts and/or any tests I can run to help narrow down if this is just my system or a broader issue.

The binding uses the standard channel update methods, so I don’t think there’s much I can do to influence this (as far as I know). What does the events log show (or even the main log)?

@chris

So I saw @Kai 's note about the rule bug fix - [Partly solved] Rules are not triggered as expected So I got hopeful that would solve my issue. I installed the latest build and reran my test. What I’m noticing is if I physically change the switch nothing is updating in HABmin or PaperUI for the light status. If I refresh the thing in HABmin then both register the new status and I get an item updated in my info file related to my rules above (still nothing from changed to registering).

So I ran a full test of:

  • Setting system into Debug
  • Turning on the switch (nothing registered in HABmin/Paper)
  • Doing a refresh in Habmin (now registering change in both)
  • Turning off the switch (nothing registered in HABmin/Paper)
  • Doing a refresh in Habmin (now registering change in both)
  • Turning off Debug

The log entries are here (too many characters, but not 33 meg this time :slight_smile: - https://drive.google.com/open?id=0B77VHtwPft8eVjJaVEgwaVVxcU0

So I noticed the 1800 polling and sure enough when I looked at the Thing Device Configuration, sure enough it’s set for an 1800 polling. Also, these are Cooper dimmers which should be broadcasting their status changes to OH I wouldn’t think it would matter on the polling?

Any thoughts or any other tests I should run?

Thanks.

Ok, solved the issue with OH not updating. When the Device was created it didn’t associate itself with the OH Controller in Group 1. Once I manually added the Controller to the Group 1 association I’m getting real time updates in HABmin and PaperUI. And I’m seeing the Log showing the device was Updated. Still not getting the rule to recognize “Changed to” but at least the first piece is solved.

Though interesting enough I have other versions of the same switch in the house and they reflect instantly w/o the need to add the Controller to the Group 1 association. So I tried removing it from the switch in question and it quit updating. The only other difference between the two switches is the one having issues is associated with an Aux switch (also Cooper) and the second one is a standalone setup…

So continuing to test / add on to this thread.

So I tested just using “Item XXXX Changed” as a condition state, and that triggers it just like “Received Update” What I can’t seem to get to work is if I try to include a condition state of “On” in either one. I also was trying to use an if(item.state=ON) and kept getting errors like:

An error occured during the script execution: Could not invoke method: org.eclipse.smarthome.model.script.actions.LogAction.logInfo(java.lang.String,java.lang.String,java.lang.Object[]) on instance: null

And in Eclipse designer it would tell me that the “The method or field item is undefined”

So it seems that there is no reported State for this dimmer switch and that might be why my rules that are State specific aren’t working.

Thoughts?

Try if(item.state==ON) instead of if(item.state=ON).

1 Like

@kai Thanks. I had tried both forms. Here is the exact rule:

rule "Light Test Updated"
when
    Item Light_GF_Dining_Main received update
then
	logInfo("Dining Room","Light Updated")
	if(Light_GF_Dining_Main.state==ON) {
		logInfo("Dining Room","On")	
	}
end

I get the Updated entry but not the state On entry in my log file. I’ve tested it both with a item created in HABmin and a manually defined item in my .items folder, same results.

I also reinstated my humidity / fan rule last night and it looks like that state check in that rule (checking humidity level) is triggering a similar null error

rule "Kids Bathroom Fan Controller"
when
    Item Sensor_SF_KidsBath_Humidity changed
    or
    Item Fan_SF_KidsBath changed from OFF to ON
then
  // This section controls the fan between a high and low set-point.
  if((Sensor_SF_KidsBath_Humidity.state > 60) && (Fan_SF_KidsBath.state = OFF)) {
	logInfo("Kids Bath Fan","On for humidity")
	Override = false
    sendCommand(Fan_SF_KidsBath, ON)
  }
  else if((Override == false) && (Sensor_SF_KidsBath_Humidity.state < 55) && (Fan_SF_KidsBath.state == ON)) {
    sendCommand(Fan_SF_KidsBath, OFF)
  }

  // This timer turns the fan off if it has been manually turned on.
  if((Fan_SF_KidsBath.state == ON) && (Sensor_SF_KidsBath_Humidity.state < 55)) {
    Override = true
    if(timerA == null) {
		timerA = createTimer(now.plusMinutes(15)) [
			Override = false
			sendCommand(Fan_SF_KidsBath, OFF)
		]
    }
  }
end

Gave me:

2016-09-07 06:55:40.722 [ERROR] [.script.engine.ScriptExecutionThread] - Rule 'Kids Bathroom Fan Controller': An error occured during the script execution: Could not invoke method: org.eclipse.xtext.xbase.lib.BooleanExtensions.operator_and(boolean,boolean) on instance: null

Could not invoke method: org.eclipse.xtext.xbase.lib.BooleanExtensions.operator_and(boolean,boolean) on instance: null

This is correct, because your rule still has Fan_SF_KidsBath.state = OFF instead of Fan_SF_KidsBath.state == OFF.

This is correct, because your rule still has Fan_SF_KidsBath.state = OFF instead of Fan_SF_KidsBath.state == OFF.

Interesting, did the parser get more picky on syntax in the last couple of months? That would explain why it worked in ~May and then quite working about a month back. I will test tonight/tomorrow so we can see if the state issue is limited to just the dimmer or a more general issue.

Thanks.

palm to forehead…

Finally dropped in a logInfo command to check the .state of the item and the dimmers are returning the % dim as a numeric value, not a on/off status. So now that I do a check to see if .state > 1 all works.

Thanks for all the patience and help.

2 Likes

I think I having a similar issue with the latest distro 2.0.0~2017011218572

I enabled logging in karaf to watch the item states. And they seem to be detected OK. However the rules do not fire correctly…

21:48:02.601 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'ZithoekS1_Switch' received command ON
21:48:02.602 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Log zithoekswitch'
21:48:02.613 [INFO ] [smarthome.event.ItemStateEvent      ] - ZithoekS1_Switch updated to ON
21:48:02.621 [INFO ] [marthome.event.ItemStateChangedEvent] - ZithoekS1_Switch changed from OFF to ON
21:48:02.648 [ERROR] [.script.engine.ScriptExecutionThread] - Rule 'Log zithoekswitch': An error occured during the script execution: Could not invoke method: org.eclipse.smarthome.model.script.actions.LogAction.logInfo(java.lang.String,java.lang.String,java.lang.Object[]) on instance: null
21:48:04.050 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'ZithoekS1_Switch' received command OFF
21:48:04.053 [INFO ] [smarthome.event.ItemStateEvent      ] - ZithoekS1_Switch updated to OFF
21:48:04.058 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Log zithoekswitch'
21:48:04.059 [INFO ] [marthome.event.ItemStateChangedEvent] - ZithoekS1_Switch changed from ON to OFF
21:48:04.072 [ERROR] [.script.engine.ScriptExecutionThread] - Rule 'Log zithoekswitch': An error occured during the script execution: Could not invoke method: org.eclipse.smarthome.model.script.actions.LogAction.logInfo(java.lang.String,java.lang.String,java.lang.Object[]) on instance: null

The rules are pretty simple and look like this:

rule "Log zithoekswitch"
when
	Item ZithoekS1_Switch changed
then
    logInfo("zithoek-switch1", ZithoekS1_Switch.state)
end

rule "Log zithoekswitch2"
when
	Item ZithoekS2_Switch changed
then
    logInfo("zithoek-switch2", ZithoekS2_Switch.state)
end

Also the rules are not triggered at all when I physically use the switch, but only when I do it using a command, for instance turning the connected Thing on and off.
I have checked for double items or things inside Karaf an this is not the case… any thoughts?

1 Like

logInfo(string, string) - try using a.toString on the switch state you are displaying

OK, makes sense. This is probably because on/off is no longer a number? I think this worked in OH1?

After changing I do not get the exception, so that’s a plus :slight_smile:
However, I do still have the issue that physical switching does not result in rules being triggered, while using a UI does…
Any ideas?

Can you show us a log of it not happening? The last snippet shows the rule triggering on changes correctly, but we don’t know what you are doing to what at the time.

The issue is not specific to Rules. When I enable state changes to be logged inside karaf I see nothing happening when I physically change the switch. So it seems de updates are not surfacing at all.
I can show you an empty log :wink: but that’s not gonna help.

What type of logging would be usefull to show the problem?

I’ve enabled ZWAVE logging. I am seeing that messages are sent after a physical switch, but ends with a message that “nodes are not consistent”. This might be the problem, but I have no idea how to fix it. I initalized each zwave node and synchronized the network. But still, no state change shows up as an ItemStateChanged event.

2017-01-15 15:51:27.892 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 10 07 56 01 26 03 00 3E F8 55
2017-01-15 15:51:27.894 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-15 15:51:27.895 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 04 00 10 07 56 01 26 03 00 3E F8 55
2017-01-15 15:51:27.896 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0D 00 04 00 10 07 56 01 26 03 00 3E F8 55
2017-01-15 15:51:27.897 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 10 07 56 01 26 03 00 3
E F8
2017-01-15 15:51:27.897 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 16: Application Command Request (ALIVE:DONE)
2017-01-15 15:51:27.898 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Starting initialisation from DONE
2017-01-15 15:51:27.898 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1ad953 already registered
2017-01-15 15:51:27.899 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 16: Incoming command class CRC_16_ENCAP
2017-01-15 15:51:27.899 [DEBUG] [.ZWaveCRC16EncapsulationCommandClass] - NODE 16: Received CRC 16 Encapsulation Request
2017-01-15 15:51:27.900 [DEBUG] [.ZWaveCRC16EncapsulationCommandClass] - NODE 16: Calling handleApplicationCommandRequest.
2017-01-15 15:51:27.900 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 16: Received SWITCH_MULTILEVEL command V3
2017-01-15 15:51:27.900 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 16: Switch Multi Level report, value = 0
2017-01-15 15:51:27.901 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-01-15 15:51:27.901 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-01-15 15:51:27.901 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_MULTILEVEL, value = 0
2017-01-15 15:51:27.903 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating channel state zwave:device:a15b9e39:node16:switch_dimmer to 0 [PercentType]
2017-01-15 15:51:27.903 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent.  lastSent=255, incoming=255
2017-01-15 15:51:30.824 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 10 0A 56 01 31 05 04 22 00 00 79 DB 16
2017-01-15 15:51:30.826 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-15 15:51:30.828 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 00 04 00 10 0A 56 01 31 05 04 22 00 00 79 DB 16
2017-01-15 15:51:30.829 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 10 00 04 00 10 0A 56 01 31 05 04 22 00 00 79 DB 16
2017-01-15 15:51:30.829 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 10 0A 56 01 31 05 04 2
2 00 00 79 DB
2017-01-15 15:51:30.830 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 16: Application Command Request (ALIVE:DONE)
2017-01-15 15:51:30.831 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Starting initialisation from DONE
2017-01-15 15:51:30.831 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1ad953 already registered
2017-01-15 15:51:30.832 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 16: Incoming command class CRC_16_ENCAP
2017-01-15 15:51:30.832 [DEBUG] [.ZWaveCRC16EncapsulationCommandClass] - NODE 16: Received CRC 16 Encapsulation Request
2017-01-15 15:51:30.832 [DEBUG] [.ZWaveCRC16EncapsulationCommandClass] - NODE 16: Calling handleApplicationCommandRequest.
2017-01-15 15:51:30.833 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 16: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V4
2017-01-15 15:51:30.833 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 16: Sensor Multi Level REPORT received
2017-01-15 15:51:30.833 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 16: Sensor Type = Power(4), Scale = 0
2017-01-15 15:51:30.834 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 16: Sensor Value = 0E+1
2017-01-15 15:51:30.834 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMultiLevelSensorValueEvent
2017-01-15 15:51:30.835 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2017-01-15 15:51:30.835 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value = 0E+1
2017-01-15 15:51:30.836 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating channel state zwave:device:a15b9e39:node16:sensor_power to 0 [DecimalType]
2017-01-15 15:51:30.837 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent.  lastSent=255, incoming=255

I don’t what to do about zwave stuff at all. You’re a bit handicapped for help, appending to a solved posting about rule triggers, when it seems to be a zwave configuration issue. Might be worth starting over?
People will probably want to know something about your offending zwave device and the Item you’re expecting to be updated.