[SOLVED] Group rule stopped triggering. (Snapshot #1220 and back a week or so)

Setup, Configuration and Use Scripts & Rules
1

My phonePresent detection suddenly stopped working.

Group:Switch:OR(ON, OFF) presenceDevices

image

rule 'PhonesPresent'
when
    Item presenceDevices changed
then
    val name = "PhonesPresent"
    logDebug(name, "presenceDevices = " + presenceDevices.state);
.
.

I never see any logDebug when group changes state. Used to work fine.
Any hints?

2

Verify in events.log that presenceDevices is indeed changing state. The rule should only ever change state when it goes from all OFF to one or more being ON and when it goes back to all OFF again.

Also, do you have debug logging enabled? If not you will never see this statement because the default logging level is info.

3

Nice catches @rlkoshak. Once again a lifesaver.

event.log matched VSC ITEMS.
(How do one even change rule logging from log to debug?)

I remember now, that some months back I tried to comment out a few logInfo entries in this rule, but then the timers stopped working. Added them back in with Debug level. Timers still worked; until now.

Here are my full rule. It starts a timer every time the group changes state to OFF.
(The items are network:pingdevices doing ARPpinging.)

Please tell if I can improve on this rule:

rule 'PhonesPresent'
when
    Item presenceDevices changed
then
    val name = "PhonesPresent"
    logInfo(name, "presenceDevices = " + presenceDevices.state);

    if (presenceDevices.state === ON) {
    	if (PresenceTimer !== null) {
          logInfo(name, "cancel:presence timer (running:" + PresenceTimer.running + ")")
    	  PresenceTimer.cancel    	
          PresenceTimer = null
    	}
        sendCommand(anyPhonesPresent, ON)
    } else {   
        logInfo(name, "start:presence timer")
      if (PresenceTimer === null || PresenceTimer.hasTerminated) {      	
        logInfo(name, "Creating timer ...")
        PresenceTimer = createTimer(now.plusMinutes(10)) [|
        PresenceTimer = null
        logInfo(name, "TO: present")
        sendCommand(anyPhonesPresent, OFF)
        ]
        } else {
        	logInfo(name, "reschedule:retVal=" + PresenceTimer.reschedule(now.plusMinutes(10)))
            logInfo(name, "reschedule:presence timer (running:" + PresenceTimer.running + ")")
        }    
    }    
end

And what do you know! Now 10min later it started working again :slight_smile: Only thing I did was changing a few logDebug to logInfo. Some marginal timing going on here?

2018-02-28 21:20:16.009 [INFO ] [smarthome.model.script.PhonesPresent] - presenceDevices = OFF
2018-02-28 21:20:16.010 [INFO ] [smarthome.model.script.PhonesPresent] - start:presence timer
2018-02-28 21:20:16.011 [INFO ] [smarthome.model.script.PhonesPresent] - Creating timer ...
2018-02-28 21:30:16.015 [INFO ] [smarthome.model.script.PhonesPresent] - TO: present
2018-02-28 21:30:16.019 [INFO ] [rthome.model.script.anyPhonesPresent] - anyPhonesPresent.state=OFF
2018-02-28 21:30:16.022 [INFO ] [rthome.model.script.anyPhonesPresent] - ALL OFF - No action taken
4

If you don’t care about the log statement this whole block of code could be reduced to:

PresenceTimer?.cancel
PresenceTimer = null

Use the method instead of the action where ever possible.

anyPhonesPresent.sendCommand(ON)

This might have been your problem. It is possible (not certain) that if you wrote this as a logDebug and the logging was set to Info level this line may not have executed since the Rules Engine knows that nothing would ever be done with the log statement.

It is a good practice to not mix your side effects (i.e. the rescheduling of the timer) with your logging anyway and if what I’m guessing is what happened, this only reinforces why that is a bad idea.

val rval = PresenceTimer.reschedule(now.plusMinutes(10))
logInfo(name, "reschedule:retVal=" + rval)

You can get rid of a lot more of this code by using Design Pattern: Expire Binding Based Timers which would turn your rules into:

rule "Phones Present"
when
    Item presenceDevices changed
then
    val name = "PhonesPresent"
    logInfo(name, "presenceDevices = " + presenceDevices.state) // semicolon is not needed

    if(presenceDevices.state == ON) { // only use === when one of the operands are null
        if(PresenceTimer.state == ON) PresenceTimer.postUpdate(OFF) // Cancel Expire based timer
        if(anyPhonesPresent.state != ON) anyPhonesPresent.sendCommand(ON)
    }
    else {
        logInfo(name, "Setting timer...")
        PresenceTimer.sendCommand(ON) // schedule/reschedule Expire based timer
    }
end

// Expire timer expired
rule "Presence Timer"
when
    Item PresenceTimer received command OFF
then
    logInfo("PresenceTimer", "To: present")
    anyPhonesPresent.sendCommand(OFF)
end
5

Wow, thank you for sharing and correcting my silly mistakes :slight_smile:

The expire binding makes this so much easier.
It works like a charm now.

(just for the sake of completeness, line 10 in the rule, there is a ‘s’ missing in the first anyphone’s’Present)

Thanks again.

6

Not silly. I’ve just a lot of experience with the Rules DSL from contributing to this forum and I spend a lot of time thinking about what I would consider best practices.

Now the “mistake” in this Rule is actually something new to me. Without the behavior you described, I never would have assumed that the call to logDebug would not execute at all if the logging level was higher.

I’m a big advocate of Expire Binding Timers. The code is so much cleaner and easier to understand.