MSR UI on a mobile browser

[toggledbits]

None of the recent code changes to Hubitat would affect the performance of actions. The most notable of the changes was resolution of race condition during startup (when the Mode and HSM states are truly updated during startup), and not remotely close to the action implementation. All of the other changes are trivial, and again, not near the action implementation.

It would be easy to prove that the actions are being sent, if you want to run a more detailed test. The logging of actions on Hubitat is, and has been for some time, unconditional, so there will be (or not) evidence in the logs that the actions were sent to Hubitat. If you remove your recently-added delays and run like it was until it fails again, then peruse the logs, I'm pretty sure you'll find those actions were being attempted, at least. I strongly suspect they will be there. If not, there's a high chance we'll see another reason for why they are not.

This highlights, again, that reporting problems in the blind isn't useful. The logs are there for a reason. If something on the engine side isn't working as expected, it should be among the first places you look.

[gwp1]

Removed the delays I'd added and... everything ran just fine for the second night in a row (one with, one sans, the delays.). lol

[toggledbits]

Of course. The performance of the Hubitat and the mesh are also an issue here. It's a complex system with many variables.

[wmarcolin]

@toggledbits

I believe I am having a similar problem to the one discussed above, the perception that MSR is much faster than Hubitat.

I explain.

The MSR instantly receives everything that happens in Hubitat, any change of a device when it happens in Hubitat, immediately the MSR recognizes and if there is an action to be taken, immediately evaluates the action and fires the commands.

Then comes the problem, when the MSR triggers the actions for Hubitat devices, it loses actions, does not execute everything, hour an action is completed in all steps, hour fails. If I order to active 5 bulbs in sequence, almost always fails some, not always the same, varies on factors that I do not dominate.

And it doesn't need to have many actions, I have situations of quick reaction action as just turn on a light also failing.

Ok has the factor of the terrible signal from Hubitat (if compared to Vera), a bad management of the mesh network, where I see that the neighbours are poorly mapped and the mesh network poorly built.

But the failure scenario also happens with devices connected direct/next to the Hub.

In summary, the perception I have is that MSR is much faster than Hubitat that misses actions.

Include delay to each action would be a chaos, ok it can be a workaround, but it can't be the final solution.

Is it possible to have something in the configuration that creates the delay when sending each command to Hubitat? Like something like 0.5 seconds between actions?

I don't know if this would solve it, maybe you guys with more experience can point some way forward as the nightmare I had with Vera now happens on Hubitat.

Thanks.

[SweetGenius]

@wmarcolin said in [Solved] Is there a cap or max number of devices a Global Reaction should not exceed?:

Is it possible to have something in the configuration that creates the delay when sending each command to Hubitat? Like something like 0.5 seconds between actions?

As stated in this thread, He added pacing to Hubitat.
From the docs:
action_pace — sets the minimum delay between actions sent to the hub (i.e. when a Reaction includes many); sending large numbers of requests can overwhelm the hub, it has been found, so this attempts to slow the pace to avoid this issue. The value must be an integer greater than 0, and the units are milliseconds; the default is 25.

"the nightmare I had with Vera now happens on Hubitat" If the problem was present before then I doubt that this will solve it.

[wmarcolin]

@sweetgenius per your history above, by adding this delay to all actions, did it solve the problem? What time frame are you using? Did you leave the default at 25 milliseconds, or did you add more?

[SweetGenius]

@wmarcolin said in [Solved] Is there a cap or max number of devices a Global Reaction should not exceed?:

per your history above,

I do not have any history above, Its not my thread nor did I comment until I read your post. I just read the thread and release notes and pointed out that both mention pacing.

[wmarcolin]

@sweetgenius ops, thanks!

[wmarcolin]

@toggledbits hi master!

I am going into a state of despair with Hubitat, and thinking that I have made a bad switch from VeraPlus to Hubitat.

Well, as you always comment, look at the log, as I already commented my suspicion that the MSR sent all commands to Hubitat, and this one that failed was confirmed, as you mention in your message.

Routines below.

Looking at the log, I don't understand what sequence the MSR performed, but I see that all of the above actions were sent to Hubitat without fail.

