Rule gets triggered twice

Hi,

I’ve only just got started really with rules really. I’ve got a rule that fires on a motion detector, all working fine. But it gets fired twice:

2015-12-19 22:54:57.712 [INFO ] [.openhab.model.script.Lighting] - Garage Light ON, for 1 minute...
2015-12-19 22:54:57.904 [INFO ] [.openhab.model.script.Lighting] - Garage Light ON, for 1 minute...
2015-12-19 22:54:58.203 [INFO ] [.b.l.i.LightwaveRFSenderThread] - Ok message received for 201,!R2D3F1

2015-12-19 22:55:59.333 [INFO ] [.b.l.i.LightwaveRFSenderThread] - Ok message received for 202,!R2D3F0

2015-12-19 22:55:59.606 [INFO ] [.openhab.model.script.Lighting] - Garage Light OFF
2015-12-19 22:56:06.611 [INFO ] [.openhab.model.script.Lighting] - Garage Light OFF
2015-12-19 22:56:06.713 [INFO ] [.b.l.i.LightwaveRFSenderThread] - Ok message received for 203,!R2D3F0

Or is that a logging thing? Its puzzling me (a) that it seems to fire twice and (b) it seems to end twice, which I wouldn’t expect given that there’s a timer involved, which I’m protecting from concurrency.

The rule:

rule "Garage PIR lighting"
when Item ZONE9_GENERAL_STATUS changed to OPEN
then
    logDebug("Lighting","Garage PIR activated")
    if(garagePIR_timer == null || garagePIR_timer.hasTerminated) {
        garage.members.forEach[light |  // for each light
               light.sendCommand(ON)
           logInfo("Lighting","Garage Light ON, for 1 minute...")
        garagePIR_timer = createTimer(now.plusMinutes(1), [| 
        garage.members.forEach[light |  // for each light
               light.sendCommand(OFF)
            garagePIR_timer = null]
        logInfo("Lighting","Garage Light OFF")  ]  
        )
    }
    else {
        garagePIR_timer.reschedule(now.plusMinutes(1))
    }
end

Is it because I’m using a group to determine the item to switch? Similar to this topic:

https://community.openhab.org/t/group-rule-triggered-twice-why/1881?u=tinkerfailure

I’m going to assume the group garage has multiple members and therefore it prints the logging for each member. If that’s the case your rule isn’t firing twice.

That occurred to me too. But no, that is the only group that has only one member!

And as garagePIR_timer = null happens, it should kill older instances running shouldn’t it?

Could you post your event log please? It should show which items/groups change state and you should be able to see if it happens twice.

It’s not doing it now I’m looking for it…

event.log


2015-12-20 00:41:25 - ZONE13_GENERAL_STATUS state updated to OPEN
2015-12-20 00:41:26 - PANEL_MESSAGE state updated to 610: General status of the zone - restored.
2015-12-20 00:41:26 - ZONE13_GENERAL_STATUS state updated to CLOSED
2015-12-20 00:41:27 - PANEL_MESSAGE state updated to 609: General status of the zone - open.
2015-12-20 00:41:27 - ZONE9_GENERAL_STATUS state updated to OPEN
2015-12-20 00:41:27 - Light_rm02_garageLight received command ON
2015-12-20 00:41:28 - PANEL_MESSAGE state updated to 610: General status of the zone - restored.
2015-12-20 00:41:28 - ZONE9_GENERAL_STATUS state updated to CLOSED
2015-12-20 00:41:29 - currentPower state updated to 550
2015-12-20 00:41:29 - pulseCount state updated to 130798
2015-12-20 00:41:29 - voltage state updated to 249.7
2015-12-20 00:41:30 - PANEL_MESSAGE state updated to 609: General status of the zone - open.
2015-12-20 00:41:30 - ZONE9_GENERAL_STATUS state updated to OPEN
2015-12-20 00:41:31 - PANEL_MESSAGE state updated to 609: General status of the zone - open.
2015-12-20 00:41:31 - ZONE13_GENERAL_STATUS state updated to OPEN
2015-12-20 00:41:31 - PANEL_MESSAGE state updated to 610: General status of the zone - restored.
2015-12-20 00:41:31 - ZONE10_GENERAL_STATUS state updated to CLOSED

openhab.log

2015-12-20 00:41:27.336 [INFO ] [.openhab.model.script.Lighting] - Garage Light ON, for 1 minute...
2015-12-20 00:41:27.415 [INFO ] [.b.l.i.LightwaveRFSenderThread] - Ok message received for 210,!R2D3F1

2015-12-20 00:42:30.291 [INFO ] [.openhab.model.script.Lighting] - Garage Light OFF
2015-12-20 00:42:30.376 [INFO ] [.b.l.i.LightwaveRFSenderThread] - Ok message received for 211,!R2D3F0

Possibly. I’ve not experimented with using “changed” as a trigger on a Group. I know that if you use “received update” on a group it will absolutely trigger the rule multiple times. Not so sure about changed.

How many members does ZONE9_GENERAL_STATUS have? Because that is what is controlling whether or not the rule gets triggered more than once.

This isn’t your problem here but I want to clear up a misperception.

Setting garagePIR_timer to null as the last line in your timer does not kill older instances running. Assuming that you have more than one timer running you have already lost your ability to access those older timers because you overwrote your pointer to those older timers when you created the new one.

BUT, in your case you have logic in place to avoid having more than one timer running anyway so this discussion is merely academic. When you check to make sure garagePIR_timer is null or hasTerminated before creating a new timer you effectively prevent having more than one timer active at any given time. So really what the garagePIR_timer = null line does is make it very clear to your code that the timer has exited.

ZONE9_GENERAL_STATUS is an item. It’s the PIR in the garage.

I just tried changing it to this, so it would act on the one light instead of a group, but it wouldn’t work. I’m not so hot on timers! As you explained in your response @rlkoshak !

java 
    rule "Garage PIR lighting"
    when Item ZONE9_GENERAL_STATUS changed to OPEN
    then
        logDebug("Lighting","Garage PIR activated")
        if(garagePIR_timer == null || garagePIR_timer.hasTerminated) {
            sendCommand(Light_rm02_garageLight, ON)
            logInfo("Lighting","Garage Light ON, for 2 minutes...")
            garagePIR_timer = createTimer(now.plusMinutes(2), [| 
            sendCommand(Light_rm02_garageLight, OFF)
                garagePIR_timer = null]
            logInfo("Lighting","Garage Light OFF")  ]  
            )
        }
        else {
            garagePIR_timer.reschedule(now.plusMinutes(2))
        }
    end

