Delayed actions suddenly not working any more

chris18 · September 14, 2022, 6:40am

I have a rule that was in Rule Machine Legacy, which just turns off the light 30 seconds after the garage doors are sensed shut.

Well, the rule stopped working, it didn't turn off the light any more.

Here's what I discovered since:

Clicking "run action" shows the problem too, it's NOT the trigger's fault.
Moving the rule from rule machine legacy to the newer rule machine doesn't help.
Changing the action to NOT be delayed means the action works fine straight away (through clicking "run action" or actually closing the garage door).
Adding a delay to an action on other rules also makes the actions not work, so delays aren't working at all on any rule.
In the logs, I see the action queued up: "Action: Off: Garage lights --> delayed: 0:00:03 (cancelable)" however there is nothing logged or done 3 seconds later.
I've rebooted and shutdown the Hub a few times, it doesn't help.
I've installed the latest suggested Hubitat firmware, but that didn't help. (Now have 2.3.2.141).
I did have some other rules which could "cancel" my delayed action, but I know that's not the issue since I wasn't triggering them, and adding delays for other rules also saw the same problem, and since deleting the rule and recreating in the newer rule machine there are no rules able to cancel it now.

This has been working fine for more than a year, and suddenly it stopped working. Here's what I have done this weekend which are possibilities for triggering this behaviour. I can't remember if the door light delay worked since I did these:

On Friday I discovered some rules weren't working at all, and logs showed memory issues, so I rebooted the Hub, and things seemed to be working after that. No new logs about memory issues.
On Sunday I installed 2 new ZBMini devices and added a couple of rules so they act together (if either goes on or off, they both do).
I installed a "rebooter" app to help with future memory issues, but have since deleted it and that didn't help the delay issue.

Is there some global setting for timers or delays that might have got messed up?

chris18 · September 14, 2022, 8:40am

Note I tried some rules that are just meant to trigger at a certain time.
And they didn't work either. I haven't used them before but I'm sure I set it up right. Nothing is logged at the time they're meant to activate.

So, it seems the system's alarms/timers just aren't working ?

The time is correct though in the logs and time settings, so it's not a total failure of the clock.

Is there anything else I can check to narrow down which aspect of the system timers has failed ?

pseudonym · September 14, 2022, 11:21am

Would you post the rule, the Scheduled Jobs, and the logs?

thebearmay · September 14, 2022, 11:58am

Might also check to make sure that the status for the lights are correct - rule won't do anything if it thinks the lights are already off.

bertabcd1234 · September 14, 2022, 1:19pm

If everything looks right, you might want to try downloading a backup, then doing a soft reset and restore of that backup. This may help clean things up if the root of your problem is database corruption. See the "Soft Reset" section of this doc: How to Troubleshoot Apps or Devices | Hubitat Documentation

chris18 · September 14, 2022, 3:15pm

Here's the info about a test of timers I just tried. This time I did the "Certain time" trigger, but I have also tried the "days of week schedule" trigger that fails similarly.

Here's the "interesting" parts of the rule - let me know if I should post the whole thing, inline or some better way.

Under "application state":
actions {1={wait=null, delay=, modes={}, method=getToggleSwitch, indent=, rule=null, label=Toggle: Dining lights , cond=0}}
capabstrue {2=When time is 7:36 AM}
|lastEvtDate|2022-09-14|
|lastEvtTime|07:33|
|sched1|On Sun, Mon, Tue, Wed, Thu, Fri, Sat at 7:26 AM|
|sched49|On Sun, Mon, Tue, Wed, Thu, Fri, Sat at 7:34 AM|

Scheduled jobs:
|Handler|Next Run Time|Prev Run Time|Status|Schedule|
|allHandlerT|2022-09-14 7:36:00am PDT||PENDING|0 36 7 * * ?|

I'm not sure why there's a "sched1" for 7.26 and a "shed49" for 7.36, except that I did previously have this rule set for 7.26 for a prior test but I deleted that trigger and created a new one for 7.36.... This isn't my problem though, since it failed the first time too.
It was 7.33 or so when I changed the rule to trigger at 7.36. But, when I captured the above, it was 7.40, which was after the rule was meant to trigger.
Why then does the "scheduled job" show that the NEXT run time is in the past (yes, today is 9/14), and the "Prev run time" is blank. That's the most curious part. Like it's still waiting to be alerted by the system for the timer it set for 7.36. But the rule was never told that 7.36 had come and gone...

Here's some log started just after I created the rule (or edited it with new trigger time) and a couple of minutes after it was meant to trigger. No mention of my time based rule is in there.

Note I know the "action" works, it's just a light toggle which works when I click "run action" in the rule config.

