Unexpected behaviour of required expression versus trigger

anne.hubitat · February 2, 2025, 6:29pm

This is on a C-8 Pro at version 2.4.0.151.

I have a rule that fired when I don't think it should have, so either my understanding of Rule Machine is incorrect, or there's a bug. The following rule should be active only when it's dark out (that is, when lights might be needed); under those conditions, it should be triggered by someone's arrival:

The kitchen "mood lighting" turned on this morning, but we were already home - no one had "arrived". I checked my logs, and the last arrival was yesterday afternoon. However, right before the rule fired (in the same second), it stopped being dark outside. There are no other events close in time to the rule firing - the previous event before those shown below is a thermostat temperature report nearly 30 seconds earlier. Here are some extracts from my syslog (so, chronological order, not reverse chronological):

Feb  1 14:31:18 192.168.1.77 1 2025-02-01T14:31:17.147-04:00 Hubby app 235 - - Syl has arrived (phone entered geofenced zone)
Feb  1 14:31:18 192.168.1.77 1 2025-02-01T14:31:17.269-04:00 Hubby app 240 - - Syl is home!
Feb  1 14:31:18 192.168.1.77 1 2025-02-01T14:31:17.454-04:00 Hubby app 241 - - Anne or Syl has arrived.
Feb  1 14:31:19 192.168.1.77 1 2025-02-01T14:31:17.657-04:00 Hubby app 245 - - At least one person (Anne, Syl, or extra person) is home.
Feb  1 14:35:14 192.168.1.77 1 2025-02-01T14:35:12.758-04:00 Hubby app 235 - - Anne has arrived (phone entered geofenced zone)
Feb  1 14:35:14 192.168.1.77 1 2025-02-01T14:35:12.882-04:00 Hubby app 236 - - Anne is home!
Feb  1 14:35:14 192.168.1.77 1 2025-02-01T14:35:13.059-04:00 Hubby app 241 - - Both Anne and Syl are now home.

The log line above that says that "At least one person" is home is from the rule that sets the variable Presence_somebody to true. So that variable has been true since yesterday. This morning:

Feb  2 08:14:02 192.168.1.77 1 2025-02-02T08:14:00.467-04:00 Hubby dev 64 - - Outdoor motion sensor: front illuminance is 666 Lux
Feb  2 08:14:02 192.168.1.77 1 2025-02-02T08:14:00.745-04:00 Hubby app 248 - - Environment: bright is now true (outdoor illuminance > 400 lux)
Feb  2 08:14:02 192.168.1.77 1 2025-02-02T08:14:00.908-04:00 Hubby app 250 - - Environment: lights are no longer needed

The last log line above is from the rule that sets the variable Environment_need_lights to false. And then in the same second:

Feb  2 08:14:02 192.168.1.77 1 2025-02-02T08:14:00.960-04:00 Hubby dev 54 - - Kitchen undercabinet lights button (VIRTUAL)(real actions) button 4 was pushed
Feb  2 08:14:02 192.168.1.77 1 2025-02-02T08:14:00.980-04:00 Hubby dev 54 - - Kitchen undercabinet lights button (VIRTUAL)(real actions) button 1 was pushed
Feb  2 08:14:02 192.168.1.77 1 2025-02-02T08:14:00.998-04:00 Hubby app 278 - - Kitchen mood lighting set because someone has arrived

So it seems that when Environment_need_lights became false (the opposite of the required condition!), the rule fired (even though the trigger had not happened at that time).

Is there something weird going on, or am I missing something obvious?

Sebastien · February 2, 2025, 6:35pm

Could you share a screenshot of the logs from the rule in question? (With all logging enabled)

hubitrep · February 2, 2025, 6:38pm

Might be related to this?

anne.hubitat · February 2, 2025, 7:23pm

I've enabled all logging on that rule; if it misbehaves again, I'll definitely post the details.

That seems possible.

anne.hubitat · February 2, 2025, 7:57pm

