Rule Machine Time Trigger Skipping Several Points

rnstarfeldt · August 2, 2022, 12:28am

I have the following Rule Machine (5.1) Trigger event:

The trigger was working correctly until 7/10/2022 when the 6:00, 7:00, 7:30, 13:00, and 13:30 triggers weren't getting triggered.

On 7/13 I tried deleting those triggers and added new triggers at the end. Once I did that, 3:00, 4:00, 5:00, 13:00, and 13:30 weren't getting triggered.

On 7/14 I tried deleting all of the triggers, and adding them over again. Now 1:00, 2:00, 14:30, 15:00, and 15:30 aren't getting triggered.

I've tried updating to the latest version of HE several times, but that didn't help.

Any ideas what is going wrong with my trigger?

bertabcd1234 · August 2, 2022, 12:59am

The best starting point to figure this out is to enable logs on your rule, particularly Trigger logging, but Action logging may also be helpful. (See here for more: https://docs.hubitat.com/index.php?title=How_to_Troubleshoot_Apps_or_Devices#Enable_Logging)

As to why I'm suggesting this: what makes you say the rule isn't triggering? Are the actions not running as expected? Perhaps there is an issue with your devices, which trigger and action logging together will help you figure out. Otherwise, logs will provide evidence that your rule isn't triggering, as right now there is none. And then either will guide further troubleshooting.

rnstarfeldt · August 2, 2022, 1:31am

I've enabled the Trigger and Action logging.

You asked what makes me think the rule isn't triggering? The rule Action saves several weather data points to a Google Sheet. The mentioned time logs are missing from the Google sheet. I will post again tomorrow once I see what the logs indicate during the noted times.

rnstarfeldt · August 2, 2022, 1:18pm

I checked the Trigger and Action logs this morning. The rule was triggered and the actions ran at 00:01 and 3:00, but skipped 1:00 and 2:00. Below is a copy of the log. Any additional thoughts on why the trigger time values are being skipped?

app:2302022-08-02 04:00:00.089 infoTriggered
app:2302022-08-02 03:00:00.865 infoAction: Send GET to: %getURL%?...
app:2302022-08-02 03:00:00.756 infoAction: Set DataIllum to IllumVar(5)
app:2302022-08-02 03:00:00.731 infoAction: Set DataWind to WindSpeed_54(0)
app:2302022-08-02 03:00:00.692 infoAction: Set DataTemp to TempVar(66)
app:2302022-08-02 03:00:00.667 infoAction: Set DataCloud to CloudVar(1)
app:2302022-08-02 03:00:00.619 infoAction: Set DataTime to current time(03:00)
app:2302022-08-02 03:00:00.591 infoAction: Set DataDate to current date(2022-08-02)
app:2302022-08-02 03:00:00.331 infoTriggered
app:2302022-08-02 00:01:00.662 infoAction: Send GET to: %getURL%?
app:2302022-08-02 00:01:00.573 infoAction: Set DataIllum to IllumVar(5)
app:2302022-08-02 00:01:00.480 infoAction: Set DataWind to WindSpeed_54(0)
app:2302022-08-02 00:01:00.441 infoAction: Set DataTemp to TempVar(68.6)
app:2302022-08-02 00:01:00.419 infoAction: Set DataCloud to CloudVar(1)
app:2302022-08-02 00:01:00.378 infoAction: Set DataTime to current time(00:01)
app:2302022-08-02 00:01:00.333 infoAction: Set DataDate to current date(2022-08-02)
app:2302022-08-02 00:01:00.086 infoTriggered

bertabcd1234 · August 2, 2022, 1:46pm

That's odd, but one thing you could check (that wouldn't really help you fix the problem but might have something staff could use to get better ideas) would be seeing what's listed under "Scheduled Jobs" on the App Status page. The App Status page is accessible from the gear icon on the top right of the app/rule page or the similar icon next to this app in the apps list. There would likely be one for each of your trigger times (though the implementation details are not public, so we don't know for sure—this just seems like the most logical way to handle this).

As an alternative, if you had a regular schedule (e.g., every hour or every half hour), you could use a periodic trigger or a custom cron string. That would be hard or impossible to do with a single periodic trigger from what I see with your desired times, but you could probably do it with two. As to why this is happening--perhaps there is an undocumented limit to the number of periodic (or any?) triggers you can have (or maybe related specifically to periodic triggers, maybe some limit on the number of scheduled jobs). This is definitely the most I've seen in a single rule.

Sebastien · August 2, 2022, 5:47pm

Have you considered triggering it trice during the night and setting a repeat every 30 minutes or hour depending on what time it was triggered on?

rnstarfeldt · August 4, 2022, 1:10am

