Rule became true but action did not run

I have a rule with a really simple condition, switch turns on, and it's been working fine. But this morning, I found that although it became true, the actions didn't run. There is a restriction but it shouldn't have been true. I'm hoping someone spots what the problem as this is my current wake up routine or recognizes a bug?

Here are the logs from yesterday and today; it should've run at 6:25AM today (yesterday was 6:35AM). And the logs clearly show it recognized it changed to true but then nothing happened.

Here's the rule:

Here are events from the rule:

And here are events from the presence device used in the restriction (the device page also shows it's still present):

@bravenel any idea what may have happened here?

According to your logs, the actions did run. What makes you think that they did not?

The logs for 6/5 show they didn't run at 6:25AM. It shows them running on 6/4 though and I can confirm they ran yesterday but not today. I was present when they ran yesterday and did not today so I can visually confirm they didn't run.
What part of the logs for 6/5 make you think it ran compared to 6/4? I don't see any log lines from today prefixed with "Action:" which is what I would've expected to see if HE thinks it tried to run things.

Ah, didn't notice the second day. It never went to false, so there was no rule truth change. Rules don't do anything unless there is a change in rule truth. And, you can see from the logs, that it never became false.

Ah, thanks for pointing that out! I totally missed the state change of the switch itself. Odd... that's this timed switch and it's always worked before.... guess I could create a scheduled rule that flips it to off nightly just in case it gets stuck again.
I'm basically using it like a button that I'm triggering from a HomeKit schedule (to make it easy to change from our phones). Any other ideas?

If it's a virtual switch, you can put it an auto-off on a timer. Look at the preferences for the device. Basically turns it into a momentary switch. But you've got a delay with cancel on truth change for 45 minutes, so I guess that won't work.

Yeah, it's a custom virtual switch (just since that allows a longer duration) acting as a momentary switch it's just the delay is longer than delays in the the action itself. My cancel on truth change is simply to allow me to stop the action in case I forgot to disable it during a day off / sick day / whatever. It was the simplest way I could think of but I suppose I could introduce another override switch and use that instead.

I just got home and as far as I can tell, the timed switch did actually turn itself off... I'm not sure why the rule events show no off for it?

Need to see the app logs for that.

Sorry, which app logs? The logs from the rule itself are in the original post. Here are the logs for that switch if that's helpful.

I had this happen again this morning. The logs show the rule saw the switch turn on and the events for the rule show the same. But, at 6:25am when it should've started changing the lighting, it didn't. You can see what I would've expected to see at 6:39am when I manually started the rule to wake my wife up and you can see there's no repeat logged which, per the rule, would've started at about 6:35am. I'm also attaching the rule (just in case) as it's changed just a bit since my OP.

@bravenel, any idea why this may not happen? I spaced and didn't check the scheduled jobs for the rule before manually activating but will definitely try to do that if I see this again. If you have any other pointers on what to check or useful data to grab please let me know.


Does this work on other days, just failed today?

Really need to see more of the logs than what you've shown.

yeah, it has generally worked but failed this morning. The last failure (that wasn't my fault) was 14 days ago when I last posted.
I'm not sure there's much else useful in the logs but here's a 3 hour section of everything in case you see something there that means more to you than me.

Given the 3 entries in a row with Bedroom wake up is on, my guess is that the rule didn't change rule truth at 6:25, so didn't run. But that's not really visible in the logs. Do you know why there are three such entries in a row?

The times are different; not sure why it was there twice at 6:39am but that's when I woke up and manually ran the rule.
At 6:35 we see the switch turn on:
dev:5752019-06-20 06:24:57.308 am debugTurning off in 5400 seconds dev:5752019-06-20 06:24:57.306 am debugSwitch Timer with Reset Version 1.0 - ON
and then after we see the rule log the event and condition:

app:10902019-06-20 06:24:57.586 am info --> Bedroom wake up(on) is on [true]
app:10902019-06-20 06:24:57.502 am info[Lighting] Gentle wake up: Bedroom wake up switch on

the next log entry is at 6:39 which should be unrelated.

Here is the event page for that switch showing it was off and then on at 6:25

This happened again this morning. Unfortunately by the time I woke up, there would not have been any scheduled tasks in the rule so no use checking that. I’ve attached logs and the event history for the rule, both of which seem to show it should have run.

Manually toggling the switch again did trigger this. It was definitely off before but maybe there is something different about the timed off vs manual off?

You should turn on logging in the rule, and then show those logs. It clearly ran. So if it didn't do what you expected there is probably some other explanation for that. Can't tell you anything more from the sparse information you've provided.

I had events and actions turned on. I would've expected useful logs from the actions part (and have seen that in the past) if it had actually run. I'm not sure how you're making the assertion it definitely ran?

I've just turned on all logging but don't think that'll help shed light on it since action logging was empty.

Given toggling the switch manually (still via HomeKit but not off via timed off) I'm wondering if there's something odd about the timer event though the code seems pretty straightforward using #runIn. The only difference (I suspect) between this and using the native one is this one allows much longer delayed off times... it does seem to turn off so I'm not sure what would be odd about events during a longer delayed off vs. a more immediate one.

However, I'm also now thinking I don't even need auto-off since all the work you've done in RM3 should allow me to turn it off via the true action... I'm a bit curious so I may tinker a bit but think in the end I'll try setting things up directly in the rule to remove the switch side of the variable and see if it fixes it or not.

The event log shows the repeat, does it not?