dev:1222022-09-14 07:39:52.351 am infoFront Door Motion sensor is inactive
dev:1342022-09-14 07:39:44.357 am infowardrobe door is closed
dev:712022-09-14 07:39:35.289 am infoWardrobe motion is active
dev:1222022-09-14 07:38:32.765 am infoFront Door Motion sensor is active
dev:902022-09-14 07:37:50.424 am infoZigbee parsed:[raw:catchall: 0000 0006 00 00 0040 00 C4BF 00 00 0000 00 00 03FDFF040101190000, profileId:0000, clusterId:0006, clusterInt:6, sourceEndpoint:00, destinationEndpoint:00, options:0040, messageType:00, dni:C4BF, isClusterSpecific:false, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:00, data:[03, FD, FF, 04, 01, 01, 19, 00, 00]]
dev:892022-09-14 07:37:31.875 am infoDining lights is off [physical]
dev:702022-09-14 07:36:52.249 am infoBack Door is closed
dev:702022-09-14 07:36:51.066 am infoBack Door is open
dev:1372022-09-14 07:36:48.843 am infoChris fan power plug is off [physical]
dev:1232022-09-14 07:35:36.089 am infoSakura lights is on [physical]
dev:1222022-09-14 07:34:37.214 am infoFront Door Motion sensor is inactive
dev:712022-09-14 07:34:23.375 am infoWardrobe motion is inactive
dev:702022-09-14 07:33:47.946 am infoBack Door is closed
dev:702022-09-14 07:33:46.408 am infoBack Door is open

pseudonym · September 14, 2022, 4:45pm

Within your rule, is logging turned on? I'm seeing devices logging, which is on by default, but I suspect your app logging isn't on.

Please post a screenshot of your rule.

chris18 · September 14, 2022, 4:54pm

Yes, logging is on.

chris18 · September 14, 2022, 4:56pm

Here's the screenshot of the rule.

pseudonym · September 14, 2022, 5:33pm

Looks like it was scheduled and logging was on so I'd follow @bertabcd1234 suggestion above. Before that, though, could you add another trigger to the rule, say 15 minutes from when you read this, and post a screenshot of those logs?

chris18 · September 14, 2022, 6:02pm

I'm not at home right now, will try tonight.

Is your intent to see what is logged when I SET the trigger? Looking in the log for the setting of a timer or something ? or the logs from when the timer is meant to go off ? I can include both...

I'll look into the reset and restore too.

Is there a way to set more logging from the system or the rule machine itself ? I can only see in each rule how much logging for that rule.

pseudonym · September 14, 2022, 8:30pm

I'm interested in seeing if a new trigger creates a new Scheduled Job and if the new trigger results in the rule actually triggering and running. It's also simple enough to completely redo it and see if a new rule works. None of this isn't even addressing your delays not working but triggering at a certain time seemed like an easier problem to debug.

I'm not aware of any way for a user to see more logging. I think the Hubitat staff can access your hub and see more details but that may be more of system level logging and not Rule Machine.

chris18 · September 15, 2022, 5:09am

Thanks, yeah, I agree the delay and this timer are probably related, so let's tackle the easiest to debug...

So I created a new "certain time" rule for 10.05pm.

