Here is my rule:
Rule Status Bar on the top shows:
Required Expression false
However rule itself shows it actually TRUE and with all these conditions must be true.
(First two lines both are true).
Of course, rule is not fired.
Why?
UPDATE
Suddenly at 7:02am (timeframe still within first two lines) pre-defined condition
became true.
Please turn on Event Logging, and show what happens there. When you say "became true", are you referring to UI display? Logs will show the state of Required Expression truth.
Did you use "Not this condition", or NOT operator in rule for second line? What time was the screenshot taken?
Ok, I will do this.
This rule was working OK for about a week+ and I did not touch it about the same timeframe.
That is why I did not have any related logs.
Today light failed to turn on. While I was checking what is going on just by observing
status for aps and devices I noticed the required conditions became true and rule
started to work.
Initially in the rule body in the "Define Required Expression" section
status was TRUE (and must be true) but in the UI status was false.
Since rule was not working it looks like whatever status is displayed
in UI takes over whatever is displayed in a rule body.
No, I did not use any time restriction condition in the rule itself and
a in a rule "Lr Chair Light Logic" which I am using as a subroutine
in this case:
Time was around 6:45am
On a side note.
Recently I moved all my rules from RM Legacy to new RM5.x
Many rules are simply recreated the exactly same logic,
few had logic a bit modified.
Now once in a wile some rules are either failing to fire all together
or firing with very noticeable (15+ sec) delays.
This did not happen with RM Legacy.
These delays are clearly related to the RM5.x
You can substantiate this claim with log evidence. There is no known evidence that RM5 introduces these sorts of delays.
Maybe if I turn on logs for all my near 100 rules.
I am sorry, but I am not planning to do this because this behavior is random
and not related to any specific rule.
Therefore problems like this is extremely hard to catch, reproduce and debug.
I am sorry again, but I will leave things "as is" at least for now.
Today's rule malfunction also could be related to whatever random delay
introduced but in this case instead of "trigger evaluation" in the "pre-dicade
conditions evaluation". Root cause could be the same.
Sure, I will turn on logs for this specific rule but who knows when this will/may
happen again. This rule is not new and was working just fine for a week+.
My point is/was:
Unfortunately I started to see these things only after I moved all
my rules from RM Legacy to RM5.x
And it is up to you to pay attention to this message or to ignore it.
You have provided no actionable information. I'm happy to chase down issues that can be documented. But what you provide is purely anecdotal, not reproducible, and not documented with logs.
If you have any understanding of how software works, you would know that a rule that fires quickly most of the time, and then slowly on some other time -- this is not the rule software causing this. There are many things going on in your hub, and you are making guesses about things without truly knowing what is happening.
Yes, this is 100% true.
I did not provide any evidence because all logs are off by default.
This way there is no any evidence at a time when something went wrong.
Train already departed.
I have nothing to say if observations considered as an anecdotal.
I am very carefully listening to all observations when somebody
reported a problem without any hard evidence, logs, etc.
I am doing a lot of HW debugging. Whatever is easy reproducible is considered
a very minor problem because this is very easy to trace and fix.
All that random problems are a real headache and requires a lot of effort
to chase them down.
Yes, I have no idea what exactly is going on and sure, have no idea about all internal details.
Yes, I am making only a guess based on my observations and huge experience with
debugging HW plus helping SW to debug their problems. Sometime this even requires
to add extra HW in order to pinpoint SW problems.
But yes, you are correct, all statements I made are based only on my observations.
What is wrong about this?
But if I will be able to catch something with a logs sure, I will provide a hard evidence.
There is nothing wrong with it, but there is nothing I can do to help you discover what the problem might be. I don't have your hub and your setup here to test, to put more debugging code in. But, what you report is a totally isolated report, with no others reporting slowdowns of rules for 15 seconds, or problems specific to RM 5, other than the documented bugs (which this is not). I can state with high confidence that there is nothing about RM 5 that could create slowdowns of 15 seconds. If you had logs that showed this, that would be different. I would imagine the slowdown is happening elsewhere in your hub, most likely with mesh network and device. But, you might also have some db issue, for which backup/soft-reset/restore might help (no way to tell, but no harm from this either).
I clearly understand your point - non reproducible problems is next to impossible to fix.
That is why I did not ask to fix anything. Just in case, I simply reported my observation.
True, it could be an isolated case only observed by myself. But point is - if somebody
else will report something similar it will be something to think about.
BTW, 15 sec delay is just made up number. The point is - these delays are very noticeable.
Sometime rule did not fire at all. And again, I am not sure because the delay was too long
or something else was going on.
The only change I made to my setup - is moving all rules from RM Legacy to RM5.
Considering "only one variable at a time" for the debugging approach the only change
was different RM. Yes, it could be who know what but that was only a change.
That is why I was thinking this could be related to the RM5.x but maybe not.
Yes, today night I will do backup/soft-reset/restore
I agree, this will be very good step regardless.
Also I will turn on logs for few rules and if I will catch something informative,
I definitely will inform you.
For the problem I reported today even without logs it was obvious - the
same status reported differently in two different places at the same time.
Do you agree - this should not happen and obviously indicates some problem?
Yes, it could be related to the corrupted data base but could be something else.
Only you can tell if this is possible because of corrupted data base.
I can only assume something.
Sure, but I need more to go on. And that's why I asked about which way you used NOT. If you used NOT operator in expression, then it displays one way, and if you use NOT on the condition, it displays another way. What you showed is the former, where in both places the condition shows (F), and the effect of the NOT is not shown there. These two means of using NOT look almost identical, but are not.
Notice in the first screenshot that the logic operators of the expression are shown in blue, and for the condition, in black.
I am not using that "NOT this Condition?" slider.
I just did the same exercise and did notice the difference how things are displayed.
(Frankly, I did not pay attention on this at all.)
But regardless which way that NOT was added the entire expression should be
evaluated the same way. Is not it?
I hope, I am correct.
When I talked about difference in two different places I was talking about
this bar (I called it Status Bar):
and Expression Definition section:
Last one was evaluated right. Time was around 6:40am.
Two first line should be TRUE and as a result the entire expression
also should be TRUE.
So rule should fire on MS Activity. Right?
But it did not I guess, because this bar showed it as a FALSE:
So, there is a difference in reporting the same status/condition in two
different places. And what was reported here:
actually prevented rule to fire.
Also, while I was simply looking in different places attempting to figure out
(unfortunately without logs) what may go wrong at around 7:02am the
above status bar became TRUE without any (it looks like) apparent reason.
This completely unexpected behavior triggered me to create this post.
And one more time, this rule was working OK for more than a week after
it was created. I did not touch it in any way.
Yes, but it would display slightly differently. In each case of your first screenshot above, it shows the same value for the condition of between Sunrise+30 and Sunset-30, namely (F). But because of the NOT on line 2, that first parenthesized sub-expression is true, and with OR that means entire rule is true. Second half of the rule is false.
As for the UI display, it is updated upon page opening, but not on its own if the page is already open. I don't know if the UI appearance is an artifact of your browser state. But, yes, it appears to me that the rule should be true, and that the trigger should fire. This is why I wanted you to turn on logs.
I recreated your rule exactly, and it behaved as expected. But, I didn't try it during the interval between 6:00 AM and Sunrise+30. I will enable that test for tomorrow morning. The other thing you can always look at to determine the state of the Required Expression is to look at the App Status page, and an Application State variable called stPrimed. This page has to be refreshed to show current status accurately, it is not a dynamic page.
Here it is false and rule says:
There is an issue with UI sometimes not updating the red Required Expression False in the black border at the top correctly while the rule is open. If you close the rule with Done, it is updated as it should be. I will track this done, and this could be what you are seeing. What is shown in red is only a UI display, and may not accurately reflect the actual state of the Required Expression.
Understand. And logs are already on.
Let me see what happens tomorrow morning. Problem may or may not pop up.
To make things worse for the debugging, I already performed soft reset + restore.
If this was due to the potential DB problem it may never show up.
Thank you very much for this tip. Next time I definitely will check stPrimed variable.
I am always refreshing pages knowing not all of them are dynamic.
Thank you very much for doing this but please keep in mind - rule was working fine
until today morning. An I am near 100% sure tomorrow morning it will be OK
(unfortunately for the debugging) too.
UPDATE
Right now time is outside sunset -30 window.
First two lines became TRUE again and rule is working just fine.
During the day between sunrise +30 and sunset -30 time frame second two lines
controlled rule triggering depend on illuminance without any problems.
This is exactly what I thought but my observation was a bit different.
Download the Hubitat app
