My phonePresent detection suddenly stopped working.
Group:Switch:OR(ON, OFF) presenceDevices
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?
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.
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.)
And what do you know! Now 10min later it started working again 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
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)
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
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.