Perhaps this is caused by the behavior of your PIR. How often does it switch from OPEN to CLOSED and back when it detect movement? If it is almost immediately it could be the case that you end up with two copies of the rule running at the same time which would set up two timers if the timing falls just right.

You can avoid that by using a lock.

...
import java.util.concurrent.locks.ReentrantLock

val ReentrantLock lock = new ReentrantLock

rule "Garage PIR lighting"
when 
    Item ZONE9_GENERAL_STATUS changed to OPEN
then
    lock.lock
    try {
        logDebug("Lighting", "Garage PIR activated")
        ...
    }
    catch(Throwable t) {
        logError("Lighting", "Error processing ZONE9_GENERAL_STATUS update: " + t)
    }
    finally {
        lock.unlock
    }
end

The try/catch/finally is there so if there are any errors in your rule the lock will still get unlocked. Otherwise an error would basically kill this rule until you restart.

It this doesn’t work, it might be worth while looking at @bob_dickenson’s Proxy design pattern posted here.

It will provide a separation between the behavior of the PIR and the switching of your light so you can smooth out any erratic behavior caused by the PIR.

Also, in the code above where you changed it I think you have an errant paren or bracket hanging out. Are you using Designer to edit your code? I cannot recommend it highly enough. It catches errors like this as you type.

Your rule should be:

rule "Garage PIR lighting"
when
    Item AONE9_GENERAL_STATUS changed to OPEN
then
    logDebug("Lighting", "Garage PIR activated")
    if(garagePIR_timer == null || garagePIR_timer.hasTerminated){
        Light_em02_garageLight.sendCommand(ON)
        logInfo("Lighting", "Garage Light ON, for 2 minutes...")
        garagePIR_timer = createTimer(now.plusMinutes(2), [|
            Light_em02_garageLight.sendCommand(OFF)
            garagePIR_timer = null
            logInfo("Lighting", "Garage Light OFF")
        ])
    }
    else {
        garagePIR_timer.reschedule(now.plusMinutes(2))
    }
end

NOTE: I also made a few stylistic changes to better follow the defacto coding standards you will see in the examples and my own preference to using the sendCommand on the Item object as opposed to the sendCommand action (I’ve found doing it this way avoids some casting problems for Items of certain types). The big change is proper indentation.

Thanks @rlkoshak. Much appreciated.