By manually changing the values of some hub variables, and letting illuminance reports from the front motion sensor "correct" them, I was able to replicate the conditions that caused the problem. Below are the logs of the "misfire", again in "forward" chronological order; app 278 is the one that is misfiring.

Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:00.809-04:00 Hubby dev 64 - - Outdoor motion sensor: front illuminance is 2280 Lux
Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:01.160-04:00 Hubby app 248 - - Environment: bright is now true (outdoor illuminance > 400 lux)
Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:01.286-04:00 Hubby app 250 - - Environment: lights are no longer needed
Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:01.351-04:00 Hubby app 278 - - Event: Hubby variable:Environment_need_lights false
Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:01.377-04:00 Hubby app 278 - - Triggered: Variable reported Presence_somebody(true) = true
Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:01.385-04:00 Hubby app 278 - - Action: Push button 4 on Kitchen undercabinet lights button (VIRTUAL)(real actions)
Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:01.403-04:00 Hubby dev 54 - - Kitchen undercabinet lights button (VIRTUAL)(real actions) button 4 was pushed
Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:01.421-04:00 Hubby app 278 - - Action: Push button 1 on Kitchen undercabinet lights button (VIRTUAL)(real actions)
Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:01.426-04:00 Hubby dev 54 - - Kitchen undercabinet lights button (VIRTUAL)(real actions) button 1 was pushed
Feb  2 15:44:03 192.168.1.77 1 2025-02-02T15:44:01.441-04:00 Hubby app 278 - - Action: Log: 'Kitchen mood lighting set because someone has arrived'
Feb  2 15:44:03 192.168.1.77 1 2025-02-02T15:44:01.447-04:00 Hubby app 278 - - Kitchen mood lighting set because someone has arrived
Feb  2 15:44:03 192.168.1.77 1 2025-02-02T15:44:01.560-04:00 Hubby app 278 - - Required Expression now false
Feb  2 15:44:03 192.168.1.77 1 2025-02-02T15:44:01.647-04:00 Hubby app 83 - - Turning on kitchen lighting (scene unchanged: 4)
Feb  2 15:44:03 192.168.1.77 1 2025-02-02T15:44:01.715-04:00 Hubby dev 50 - - Kitchen undercabinet lights (left of sink) was turned on [digital]
Feb  2 15:44:03 192.168.1.77 1 2025-02-02T15:44:01.739-04:00 Hubby app 179 - - Changed kitchen lighting scene to: 4: mood lighting
Feb  2 15:44:03 192.168.1.77 1 2025-02-02T15:44:01.755-04:00 Hubby dev 62 - - Kitchen undercabinet lights (right of sink) was turned on [digital]
Feb  2 15:44:03 192.168.1.77 1 2025-02-02T15:44:01.902-04:00 Hubby dev 61 - - Kitchen undercabinet lights (left of stove) was turned on [digital]

The relevant lines are:

Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:01.351-04:00 Hubby app 278 - - Event: Hubby variable:Environment_need_lights false
Feb  2 15:44:02 192.168.1.77 1 2025-02-02T15:44:01.377-04:00 Hubby app 278 - - Triggered: Variable reported Presence_somebody(true) = true

"Environment_need_lights" being false should inhibit the rule, and its becoming false (or true for that matter) should not act as a trigger for this rule, whereas "Presence_somebody" was already true, so it did not change, therefore should not have been considered to have been triggered at this time.

Definitely a bug, I think.

aaiyar · February 2, 2025, 8:02pm

When you post logs, can you post them as screenshots? They’re much easier to read.

bravenel · February 2, 2025, 8:29pm

Impossible to say without the real logs. You aren't showing what we need to see. Screenshots of the full sequence for the app. What you just posted is very misleading, as you have reversed the order of the log lines. Don't do that! Just show the logs as they are produced by the hub.

anne.hubitat · February 2, 2025, 9:26pm

I hate screenshots when reading logs, as it makes it impossible to copy/paste them so I can use tools on them. However, I'm happy to provide you with what you prefer.

As you wish. I filtered on that app; here is the sequence that I showed before, as a screenshot from the Hubitat's logs directly:

Please let me know if there's anything else I can provide that could be helpful.

aaiyar · February 2, 2025, 9:34pm

I think what you've posted is pretty clear.

This is related to a bug report from @mluck and @mattias, and I believe it is on @bravenel's radar to be fixed.

On Discourse (the community platform) HE logs lend themselves better to a screenshot over text that is cut & paste.

mattias · February 2, 2025, 9:55pm

@anne.hubitat are you saying that the triggered event that is recorded in the logs didn’t actually happen?

