Inconsistent rule execution times depending on whether sitemap or another rules triggers

Add-ons Bindings
1

I have a bit of a strange issue which I need some help with. I have a bunch of lights in our living room, some z-wave, other hue, which I’d like to change together as various ‘scenes’. eg. cooking, dinner, tv. So I’ve setup a String item that holds the current scene and rules that act on changes

.items

String Living_Room_Light_Scene

.rules

rule "Living Room: Switch to a new light scene"
when
	Item Living_Room_Light_Scene received command
then
	logInfo('debug', 'Light scene received a command: '+ receivedCommand)
	 if(receivedCommand == 'cooking') {
		Wall_Switch_Kitchen_Downlights.sendCommand(ON)
		Wall_Switch_Kitchen_Island.sendCommand(ON)
		Wall_Switch_Dining_Room.sendCommand(20)
		Living_Room_Play_Lamp_1_Dimmer.send(new HSBType(new DecimalType(30), new PercentType(60), new PercentType(90)))
		Living_Room_Play_Lamp_2_Dimmer.send(new HSBType(new DecimalType(30), new PercentType(60), new PercentType(90)))
		Wall_Switch_Living_Downlights_Rear.sendCommand(40)
		Wall_Switch_Living_Downlights_Front.sendCommand(40)
		Wall_Switch_Living_Sconce.sendCommand(30)
	} else if(receivedCommand == 'dinner') {
		Wall_Switch_Kitchen_Downlights.sendCommand(ON)
		Wall_Switch_Kitchen_Island.sendCommand(ON)
		Wall_Switch_Dining_Room.sendCommand(20)
		Living_Room_Play_Lamp_1_Dimmer.send(new HSBType(new DecimalType(30), new PercentType(60), new PercentType(90)))
		Living_Room_Play_Lamp_2_Dimmer.send(new HSBType(new DecimalType(30), new PercentType(60), new PercentType(90)))
		Wall_Switch_Living_Downlights_Rear.sendCommand(OFF)
		Wall_Switch_Living_Downlights_Front.sendCommand(OFF)
		Wall_Switch_Living_Sconce.sendCommand(30)
	} else if(receivedCommand == 'tv') {
		Wall_Switch_Kitchen_Downlights.sendCommand(OFF)
		Wall_Switch_Kitchen_Island.sendCommand(ON)
		Wall_Switch_Dining_Room.sendCommand(OFF)
		Living_Room_Play_Lamp_1_Dimmer.send(new HSBType(new DecimalType(30), new PercentType(60), new PercentType(30)))
		Living_Room_Play_Lamp_2_Dimmer.send(new HSBType(new DecimalType(30), new PercentType(60), new PercentType(30)))
		Wall_Switch_Living_Downlights_Rear.sendCommand(20)
		Wall_Switch_Living_Downlights_Front.sendCommand(20)
		Wall_Switch_Living_Sconce.sendCommand(8)
	} else if(receivedCommand == 'movie') {
		Wall_Switch_Kitchen_Downlights.sendCommand(OFF)
		Wall_Switch_Kitchen_Island.sendCommand(OFF)
		Wall_Switch_Dining_Room.sendCommand(OFF)
		Living_Room_Play_Lamp_1_Dimmer.send(new HSBType(new DecimalType(30), new PercentType(60), new PercentType(10)))
		Living_Room_Play_Lamp_2_Dimmer.send(new HSBType(new DecimalType(30), new PercentType(60), new PercentType(10)))
		Wall_Switch_Living_Downlights_Rear.sendCommand(OFF)
		Wall_Switch_Living_Downlights_Front.sendCommand(10)
		Wall_Switch_Living_Sconce.sendCommand(OFF)
	} else if(receivedCommand == 'breakfast') {
		Wall_Switch_Kitchen_Downlights.sendCommand(OFF)
		Wall_Switch_Kitchen_Island.sendCommand(ON)
		Wall_Switch_Dining_Room.sendCommand(20)
		Living_Room_Play_Lamp_1_Dimmer.sendCommand(OFF)
		Living_Room_Play_Lamp_2_Dimmer.sendCommand(OFF)
		Wall_Switch_Living_Downlights_Rear.sendCommand(OFF)
		Wall_Switch_Living_Downlights_Front.sendCommand(OFF)
		Wall_Switch_Living_Sconce.sendCommand(OFF)
	} else if(receivedCommand == 'off') {
		Wall_Switch_Kitchen_Downlights.sendCommand(OFF)
		Wall_Switch_Kitchen_Island.sendCommand(OFF)
		Wall_Switch_Dining_Room.sendCommand(OFF)
		Living_Room_Play_Lamp_1_Dimmer.sendCommand(OFF)
		Living_Room_Play_Lamp_2_Dimmer.sendCommand(OFF)
		Wall_Switch_Living_Downlights_Rear.sendCommand(OFF)
		Wall_Switch_Living_Downlights_Front.sendCommand(OFF)
		Wall_Switch_Living_Sconce.sendCommand(OFF)
	} else (
		logInfo('debug', 'Light scene unknown ' + receivedCommand + '. Doing nothing..')
	)

