[Reactor] Variables not updating correctly in latest-25201-2aa18550

[Alan_F]

Had the same issue with the same switch last night. Google assistant turns the virtual switch on. The Hubitat turns it off 5 seconds later. Reactor should see the switch on and initiate the night thermostat and lights-off actions. The logs on the Hubitat show the switch turned on, but Reactor missed it. On a second attempt, Reactor reacted. I definitely notice if this reaction fails, as the lights in the bedroom don't turn out. I can't remember any failures prior to version 22021. I haven't made any changes to the default settings related to the communications with Hubitat, but I was under the impression that those related to ensuring that MSR didn't hit Hubitat with too many commands at once, so I'm not sure they would have any relationship to MSR not receiving an entity update from Hubitat.

[toggledbits]

In logging.yaml, turn up the logging on HubitatController by adding a section like that shown below. Indent the HubitatController: line like the other items already in the file. If HubitatController: is already in the file, just modify it as shown. Then restart Reactor. Capture the log file (name shown below) the next time this happens (make sure the time range in the file includes the time range of the miss). I will need the entire log without redaction, the time of the (non-)event, and your timezone. I'll give you a safe place to post the log when you have it.

Do not take any corrective actions. At least, don't do anything for at least 5 minutes. Then you can fix whatever should have happened. But leave it alone at least 5 minutes after the expected event.

  HubitatController:
    level: 5
    streams:
      - type: file
        name: hubitat.log
        keep: 2
        level: 999

[Alan_F]

Done. At the rate it's been going I'd expect it to be at least a few days before I get anything.

I am connected to two Hubitat devices... one at my house and one at my parents' house. If there is a way to filter by name should I have it only do the detailed logs for one to keep the log size more manageable?

If I get a misfire, will I need to pull the logs right away (after the 5 minute wait to re-issue the command) before they get overwritten? Since this happens at bedtime my wife would probably be happier if I wait until morning to pull the logs... she already won't be super happy with the 5 minute wait to turn out the lights. But it wouldn't be the first time I got out of bed to go to the computer and troubleshoot home automation

[toggledbits]

You should have plenty of time before the logs rotate away. If in doubt, up the keep value to something higher, maybe even 10. How much it logs really depends on your system activity. Just to be safe, also remove the recycle: true line (starts a new log on every Reactor restart -- don't need that, maybe don't want that).

To limit the log to just the one unit, make the HubitatController: line read "HubitatController#id":, where id is the ID you assigned to it in your config. I always quote when introducing special characters.

[Alan_F]

Ok. Currently I have log from 14:47 hours at 1.3 MB, log.1 from 1411 hours at 2 MB, and log.2 from 13:31 hours at 2 MB, so it looks like I'm getting about 40 minutes per log file. I'll bump up the keep value and filter to just the one device id to make sure they persist until morning.

[toggledbits]

You can also add maxsize: n where n is an integer number of megabytes (default 2) before the log file rotates. Same indent level as keep.

[Alan_F]

@toggledbits So it took quite a while to capture a missed reaction, but I had one this morning. The Hubitat log shows a switch turn on twice. The (virtual) switch is set to auto-off in Hubitat. The reactor log shows the reaction only fired the second time the switch was turned on. What's the best way to send you the logs?

[toggledbits]

PM'd link and instructions.

[toggledbits]

@alan_f OK. I've looked at the logs. Here's what I see going on:

1. At 11:57:56.126Z, Reactor, specifically HubitatController receives an event from the hub on the events websocket for device 519 switch state changing to on (your virtual switch).
2. 7ms later, HubitatController enqueues a request to the hub's Maker API for a full device update. This is an asynchronous operation done in response to the received event.
3. 1ms later (now 11:57:56.134Z) the device update request is made via HTTP to the hub.
4. At 11:58:01.134Z, HubitatController receives another update event on the websocket for the switch returning to off.
5. Over the next 3ms, steps 2 and 3 above repeat for the new event as expected.

What's not here in this timing is the response from Hubitat to the query to Maker API between steps 3 and 4. We would have had to have log level 6 to confirm it, but it appears from what we do have here that Maker API did not respond to the HTTP request within the 5 second timing of the switch reset. That is, by the time Maker API got around to responding with the full state of the switch, the switch had already gone back to off state, so Reactor saw no change. For whatever reason, the hub was busy and didn't respond within 5 seconds, which is a bit alarming, actually.

HubitatController uses the full update, rather than acting piecewise to the event and its single value, because some attributes are driven by multiple values from the device, and it needs all of the values together to correctly ascertain the target attribute values on the entity.

I see two immediate solutions for this:

1. Increase the timing of the reset of your virtual switch at the hub. Go to 10 or 15 seconds. If the hub doesn't respond within that window, it needs to be examined more closely.
2. Don't automatically reset the virtual switch on the hub, do it in the Reactor rule that responds to the switch change. This will be more reliable than #1 because it removes the effect of latency... it will not matter how long it takes the hub to respond, when Reactor sees the change, it will reset the switch and (maybe) perform the other actions. Your trigger remains the switch state, but alone; your other conditions can go into a conditioned action group in the SET reaction of the rule with the action to modify the thermostat.

I will take a second look at HubitatController to see if I can remove the need for the additional query, but at the time it was written, it seemed necessary given the limited data in the event from the websocket.

[Alan_F]

Option 2 seems like the way to go. I'll make that change and wait for nothing to happen