[Resolved] Hubitat upgrade 2.5.3.123 may have broken login

[therealdb]

@gwp1 I’m 110% sure I’m on the latest version, since it’s reported at the top.

[wmarcolin]

@gwp1 @Alan_F and @therealdb

Trying to collaborate with the discussion, what I have seen is that actions that occur during the update process, ie if I turn on or off some switch, or if there was an action in progress and I perform the update the state of the action would end during the update, this action remains activated and switch with old status. In other words, it seems to me that maybe there has to be something that downloads all the actions, performs the update, and then when restarting with the new version restarts the actions. Or also take the updated status of the devices.

In theory that's what MSR does, that's what I see in the logs, but my feeling is that again we come back to the issue that MSR is much faster than Hubitar and things get left behind when rebooting. When we manually reload an action, or turn a switch on or off, we do a manual re-sync.

My suggestion is on the next update, we have to watch the ongoing actions that are paused and the status of devices, perform the upgrade, look at the log when it returns and try to create some consistency in this eventual problem scenario.

[toggledbits]

@alan_f said in [SOLVED] Expressions not auto-updating when dependencies change (22022):

Probably unrelated to the updates, but I had a rare misfire this morning where Reactor didn't see a switch thrown on my Hubitat hub. I turned on a virtual switch via a Hubitat dashboard. That switch being on should start a reaction to set my Thermostat to daytime settings. The switch turns off automatically 5 seconds later. The MSR logs don't show the switch turning on (or off) the first time I clicked it, but the Hubitat dashboard showed it in an 'on' state for 5 seconds.

Do you have the community Hub Information app installed, with a device created for it?

[Alan_F]

@toggledbits Yes, I have the hub information app and I see the data from it in MSR and Influx.

[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