end

.sitemap

	Frame label="Inside lights" icon="light" {
		Switch item=Living_Room_Light_Scene label="Living Room" mappings=['off'='Off','cooking'='On']
		Selection item=Living_Room_Light_Scene label="Scene:" icon="light" mappings=['cooking'='Cooking','breakfast'='Breakfast','tv'='TV - Dimmed','movie'='TV - Dark']
	}

so far so good. I’ve added a field into the sitemap and when I make changes from the web or mobile apps, I get consistent, very fast (sub 2s) response times to the lighting changes.

Now, the problems start when I want to trigger the same scenes from click on a Hue Dimmer Switch (the 4 button one). I have a rule that listens for the button presses and then updates the Living_Room_Light_Scene item - which I expected to occur very quickly.

Instead I am seeing either it working very slowly (4-10s) or not at all. While at other times, it appears to work fairly quickly. In all cases, I’m seeing my debug messages from the rule that runs on Dimmer button presses get triggered promptly, but the subsequent actions are either slow or never occur. Am I hitting some type of limit or issue? Here’s the rule listening for button presses:

rule "Manage Hue Dimmer switch button presses"
when
	Channel "hue:0820:001788a0e258:14:dimmer_switch_event" triggered
then
	var Number currentSceneId = 0;
	if(Living_Room_Scene_Number.state == NULL) {
		Living_Room_Scene_Number.postUpdate(0)
	} else {
		currentSceneId = Living_Room_Scene_Number.state
	}
  var newCommand = Hue_Remote_Kitchen_Button_Value.state.toString
	var maxSceneId = 5

	logInfo('debug', 'Button press found. Value: ' + newCommand )
	
	// how about the on switch?
	if( newCommand == '1002.0') {
		if(Living_Room_Scene_Number.state == NULL || Living_Room_Scene_Number.state == UNDEF || Living_Room_Scene_Number.state == maxSceneId) {
			currentSceneId = 0
		}
		currentSceneId = currentSceneId + 1

		if(currentSceneId == 1) {
			Living_Room_Light_Scene.sendCommand('cooking')
		} else if(currentSceneId == 2) {
			Living_Room_Light_Scene.sendCommand('dinner')
		} else if(currentSceneId == 3) {
			Living_Room_Light_Scene.sendCommand('tv')
		} else if(currentSceneId == 4) {
			Living_Room_Light_Scene.sendCommand('movie')
		} else if(currentSceneId == 5) {
			Living_Room_Light_Scene.sendCommand('breakfast')
		}

		Living_Room_Scene_Number.postUpdate(currentSceneId)
	}

        // off switch clicks
	if( newCommand == '4002.0' || newCommand == '4000.0' ) {
		if(Living_Room_Scene_Number.state == NULL || Living_Room_Scene_Number.state == UNDEF || Living_Room_Scene_Number.state == maxSceneId) {
			currentSceneId = 0
		}
		Living_Room_Light_Scene.sendCommand('off')
	}

My log is getting Info like this:

2022-02-21 17:09:14.643 [INFO ] [org.openhab.core.model.script.debug ] - Button press found. Value: 1002.0
2022-02-21 17:09:14.645 [INFO ] [org.openhab.core.model.script.debug ] - Light scene received a command: cooking
2022-02-21 17:09:19.247 [INFO ] [org.openhab.core.model.script.debug ] - Button press found. Value: 1002.0
2022-02-21 17:09:19.248 [INFO ] [org.openhab.core.model.script.debug ] - Light scene received a command: dinner
2022-02-21 17:09:21.805 [INFO ] [org.openhab.core.model.script.debug ] - Button press found. Value: 1002.0
2022-02-21 17:09:21.807 [INFO ] [org.openhab.core.model.script.debug ] - Light scene received a command: tv
2022-02-21 17:09:26.933 [INFO ] [org.openhab.core.model.script.debug ] - Button press found. Value: 1002.0
2022-02-21 17:09:26.933 [INFO ] [org.openhab.core.model.script.debug ] - Light scene received a command: movie
2022-02-21 17:09:28.466 [INFO ] [org.openhab.core.model.script.debug ] - Button press found. Value: 1002.0
2022-02-21 17:09:28.468 [INFO ] [org.openhab.core.model.script.debug ] - Light scene received a command: breakfast
2022-02-21 17:09:32.053 [INFO ] [org.openhab.core.model.script.debug ] - Button press found. Value: 1000.0
2022-02-21 17:09:32.564 [INFO ] [org.openhab.core.model.script.debug ] - Button press found. Value: 1002.0
2022-02-21 17:09:32.565 [INFO ] [org.openhab.core.model.script.debug ] - Light scene received a command: cooking

