Loss of device control over time

kvng · 2024-02-16 17:55:06 UTC

I have noticed pistons losing device control after months of operating correctly. The pistons are still running when triggered but when they go to make a change to a device, the change doesn’t happen. I can restore proper operation by editing the piston, making no changes and saving it. Rebooting the hub doesn’t seem to fix it. I’ve had it happen on multiple pistons and several different types of devices. I have about 100 devices and 50 pistons and I’m seeing this about once a month.

lflorack · 2024-02-16 21:58:34 UTC

I find that pausing and then un-pausing works for me. The question remains however. Why does it happen?

E_Sch · 2024-02-18 01:47:26 UTC

would need to see logs when the problem is happening.

would be good to also see if the device operates if you open the device page and do the commands work there.

lflorack · 2024-02-18 03:49:32 UTC

In my case, there is nothing in the logs at the times the webCoRE piston did not execute as programmed. This piston runs nightly to turn some lights off and has done so without fail previously. Also, the device operates as expected via the device page or the Hubitat dashboard.

I know that gives you absolutely nothing to work with, but just passing along the info. I’ll keep my eye out to see if I can find anything to help document this. It doesn’t happen often at all, so it may be a while.

kvng · 2024-02-18 15:07:19 UTC

The piston logs look normal. I’ve looked at Hubitat event logs for the affected device when this is happening. I see an entry indicating the command was sent to the device but I don’t see the acknowledgement from the device confirming the action. When I make the same change from the Hubitat web interface, the action works and both the command and acknowledgment are logged. I haven’t done screenshots but I will try to remember to do so next time this happens and post here.

E_Sch · 2024-02-18 20:00:08 UTC

anything in piston logs about command optimization being used?

kvng · 2024-02-19 15:55:24 UTC

Not in this case. I’ve seen that in other cases where weak communication causes the device state to be out of sync with the hub. This is resolved by toggling the device a time or two. Toggling doesn’t resolve this problem.

The command to change device state is sent to Hubitat and logged there but for some reason the device never properly receives it. Updates from the Hubitat GUI work properly so there’s nothing wrong with the device or communication to it. Perhaps WebCoRE is presenting a bad parameter value to Hubitat that makes its updates not work.

E_Sch · 2024-02-19 20:29:40 UTC

Would need to see some logs of either device, or webcore to show your hypothesis.

It should be able to see things from either side (webcore, or device handler) to see what is happening.

Given the 10s of thousands of pistons out there, there should be one side or the other to show what is going on. Things log pretty well in webcore and device handlers in hubitat to see commands called, etc.

kvng · 2024-02-20 02:23:36 UTC

I’ll post some logs next time it happens. It might be a couple of weeks.

lflorack · 2024-02-20 14:05:42 UTC

A similar event happened to me yesterday (19 February) morning. I normally keep webCoRE piston logging level set to ‘None’ once I complete writing and troubleshooting each piston - preferring to watch the log entries I intentionally have the piston post there. I know this limits what we can see from webCoRE, but it’s mostly not an issue. However, using the webCoRE piston code, webCoRE log, the device Event Log and the Hubitat Past logs will at least show some of the information sufficient to indicate an issue.

Background
This piston has been in place for years - initially on SmartThings and now on Hubitat. It has worked very well, even now. It’s just odd that it sometimes fails without a corresponding entry in the various logs.

Each morning, my outside front lights ((2) Carriage lights and (2) Front Door - all Z-wave dimmable) turn off and log the event, at @AMFrontStopTime which is randomized and pre-calculated earlier in the morning. Yesterday, @AMFrontStopTime was 07:47. I normally write some robustness into my pistons. Two minutes after @AMFrontStopTime (07:49 in this case), I test to see if any of the (4) lights are still on and if any are, the piston turns them off ‘again’ and logs that as a ‘warning’.

Code and Logs
Here’s the relevant portion of ‘Outside Front Lights’ piston (I can post the whole piston if desired):

And here’ the webCoRE log from that timeframe. Note that there is no entry for the initial turn-off at 07:47. Just the 2nd turn-off at 07:49:

Here’s the Front Door’s device event log from the same timeframe. Note that, again, there is no entry for 07:47:

Lastly, here’s the Hubitat log for the front door during the same timeframe. Again, no 07:47
entry:

What does all this show? I think that either webCoRE did not send a turn-off command at 07:47, or the hub didn’t receive it. It should be noted however, that sending on/off commands from the device page or dashboard work every time I’ve tested it.

kvng · 2024-02-20 15:46:58 UTC

The event log for the device may have additional information.

lflorack · 2024-02-20 16:05:35 UTC

I posted the Event Log for one of the lights involved above. It shows the same lack of any activity at 07:47 - but a succesful identical command at 07:49. Here it is again:

lflorack · 2024-02-20 16:16:18 UTC

An additional thing that I did not mention previously, is that I’m in the beta test and I’m using beta Firmware version: 2.3.8.119. it may have nothing to do with it, but it’s worth mentioning.

If you’re in the beta test group, it may be worth looking at this thread as it may be relevant:
[2.3.7] Anyone else having general z-wave flakiness? [C8]

kvng · 2024-02-20 17:43:05 UTC

Sorry I missed that. When things are working right (see below), you get a second event from the device acknowledging the command. That is missing in your event log. It is the failure mode I also see.

lflorack · 2024-02-20 17:56:54 UTC

I looked at the Hubitat log for all activity executed around 07:47 on the 19th - when the first attempt to turn the Outside Front Lights off was scheduled to happen. It appears that both the hub and webCoRE were busy at 07:47. My ‘Gloomy Lights’ Piston was switching off the (10) lights [(3) Z-wave on/off, (7) Zigbee dimmable] it controls. There was also an all-to-common Alexa error to deal with too.

I would have thought that this wouldn’t be an issue for the hub or webCoRE, but maybe it is.

lflorack · 2024-02-20 18:19:57 UTC

No problem.
That’s interesting. I did not notice that the device response was missing.

E_Sch · 2024-02-20 20:00:55 UTC

Interesting. I have the latest HE version.

I did find on 1 of my hubs after that update, that I had to shutdown the hub for several minutes after that update, to let the zwave network settle down. I left the hub powered off, then rebooted and things settled down.

Not sure what to make of it.

There has not been changes in webcore in these areas, will have to watch the logs and the scheduled times on the piston page (IDE or HE console-> apps -> gear icon next to piston in question to see subscription and timer events.)

E_Sch · 2024-02-20 20:14:15 UTC

I did hear they updated some more zwave libraries in recent releases…I had never had to power off to settle the zwave network before, but it did smooth things out for me.

lflorack · 2024-02-20 21:26:10 UTC

Hmm. I may try powering down, waiting and then restarting the hub to see if it makes a difference.

kvng · 2024-03-05 23:01:34 UTC

I continue to watch for this. I thought I had an example a few times but they seemed to recover by themselves. The most recent one, I could tell by log messages, had been broken for 7 days. I turned on piston logging to try to gather some information and that seems to have started it working again.