@bertabcd1234 You recommended looking at the "Scheduled Jobs." Here is the list:
Handler, Next Run Time, Prev Run Time, Status, Schedule
|allHandlerT|2022-08-03 21:00:00 CDT|2022-08-02 21:00:00 CDT|PENDING|0 0 21 * * ?|
|allHandlerT|2022-08-03 22:00:00 CDT|2022-08-02 22:00:00 CDT|PENDING|0 0 22 * * ?|
|allHandlerT|2022-08-03 23:00:00 CDT|2022-08-02 23:00:00 CDT|PENDING|0 0 23 * * ?|
|allHandlerT|2022-08-04 00:01:00 CDT|2022-08-03 00:01:00 CDT|PENDING|0 1 0 * * ?|
|allHandlerT|2022-08-04 03:00:00 CDT|2022-08-03 03:00:00 CDT|PENDING|0 0 3 * * ?|
|allHandlerT|2022-08-04 04:00:00 CDT|2022-08-03 04:00:00 CDT|PENDING|0 0 4 * * ?|
|allHandlerT|2022-08-04 05:00:00 CDT|2022-08-03 05:00:00 CDT|PENDING|0 0 5 * * ?|
|allHandlerT|2022-08-04 06:00:00 CDT|2022-08-03 06:00:00 CDT|PENDING|0 0 6 * * ?|
|allHandlerT|2022-08-04 07:00:00 CDT|2022-08-03 07:00:00 CDT|PENDING|0 0 7 * * ?|
|allHandlerT|2022-08-04 07:30:00 CDT|2022-08-03 07:30:00 CDT|PENDING|0 30 7 * * ?|
|allHandlerT|2022-08-04 08:00:00 CDT|2022-08-03 08:00:00 CDT|PENDING|0 0 8 * * ?|
|allHandlerT|2022-08-04 08:30:00 CDT|2022-08-03 08:30:00 CDT|PENDING|0 30 8 * * ?|
|allHandlerT|2022-08-04 09:00:00 CDT|2022-08-03 09:00:00 CDT|PENDING|0 0 9 * * ?|
|allHandlerT|2022-08-04 09:30:00 CDT|2022-08-03 09:30:00 CDT|PENDING|0 30 9 * * ?|
|allHandlerT|2022-08-04 10:00:00 CDT|2022-08-03 10:00:00 CDT|PENDING|0 0 10 * * ?|
|allHandlerT|2022-08-04 10:30:00 CDT|2022-08-03 10:30:00 CDT|PENDING|0 30 10 * * ?|
|allHandlerT|2022-08-04 11:00:00 CDT|2022-08-03 11:00:00 CDT|PENDING|0 0 11 * * ?|
|allHandlerT|2022-08-04 11:30:00 CDT|2022-08-03 11:30:00 CDT|PENDING|0 30 11 * * ?|
|allHandlerT|2022-08-04 12:00:00 CDT|2022-08-03 12:00:00 CDT|PENDING|0 0 12 * * ?|
|allHandlerT|2022-08-04 12:30:00 CDT|2022-08-03 12:30:00 CDT|PENDING|0 30 12 * * ?|
|allHandlerT|2022-08-04 13:00:00 CDT|2022-08-03 13:00:00 CDT|PENDING|0 0 13 * * ?|
|allHandlerT|2022-08-04 13:30:00 CDT|2022-08-03 13:30:00 CDT|PENDING|0 30 13 * * ?|
|allHandlerT|2022-08-04 14:00:00 CDT|2022-08-03 14:00:00 CDT|PENDING|0 0 14 * * ?|
|allHandlerT|2022-08-04 16:00:00 CDT|2022-08-03 16:00:00 CDT|PENDING|0 0 16 * * ?|
|allHandlerT|2022-08-04 16:30:00 CDT|2022-08-03 16:30:00 CDT|PENDING|0 30 16 * * ?|
|allHandlerT|2022-08-04 17:00:00 CDT|2022-08-03 17:00:00 CDT|PENDING|0 0 17 * * ?|
|allHandlerT|2022-08-04 17:30:00 CDT|2022-08-03 17:30:00 CDT|PENDING|0 30 17 * * ?|
|allHandlerT|2022-08-04 18:00:00 CDT|2022-08-03 18:00:00 CDT|PENDING|0 0 18 * * ?|
|allHandlerT|2022-08-04 18:30:00 CDT|2022-08-03 18:30:00 CDT|PENDING|0 30 18 * * ?|
|allHandlerT|2022-08-04 19:00:00 CDT|2022-08-03 19:00:00 CDT|PENDING|0 0 19 * * ?|
|allHandlerT|2022-08-04 20:00:00 CDT|2022-08-03 20:00:00 CDT|PENDING|0 0 20 * * ?|

From that, the missing trigger times aren't showing up in the scheduler either. Let me know if that helps determine any next steps.

If we can't figure out a solution, I agree with both you and @bertabcd1234 that a reasonable option would be to use a periodic trigger, set at 30 minutes. At would give me more data than I want, but I could delete / ignore the data I don't need.