I have found a workaround for the problem described below. It is explained on post # 20 of this thread. I am still hoping that an actual fix will be developed by the Hubitat developers when they get the bandwidth to address the issue.
Original post with problem description
I have a rule-machine rule that is sometimes trigger multiple times when it should only be triggered once.
@bravenel I am threading you in because you seem to have dealt with these types of issues in past threads.
In the example that is documented below, it is trigger 5 times when it should only have triggered once. This is causing serious problems because the devices I am turning off are getting flooded with events.
I attempted to add some logic to prevent it from running multiple times, but it does not help.
Here are the logs -- the events that happened at 11:30PM show the problem clearly. I am logging events and triggers, but not actions. Having said that, one can clearly see which path of the if-them that was taken by the message I logged:
This has been happening for a while -- I have given up trying to troubleshoot it myself as I suspect it is a bug somewhere in Hubitat. Here is the exact version that was running last night:
Interestingly, the rule shows that it is scheduled to run multiple times right now. If I reboot the hub, based on past experience, things will behave for some period of time before it starts to misbehave again.
Unfortunately, I just stopped the rule, which removed all the scheduled jobs.
I also re-wrote it to simplify the logic to prevent multiple runs using the technique you suggested on this post.
Next time it happens I will try hitting "update" to see what happens, but even if hitting update cleans out the backlog of scheduled events, it won't solve the problem. This has been going on for several months -- it just took me a while to narrow it down to this rule.
I have a rule that has started to do a similar thing, but it only triggers twice. There are two scheduled jobs instead of one. If I open the rule and hit Done or toggle the required expression from true to false and back, it will correct itself. It happens about once a week.
Update: In my original post I said I was not going to change anything until Bruce replied. I did hit "Done" on the rule since you are never supposed to leave a rule without hitting "done". The act of hitting "done" cleaned up the backlog of scheduled events, per the 3rd screenshot.
@bravenel , it just happened again. I have made some changes since I originally reported the issue:
I migrated from a C7 hub to a C8-pro hub
I turned on the option to "ignore trigger events while running".
I reverted back to my clock-based approach to attempt to eliminate duplicate runs.
The rule now shows that it ran 9-times at 11:30PM last night when I look at "Scheduled jobs", and it is scheduled to run 9-times tonight.
The logs show that the event happen 9 times, but it only triggered once, probably because I turned on the "ignore trigger events while running".
I am not going to change anything until I hear back from you.
Could you just delay the actions by 60 seconds such that the time ticks over and the match no longer exists? Didn't seem the timing was critical. Then the lights would be triggered just once?
I have wondered if Hubitat suffers from race conditions when inputs repeatedly match. I'm not sure how the matching logic works.
If I understand the suggestion correctly, I think that would result in the 9 actions all happening 60-seconds later.
The good news is that turning on "ignore trigger events while running" helps quite a bit. When the event is still sometimes generated multiple times, the most that I have seen is actions being triggered twice, about 46MS apart. In that instance, 9 events had been generated...
Woke up this morning. The rule worked properly last night (1 event, 1 trigger) at 9:30PM and 11:30PM last night.
At 1:30AM it was sent 5 events, but only triggered once.
It currently shows 5 events queued up for 9:30AM this morning (see screenshot below). There should only be 1 event queued for 9:30AM.
The option to "ignore trigger events while running" prevents multiple triggers the vast majority of the time. In the one instance where it did not, only 2 of the 9 events caused the rule to be triggered, which is an improvement.
@bravenel Is this being treated as a bug that will be investigated when time permits, or is additional information needed?
I am looking into this. One thing I see right off is that the cron string in the Scheduled Jobs is invalid, have 4 trailing * instead of 3. Will dig around a bit on this...
Found the cause of that problem, and a fix for it will be in the next release. That may (or may not) fix this problem.
The cron string I have in my rule has only 3 *s, not 4. Interesting that the schedule shows 4 *s. (Screenshot below).
Update: I just realized that this was your point -- that my rule has 3 *s but the schedule shows 4.
Found the cause of that problem, and a fix for it will be in the next release. That may (or may not) fix this problem.
That's fantastic -- thank you! I will try the next release when it comes out.
Marc
...and here's the screenshot I referenced above, but forgot to include...
Yeah, I found the line of code where the extra * comes from, and the reason for that particular mistake. I don't now why that would cause what you've seen, and I'm not sure if fixing that will fix your problem or not. But, it might... If not, we'll go from there...
@bravenel, unfortunately, it looks like the update didn't solve the problem. Per the screenshot below, I have 2 jobs scheduled for 11:30PM. I suspect the number of jobs will continue to grow as time goes on...
Something I just noticed. The log shows the sunrise / sunset events being schedule 3 times each at midnight. (Clarification: The events are being added to the schedule at midnight; the are scheduled to execute at the correct time.)
I looked back through the logs and this is not new - this was happening before the upgrade -- I just never noticed it.
@bravenel I found a work-around for the problem. Sharing this in case it helps others that are having the problem and in case it provides you useful information for identifying the root-cause.
The first rule has the 2 triggers that are based on sunrise. This rule also contains all the logic I want executed.
The second rule has the cron trigger and runs the first rule whenever it is triggered.
I've been running this way for about a week, and I am no longer seeing the "pile up" of scheduled jobs, so it looks like the problem has something to do with having a rule with both sunrise-based triggers and a cron-based trigger.
Hope this helps!
Marc
Here are screenshots of the 2 rules referenced above.
