Why would an action become very slow?

william.cage · January 9, 2021, 4:22pm

I have been using hubitat for about a year. Nothing fancy. All told right now, I have 3 smart switches, a couple of smart locks, a motion detector, and a magnetic door switch. Everything has been working as expected up until the last couple of months.

The magnetic door switch is used to detect when the pantry door has been opened and it turns on the light using a smart switch. Similarly it turns it off when the door is closed. It has worked perfectly for many months until recently. Now, it takes 10-20 seconds for the light to turn on or off. No hardware has been added, removed, or changed on the network. It is very puzzling to me.

I looked at the logs to see if that would help and what I am seeing is that everything is happening immediately up to the action to turn on the light, then time elapses before the light turns on (see the log snippet below).

I can use the switch directly and it is responsive as expected. I can use the icon on the dashboard to turn the light on and off and it is immediate. It is only when it is being turned on through the app.

I have changed the batteries in the magnetic switch. The hubitat itself is up-to-date. I moved the hubitat hub to a position that is much closer to the pantry (about 10 feet away now) and I have done a z-wave repair.

Does anyone have any suggestions for how to troubleshoot this?

Log file snippet. Starts at the bottom. Notice that everything happens in milliseconds until the last step of actually having the light turn on. In this case, it took 9 seconds. Until recently, it was basically immediate.

[dev:98]2021-01-09 09:52:47.176 am [info]Pantry Light Switch was turned on [digital]

[app:161]2021-01-09 09:52:38.475 am [info]Action: On: Pantry Light Switch

[app:161]2021-01-09 09:52:38.454 am [info]Pantry Light - Turn On Triggered

[app:161]2021-01-09 09:52:38.447 am [info]Pantry Light - Turn On: PantryDoor contact open

[dev:161]2021-01-09 09:52:38.384 am [info]PantryDoor was opened

--- Live Log Started, waiting for events ---

Sebastien · January 9, 2021, 4:33pm

Out of curiosity, have you tried recreating the rule and disabling the original?

And Welcome to the community!

william.cage · January 9, 2021, 4:35pm

Nope, but I will do that now. Thanks for the suggestion.

bobbles · January 9, 2021, 4:36pm

If your problem persists after defining a new rule you could try a reboot of the hub.

Sebastien · January 9, 2021, 4:41pm

And if the reboot doesn't help, try backing up your hub, saving the backup locally and then restoring the local copy. This can resolve some database corruption issues.

william.cage · January 9, 2021, 4:47pm

Ok, I removed the rules (on and off) and recreated them. Same result. The logging is a little different; I guess I didn't set the log rules the same when I recreated, but you can see in the log snippet below it did not improve the situation; this time it was 9 seconds to turn on and 13 seconds to turn off.

[dev:98]2021-01-09 10:42:23.480 am [info]Pantry Light Switch is off [physical]
[dev:98]2021-01-09 10:42:23.427 am [info]Pantry Light Switch was turned off [digital]
[dev:161]2021-01-09 10:42:10.638 am [info]PantryDoor was closed
[dev:161]2021-01-09 10:42:10.634 am [info]PantryDoor was closed

[dev:98]2021-01-09 10:40:09.040 am [info]Pantry Light Switch was turned on [digital]
[dev:161]2021-01-09 10:40:00.148 am [info]PantryDoor was opened

william.cage · January 9, 2021, 4:49pm

Thanks for helping out. I have rebooted the hub several times and actually shut it down to move it to a location closer to the switch. That did not solve it.

william.cage · January 9, 2021, 4:49pm

OK. I will give this a try now.

william.cage · January 9, 2021, 5:04pm

I did a backup and restore of the hub. That process caused the hub to perform a restart also. My results did not change (9 seconds for on, 10 seconds for off).

Is there a way to trouble shoot to see where the delay is? The log indicates that the initial trigger is occurring as expected. The logic within the app is fine up to the action. Then there is the delay. How do I determine if it is the actual action step in the app, the transmission of the command to the switch over z-wave, or the switch itself that is causing the delay?

Since no hardware has changed, the only changes introduced into the system over this time are updates to the hub software. I can imagine that these updates could involve any of the 3 areas where the delay might be introduced. I am at a loss for how to troubleshoot this. I do appreciate everyone's suggestions.

william.cage · January 9, 2021, 5:18pm

OK, I enabled debugging at the switch. The log results are below. This seems to indicate that the switch itself is responding quickly. I may be reading too much into this log output, but for now, It makes me think that the delay is either at the app issuing the command or the transmission of the command over z-wave. Any opinions on this?

[dev:98]2021-01-09 11:11:07.720 am [info]Pantry Light Switch is off [physical]
[dev:98]2021-01-09 11:11:07.708 am [debug]parse description: zw device: 0B, command: 2503, payload: 00 , isMulticast: false
[dev:98]2021-01-09 11:11:07.656 am [info]Pantry Light Switch was turned off [digital]
[dev:98]2021-01-09 11:11:07.651 am [debug]parse description: zw device: 0B, command: 2503, payload: 00 , isMulticast: false
[dev:161]2021-01-09 11:10:54.863 am [info]PantryDoor was closed

