Currently debugging a straightforward RM rule (1 req'd exp, 1 trigger, 1 action), so I have logs enabled for "Triggers". The rule is working as intended, however I was surprised to see repeat logs (every 1-2 min) after the required expression changes to false. The required expression is, indeed, false, but I would have expected a log entry only when its state changes:
Disabling logging on triggers makes those log entries go away.
This hub is on 2.3.5.131
What is the trigger? I would guess the trigger is happening at those times and the log entry is telling you that it is not running the rule because of the required expression.
Correct, however I find that hypothesis puzzling - if the required expression is false, why is the trigger even evaluated at all? And even if it turns out RM's internal machinery works that way, I don't see upside of flooding the logs with an update that nothing has changed. I am probably missing something, but the upshot is that I'm turning off the trigger logging.
Here's the rule:
Because the trigger is how the rule runs in the 1st place. So any time a trigger event happens, the rule starts.
In this case it immediately sees the required expression is false and bails out.
If it didn't log that, then you would have no evidence the rule even tried to run from a trigger event. Which if you were trying to troubleshoot would be a bad thing!
Right. Or more specifically, the trigger event(s) are subscribed to by the rule, no matter what. So the trigger condition is likely not evaluated, contrary to what I assumed in my earlier post.
I would have evidence from an earlier log entry of required expression state changing to false, but I see your point.
So if I understand correctly, those logs that read "Required Expression false" actually mean "Trigger event occured, required expression was false so trigger condition not evaluated and actions not run". Fair enough.
Thanks !
That's how I read them. Logging is always tricky to get right / please everyone. I totally see your point/comments - and wasn't trying to dismiss them.
Have you had an event on the switch in your required expression since you created the rule (e.g., turning it on and back off)? Normally, a false required expression does actually unsubscribe from the trigger events, but that's just an implementation detail as it was the last I remembered; the main thing is that it just won't run the actions if a trigger event happens while the expression is false, and I recall that there is some sort of "failsafe" that checks it in this manner regardless. That's probably what you're seeing, but it would be unusual to see it long-term.
Not quite right. If the Required Expression is false, there should be no trigger event subscriptions at all. Please show the Event Subscriptions from the App Status page when the Required Expression is false.
Oops. Sorry if I got that wrong. I thought it was still subscribed if the required expression was false (and I didn't go look/check - obviously).
My apologies!
No problem, but it would be interesting if this is the case. You're right that there is a fallback check if it gets triggered despite Required Expression false. I'd really like to find out what is going on with this case.
Okay, let me take a more systematic look at this tonight then, when I have more time. Because right now I can't explain what I'm seeing:
Tonight I'll try disabling this app and recreate it from scratch to try and reproduce step by step what I saw initially.
No worries! Glad you jumped in to help
I disabled the original rule and created a new rule from scratch. In the spirit of retracing my steps, I did not use a hub variable to start. However I picked a CO2 threshold that guarantees the rule is triggered at the next event.
The rule was initialized while the switch was on, so the required expression was initially true. The rule was soon triggered. I started getting the repetitive "Required expression false" messages:
This is the event subscription section of the app status page after the required expression became false (the list looks the same as when the required expression was true) :
This is the rule definition:
I flipped the switch on again, the required expression became true and the rule soon triggered again, so the required expression went back to false. This time, no repetitive "Required Expression false" logs (actually, not a single instance of that message).
The app status page now looks like this (looks right to me):
I flipped the switch on, one more time. Rule triggers normally, no "Required Expression false" logs, event subscription only includes the switch.
I disabled this new rule and created yet another (identical) one but this time I installed it while the switch was off, therefore the required expression was initially false. I got the same result - repeat logs of "Required Expression false" and three event subscriptions in app status, etc.
Hope this helps.
Thanks. I will look into this. It appears to be related to the startup of the rule, when it is first initialized. It gets the trigger event subscriptions even though the Required Expression is false. Once the Required Expression flips to true and then false again, it works as expected.
That's what is happening. The work-around until this gets fixed is to hit Update Rule button.
This should be fixed in the next release.
Download the Hubitat app
