Rules cycling despite reentrant.lock

I have two rules that keep cycling and I don’t understand why. I thought reentrant.lock would prevent this from happening…(warning: I am no expert, so likely I am misunderstanding quite basic)
So here my situation:
I have three Hue Lights and a few RC controlled outlets that are accessed through pilight; pilight is free, runs on low cost hardware and allows me and others to use either the RC remote or access it through OpenHAB (OH2 build #456 runs on RPI).
I use a rule to switch my Hue lights on and off in synch with the pilights. Works like a charm.
Unfortunately the communication is not always reliable and some of the outlets sometimes don’t ‘get the message’ always in the first try. So I thought it would be good to send another one or two commands to the pilights when the rule got triggered. Rules are pasted below. Needed some thread.sleep’s to make the system wait in order not to re-trigger the same rule more than once, which is already strange as the pilights have different codes for on and off, so should not be triggered twice. Still…works as long as I wait for the rules to finish.
If i don;t wait, the rules start cycling forever (meaning the lights switch on and off by themselves in a endless loop).
What am misunderstanding?

import java.util.concurrent.locks.ReentrantLock
val ReentrantLock  lock = new ReentrantLock()

rule "Synchronize Hue lights OFF"
when
	Item LivingroomLamps changed to OFF  
then {
		lock.lock
		try {
			sendCommand(Light_couch_Toggle,OFF)
			sendCommand(Light_cube_Toggle,OFF)
			sendCommand(Light_balcony_Toggle,OFF)
  			sendCommand(LivingroomLamps,OFF)
			Thread.sleep(10000)
			sendCommand(LivingroomLamps,OFF)
			Thread.sleep(10000)		
		} finally  {
			lock.unlock
		}
	} 
end	

rule "Synchronize Hue lights On"
when
	Item LivingroomLamps changed to ON 
then {  
		lock.lock
		try {
			sendCommand(Light_couch_Toggle,ON) 
			sendCommand(Light_cube_Toggle,ON)
			sendCommand(Light_balcony_Toggle,ON)
			sendCommand(LivingroomLamps,ON)
			Thread.sleep(10000)
			sendCommand(LivingroomLamps,ON)
			Thread.sleep(10000)		
		} finally {
			lock.unlock
		}
	}
end 

Is that a Group?

A reentrant lock only prevents multiple instances of the rule from executing that code at the same time, but it doesn’t prevent the other rules from executing it at all. Instead the other rules just wait their turn and execute in order.

If you want to prevent the other instance of the rule from running at all you need a latch.

if(!lock.isLocked){
    lock.lock
    try {
        ...
    } finally {
        lock.unlock
    }
}

With this minor change, any rule that triggers while the lock is locked will just exit instead of waiting for its turn at the lock.

Assuming LivingroomLamps is a Group, how is it configured? Depending on how the Group’s state is being defined (OR, AND?) it is possible that there is an error such that when you send the command to LivingroomLamps to OFF and that OFF command gets forwarded to the members of the Group the changes in those members is causing the Group to turn back ON, putting you into a loop. Or there is some sort of interaction when you have lots of commands flying around at the same time.

Without seeing the Item definitions it is hard to tell.

2 Likes

With my apologies for forgetting to mention this @rossko57, @rlkoshak
Living room lamps is a switch, here the items declarations of all items used in rule and their groups (I omitted color pickers and dimmers for hue lamps):

Group All
Group:Switch:OR(ON, OFF) Lamps "All Lights [(%d)]" (All)
Group:Switch:OR(ON, OFF) KakuLamps "Living Room Lights Paintings [(%d)]" (Lamps)
Group HueLamps "Living Room Lights Ambiance" 

/* Kaku */
Switch  LivingroomLamps    "Living Room Lamps Paintings" (KakuLamps)  {pilight="kaku#LivingroomLamps"}

/* Hue lights */
Switch	Light_couch_Toggle "Couch Lamp" (HueLamps)	{channel="hue:0210:00178828f299:1:color"}
Switch	Light_cube_Toggle "Cube Lamp" (HueLamps)	{channel="hue:0210:00178828f299:2:color"} 
Switch	Light_balcony_Toggle "Balcony Lamp" (HueLamps)	{channel="hue:0210:00178828f299:3:color"} 
 

Some of the group declarations looks redundant and overkill, they are related to other yet unrealized plans

Works awesomely well!!! Thank you @rlkoshak

Hi,
although your decription sounds very clear to me, by using your lock-code I get following error:

12:55:19.632 [ERROR] [.script.engine.ScriptExecutionThread] - Rule ‘CheckAnwesenheitJuergen’: An error occured during the script execution: The name ‘.islocked’ cannot be resolved to an item or type.

My useage is like:

import org.openhab.core.library.types.*
import java.util.concurrent.locks.ReentrantLock

var ReentrantLock lock = new java.util.concurrent.locks.ReentrantLock()

rule “Check”

when
Item MyItem changed to ON
then
logInfo(“CheckStart”,“MyItem = {}”, MyItem)
if (!lock.islocked) {
lock.lock
try {
logInfo(“Check”,“MyItem = {}”, MyItem)

}
finally{
lock.unlock
}
}
end

I only get the LogInfo “CheckStart”

Not sure whether this will be the solution, but I believe it should read:

lock.isLocked

Please note the capital ‘L’ in isLocked

Right on the spot. I have to get used to case - sensitivity .
Thanks

I am seeing:

2017-02-16 19:24:05.303 [ERROR] [o.o.c.s.ScriptExecutionThread ] - Error during the execution of rule 'Alarm Triggered': The name '<XFeatureCallImplCustom>.isLocked' cannot be resolved to an item or type.

I have the case right on lock.isLocked…

import org.openhab.core.library.types.*
import java.util.concurrent.locks.ReentrantLock

var Lock lock = new ReentrantLock()

rule "Alarm Triggered"
when
  Item Alarms received update
then
  if(!lock.isLocked) {
    lock.lock()
    try {  
      logInfo("Testing", "Alarms received update")
      val alarm = Alarms.members.filter[s|s.lastUpdate("mapdb") != null].sortBy[lastUpdate("mapdb")].last
      if (alarm.state == OPEN) {
        logInfo("Testing", "Test: " + alarm)
      }
    } 
    finally {
      lock.unlock()
    }
  }
end

Needs to be var ReentrantLock, not just var Lock, however rule still triggers twice:

2017-02-16 20:00:54.626 [INFO ] [g.openhab.model.script.Testing] - Alarms received update
2017-02-16 20:00:54.627 [INFO ] [g.openhab.model.script.Testing] - Test: First_Floor_Condensate_Alarm (Type=ContactItem, State=OPEN)
2017-02-16 20:00:54.627 [INFO ] [g.openhab.model.script.Testing] - Alarms received update
2017-02-16 20:00:54.628 [INFO ] [g.openhab.model.script.Testing] - Test: First_Floor_Condensate_Alarm (Type=ContactItem, State=OPEN)

If the second trigger arrives after the rule is completed, it will run twice. The lock only stops reentrancy, i.e. two copies of the rule running at the same time.

Alarms is a group and multiple updates are the norm, as you know

I am missing the (ALL), but yes, I have:

Group:Contact:OR(OPEN, CLOSED) Alarms

Having got a lock now, you can work around the multiple update ‘feature’ by having your rule sleep while it has a hold of the lock. Further updates will be bounced until the lock is released.

All that did was delay the 2nd firing of the rule.

Before Delay:

2017-02-16 20:00:54.626 [INFO ] [g.openhab.model.script.Testing] - Alarms received update
2017-02-16 20:00:54.627 [INFO ] [g.openhab.model.script.Testing] - Test: First_Floor_Condensate_Alarm (Type=ContactItem, State=OPEN)
2017-02-16 20:00:54.627 [INFO ] [g.openhab.model.script.Testing] - Alarms received update
2017-02-16 20:00:54.628 [INFO ] [g.openhab.model.script.Testing] - Test: First_Floor_Condensate_Alarm (Type=ContactItem, State=OPEN)

With Delay:

2017-02-16 20:14:58.307 [INFO ] [g.openhab.model.script.Testing] - Alarms received update
2017-02-16 20:14:58.564 [INFO ] [g.openhab.model.script.Testing] - Test: First_Floor_Condensate_Alarm (Type=ContactItem, State=OPEN)
2017-02-16 20:14:58.795 [INFO ] [g.openhab.model.script.Testing] - Alarms received update
2017-02-16 20:14:58.796 [INFO ] [g.openhab.model.script.Testing] - Test: First_Floor_Condensate_Alarm (Type=ContactItem, State=OPEN)

Rule:

import java.util.concurrent.locks.ReentrantLock

var ReentrantLock lock = new ReentrantLock()

rule "Alarm Triggered"
when
  Item Alarms received update
then
  if (!lock.isLocked) {
    lock.lock()
    try {
      Thread::sleep(200)
      logInfo("Testing", "Alarms received update")
      val alarm = Alarms.members.filter[s|s.lastUpdate("mapdb") != null].sortBy[lastUpdate("mapdb")].last
      if (alarm.state == OPEN) {
        logInfo("Testing", "Test: " + alarm)
      }
    }
    finally {
      lock.unlock()
    }
  }
end

Try this out of curiousity

    ...
    finally {
      lock.unlock()
    }
  } else {
      logInfo("testing", "locked, update ignored")
 }