I wrote down the timing of each step I did. (Timing done by eye from my phone, which seemed to match time reported by Hubitat's live logging within a second or so).

9:55:00 I clicked "new rule"
9:55:48 Clicked "done" after naming the rule
9:56:22 Clicked "done" after having added a trigger and selected 10.05 for the time.
9:56:36 Clicked "done with trigger"
9:57.17 Clicked "done with action"
9.57.34 Clicked "Done with actions"
9.57.51 Finished selecting the all the logging to enable.
9.58.05 Clicked "install rule"
9.58.21 Clicked "Done" on the rule

Logging throughout that time shows nothing until the last 2 clicks ("install rule" and "done"), at which time it logged "Initialized".

app:2502022-09-14 09:58:20.184 pm infoInitialized
app:2502022-09-14 09:58:04.420 pm infoInitialized
dev:892022-09-14 09:57:18.307 pm infoDining lights is on [physical]
dev:1372022-09-14 09:56:49.666 pm infoChris fan power plug is off [physical]
dev:1232022-09-14 09:55:37.141 pm infoSakura lights is on [physical]
dev:812022-09-14 09:54:36.259 pm infoGarage lights switch is on

So I waited until 10.07, and then went back and collected the rest of the logs up until that point:

dev:712022-09-14 10:07:15.151 pm infoWardrobe motion is active
dev:712022-09-14 10:06:52.197 pm infoWardrobe motion is inactive
dev:1372022-09-14 10:06:49.999 pm infoChris fan power plug is off [physical]
dev:1232022-09-14 10:05:37.428 pm infoSakura lights is on [physical]
dev:712022-09-14 10:05:30.742 pm infoWardrobe motion is active
dev:892022-09-14 10:05:16.018 pm infoDining lights is on [physical]
dev:1402022-09-14 10:03:26.851 pm infoDining movement is active
dev:1402022-09-14 10:03:07.088 pm infoDining movement is inactive
dev:1372022-09-14 10:01:49.682 pm infoChris fan power plug is off [physical]
dev:892022-09-14 10:01:17.167 pm infoDining lights is on [physical]
dev:1232022-09-14 10:00:37.150 pm infoSakura lights is on [physical]
dev:682022-09-14 09:59:33.655 pm infoGarage smoke carbon monoxide clear
dev:682022-09-14 09:59:33.652 pm debugparse:zw device: 0E, command: 7105, payload: 00 00 00 FF 02 00 00 , isMulticast: false
dev:682022-09-14 09:59:33.358 pm infoGarage smoke smoke clear
dev:682022-09-14 09:59:33.351 pm debugparse:zw device: 0E, command: 7105, payload: 00 00 00 FF 01 00 00 , isMulticast: false
dev:682022-09-14 09:59:33.052 pm infoGarage smoke battery is 81%
dev:682022-09-14 09:59:33.040 pm debugparse:zw device: 0E, command: 8003, payload: 51 , isMulticast: false
dev:682022-09-14 09:59:32.880 pm debugGarage smoke Device wakeup notification
dev:682022-09-14 09:59:32.865 pm debugparse:zw device: 0E, command: 8407, payload: , isMulticast: false
dev:682022-09-14 09:59:29.670 pm debugHeartbeat
dev:682022-09-14 09:59:29.667 pm debugSupervision Get - SessionID: 41, CC: 113, Command: 5
dev:682022-09-14 09:59:29.664 pm debugparse:zw device: 0E, command: 6C01, payload: 29 09 71 05 00 00 00 FF 09 05 00 , isMulticast: false
dev:682022-09-14 09:59:22.823 pm debugHeartbeat
dev:682022-09-14 09:59:22.773 pm debugSupervision Get - SessionID: 40, CC: 113, Command: 5
dev:682022-09-14 09:59:22.743 pm debugparse:zw device: 0E, command: 6C01, payload: 28 09 71 05 00 00 00 FF 09 05 00 , isMulticast: false

None of that appears relevant. Nothing interesting when the timers are meant to go off.

chris18 · September 15, 2022, 5:13am

I'm in PDT timezone, so in case there was some timezone confusion, I edited the trigger to go off at 5.12am, in case that would be interpreted as UTC, in which case it should have gone off at 10.12pm, but it didn't do that...

chris18 · September 15, 2022, 5:37am

Ah, I forgot to get the scheduled job info, so I deleted that rule, and created another.
I was creating the new rule (same as the old rule, but set to trigger at 10.30pm) from 10.17.35 until 10.18.38. Then, at 10.18.56 I went to the settings page for the rule and found:

Scheduled Jobs

Handler Next Run Time Prev Run Time Status Schedule


allHandlerT	2022-09-14 10:30:00pm PDT		PENDING	0 30 22 * * ?

Then, at 10.36 (after not seeing any lights toggle), I went back to that page, and got the scheduled jobs info again as:

Handler	Next Run Time	Prev Run Time	Status	Schedule
allHandlerT	2022-09-14 10:30:00pm PDT		PENDING	0 30 22 * * ?

ie. there was no change - and it's now pointing to the past when the trigger should have triggered but didn't.

chris18 · September 15, 2022, 5:57am

So these symptoms seem to show that the rule machine isn't getting notified by the system at the correct time to do actions.

I wanted to check though if rule machine had problems with other time based actions. So, I created a rule which would toggle a light if I press a certain button, but only if the time was between 10.50 and 10.52 (by setting conditions in the action). The rule worked perfectly. It ignored my button pressed before 10.50 and after 10.52, but flashed the light when I pressed it between those times.

This backs up what I'm seeing on some other rules I have responding to garage doors and porch movement only between sunset and sunrise, which do seem to be correctly working.

So, my rule machine can ask the system what the time is now, but can't ask to be called back at a certain time.

chris18 · September 15, 2022, 6:20am

Ah, I noticed that in the doc for soft reset, it said one reason to do it was if "...apps with "Scheduled Jobs" that appear to be scheduled correctly but do not execute when expected"

so it does seem my issue is a known issue...

So, I followed those instructions to do a soft reset, and now my system works again ! Huzzah ! The delays are working for sure, I haven't tested the time trigger.

Thank you both.
I'd like to continue trying to debug to figure out what the bug actually is, but I'm content instead having it working again.

I hope it doesn't occur regularly. Does anyone know if there's some cause that makes it more likely it will happen again ?

bertabcd1234 · September 15, 2022, 1:26pm

If a soft reset helped, the cause was likely database corruption. The best way to avoid that is by always properly shutting down or rebooting the hub from Settings (or the Diagnostic Tool, POST endpoint, etc.) when you need to, rather than pulling power, which is probably the #1 cause.

Database corruption, not so much a bug. It shouldn't happen on its own (except rarely via the above), so if it keeps coming back, that would be worth looking into.

Just a possible symptom of a corrupt database.

chris18 · September 15, 2022, 2:26pm

Probably when I had to pull power due to running out of memory...
And this explains why the rebooter app didn't work - it relied on timers too.
I will reinstall that, and it will probably work next time.

chris18 · September 15, 2022, 4:10pm

It's a curious symptom of a corrupt database...
Are upcoming timing events placed into the database ?
I would have thought there'd be a separate RAM struct for that type of thing, but I suppose if the machine powers down before a timer goes off you'd want the timer to still exist after powering back on without having to re-inspect every rule...