I’m running OpenHAB 3.2.0 on a VM instance in a Proxmox host, with 4Gb RAM and 2 cores of a Ryzen 5600G CPU. Seems plenty.

It appears to me that whether I change Living_Room_Light_Scene from the Sitemap/UI or from another rule, it should behave the same. The fact it’s not has me perplexed. Can anyone provide some guidance or suggestions?

2

Looking at the posted log I don’t see any noticeable relay between the run of the rule of the Hue button and the lightscene (max 0.002 seconds). The Hue command 1000.0 “seems” not to be executed, however that is as coded ( no matching if statement).
Please give more details on the observed delay.

3

The Hue command 1000.0 “seems” not to be executed, however that is as coded ( no matching if statement).

Yes that’s by design… 1000.0 is the downpress and is not always returned. 1002.0 is the release of a short press (there are codes for long press and holds as well)

Looking at the posted log I don’t see any noticeable relay between the run of the rule of the Hue button and the lightscene (max 0.002 seconds).

I agree. Hence my confusion. As I mentioned in my OP, sometimes it works fine - quickly and as expected. Other times, it will take 4-10 seconds OR not work at all. At those times, if I pull out the phone and switch it from the sitemap, it’s fast.

4

You need to investigate where this delay is happening.
In the posted log you only show the debug lines from the rule, the actual events.log entries of the changed items.state are missing. Between those lines a delay could be visible.
A missing command execution would not show some of those expected entries, check which expected entries are logged and which not. That will tell where the command got lost.

1 Like
5

I don’tthink this is your problem, but -

There’s a timing race there - postUpdate() is asynchronous, and is unlikely to have taken effect if you read the state back from the Item a few lines later. You’ll almost certainly get the “old” state still.
Rule of thumb, never follow myItem.postUpdate(xx) with myItem.state in the same rule, use the xx that you already know the value of.

What is the relationship of that Item to the the button-click event that triggers the rule? I’m suspecting another asynchronous race hidden there.

6

You need to investigate where this delay is happening.
In the posted log you only show the debug lines from the rule, the actual events.log entries of the changed items.state are missing.

Good tip! tbh I’ve never really used events.log (how did I miss this!? I’ve been using OpenHAB for years!) but looking at it now it will be very helpful to debug this issue. Will take a look when I’m testing next.

7

If I was to attack this from the beginning it may look something like

rule "Manage Hue Dimmer switch button presses"
when
	Channel "hue:0820:001788a0e258:14:dimmer_switch_event" triggered
then
  var current_Scene = Living_Room_Light_Scene.state.toString
  val new_Scene = ""
if( receivedEvent == '1002.0') {
  switch(current_Scene) {
      case "cooking": {
          logInfo("Living Scene", "Set to dinner")
          new_Scene = "dinner"
      }
      case "dinner": {
          logInfo("Living Scene", "Set to tv")
          new_Scene = "tv"
      }
      case "tv": {
        logInfo("Living Scene", "Set to movie")
        new_Scene = "movie"
      }
      case "movie": {
        logInfo("Living Scene", "Set to breakfast")
        new_Scene = "breakfast"
      }
      case "breakfast": {
        logInfo("Living Scene", "Set to off")
        new_Scene = "off"
      }
      case "off": {
        logInfo("Living Scene", "Set to cooking")
        new_Scene = "cooking"
      }
      default: {
        logInfo("Living Scene", "Default to off")
        new_Scene = "off"
      }
    }
} else {
    new_Scene = "off"
	}


  Living_Room_Light_Scene.sendCommand(new_Scene)

end
8

Yeah I wonder if you might be onto something there. Tho I never read it later in the same execution it would be possible that subsequent executions still weren’t updated. I understood there would be a delay, but possible underestimated by how much. I’ve updated the rule to not use the scene cycling anymore - as in practice it was always difficult to know where in the scene set you were.

Now that I’ve moved to the top 3 buttons each having a specific scene (no postUpdates) they always seem to respond promptly. Doesn’t fully explain why the logging appeared to show the correct scenes being called as I’d expect duplicates (eg. cooking / cooking / dinner / movie / movie / movie) if there was a delay in setting the variable and hence not updated on subsequent executions.

Might have to chalk this one up to the X-Files for now. Thanks all for the suggestions and comments.

9

But you do in some circumstances, it was in the extract I posted above.
Living_Room_Scene_Number.postUpdate(currentSceneId)
followed by
if(Living_Room_Scene_Number.state == ...
It’s a trap we all fall into, treating Items like variables, and they are just not.

The bit I didn’t understand was that your rule was triggered by a channel event, but proceeded to do stuff based on an apparently unrelated Item state - Hue_Remote_Kitchen_Button_Value.
(The rule @denominator suggests uses the actual event information.)

For what it’s worth, my suspicion is that there was no “execution delay” as such - just that execution at button press time used old values (so not giving the expected result).

1 Like