end

I use .lock / .unlock without brackets, but I don’t suppose that matters

2017-02-16 20:32:28.070 [INFO ] [g.openhab.model.script.Testing] - Alarms received update
2017-02-16 20:32:28.070 [INFO ] [g.openhab.model.script.Testing] - Test: First_Floor_Condensate_Alarm (Type=ContactItem, State=OPEN)
2017-02-16 20:32:28.271 [INFO ] [g.openhab.model.script.Testing] - Alarms received update
2017-02-16 20:32:28.271 [INFO ] [g.openhab.model.script.Testing] - Test: First_Floor_Condensate_Alarm (Type=ContactItem, State=OPEN)

Interesting, I added a test if if it was locked and I think the issue is that the rule is being triggered faster then the lock can setup.

2017-02-16 20:34:54.654 [INFO ] [g.openhab.model.script.Testing] - Lock: false
2017-02-16 20:34:54.654 [INFO ] [g.openhab.model.script.Testing] - Lock: false
2017-02-16 20:34:54.855 [INFO ] [g.openhab.model.script.Testing] - Alarms received update
2017-02-16 20:34:54.914 [INFO ] [g.openhab.model.script.Testing] - Test: First_Floor_Condensate_Alarm (Type=ContactItem, State=OPEN)
2017-02-16 20:34:55.115 [INFO ] [g.openhab.model.script.Testing] - Alarms received update

