Errors after updating to MQTTController build 25139

[LibraSun]

As is my custom, I often create ungainly Rules designed to push the limits of MSR until some problem crops up (UI glitch, runtime error, faulty logic, etc.). I'm starting this topic - and sharing a cautionary example below - to invite MSR power users to embrace best practices in their routines.

[LibraSun]

Onward to my wayward example...

Most recently, I noticed this line in Reactor.log

Rule:WARN (Circulate House Air (auto)) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...

suggesting that I had an issue in my "Circulate House Air" rule that caused "flapping" -- uncontrolled or unexpectedly high rates of triggering -- which invoked MSR's automatic throttling (suppression) of that rule.

Because it's a fairly simple rule -- watch two Expressions (one a boolean, the other a calculated value from sensors), and check whether particular virtual switch is ON -- I was easily able to scrutinize its logic and layout.

Here were the essentials:

TRIGGERS

[ Expression Value ] [ tempVar ] [ > ] [ 2 ] // IF temperature variation exceeds a certain threshold (a rare occurrence!); Pulse for 10 sec., repeat every 1200 secs.

CONSTRAINTS

[ Expression Value ] [ modesMatch ] [ is TRUE ] // only when A/C and Vera show same House Mode setting for 10+ secs.
[ Entity Attribute ] [ VSwitch.status ] [ is TRUE ] // switch must also be ON

REACTION

[ Entity Action ] [ ACblower.power ] [ == ] [ 1 ] // turn on blower (auto-resets itself after 30 seconds)

EXPRESSIONS

tempVar := <mean deviation formula based on 4 sensors>
modesMatch := <TRUE when A/C house mode matches Vera's>

At first glance, all seemed well. Except MSR had expressly warned me (via the Log, at least) that something was amiss.

Speculating that it was simply the arrangement of items within TRIGGERS and CONSTRAINTS, I moved the "VSwitch" condition from Constraints up into Triggers, and the "tempVar" expression down into Constraints, then re-enabled the Rule.

Yet the throttling problem remains, according to the Log. While currently tempVar == 3, the VSwitch is OFF and modesMatch is FALSE -- that is, both Triggers and Constraints read 'false' -- so I would have thought it impossible for the Rule to be so active behind the scenes.

Any insights on this problem?

[LibraSun]

FEATURE REQUEST

Display each active Rule's current rate and/or display a warning in UI whenever Throttling occurs. (Probably already on the MSR roadmap)

[toggledbits]

If your log level is 5 or above for the rule in question, you will see messages logged like this:

2021-03-15T15:21:07.639Z <Rule:5:Rule.js:444> {ruleid} notification {type} {data} from {sender}

So this will tell you what is triggering the request for re-evaluation.

If you didn't know, you can set the logging level (in config/logging.yaml) for a particular rule, so it's useful to set the generic level (level entry under Rule:) to 4 to keep other rules quiet, and then create a new entry with key Rule#ruleid: and subkey level set to 5 or whatever. This will focus the detailed debug output on the single rule and hold the noise down from the stuff you're not as interested in.

logging:
  ... other stuff ...
  Rule:
    level: 4
  Rule#rule-f984r5nfe
    level: 5

[LibraSun]

So far, with the default logging level of 4 set in LOGGING.YAML, I merely see these not-so-illustrative entries immediately before the <WARN> line:

2021-03-15T15:34:34.150Z <Rule:5:Rule.js:800> Rule#rule-km9hxs0z (Circulate House Air (auto)) evaluate() acquiring mutex

2021-03-15T15:34:34.150Z <Rule:5:Rule.js:804> Rule#rule-km9hxs0z._evaluate() mutex acquired, evaluating

2021-03-15T15:34:34.151Z <Rule:5:Rule.js:808> Rule#rule-km9hxs0z update rate is 61/min limit 60/min

I'll proceed to try higher level inspection (by altering the level: for this Rule only) later today, and see what specifically turns up. For now, I have the Rule disabled.

[toggledbits]

Do not (ever) change the default logging level. Only change the logging level for the specific Rule and Rule#rule-id classes.