Toggle flips back to off when turning a switch on in HASS

firix · May 1, 2020, 8:16pm

Hello everyone,

I have a problem with one of my Z-Wave switches. It’s Zooz Zen26 and what’s going on is when I switch it on in HASS, the toggle flips back to off almost immediately and stays off forever (while the light actually stays on).

Here’s the chunk of the OZW log that seems to be relevant:

2020-05-01 09:28:36.773 Info, Node008, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
2020-05-01 09:28:36.773 Info, Node008, SwitchBinary::Set - Setting node 8 to On
2020-05-01 09:28:36.773 Detail, Node008, Queuing (Send) SwitchBinaryCmd_Set (Node=8): 0x01, 0x0a, 0x00, 0x13, 0x08, 0x03, 0x25, 0x01, 0xff, 0x25, 0x41, 0x52
2020-05-01 09:28:36.774 Detail, Node008, Queuing (Send) SwitchBinaryCmd_Get (Node=8): 0x01, 0x09, 0x00, 0x13, 0x08, 0x02, 0x25, 0x02, 0x25, 0x42, 0xaf
2020-05-01 09:28:36.774 Detail,
2020-05-01 09:28:36.774 Info, Node008, Sending (Send) message (Callback ID=0x41, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=8): 0x01, 0x0a, 0x00, 0x13,
0x08, 0x03, 0x25, 0x01, 0xff, 0x25, 0x41, 0x52
2020-05-01 09:28:36.899 Detail, Node008,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-05-01 09:28:36.899 Detail, Node008,   ZW_SEND_DATA delivered to Z-Wave stack
2020-05-01 09:28:36.943 Detail, Node008,   Received: 0x01, 0x07, 0x00, 0x13, 0x41, 0x00, 0x00, 0x11, 0xbb
2020-05-01 09:28:36.943 Detail, Node008,   ZW_SEND_DATA Request with callback ID 0x41 received (expected 0x41)
2020-05-01 09:28:36.943 Info, Node008, Request RTT 169 Average Request RTT 121
2020-05-01 09:28:36.943 Detail,   Expected callbackId was received
2020-05-01 09:28:36.943 Detail,   Expected reply was received
2020-05-01 09:28:36.943 Detail,   Message transaction complete
2020-05-01 09:28:36.943 Detail,
2020-05-01 09:28:36.943 Detail, Node008, Removing current message
2020-05-01 09:28:36.943 Detail,
2020-05-01 09:28:36.943 Info, Node008, Sending (Send) message (Callback ID=0x42, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=8): 0x01, 0x09, 0x00, 0x13, 0x08, 0x02, 0x25, 0x02, 0x25, 0x42, 0xaf
2020-05-01 09:28:36.952 Detail, Node008,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-05-01 09:28:36.952 Detail, Node008,   ZW_SEND_DATA delivered to Z-Wave stack
2020-05-01 09:28:37.017 Detail, Node008,   Received: 0x01, 0x07, 0x00, 0x13, 0x42, 0x00, 0x00, 0x07, 0xae
2020-05-01 09:28:37.017 Detail, Node008,   ZW_SEND_DATA Request with callback ID 0x42 received (expected 0x42)
2020-05-01 09:28:37.017 Info, Node008, Request RTT 74 Average Request RTT 97
2020-05-01 09:28:37.017 Detail,   Expected callbackId was received
2020-05-01 09:28:37.088 Detail, Node008,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x08, 0x03, 0x25, 0x03, 0xff, 0x20
2020-05-01 09:28:37.088 Detail,
2020-05-01 09:28:37.088 Info, Node008, Response RTT 145 Average Response RTT 164
2020-05-01 09:28:37.088 Info, Node008, Received SwitchBinary report from node 8: level=On
2020-05-01 09:28:37.088 Detail, Node008, Refreshed Value: old value=false, new value=true, type=bool
2020-05-01 09:28:37.088 Detail, Node008, Changes to this value are not verified
2020-05-01 09:28:37.088 Detail, Node008,   Expected reply and command class was received
2020-05-01 09:28:37.088 Detail, Node008,   Message transaction complete
2020-05-01 09:28:37.088 Detail,
2020-05-01 09:28:37.088 Detail, Node008, Removing current message
2020-05-01 09:28:37.088 Detail, Node008, Notification: ValueChanged
2020-05-01 09:28:37.138 Detail, Node008,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x08, 0x03, 0x25, 0x03, 0x00, 0xdf
2020-05-01 09:28:37.138 Detail,
2020-05-01 09:28:37.138 Info, Node008, Received SwitchBinary report from node 8: level=Off
2020-05-01 09:28:37.138 Detail, Node008, Refreshed Value: old value=true, new value=false, type=bool
2020-05-01 09:28:37.138 Detail, Node008, Changes to this value are not verified
2020-05-01 09:28:37.138 Detail, Node008, Notification: ValueChanged