Can you show the “location events” log filtered on those two variables?

It’s not the same bug as we reported in that other thread, but similar in that variables are used in both required expression and trigger.

In your case it feels like your trigger is treated as a condition rather than an event

bravenel · February 2, 2025, 11:11pm

Please show the Event Subscriptions section of the App Status page. Have you hit Done or Update on this rule since you updated to 2.4.0.151? What you're showing is a bug that was fixed, but the nature of the bug could have left the old (wrong) event subscriptions. So, if you haven't done so, hit Update. Before and after screenshots of the Event Subscriptions would be telling.

anne.hubitat · February 2, 2025, 11:43pm

Yes - or rather, it happened yesterday. That variable (Presence_somebody) became true yesterday afternoon (Feb 1) and did not change at the time the rule was triggered this morning (Feb 2).

Sure. For Presence_somebody, which is supposed to be the trigger:

And for Environment_need_lights, which is supposed to be a required condition:

(For the above, it usually changes programmatically a bit before sunset and a bit after sunrise, but this afternoon I manually set it
to true in order to let an automation set it to false to replicate the
conditions that has caused the misfire this morning.)

... and the condition was treated as a trigger.

bravenel · February 2, 2025, 11:47pm

For you rule to work correctly, it would need two Event Subscriptions, that would look like this (names changed to your two variables):

Please show yours.

anne.hubitat · February 2, 2025, 11:49pm

Hang on, working on that. The docs don't quite match the current appearance of the Apps page, but I think I've found what you're asking for. I will collect the info before and after doing "Update"...

bravenel · February 2, 2025, 11:51pm

Circle i

Screenshot 2025-02-02 at 4.50.53 PM

anne.hubitat · February 2, 2025, 11:54pm

Before:

After I hit "update" and "done":

No change, I'm afraid.

Let me try rebuilding the rule from scratch...

bravenel · February 2, 2025, 11:55pm

That's the bug that was introduced in 149, and fixed in 150. Odd that hitting Update doesn't fix it. But, yeah, rebuilding the rule should work.

anne.hubitat · February 3, 2025, 12:03am

I renamed the old one and disabled it. Here is the new rule, same as the old rule:

And its event subscriptions:

Still the same! What on earth?

Something occurs to me which may be related; I'll describe it in a separate message.

anne.hubitat · February 3, 2025, 12:08am

Not that it matters, but just FYI, in the upper corner of the page for a particular app, I see:
icons

The "circle i" icon appears down the right-hand side of the general Apps page. In any case, I did eventually find the info.

anne.hubitat · February 3, 2025, 12:28am

I deleted a hub variable a few days ago (I think on Jan 29) despite the Hubitat claiming that it was in use. Here's what happened: in a Room Lighting app which was created by automatic translation from another app ("Motion and Mode Lighting"), there was a section "Disable Activation upon these Events", with "Variable becomes true" checked off, and the now-removed variable mentioned.

I didn't want to do things that way, so I unchecked "Variable becomes true", and instead set up "Limit Activation under these Conditions", with "Variable is false", "Environment_need_lights". My now-removed variable was also mentioned in another place, where I also removed mention of it.

Then I wanted to clean up the unused Hub Variable, but the Hubitat claimed it was in use, by the very two rules I had just removed it from! I went back to the rules, and I remember what I did to the rule I am describing now: I re-enabled "Disable Activation upon these Events", I re-enabled "Variable becomes true", and the pull-down menu still had my old variable checked off! So I un-checked it, then I re-un-checked "Variable becomes true". IMHO that should have cleared the ghost from the machine. (I cleaned up the other location too, though I no longer remember what is was.)

But when I went back to Hub Variables to really clean up the unused variable, I was still told that it was in use by those same two rules! At that point I rather lost patience, I'm afraid, and told the hub to do remove the variable anyway, despite its dire warnings that I might break things.

Whether or not any of this is related, I have no idea, since I have no clue about the data structures that implement the connections between the rules and the variables. It just seems unlikely that even if I did throw something out of whack in the list of variables, even a newly-created rule (as I demonstrated in my previous posting) would suffer. You said that rule should result in two event subscriptions, and I see only one - that sounds like a different problem, but what do I know?!

Is there anything else I can look up which would help?