[latest-21349]2021-12-17T01:46:57.319Z <Rule:NOTICE> Rule#rule-kx9oxcss configuration changed; reloading
[latest-21349]2021-12-17T01:46:57.321Z <Rule:NOTICE> Rule#rule-kx9oxcss stopping rule
[latest-21349]2021-12-17T01:46:57.324Z <Rule:NOTICE> Rule Rule#rule-kx9oxcss stopped
[latest-21349]2021-12-17T01:46:57.325Z <Rule:INFO> Rule#rule-kx9oxcss (nGarden) started
[latest-21349]2021-12-17T01:46:57.327Z <Rule:INFO> nGarden (Rule#rule-kx9oxcss) SET!
[latest-21349]2021-12-17T01:46:57.331Z <Engine:INFO> Enqueueing "nGarden<SET>" (rule-kx9oxcss:S)
[latest-21349]2021-12-17T01:46:57.345Z <Engine:NOTICE> Starting reaction nGarden<SET> (rule-kx9oxcss:S)
[latest-21349]2021-12-17T01:46:57.346Z <HubitatController:null> HubitatController#hubitat final action path for power_switch.on on Entity#hubitat>298: http://192.168.33.22/apps/api/67/devices/298/on
[latest-21349]2021-12-17T01:46:57.348Z <Engine:INFO> Enqueueing "nLight Garden ON" (re-kx65h5u7)
[latest-21349]2021-12-17T01:46:57.350Z <Engine:INFO> Enqueueing "nLight Security ON" (re-kx67amal)
[latest-21349]2021-12-17T01:46:57.352Z <Engine:INFO> Enqueueing "nLight Corredor Evening" (re-kx659j8a)
[latest-21349]2021-12-17T01:46:57.377Z <Engine:NOTICE> Resuming reaction nGarden<SET> (rule-kx9oxcss:S) from step 4
[latest-21349]2021-12-17T01:46:57.378Z <HubitatController:null> HubitatController#hubitat final action path for power_switch.on on Entity#hubitat>296: http://192.168.33.22/apps/api/67/devices/296/on
[latest-21349]2021-12-17T01:46:57.379Z <Engine:NOTICE> Starting reaction nLight Garden ON (re-kx65h5u7)
[latest-21349]2021-12-17T01:46:57.380Z <HubitatController:null> HubitatController#hubitat final action path for power_switch.on on Entity#hubitat>97: http://192.168.33.22/apps/api/67/devices/97/on
[latest-21349]2021-12-17T01:46:57.381Z <Engine:NOTICE> Starting reaction nLight Security ON (re-kx67amal)
[latest-21349]2021-12-17T01:46:57.382Z <HubitatController:null> HubitatController#hubitat final action path for power_switch.on on Entity#hubitat>197: http://192.168.33.22/apps/api/67/devices/197/on
[latest-21349]2021-12-17T01:46:57.383Z <Engine:NOTICE> Starting reaction nLight Corredor Evening (re-kx659j8a)
[latest-21349]2021-12-17T01:46:57.384Z <HubitatController:null> HubitatController#hubitat final action path for power_switch.on on Entity#hubitat>419: http://192.168.33.22/apps/api/67/devices/419/on
[latest-21349]2021-12-17T01:46:57.456Z <Engine:NOTICE> Resuming reaction nGarden<SET> (rule-kx9oxcss:S) from step 5
[latest-21349]2021-12-17T01:46:57.457Z <HubitatController:null> HubitatController#hubitat final action path for power_switch.on on Entity#hubitat>297: http://192.168.33.22/apps/api/67/devices/297/on
[latest-21349]2021-12-17T01:46:57.563Z <Engine:NOTICE> Resuming reaction nLight Garden ON (re-kx65h5u7) from step 1
[latest-21349]2021-12-17T01:46:57.564Z <HubitatController:null> HubitatController#hubitat final action path for power_switch.on on Entity#hubitat>162: http://192.168.33.22/apps/api/67/devices/162/on
[latest-21349]2021-12-17T01:46:57.673Z <Engine:NOTICE> Resuming reaction nLight Security ON (re-kx67amal) from step 1
[latest-21349]2021-12-17T01:46:57.674Z <HubitatController:null> HubitatController#hubitat final action path for power_switch.on on Entity#hubitat>229: http://192.168.33.22/apps/api/67/devices/229/on
[latest-21349]2021-12-17T01:46:57.782Z <Engine:NOTICE> Resuming reaction nLight Corredor Evening (re-kx659j8a) from step 1
[latest-21349]2021-12-17T01:46:57.784Z <Engine:NOTICE> nLight Corredor Evening delaying until 1639705619783<16/12/2021 20:46:59>
[latest-21349]2021-12-17T01:46:57.889Z <Engine:NOTICE> Resuming reaction nGarden<SET> (rule-kx9oxcss:S) from step 6
[latest-21349]2021-12-17T01:46:57.890Z <HubitatController:null> HubitatController#hubitat final action path for power_switch.on on Entity#hubitat>449: http://192.168.33.22/apps/api/67/devices/449/on
[latest-21349]2021-12-17T01:46:57.995Z <Engine:NOTICE> Resuming reaction nLight Garden ON (re-kx65h5u7) from step 2
[latest-21349]2021-12-17T01:46:57.996Z <HubitatController:null> HubitatController#hubitat final action path for power_switch.on on Entity#hubitat>385: http://192.168.33.22/apps/api/67/devices/385/on
[latest-21349]2021-12-17T01:46:58.106Z <Engine:NOTICE> Resuming reaction nLight Security ON (re-kx67amal) from step 2
[latest-21349]2021-12-17T01:46:58.106Z <Engine:INFO> nLight Security ON all actions completed.
[latest-21349]2021-12-17T01:46:58.214Z <Engine:NOTICE> Resuming reaction nGarden<SET> (rule-kx9oxcss:S) from step 7
[latest-21349]2021-12-17T01:46:58.215Z <Engine:INFO> nGarden<SET> all actions completed.
[latest-21349]2021-12-17T01:46:58.321Z <Engine:NOTICE> Resuming reaction nLight Garden ON (re-kx65h5u7) from step 3
[latest-21349]2021-12-17T01:46:58.322Z <Engine:INFO> nLight Garden ON all actions completed.
[latest-21349]2021-12-17T01:46:59.795Z <Engine:NOTICE> Resuming reaction nLight Corredor Evening (re-kx659j8a) from step 2
[latest-21349]2021-12-17T01:46:59.796Z <HubitatController:null> HubitatController#hubitat final action path for color_temperature.set on Entity#hubitat>419: http://192.168.33.22/apps/api/67/devices/419/setColorTemperature/2850
[latest-21349]2021-12-17T01:46:59.800Z <Engine:NOTICE> Resuming reaction nLight Corredor Evening (re-kx659j8a) from step 3
[latest-21349]2021-12-17T01:46:59.800Z <Engine:INFO> nLight Corredor Evening all actions completed.

I have checked each of the devices, all are in the log. I am even using the action_pace: 100 setting and I see that the interval was obeyed.

But out of 10 lights that should be on, as you can see on the Hubitat's panel only 2 were.

Sorry @toggledbits to ask, and I will understand if you don't answer because I see that the MSR is perfect.

Any recommendations for Hubitat? Reset the whole Z-wave radio and pair it again? Any APP that can check radio occupancy or Hubitat processing? Maybe you with your experience can give me some guidance, and again sorry, I know it is not MSR, but I'm almost back to the Vera with all its problems of drive and evolution.

[Crille]

@wmarcolin I don't have a Hubitat myself but have you looked at the logs on the hub per https://docs.hubitat.com/index.php?title=Logs for hints of what is happening when set reaction fires?

[gwp1]

@wmarcolin Something you've not surfaced, wireless interference. How close is your Hubitat to your WiFi router (they should not be near each other as they will interfere due to the frequencies in use), how close are your z-wave hubs to each other, etc.

Are all devices the kind that are plugged into electricity? I've discovered with some battery-operated devices that they sleep a lot to conserve battery and that delays actions. My iblind controllers are a perfect example: sending a refresh first and then the command seems to make them much happier regarding responding to commands.

As @toggledbits noted in a response to me previously in the thread (and you've supported), the mesh plays a huge role, too.

I had a Veralite and then moved to a VeraSecure. I've done direct comparisons between my VeraSecure and Hubitat using MSR to trigger the rules and the Hubitat was much faster. That, amongst other reasons, is why my VeraSecure is now completely offline.

[toggledbits]

@wmarcolin said in [Solved] Is there a cap or max number of devices a Global Reaction should not exceed?:

Looking at the log, I don't understand what sequence the MSR performed, but I see that all of the above actions were sent to Hubitat

Hmmm. I can't answer for the Hubitat part, but I explain the order. The first three actions in nGarden<SET> are Run Reaction, so these enqueue those reactions with the executive -- they are not run in-line. That's why you see the three "Enqueueing" lines, followed by a resume of nGarden<Set> from step 4. We see the action output for device 298, which is step 3 (numbered from 0), before the enqueue messages because enqueueing itself is an asynchronous operation, so the executive quickly started the three Run Reaction enqueue requests, then ran the device 298 Entity Action. Running an entity action is asynchronous, so the executive had to wait for that operation to finish. Since it went into a wait state, the tasks for the three Run Reaction enqueues could run, so they did. When they were done and the 298 device action was finished sending, nGarden<SET> could then resume from step 4 (numbered from 0, so 5 as we look at it). That's device 296 so we see that on the next line. Again, device actions have to wait for the send, so execution paused of nGarden<Set> paused there, which allowed nLight Garden ON, the first of the three enqueued reactions, to start and send its first command to device 97. That blocked that reaction, so nLight Security ON was next in the queue and it started and sent its first device action to 197. That blocked that reaction, so nLight Corredor Evening started and ran its first action against 419. It blocked, of course, so everything paused about 70ms until nGarden<Set> became the first ready task, so it resumed at step 5 (from 0, or 6 as we count from 1). And so on, until all were sent.

I'm not sure what your pacing configuration was at this point, but overall it appears about right for the number of tasks sent. It's hard to tell without more debug on, and maybe I'll add some "standard" messages about device queueing while we're looking at this (since debug on a Controller instance can be very large and a bit like sipping from a firehouse).

One thing to note also is that each Entity Action blocks while sending -- the reaction waits for the hub to acknowledge the request. For that to happen, the request must be sent, and the hub has to give an HTTP 200 (OK) response to the request (if it gives an error, that would be logged, and there are no errors logged in this snippet). So at the least, the hub has acknowledged the request, but that doesn't mean it has completed the request, let alone that the request was successful in its overall execution (e.g. manipulating the device). That's a different and much bigger problem.

I'm not done looking at this. I want to study the timing more carefully as well. There's something about it that doesn't seem right to me. As I said, I'm going to add some more standard (non-debug) diagnostic output to this while we're looking at it, and roll a new release later today, for you to try and send me new logs.

[wmarcolin]

@crille thanks for your comment, I will look at the log information. I think I even have to activate it, because so far nothing has shown up. Thanks for the information.

[wmarcolin]

@gwp1

Ok, as you can see from the picture, my Hubitat is next to my Asus router, where the Vera Plus used to be. In theory radio waves from the router should interfere with the Zigbee because both frequencies are in 2.4, and should not in any way interfere with the Hubitat that works at a frequency of 900 Mhz. But I'm trying everything, and I've already moved the Hubitat 2 meters away from the router.

The vera was already disconnected and I have also removed it and put it away, who knows, maybe in the future I will find some use for it.

With respect to your comment of battery devices, I understand, but it is not the case, as I mentioned above I tried to make a sequence of lights, the 6 devices are 4 Aeontec Micro Switch G2 (DSC26103), 1 Zipato Bulb 2, and another Everspring AN145, that is all connected to the electricity all the time. Your battery point is very valid, but it is not what has caused me panic.

Finally, your comment about Hubitat being faster than Vera is what I read everywhere, but unfortunately, this is not what is happening to me at the moment. Slow reactions, even using Hubitat's own dashboard commands it takes a while for the action to happen, so I go back to the mesh network issue above. Maybe now moving it can help.

But still remains the question of the lack of response to MSR at the same speed.

I will now read the post of @toggledbits to see what he comments.

Thank you very much for your attention.

[toggledbits]

Build 21351 just posted. This has a fix for a problem in the setup of the task queue for HubitatController that is likely causing it to not pace as expected. Let's give this a try, and in addition, try a few different values for action_pace. I would start from 25 and work up.

[wmarcolin]

@toggledbits once again thank you for your kind attention.

What depends on me to send log, do tests I am at your disposal. Just tell me what I should do that I will be promptly attending.

@gwp1 in a previous message I had informed that I had moved Hubitat 2 meters away from my central office, which has my Asus router, no-break, the modems of the internet providers. I have just radicalized, and now the Hubitat is more than 20 meters away and open space, well away from all this magnetic field and radio frequency of a possible interference, let's see if this helps communication.

So now it remains to investigate why the very fast MSR running on a dedicated notebook (Intel(R) Core(TM) i5-3320M CPU @ 2.60GHz 8Gb RAM, 300Gb SSD), maybe running over the Hubitat.

Thanks

[toggledbits]

@wmarcolin said in [Solved] Is there a cap or max number of devices a Global Reaction should not exceed?:

Just tell me what I should do that I will be promptly attending.

You are always helpful, and that's appreciated. For the moment, just run it as it comes. Let's see what happens. Start with a 25 for action_pace, and if you continue to have issues, move it up to 50. If 50 isn't enough, then I'll ask for logs. Let me know how it goes.

[wmarcolin]

@toggledbits

OK, changed action_pace to 25 (it was 100), and upgraded to build 21351.

[wmarcolin]

@toggledbits in this last upgrade process, I got these zombie processes. How is it possible to kill them? Thanks.

[toggledbits]

Stop Reactor. Then grab the reactor.log file and upload it to me. I'm going to DM you a link.

After you've uploaded the log file, remove the storage/states/reaction_queue.json file and restart Reactor.