Error: Command timeout

[wmarcolin]

Hi Patrick! @toggledbits

I don't remember before version 21277 receiving this kind of message.

This is in the log, this warning appears hundreds of times, every 1 second it repeats.

[latest-21281]2021-10-10T16:13:46.107Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-10T16:13:46.482Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-10T16:13:46.835Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...

As you can see, the rule that has generated this warning is run on demand at 10am, where the information is loaded into local variables, and then I use it to send the information by Telegram, only once a day.

I started using this matchEntities() instruction recently when it was made available, and I see you have been making recent adjustments. Wouldn't this situation of continuing to evaluate be related?

I will turn the rule off, so as not to generate this situation that surely damages the functioning of the MSR, and I look forward to your comments please.

Thanks

[toggledbits]

Update to 21281. It would be great if everyone would make sure they are on the latest release before reporting problems.

[wmarcolin]

@toggledbits master I am already with version 21281, the error started at 21277.

[toggledbits]

Sigh. Sorry, I'm running fast today... way too fast, much on my plate.

So looking at what you've done... I would not do it this way. Put those expressions in the variables they are meant to manipulate.

Also, your matchEntities() for BatterySensor, you should not include level. That is an attribute of the capability battery_power, and since we're matching capabilities, it won't match anything and creates needless work. You can list capabilities here, but not attributes. All attributes of the capability come with the capability. Same for FaultSensor: remove failed; it's an attribute, not a capability.

And please, when posting log snippets, showing me just the error is one line away from showing me nothing. I need to see several dozen lines from before the error for context.

[wmarcolin]

@toggledbits master, as you instructed, I believe this is the correct way to do it, and apparently, the error is gone.

Thanks!

[toggledbits]

LOL! OK. Yes, this is better structure-wise. It is much less efficient to use SetVariable to accomplish what is effectively the same as putting the expressions on the variables as you have now done.

I did replicate your prior structure on my system to try it out, but I was unable to replicate the throttling. Nonetheless, I think I understand why it would have happened... and I'm guessing you have significantly more devices on your system than I have on my development system (maybe, I've got about 100 across the four hubs I use for development). I can see why it would throttle, I just could not make it do it. Nonetheless, I'm going to see what I can do about preventing it, based on my assumption about how it happened for you.

Another thing... mentioned in another thread is a small step up you could take in efficiency in BatteryMSG: you are doing getEntity() twice on the same ID. You can improve on that by using a temporary variable inside the loop to store the getEntity() result, and use that temporary variable in the string assembly:

join( each id in BatteryLow: do
    e = getEntity( id ),
    e.name + " " + int( e.attributes.battery_power.level * 100 ) + "%"
done, ', ' )

The do...done block looks like a single expression to each. The result of a do...done block is the result of the last expression executed within it. That block contains two expressions, the first being the e = getEntity() which does the lookup and stores the value in a temporary variable, and the second which uses the temporary variable to build the result string for the entity. This saves you the cycles looking up the same entity twice.

[wmarcolin]

@toggledbits hi my friend!

The warning message has appeared again.

Looking at the log, it is not an error, this message appears several times intermittently, only being interrupted when another action occurs.

[latest-21281]2021-10-12T13:30:35.222Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T13:32:10.561Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T13:32:10.695Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T13:32:11.054Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T13:32:12.810Z Rule:INFO Internal Motion (Rule#rule-kpq9tnbr) SET!
[latest-21281]2021-10-12T13:32:22.152Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T13:33:15.364Z Rule:INFO Internal Motion (Rule#rule-kpq9tnbr) RESET!
[latest-21281]2021-10-12T13:33:55.112Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T13:34:29.630Z Rule:INFO Internal Motion (Rule#rule-kpq9tnbr) SET!
[latest-21281]2021-10-12T13:35:27.808Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T13:35:40.960Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T13:35:41.809Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T13:35:50.185Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...

Here is another cut of the log, 45 minutes later the warnings follow.

[latest-21281]2021-10-12T14:16:04.876Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T14:16:05.201Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...
[latest-21281]2021-10-12T14:16:05.389Z Rule:WARN Rule#rule-ku32lfti (Warning (93) Devices) update rate 61/min exceeds limit (60/min)! Logic loop? Throttling...

I will stop the task again, I am concerned, even though a safe warning is consuming MSR processing.

A topic that catches my attention. The action is scheduled to run on my schedule from 8:00am to 8:05am (-5), and because it is a local variable, it should not be updated outside this time, is my understanding.

If it is a global variable, the update is recurrent, because it is active 24 hours, now why is an action with a defined time, and local variable still being executed in a loop?

[toggledbits]

@wmarcolin said in Logic loop? Throttling...:

A topic that catches my attention. The action is scheduled to run on my schedule from 8:00am to 8:05am (-5), and because it is a local variable, it should not be updated outside this time, is my understanding.

That's incorrect. Any changes to a watched device will cause the rule to re-evaluate. The first step in re-evaluating the rule is re-evaluating all of the rule's expressions; only after that are the conditions then evaluated, because the conditions may reference the rule's variables. This is documented behavior. So given that you may be doing a getEntity() on several dozen, or hundred, devices, you are making that rule subject to re-evaluation any time any of those devices changes, for any reason. Reactor does not "see through" to the attribute you are eventually referring to; it does not and could not (reasonably) do that.

To reduce the evaluation rate of the rule, you'd have to make your expressions global. There is (currently) no throttling on the evaluation of global expressions, and they evaluate/update much faster than rules. I suggest you move all of your expressions that perform getEntity() on the result of matchEntities() into global expressions; specifically, I mean BatterySensor which creates the battery-operated device array, and BatteryLow which checks and evaluates (using getEntity()) the battery level of each matching device in BatterySensor, and BatteryMSG which builds the text from BatteryLow. You can then use an Expression Value condition in your rule to check the value of BatteryMSG for a non-empty string. This will be the most efficient setup for the potentially large number of devices these expressions have to sift through.

The same method should be applied to FaultSensor and its progeny.

I would also update to 21286.

[wmarcolin]

@toggledbits ok master, I will download version 21286, move these expressions to global variables, and come back tomorrow after operating 24 hours with the changes.

I really worry about not having actions that are exhaustively generating processing.

[toggledbits]

When you train a rule or expression on a large number of devices, you're going to get activity when those devices change, and that can be a lot. There's more activity than you know, normally. Not everything gets logged at the default level. 21286 does contain a bit more logging.

[wmarcolin]

@toggledbits your suggestion worked perfectly!!

With the version updated to 21286, moving all rules to the Global variable, the warnings ended, and I can see in the log that the action started to be invoked only at the given times, and the variable update as Global occurs only when there is an effective change in the device.

Great knowledge exercise and one more lesson from you.

Thanks @toggledbits !