From what I can derive from it, there are two reports coming from the switch, the first with level=On and the second with level=Off in a short succession after the first one. Maybe this makes HASS think the switch is off.

Sometimes (rarely though) everything behaves as expected (i.e. the toggle sticks to On), here’s the relevant log as well:

2020-05-01 11:07:05.826 Info, Node008, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
2020-05-01 11:07:05.827 Info, Node008, SwitchBinary::Set - Setting node 8 to On
2020-05-01 11:07:05.827 Detail, Node008, Queuing (Send) SwitchBinaryCmd_Set (Node=8): 0x01, 0x0a, 0x00, 0x13, 0x08, 0x03, 0x25, 0x01, 0xff, 0x25, 0xa4, 0xb7
2020-05-01 11:07:05.827 Detail, Node008, Queuing (Send) SwitchBinaryCmd_Get (Node=8): 0x01, 0x09, 0x00, 0x13, 0x08, 0x02, 0x25, 0x02, 0x25, 0xa5, 0x48
2020-05-01 11:07:05.827 Detail,
2020-05-01 11:07:05.827 Info, Node008, Sending (Send) message (Callback ID=0xa4, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=8): 0x01, 0x0a, 0x00, 0x13,
0x08, 0x03, 0x25, 0x01, 0xff, 0x25, 0xa4, 0xb7
2020-05-01 11:07:05.835 Detail, Node008,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-05-01 11:07:05.835 Detail, Node008,   ZW_SEND_DATA delivered to Z-Wave stack
2020-05-01 11:07:05.878 Detail, Node008,   Received: 0x01, 0x07, 0x00, 0x13, 0xa4, 0x00, 0x00, 0x05, 0x4a
2020-05-01 11:07:05.878 Detail, Node008,   ZW_SEND_DATA Request with callback ID 0xa4 received (expected 0xa4)
2020-05-01 11:07:05.879 Info, Node008, Request RTT 51 Average Request RTT 205
2020-05-01 11:07:05.879 Detail,   Expected callbackId was received
2020-05-01 11:07:05.879 Detail,   Expected reply was received
2020-05-01 11:07:05.879 Detail,   Message transaction complete
2020-05-01 11:07:05.879 Detail,
2020-05-01 11:07:05.879 Detail, Node008, Removing current message
2020-05-01 11:07:05.879 Detail,
2020-05-01 11:07:05.879 Info, Node008, Sending (Send) message (Callback ID=0xa5, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=8): 0x01, 0x09, 0x00, 0x13,
0x08, 0x02, 0x25, 0x02, 0x25, 0xa5, 0x48
2020-05-01 11:07:05.888 Detail, Node008,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-05-01 11:07:05.888 Detail, Node008,   ZW_SEND_DATA delivered to Z-Wave stack
2020-05-01 11:07:06.176 Detail, Node008,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x08, 0x03, 0x25, 0x03, 0xff, 0x20
2020-05-01 11:07:06.176 Detail,
2020-05-01 11:07:06.176 Info, Node008, Response RTT 298 Average Response RTT 652
2020-05-01 11:07:06.176 Info, Node008, Received SwitchBinary report from node 8: level=On
2020-05-01 11:07:06.176 Detail, Node008, Refreshed Value: old value=false, new value=true, type=bool
2020-05-01 11:07:06.176 Detail, Node008, Changes to this value are not verified
2020-05-01 11:07:06.176 Detail, Node008, Notification: ValueChanged
2020-05-01 11:07:07.563 Detail, Node008,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x08, 0x03, 0x25, 0x03, 0xff, 0x20
2020-05-01 11:07:07.563 Detail,
2020-05-01 11:07:07.563 Info, Node008, Response RTT 1685 Average Response RTT 1168
2020-05-01 11:07:07.563 Info, Node008, Received SwitchBinary report from node 8: level=On
2020-05-01 11:07:07.563 Detail, Node008, Refreshed Value: old value=true, new value=true, type=bool
2020-05-01 11:07:07.563 Detail, Node008, Changes to this value are not verified
2020-05-01 11:07:07.563 Detail, Node008, Notification: ValueChanged
2020-05-01 11:07:07.703 Detail, Node008,   Received: 0x01, 0x07, 0x00, 0x13, 0xa5, 0x00, 0x00, 0xb6, 0xf8
2020-05-01 11:07:07.703 Detail, Node008,   ZW_SEND_DATA Request with callback ID 0xa5 received (expected 0xa5)
2020-05-01 11:07:07.703 Info, Node008, Request RTT 1825 Average Request RTT 1015
2020-05-01 11:07:07.703 Detail,   Expected callbackId was received
2020-05-01 11:07:07.822 Detail, Node008,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x08, 0x03, 0x25, 0x03, 0xff, 0x20
2020-05-01 11:07:07.822 Detail,
2020-05-01 11:07:07.822 Info, Node008, Response RTT 1944 Average Response RTT 1556
2020-05-01 11:07:07.822 Info, Node008, Received SwitchBinary report from node 8: level=On
2020-05-01 11:07:07.822 Detail, Node008, Refreshed Value: old value=true, new value=true, type=bool
2020-05-01 11:07:07.822 Detail, Node008, Changes to this value are not verified
2020-05-01 11:07:07.822 Detail, Node008,   Expected reply and command class was received
2020-05-01 11:07:07.822 Detail, Node008,   Message transaction complete
2020-05-01 11:07:07.822 Detail,
2020-05-01 11:07:07.823 Detail, Node008, Removing current message
2020-05-01 11:07:07.823 Detail, Node008, Notification: ValueChanged
2020-05-01 11:07:07.898 Detail, Node008,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x08, 0x03, 0x25, 0x03, 0xff, 0x20
2020-05-01 11:07:07.898 Detail,
2020-05-01 11:07:07.898 Info, Node008, Received SwitchBinary report from node 8: level=On
2020-05-01 11:07:07.898 Detail, Node008, Refreshed Value: old value=true, new value=true, type=bool
2020-05-01 11:07:07.898 Detail, Node008, Changes to this value are not verified
2020-05-01 11:07:07.898 Detail, Node008, Notification: ValueChanged

