Z-Wave Switch ERROR: Dropping command, expected response not received after 1 attempt(s)

gourmetbreakfast · December 11, 2020, 2:34am

I am setting up my first Z-Wave network and trying it out with just the controller and one z-wave switch. It’s an Eaton accessory switch. It shows up just fine as RF9517 Accessory Light Switch and there is a Remote Switch Switch entity. But when I try to toggle it, the command fails.

I’m using Home Assistant 0.118.5 on a Raspberry Pi 3 B and a Zooz Z-Wave Plus S2 USB Stick ZST10.

2020-12-10 21:24:12.484 Detail, Node005, Removing current message
2020-12-10 21:24:12.484 Detail, Node005, Notification: Notification - TimeOut
2020-12-10 21:24:14.406 Detail, Node001, Queuing (Controller) Request Node Neighbor Update
2020-12-10 21:24:14.406 Detail, Node005, Queuing (Controller) Request Node Neighbor Update
2020-12-10 21:24:14.407 Info, Requesting Neighbor Update for node 1
2020-12-10 21:24:14.407 Detail, Node001, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x20, 0x93
2020-12-10 21:24:14.407 Detail, Notification: ControllerCommand - Starting
2020-12-10 21:24:14.408 Detail, 
2020-12-10 21:24:14.408 Info, Node001, Sending (Command) message (Callback ID=0x20, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x20, 0x93
2020-12-10 21:24:14.554 Detail, Node001,   Received: 0x01, 0x05, 0x00, 0x48, 0x20, 0x21, 0xb3
2020-12-10 21:24:14.554 Detail, 
2020-12-10 21:24:14.554 Info, Node001, REQUEST_NEIGHBOR_UPDATE_STARTED
2020-12-10 21:24:14.554 Detail, Node033,   Expected callbackId was received
2020-12-10 21:24:14.554 Detail, Node033,   Expected reply was received
2020-12-10 21:24:14.554 Detail, Node033,   Message transaction complete
2020-12-10 21:24:14.554 Detail, 
2020-12-10 21:24:14.554 Detail, Node001, Removing current message
2020-12-10 21:24:14.554 Detail, Notification: ControllerCommand - InProgress
2020-12-10 21:24:14.555 Info, WriteNextMsg Controller nothing to do
2020-12-10 21:24:24.210 Detail,   Received: 0x01, 0x05, 0x00, 0x48, 0x20, 0x23, 0xb1
2020-12-10 21:24:24.210 Detail, 
2020-12-10 21:24:24.210 Warning, WARNING: REQUEST_NEIGHBOR_UPDATE_FAILED
2020-12-10 21:24:24.210 Detail, Notification: ControllerCommand - Failed
2020-12-10 21:24:24.211 Info, Requesting Neighbor Update for node 5
2020-12-10 21:24:24.211 Detail, Node005, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=5): 0x01, 0x05, 0x00, 0x48, 0x05, 0x21, 0x96
2020-12-10 21:24:24.212 Detail, Notification: ControllerCommand - Starting
2020-12-10 21:24:24.212 Detail, 
2020-12-10 21:24:24.212 Info, Node005, Sending (Command) message (Callback ID=0x21, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=5): 0x01, 0x05, 0x00, 0x48, 0x05, 0x21, 0x96
2020-12-10 21:24:24.234 Detail, Node005,   Received: 0x01, 0x05, 0x00, 0x48, 0x21, 0x21, 0xb2
2020-12-10 21:24:24.234 Detail, 
2020-12-10 21:24:24.234 Info, Node005, REQUEST_NEIGHBOR_UPDATE_STARTED
2020-12-10 21:24:24.234 Detail, Node033,   Expected callbackId was received
2020-12-10 21:24:24.234 Detail, Node033,   Expected reply was received
2020-12-10 21:24:24.234 Detail, Node033,   Message transaction complete
2020-12-10 21:24:24.234 Detail, 
2020-12-10 21:24:24.234 Detail, Node005, Removing current message
2020-12-10 21:24:24.234 Detail, Notification: ControllerCommand - InProgress
2020-12-10 21:24:24.236 Info, WriteNextMsg Controller nothing to do
2020-12-10 21:24:24.579 Detail,   Received: 0x01, 0x05, 0x00, 0x48, 0x21, 0x22, 0xb1
2020-12-10 21:24:24.580 Detail, 
2020-12-10 21:24:24.580 Info, REQUEST_NEIGHBOR_UPDATE_DONE
2020-12-10 21:24:24.580 Detail, Requesting routing info (neighbor list) for Node 5
2020-12-10 21:24:24.580 Detail, Node005, Queuing (Command) Get Routing Info (Node=5): 0x01, 0x07, 0x00, 0x80, 0x05, 0x00, 0x00, 0x03, 0x7e
2020-12-10 21:24:24.580 Detail, Notification: ControllerCommand - Completed
2020-12-10 21:24:24.581 Detail, 
2020-12-10 21:24:24.581 Info, Node005, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=5): 0x01, 0x07, 0x00, 0x80, 0x05, 0x00, 0x00, 0x03, 0x7e
2020-12-10 21:24:24.586 Detail, Node005,   Received: 0x01, 0x20, 0x01, 0x80, 0x01, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x5f
2020-12-10 21:24:24.586 Detail, 
2020-12-10 21:24:24.586 Info, Node005, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2020-12-10 21:24:24.586 Info, Node005,     Neighbors of this node are:
2020-12-10 21:24:24.586 Info, Node005,     Node 1
2020-12-10 21:24:24.586 Detail,   Expected reply was received
2020-12-10 21:24:24.586 Detail,   Message transaction complete
2020-12-10 21:24:24.586 Detail, 
2020-12-10 21:24:24.586 Detail, Node005, Removing current message
2020-12-10 21:24:37.926 Info, Node005, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
2020-12-10 21:24:37.927 Info, Node005, SwitchBinary::Set - Setting node 5 to On
2020-12-10 21:24:37.927 Detail, Node005, Queuing (Send) SwitchBinaryCmd_Set (Node=5): 0x01, 0x0a, 0x00, 0x13, 0x05, 0x03, 0x25, 0x01, 0xff, 0x25, 0x22, 0x3c
2020-12-10 21:24:37.927 Detail, Node005, Queuing (Send) SwitchBinaryCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x25, 0x02, 0x25, 0x23, 0xc3
2020-12-10 21:24:37.927 Detail, 
2020-12-10 21:24:37.927 Info, Node005, Sending (Send) message (Callback ID=0x22, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=5): 0x01, 0x0a, 0x00, 0x13, 0x05, 0x03, 0x25, 0x01, 0xff, 0x25, 0x22, 0x3c
2020-12-10 21:24:37.936 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-12-10 21:24:37.936 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2020-12-10 21:24:37.957 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x22, 0x00, 0x00, 0x03, 0x00, 0xb8, 0x7f, 0x7f, 0x7f, 0x7f, 0x01, 0x01, 0x04, 0x00, 0x00, 0x00, 0x00, 0x02, 0x01, 0x00, 0x00, 0x6a
2020-12-10 21:24:37.957 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x22 received (expected 0x22)
2020-12-10 21:24:37.957 Info, Node005, Request RTT 29 Average Request RTT 28
2020-12-10 21:24:37.957 Detail,   Expected callbackId was received
2020-12-10 21:24:37.957 Detail,   Expected reply was received
2020-12-10 21:24:37.957 Detail,   Message transaction complete
2020-12-10 21:24:37.957 Detail, 
2020-12-10 21:24:37.957 Detail, Node005, Removing current message
2020-12-10 21:24:37.957 Detail, 
2020-12-10 21:24:37.958 Info, Node005, Sending (Send) message (Callback ID=0x23, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x25, 0x02, 0x25, 0x23, 0xc3
2020-12-10 21:24:37.966 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-12-10 21:24:37.966 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2020-12-10 21:24:37.986 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x23, 0x00, 0x00, 0x03, 0x00, 0xb8, 0x7f, 0x7f, 0x7f, 0x7f, 0x01, 0x01, 0x03, 0x00, 0x00, 0x00, 0x00, 0x02, 0x01, 0x00, 0x00, 0x6c
2020-12-10 21:24:37.986 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x23 received (expected 0x23)
2020-12-10 21:24:37.986 Info, Node005, Request RTT 28 Average Request RTT 28
2020-12-10 21:24:37.986 Detail,   Expected callbackId was received
2020-12-10 21:24:42.493 Detail, Node005, Polling: COMMAND_CLASS_SWITCH_BINARY index = 0 instance = 1 (poll queue has 0 messages)
2020-12-10 21:24:42.493 Detail, Node005, Queuing (Poll) SwitchBinaryCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x25, 0x02, 0x25, 0x24, 0xc4
2020-12-10 21:24:47.958 Error, Node005, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-12-10 21:24:47.959 Detail, Node005, Removing current message
2020-12-10 21:24:47.959 Detail, Node005, Notification: Notification - TimeOut
2020-12-10 21:24:47.962 Detail, 
2020-12-10 21:24:47.963 Info, Node005, Sending (Poll) message (Callback ID=0x24, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x25, 0x02, 0x25, 0x24, 0xc4
2020-12-10 21:24:47.971 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-12-10 21:24:47.972 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2020-12-10 21:24:47.991 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x24, 0x00, 0x00, 0x02, 0x00, 0xb6, 0x7f, 0x7f, 0x7f, 0x7f, 0x01, 0x01, 0x03, 0x00, 0x00, 0x00, 0x00, 0x02, 0x01, 0x00, 0x00, 0x64
2020-12-10 21:24:47.991 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x24 received (expected 0x24)
2020-12-10 21:24:47.991 Info, Node005, Request RTT 28 Average Request RTT 28
2020-12-10 21:24:47.991 Detail,   Expected callbackId was received
2020-12-10 21:24:57.963 Error, Node005, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-12-10 21:24:57.963 Detail, Node005, Removing current message
2020-12-10 21:24:57.963 Detail, Node005, Notification: Notification - TimeOut

RickKramer · December 11, 2020, 10:18am

What is the distance between the devices? Is it possible they are too far apart to communicate?

gourmetbreakfast · December 11, 2020, 12:58pm

At first, the devices were one floor apart (controller in basement, switch on main floor). I’ve since moved the RPI to the same floor as the switch and same result.

I thought it might be a faulty switch, so I tried it with a different accessory switch that was in the same room as the ZooZ controller and same result.

Update: I tried swapping out the ZooZ with a GoControl CECOMINOD016164 HUSBZB-1 USB Hub. Same result.

Update: The switch I was trying to get to work was an accessory switch. I tried with a master/primary switch of the same make. Works perfectly fine. I’m going to write this off as this particular model of accessory switch not playing well with OpenZWave / Home Assisstant.