Sebastien · January 9, 2021, 5:30pm

Are both the sensor ans switch Z-Wave?

Can you provide a screenshot of the rule you are using?

william.cage · January 9, 2021, 5:36pm

OK. Just trying to narrow down where the problem might be. I added another action to the rule to notify that the it was turning off. I am assuming that the actions are run in order. It is interesting that I get the notification on my phone well before the actual completion of turning off the light. The log reflects what is being seen in reality; the message hits my phone almost immediately, the light (in this instance) turns off after 12 seconds.

dev:982021-01-09 11:27:09.925 am infoPantry Light Switch was turned off [digital]
dev:982021-01-09 11:27:09.915 am debugparse description: zw device: 0B, command: 2503, payload: 00 , isMulticast: false
dev:982021-01-09 11:27:09.881 am debugparse description: zw device: 0B, command: 2503, payload: 00 , isMulticast: false
app:2912021-01-09 11:26:57.312 am infoAction: Notify SM-G975U: 'Light off'
app:2912021-01-09 11:26:57.296 am infoAction: Off: Pantry Light Switch
app:2912021-01-09 11:26:57.274 am infoPantry Light Off Triggered
app:2912021-01-09 11:26:57.251 am infoPantry Light Off: PantryDoor contact closed
dev:1612021-01-09 11:26:57.138 am infoPantryDoor was closed

william.cage · January 9, 2021, 5:41pm

william.cage · January 9, 2021, 5:42pm

Sebastien · January 9, 2021, 5:47pm

Could you try creating the rule in the Simple Automation App instead of Rule Machine? I don’t think it will make a difference, but just in case...

You can confirm that when you toggle it from your phone through the app, it is still instantaneous?

william.cage · January 9, 2021, 6:01pm

I will give that a shot, but I found an interesting thing (to me) by playing around. I have another switch that controls the driveway lights. For grins, I created another rule that would use the pantry door trigger to turn on the driveway. Now there are two independent rules, both using the contact switch to cause action on two different switches. When I open the contact switch, both light switches turn on simultaneously, both of them delayed.

To me, that eliminates the structure of the rules themselves. The fact that the notification action that I was playing with before occurs quickly, as expected seems to indicate that the communication over z-wave is not the issue. I am leaning toward the driver for the switch itself being the issue.

Let me try your suggestion, but I am curious if you think my troubleshooting logic holds water.

william.cage · January 9, 2021, 6:08pm

I created the 'Simple Automation Rule' that turns the light on/off. I get the same delay. I can confirm that when I use the dashboard (from the phone or the computer) I get instantaneous response.

Sebastien · January 9, 2021, 6:14pm

I think you have done some really good troubleshooting. The only problem is that you seem to have eliminated all the potential causes... but obviously there must be something that we are missing since you are still seeing a delay when the switch is triggered by the rule.

Tagging @bobbyD in case there is something that he can see that I can’t.

Hub Issue - Rebooting, unplugging the hub to move it and finally restoring the backup would have dealt with this.
Rule Issue - The message goes to your phone immediately where the switch is delayed. You also re-created the rule in RM and then created it in Simple Rule and are getting the same result. It is a very simple rule, so there should be no issue there.
Driver Issue - I assume the driver is okay since it works with the Dashboard. Could you confirm which one you are using, just in case? When you toggle the switch via the device page, does it react immediately and does the status update as soon as it changes? (I expect it does since it reacts immediately with the dashboard...)
Z-Wave Issue - When you toggle the switch via the app, it toggles immediately, so the Z-Wave signal should be good... Typically, to resolve Z-Wave issues, the hub is shut down and unplugged at the wall outlet and left to rest for a couple minutes before powering it back on. Moving the hub would have accomplished this...
Switch issue - When you toggle the switch, it reacts immediately.

I am stumped... Though extremely curious as to what we are missing!

william.cage · January 9, 2021, 6:23pm

Just to blow my last thought out of the water, I changed the switch driver from GE Enbrighten Z-Wave Smart Switch to Generic Z-Wave Smart Switch to see if I could pin it to the driver. No luck. Same delay. Unless the driver code is actually the same, that would rule out the driver.

It is interesting that it is consistent across switches and rules. That seems to point to driver. Also, it worked like a charm for almost a year and only recently started this. The only difference on my system are changes introduced through hub updates. No new smart devices, no changes to rules (other than now for troubleshooting).

My experience is that the tougher it is to figure out, the simpler the cause turns out to be. Something dumb usually, but I have to admit that I am running out of ideas for how to narrow down the possible cause.

I do appreciate your help on this though.

Sebastien · January 9, 2021, 6:25pm

Do you know how to revert to a previous version of the hub? That would eliminate or confirm this one...