Wait for Expression rule fails to finish - bug or bad rule?

[Alan_F]

I have a rule that uses a 'wait for expression' that seemed to silently fail today. The rule usually works, but a few minutes ago the rule logged the 'wait for expresson' line and then nothing after that.

The rule is used to adjust the power reserve of my home batteries when there is high power draw. (I don't want to draw down the batteries when charging my cars or using high draw appliances if the grid is available).

The two criteria are that either my clothes dryer is reporting that it is drying OR the house load is > 5 kW. Once it fires, the reset requires both the dryer to NOT be drying and the house load to be < 5 kW for a duration of 1 minute.

To prevent multiple activation of the rule, I use a hub variable ("powerwall_load_rule") that I set to false when the rule runs the first time and only set back to true when the rule has completed its 'wait for expression' process. Since the rule will be triggered everytime the house load changes, the first action is to exit the rule if the variable is false, since that means there is already an instance of the rule in progress.

I use required expressions to not run the rule when the reserve level is already 100% nor when the battery is already below its reserve level, since in either of those cases, I would already be on grid power.

Here is the rule:

Here are the logs from the failure (newest at the top). I have it set to log actions but not triggers:

app:943 2023-07-04 13:24:34.700 info Action: Wait for Expression: Dryer currentState(power off) ≠ drying(T) AND
Power level of Powerwall - Home Power(5863) < 5000.0(F) [FALSE] --> duration: 0:01:00 (waiting for Expression to be true)
app:943 2023-07-04 13:24:34.537 info Action: Dim: Powerwall: 100
app:943 2023-07-04 13:24:34.525 info Action: Set powerwall_load_rule to false
app:943 2023-07-04 13:24:34.512 info Action: ELSE (do actions)
app:943 2023-07-04 13:24:34.509 info Action: Exit Rule (skipped)
app:943 2023-07-04 13:24:34.506 info Action: IF (Variable powerwall_load_rule(true) = false(F) [FALSE]) THEN (skipping)

The previous time it ran it looked like this:

app:943 2023-07-04 08:46:34.616 info Action: END-IF
app:943 2023-07-04 08:46:34.605 info Action: Set powerwall_load_rule to true
app:943 2023-07-04 08:46:34.542 info Action: Dim: Powerwall: powerwall_reserve_level(30)
app:943 2023-07-04 08:46:34.487 info Wait over: duration
app:943 2023-07-04 08:46:34.441 info Expression still true: power is 1661, still waiting for 0:00:00
app:943 2023-07-04 08:45:34.487 info Expression now true: Powerwall - Home Power power is 1675, waiting for duration 0:01:00
app:943 2023-07-04 08:44:34.411 info Expression now false: power is 8941, waiting for Expression to be true
app:943 2023-07-04 08:43:40.825 info Expression now false: power is 9120, waiting for Expression to be true
app:943 2023-07-04 08:43:34.599 info Action: Wait for Expression: Dryer currentState(power off) ≠ drying(T) AND
Power level of Powerwall - Home Power(9099) < 5000.0(F) [FALSE] --> duration: 0:01:00 (waiting for Expression to be true)
app:943 2023-07-04 08:43:34.414 info Action: Dim: Powerwall: 100
app:943 2023-07-04 08:43:34.402 info Action: Set powerwall_load_rule to false
app:943 2023-07-04 08:43:34.389 info Action: ELSE (do actions)
app:943 2023-07-04 08:43:34.387 info Action: Exit Rule (skipped)
app:943 2023-07-04 08:43:34.384 info Action: IF (Variable powerwall_load_rule(true) = false(F) [FALSE]) THEN (skipping)

That is the expected behavior. I didn't modify the rule between the time it worked and the time it failed, so I think this may be a bug in Rule Machine.

Here is something else odd that I noticed. The rule currently shows this:

Looking through the logs, the value 9099 was from the activation at 08:43 today. The latest activation shows the home power was 5863 at 13:24. Why does the Local Variables section still show the 9099 value?

[FriedCheese2006]

The "failure" looks like the load did not stay above 5kw or the dryer status did not stay for the duration so the expression was never satisfied. Hard to say for sure though without the device logs to go with the app.

Small tweak suggestion, move your variable to being a required expression.

[Alan_F]

Either I didn't explain correctly or I don't understand your response. The condition that needs to be satisfied for 1 minute is the dryer is not drying (it was not) and the power stays below 5 kW. The power definitely dropped below 5kW and stayed there. In the successful run it kept logging the revaluations of the conditions. On the failed one it never revaluated. It should have either logged "expression not true" or "expression is true, waiting for 1 minute to pass" as it did the successful time.

Good point on the variable. I think I can actually remove it entirely, as the "level not =100" serves the same purpose. Once the rule sets the dim level to 100, it won't re-trigger until it returns to a lower value due to that required expression.

[FriedCheese2006]

I had a neurological bit flip.

I meant to say that, to your point, the rule didn't see the power change. My second sentence still stands. It's hard to say for sure whether or not the app stopping there was correct without the device logs to show that the attribute values actually updated for the device.

In the successful logs, the evaluation happens again because the app was seeing updates for the device.

[Alan_F]

The device doesn't record anything in the log even though I have that option turned on (I'll have to bring that to the attention of the community app developer) but I can see that the value has changed since then. So as long as it changed at some point after 2023-07-04 13:24:34.700, the rule should have reacted to that, whether that was minutes later or hours later. It still seems like Rule Machine just glitched here.

I simplified the rule so it no longer has the if/then conditional statement or the variable. Now it just sets the dim level, waits for the expression to be true for 1 minute, and resets the dim level.

Any suggestions for things I can check if it happens again? I'm going to turn on all logging for this rule, instead of just Actions, in case that helps figure things out.

[FriedCheese2006]

Even without logging, you can check the "events" from the device page. Those are really what represents what the app should see.

[Alan_F]

Thanks. Exactly what I was looking for. I also managed to tweak the device driver to add logging on each value change, and I can see the values changing once per minute in either place.