Rule:

import java.util.concurrent.locks.ReentrantLock

var ReentrantLock lock = new ReentrantLock()

rule "Alarm Triggered"
when
  Item Alarms received update
then
  logInfo("Testing", "Lock: " + lock.isLocked)
  if (!lock.isLocked) {
    lock.lock()
    try {
      Thread::sleep(200) 
      logInfo("Testing", "Alarms received update")
      val alarm = Alarms.members.filter[s|s.lastUpdate("mapdb") != null].sortBy[lastUpdate("mapdb")].last
      if (alarm.state == OPEN) {
        logInfo("Testing", "Test: " + alarm)
      }
    } 
    finally {
      lock.unlock()
    }
  } else {
    logInfo("Testing", "locked, update ignored")
 }
end

Every once and a long time, the rule will not fire in the same ms and it will work!

2017-02-16 20:37:31.061 [INFO ] [g.openhab.model.script.Testing] - Lock: false
2017-02-16 20:37:31.062 [INFO ] [g.openhab.model.script.Testing] - Lock: false
2017-02-16 20:37:31.091 [INFO ] [g.openhab.model.script.Testing] - locked, update ignored
2017-02-16 20:37:31.262 [INFO ] [g.openhab.model.script.Testing] - Alarms received update
2017-02-16 20:37:31.262 [INFO ] [g.openhab.model.script.Testing] - Test: First_Floor_Condensate_Alarm (Type=ContactItem, State=OPEN)

That is more what I am looking for, but 99% of the time it fires twice.

Just a side note: Using a lock, the check with " if !lock.islocked" isn’t needed, the lock does that already!

In this case, we want to take a different action if we enter the rule and the lock is locked, rather than just queue for it, hence the if-test. Or do you mean you can put the .lock method in the test?
If (!mylock.lock) { … does that work? Would save tme

Looks like you will either have to write code that doesn’t matter if it runs twice, for find a trigger condition other than update-of-group. I cannot think of any locking or debouncing technique quicker than what you have tried.

What is the Openhab host, out of interest? I developed a set of rules on an ancient Windows XP laptop, worked lovely. When transferred to a dual core desktop, it showed up all sorts of reentrant hiccups and needed lots of rework.