Here I can see 4 reports (why though?), all with level=On.

None of my other Z-Wave switches show such behavior. This one is the farthest from the hub though. Here’s my network topology:

The problematic node is the one at the bottom. RTT fluctuates wildly between 200 and 1800 ms. Could high RTT be a probable root cause? If so, is there anything (configuration-wise) that can be done to compensate it?

freshcoast · May 1, 2020, 8:31pm

What version of firmware is your switch running? There have been some updates. https://www.support.getzooz.com/kb/article/302-zen26-s2-switch-change-log/

pnbruckner · May 1, 2020, 9:18pm

Please see the Z-Wave refresh_value and delay configuration parameters. Often for dimmable lights you must set refresh_value to true and set an appropriate delay value. This will cause HA to re-interrogate the light after the specified delay to update the entity that represents it.

firix · May 1, 2020, 9:26pm

Mine is on 2.01. I haven’t upgraded to the latest since updates don’t seem to be relevant for my problem, but can still give it a shot just in case.

firix · May 1, 2020, 9:27pm

Aren’t refresh_value and delay for the light platform only? My switch is not dimmable and is registered as a switch in HASS, not a light.

pnbruckner · May 1, 2020, 9:31pm

Yes, you’re right. Sorry, I misunderstood your question.

All of my switches and dimmable lights are GE/Jasco Z-Wave devices. I’ve never seen this problem exactly, so I guess I don’t have any other useful suggestions. Good luck!

freshcoast · May 1, 2020, 10:22pm

There were some notes about fixes to behavior regarding on/off status reports, however they seem to be only when not using a connected load, or disabled physical control. Still, might be worth a shot.

Like @pnbruckner I was originally going to suggest the refresh_value, but realized it was just a toggle switch. I have not seen this behavior before either. Your behavior is actually backwards from the dimmer problem, since the switch reports the correct state first, then reports the off state. If the switch is telling HA it is off, there isn’t much it can do. It’s almost as if the ‘off’ reply was a delayed response to the Get issued by OZW.

firix · May 2, 2020, 2:54am

Yeah, I’m probably gonna try a few things over the weekend. Will update the firmware to the latest and also probably swap this switch with some other one that is working reliably now. That in theory should narrow down the problem to either a faulty switch or something to do with the network topology.

firix · May 4, 2020, 4:53pm

Somewhat unexpectedly, but upgrading to the latest firmware has totally solved the problem. The switch now behaves correctly.